工欲善其事，必先利其器

很多程序員可能都忘了記錄應(yīng)用程序的行為是一件多么重要的事，當(dāng)遇到多線程環(huán)境下高壓力導(dǎo)致的并發(fā)bug時(shí)，你就能體會(huì)到記錄log的重要性。

有的人很高興的就在代碼里加上了這么句：

log.info("Happy and carefree logging");

他可能都沒(méi)有意識(shí)到應(yīng)用程序的日志在維護(hù)，調(diào)優(yōu)和故障識(shí)別中的重要性。我認(rèn)為slf4j是最好的日志API，最主要是因?yàn)樗С忠粋€(gè)很棒的模式注入的方式：

log.debug("Found {} records matching filter: '{}'", records, filter);

log4j的話你只能這樣：

log.debug("Found " + records + " recordsmatching filter: '" + filter + "'");

這樣寫(xiě)不僅更啰嗦和可讀性差，而且字符串拼接影響效率（當(dāng)這個(gè)級(jí)別并不需要輸出的時(shí)候）。

slf4j引入了{(lán)}注入特性，并且由于避免了每次都進(jìn)行字符串拼接，toString方法不會(huì)被調(diào)用，也不再需要加上isDebugEnabled了。slf4j是外觀模式的一種應(yīng)用，它只是一個(gè)門(mén)面。具體實(shí)現(xiàn)的話我推薦logback框架，之前已經(jīng)做過(guò)一次廣告了，而不是已經(jīng)很完備的log4j。它有許多很有意思的特性，和log4j不同的是，它還在積極的開(kāi)發(fā)完善中。

還有一個(gè)要推薦的工具是perf4j：

Perf4J is to System.currentTimeMillis() as log4j is to System.out.println()

就好比log4j是System.out.println的一種更好的替換方式一樣，perf4j更像是System.currentTimeMillis()的替代。我已經(jīng)在一個(gè)項(xiàng)目中引入了perf4j，并在高負(fù)載的情況下觀察它的表現(xiàn)。管理員和企業(yè)用戶(hù)都被這個(gè)小工具提供的漂亮的圖表驚呆了。我們可以隨時(shí)查看性能問(wèn)題。perf4j應(yīng)該專(zhuān)門(mén)開(kāi)一篇文章來(lái)講，現(xiàn)在的話可以先看下它的開(kāi)發(fā)者指南。還有一個(gè)Ceki Gülcü（log4j,slf4j和logback工程的創(chuàng)建者）提供了一個(gè)簡(jiǎn)單的方法供我們移除對(duì)commons-logging的依賴(lài)。

不要忘了日志級(jí)別

每次你要加一行日志的時(shí)候，你都會(huì)想，這里該用哪種日志級(jí)別？大概有90%的程序員都不太注意這個(gè)問(wèn)題，都是用一個(gè)級(jí)別來(lái)記錄日志，通常不是INFO就是DEBUG。為什么？

日志框架和System.out相比有兩大優(yōu)勢(shì)：分類(lèi)和級(jí)別。兩者可以讓你可以選擇性的過(guò)濾日志，永久的或者只是在排查錯(cuò)誤的時(shí)候。

ERROR :發(fā)生了嚴(yán)重的錯(cuò)誤，必須馬上處理。這種級(jí)別的錯(cuò)誤是任何系統(tǒng)都無(wú)法容忍的。比如：空指針異常，數(shù)據(jù)庫(kù)不可用，關(guān)鍵路徑的用例無(wú)法繼續(xù)執(zhí)行。

WARN :還會(huì)繼續(xù)執(zhí)行后面的流程，但應(yīng)該引起重視。其實(shí)在這里我希望有兩種級(jí)別：一個(gè)是存在解決方案的明顯的問(wèn)題（比如，"當(dāng)前數(shù)據(jù)不可用，使用緩存數(shù)據(jù)"），另一個(gè)是潛在的問(wèn)題和建議（比如“程序運(yùn)行在開(kāi)發(fā)模式下”或者“管理控制臺(tái)的密碼不夠安全”）。應(yīng)用程序可以容忍這些信息，不過(guò)它們應(yīng)該被檢查及修復(fù)。

DEBUG :開(kāi)發(fā)人員關(guān)注的事。后面我會(huì)講到什么樣的東西應(yīng)該記錄到這個(gè)級(jí)別。

TRACE :更為詳盡的信息，只是開(kāi)發(fā)階段使用。在產(chǎn)品上線之后的一小段時(shí)間內(nèi)你可能還需要關(guān)注下這些信息，不過(guò)這些日志記錄只是臨時(shí)性的，最終應(yīng)該關(guān)掉。DEBUG和TRACE的區(qū)別很難區(qū)分，不過(guò)如果你加了一行日志，在開(kāi)發(fā)測(cè)試完后又刪了它的話，這條日志就應(yīng)該是TRACE級(jí)別的。

上面的列表只是一個(gè)建議，你可以根據(jù)自己的規(guī)則來(lái)記錄日志，但最好要有一定的規(guī)則。我個(gè)人的經(jīng)驗(yàn)是：在代碼層面不要進(jìn)行日志過(guò)濾，而是用正確的日志級(jí)別能夠快速的過(guò)濾出想要的信息，這樣能節(jié)省你很多時(shí)間。

最后要說(shuō)的就是這個(gè)臭名昭著的is*Enabled的條件語(yǔ)句了。有的人喜歡把每次日志前加上這個(gè)：

if(log.isDebugEnabled())
 log.debug("Place for your commercial");

個(gè)人認(rèn)為，應(yīng)該避免在代碼里加入這個(gè)亂哄哄的東西。性能看起來(lái)沒(méi)有什么提升（尤其是用了slf4j之后）,更像是過(guò)早的優(yōu)化。還有，沒(méi)發(fā)現(xiàn)這么做有點(diǎn)多余么？很少有時(shí)候是明確需要這種顯式的判斷語(yǔ)句的，除非我們證明構(gòu)造日志消息本身開(kāi)銷(xiāo)太大。不然的話，該怎么記就怎么記，讓日志框架去操心這個(gè)吧。

你清楚你在記錄什么嗎？

每次你寫(xiě)下一行日志，花點(diǎn)時(shí)間看看你到底在日志文件里打印了些什么。讀一遍你的日志，找出異常的地方。首先，至少要避免空指針異常：

log.debug("Processing request with id: {}", request.getId());

你確認(rèn)過(guò)request不是null了嗎？

記錄集合也是一個(gè)大坑。如果你用Hibernate從數(shù)據(jù)庫(kù)里獲取領(lǐng)域?qū)ο蟮募系臅r(shí)候,不小心寫(xiě)成了這樣：log.debug("Returning users: {}", users);

slf4j只會(huì)在這條語(yǔ)句確實(shí)會(huì)打印的時(shí)候調(diào)用toString方法，當(dāng)然這個(gè)很酷。不過(guò)如果內(nèi)存溢出了，N+1選擇問(wèn)題，線程餓死，延遲初始化異常，日志存儲(chǔ)空間用完了...這些都有可能發(fā)生。最好的方式是只記錄對(duì)象的ID（或者只記錄集合的大?。２贿^(guò)收集ID需要對(duì)每個(gè)對(duì)象調(diào)用getId方法，這個(gè)在Java里可真不是件簡(jiǎn)單的事。Groovy有個(gè)很棒的展開(kāi)操作符（users*.id）,在Java里我們可以用Commons Beanutils庫(kù)來(lái)模擬下：

log.debug("Returning user ids: {}", collect(users, "id"));

collect方法大概是這么實(shí)現(xiàn)的：

public static Collection collect(Collection collection, String propertyName) {
 return CollectionUtils.collect(collection, new BeanToPropertyValueTransformer(propertyName));
}

最后要說(shuō)的是，toString方法可能沒(méi)有正確的實(shí)現(xiàn)或者使用。

首先，為了記錄日志，為每個(gè)類(lèi)創(chuàng)建一個(gè)toString的做法比比皆是，最好用 ToStringBuilder來(lái)生成（不過(guò)不是它的反射實(shí)現(xiàn)的那個(gè)版本）。

第二，注意數(shù)組和非典型的集合。數(shù)組和一些另類(lèi)的集合的toString實(shí)現(xiàn)可能沒(méi)有挨個(gè)調(diào)用每個(gè)元素的toString方法。可以使用JDK提供的Arrays#deepToString方法。經(jīng)常檢查一下你自己打印的日志，看有沒(méi)有格式異常的一些信息。

避免副作用

日志打印一般對(duì)程序的性能沒(méi)有太大影響。最近我一個(gè)朋友在一些特殊的平臺(tái)上運(yùn)行的一個(gè)系統(tǒng)拋出了Hibernate的LazyInitializationException異常。你可能從這已經(jīng)猜到了，當(dāng)會(huì)話連接進(jìn)來(lái)的時(shí)候，一些日志打印導(dǎo)致延遲初始化的集合被加載。在這種情況下，把日志級(jí)別提高了，集合也就不再被初始化了。如果你不知道這些上下文信息，你得花多長(zhǎng)時(shí)間來(lái)發(fā)現(xiàn)這個(gè)BUG。

另一個(gè)副作用就是影響程序的運(yùn)行速度?？焖倩卮鹨幌逻@個(gè)問(wèn)題：如果日志打印的過(guò)多或者沒(méi)有正確的使用toString和字符串拼接，日志打印就會(huì)對(duì)性能產(chǎn)生負(fù)面影響。能有多大？好吧，我曾經(jīng)見(jiàn)過(guò)一個(gè)程序每15分鐘就重啟一次，因?yàn)樘嗟娜罩緦?dǎo)致的線程餓死。這就是副作用！從我的經(jīng)驗(yàn)來(lái)看，一小時(shí)打印百來(lái)兆差不多就是上限了。

當(dāng)然如果由于日志打印異常導(dǎo)致的業(yè)務(wù)進(jìn)程中止，這個(gè)副作用就大了。我經(jīng)常見(jiàn)到有人為了避免這個(gè)而這么寫(xiě)：

try {
 log.trace("Id=" + request.getUser().getId() + " accesses " + manager.getPage().getUrl().toString())
} catch(NullPointerException e) {}

這是段真實(shí)的代碼，但是為了讓世界清凈點(diǎn)，請(qǐng)不要這么寫(xiě)。

描述要清晰

每個(gè)日志記錄都會(huì)包含數(shù)據(jù)和描述。看下這個(gè)例子：

log.debug("Message processed");
log.debug(message.getJMSMessageID());
log.debug("Message with id '{}' processed", message.getJMSMessageID());

當(dāng)在一個(gè)陌生的系統(tǒng)里排查錯(cuò)誤的時(shí)候，你更希望看到哪種日志？相信我，上面這些例子都很常見(jiàn)。還有一個(gè)反面模式：

if(message instanceof TextMessage)
    //...
else
    log.warn("Unknown message type"); 

在這個(gè)警告日志里加上消息類(lèi)型，消息ID等等這些難道很困難嗎？我是知道發(fā)生錯(cuò)誤了，不過(guò)到底是什么錯(cuò)誤？上下文信息是什么？

第三個(gè)反面例子是“魔法日志”。一個(gè)真實(shí)的例子：團(tuán)隊(duì)里的很多程序員都知道，3個(gè)&號(hào)后面跟著！號(hào)再跟著一個(gè)#號(hào)，再跟著一個(gè)偽隨機(jī)數(shù)的日志意味著”ID為XYZ的消息收到了”。沒(méi)人愿意改這個(gè)日志，某人敲下鍵盤(pán)，選中某個(gè)唯一的”&&&!#”字符串，他就能很快找到想要的信息。

結(jié)果是，整個(gè)日志文件看起來(lái)像一大串隨機(jī)字符。有人不禁會(huì)懷疑這是不是一個(gè)perl程序。

日志文件應(yīng)當(dāng)是可讀性強(qiáng)的，清晰的，自描述的。不要用一些魔數(shù)，記錄值，數(shù)字，ID還有它們的上下文。記錄處理的數(shù)據(jù)以及它的含義。記錄程序正在干些什么。好的日志應(yīng)該是程序代碼的一份好的文檔。

我有提過(guò)不要打印密碼還有個(gè)人信息嗎？相信沒(méi)有這么傻的程序員。

調(diào)整你的格式

日志格式是個(gè)很有用的工具，無(wú)形中在日志添加了很有價(jià)值的上下文信息。不過(guò)你應(yīng)該想清楚，在你的格式中包含什么樣的信息。比如說(shuō)，在每小時(shí)循環(huán)寫(xiě)入的日志中記錄日期是沒(méi)有意義的，因?yàn)槟愕娜罩久鸵呀?jīng)包含了這個(gè)信息。相反的，如果你沒(méi)記錄線程名的話當(dāng)兩個(gè)線程并行的工作的時(shí)候，你就無(wú)法通過(guò)日志跟蹤線程了——日志已經(jīng)重疊到一起了。在單線程的應(yīng)用程序中，這樣做沒(méi)問(wèn)題，不過(guò)那個(gè)已經(jīng)是過(guò)去的事兒了。

從我的經(jīng)驗(yàn)來(lái)看，理想的日志格式應(yīng)當(dāng)包括（當(dāng)然除了日志信息本身了）：當(dāng)前時(shí)間（無(wú)日期，毫秒級(jí)精度），日志級(jí)別，線程名，簡(jiǎn)單的日志名稱(chēng)（不用全稱(chēng)）還有消息。在logback里會(huì)是這樣的：

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
 <encoder>
  <pattern>%d{HH:mm:ss.SSS} %-5level [%thread][%logger{0}] %m%n</pattern>
 </encoder>
</appender> 

文件名，類(lèi)名，行號(hào)，都不用列進(jìn)來(lái)，盡管它們看起來(lái)很有用。我還在代碼里見(jiàn)過(guò)空的日志記錄：

log.info(""); 因?yàn)槌绦騿T認(rèn)為行號(hào)會(huì)作為日志格式的一部分，并且他知道如果空日志消息出現(xiàn)在這個(gè)文件的67行的話，意味著這個(gè)用戶(hù)是認(rèn)證過(guò)的。不僅這樣，記錄類(lèi)名方法名，或者行號(hào)對(duì)性能都有很大的影響。

日志框架的一個(gè)比較高級(jí)的特性是診斷上下文映射（Mapped Diagnostic Context）。MDC只是一個(gè)線程本地的一個(gè)map。你可以把任何鍵值對(duì)放到這個(gè)map里，這樣的話這個(gè)線程的所有日志記錄都能從這個(gè)map里取到相應(yīng)的信息作為輸出格式的一部分。

記錄方法的參數(shù)和返回值

如果你在開(kāi)發(fā)階段發(fā)現(xiàn)了一個(gè)BUG，你通常會(huì)用調(diào)試器來(lái)跟蹤具體的原因?，F(xiàn)在假設(shè)不讓你用調(diào)試器了，比如，因?yàn)檫@個(gè)BUG幾天前在用戶(hù)的環(huán)境里出現(xiàn)了，你能拿到的只有一些日志。你能從中發(fā)現(xiàn)些什么？

如果你遵循打印每個(gè)方法的入?yún)⒑统鰠⑦@個(gè)簡(jiǎn)單的原則，你根本不需要調(diào)試器。當(dāng)然每個(gè)方法可能訪問(wèn)外部系統(tǒng)，阻塞，等待，等等，這些都應(yīng)該考慮進(jìn)來(lái)。就參考以下這個(gè)格式就好：

public String printDocument(Document doc, Mode mode) {
 log.debug("Entering printDocument(doc={}, mode={})", doc, mode);
 String id = ...; //Lengthy printing operation
 log.debug("Leaving printDocument(): {}", id);
 return id;
}

由于你在方法的開(kāi)始和結(jié)束都記錄了日志，所以你可以人工找出效率不高的代碼，甚至還可以檢測(cè)到可能會(huì)引起死鎖和饑餓的誘因——你只需看一下“Entering”后面是不是沒(méi)有”Leaving“就明白了。如果你的方法名的含義很清晰，清日志將是一件愉快的事情。同樣的，分析異常也更得更簡(jiǎn)單了，因?yàn)槟阒烂恳徊蕉荚诟尚┦裁础４a里要記錄的方法很多的話，可以用AOP切面來(lái)完成。這樣減少了重復(fù)的代碼，不過(guò)使用它得特別小心，不注意的話可能會(huì)導(dǎo)致輸出大量的日志。

這種日志最合適的級(jí)別就是DEBUG和TRACE了。如果你發(fā)現(xiàn)某個(gè)方法調(diào)用 的太頻繁，記錄它的日志可能會(huì)影響性能的話，只需要調(diào)低它的日志級(jí)別就可以了，或者把日志直接刪了（或者整個(gè)方法調(diào)用只留一個(gè)？）不過(guò)日志多了總比少了要強(qiáng)。把日志記錄當(dāng)成單元測(cè)試來(lái)看，你的代碼應(yīng)該布滿了日志就像它的單元測(cè)試到處都是一樣。系統(tǒng)沒(méi)有任何一部分是完全不需要日志的。記住，有時(shí)候要知道你的系統(tǒng)是不是正常工作，你只能查看不斷刷屏的日志。

觀察外部系統(tǒng)

這條建議和前面的有些不同：如果你和一個(gè)外部系統(tǒng)通信的話，記得記錄下你的系統(tǒng)傳出和讀入的數(shù)據(jù)。系統(tǒng)集成是一件苦差事，而診斷兩個(gè)應(yīng)用間的問(wèn)題(想像下不同的公司，環(huán)境，技術(shù)團(tuán)隊(duì)）尤其困難。最近我們發(fā)現(xiàn)記錄完整的消息內(nèi)容，包括Apache CXF的SOAP和HTTP頭，在系統(tǒng)的集成和測(cè)試階段非常有效。

這樣做開(kāi)銷(xiāo)很大，如果影響到了性能的話，你只能把日志關(guān)了。不過(guò)這樣你的系統(tǒng)可能跑的很快，掛的也很快，你還無(wú)能為力？當(dāng)和外部系統(tǒng)進(jìn)行集成的時(shí)候，你只能格外小心并做好犧牲一定開(kāi)銷(xiāo)的準(zhǔn)備。如果你運(yùn)氣夠好，系統(tǒng)集成由ESB處理了，那在總線把請(qǐng)求和響應(yīng)給記錄下來(lái)就最好不過(guò)了?？梢詤⒖枷翸ule的這個(gè)日志組件。

有時(shí)候和外部系統(tǒng)交換的數(shù)據(jù)量決定了你不可能什么都記下來(lái)。另一方面，在測(cè)試階段和發(fā)布初期，最好把所有東西都記到日志里，做好犧牲性能的準(zhǔn)備。可以通過(guò)調(diào)整日志級(jí)別來(lái)完成這個(gè)。看下下面這個(gè)小技巧：

Collection<Integer> requestIds = //...
if(log.isDebugEnabled())
 log.debug("Processing ids: {}", requestIds);
else
 log.info("Processing ids size: {}", requestIds.size()); 

如果這個(gè)logger是配置成DEBUG級(jí)別，它會(huì)打印完整的請(qǐng)求ID的集合。如果它配置成了打印INFO信息的話，就只會(huì)輸出集合的大小。你可能會(huì)問(wèn)我是不是忘了isInfoEnabled條件了，看下第二點(diǎn)建議吧。這里還有一個(gè)值得注意的是ID的集合不能為null。盡管在DEBUG下，它為NULL也能正常打印，但是當(dāng)配置成INFO的時(shí)候一個(gè)大大的空指針。還記得第4點(diǎn)建議中提到的副作用吧？

正確的記錄異常

首先，不要記錄異常，讓框架或者容器來(lái)干這個(gè)。當(dāng)然有一個(gè)例外：如果你從遠(yuǎn)程服務(wù)中拋出了異常（RMI，EJB等），異常會(huì)被序列化，確保它們能返回給客戶(hù)端 （API中的一部分）。不然的話，客戶(hù)端會(huì)收到NoClassDefFoundError或者別的古怪的異常，而不是真正的錯(cuò)誤信息。

異常記錄是日志記錄的最重要的職責(zé)之一，不過(guò)很多程序員都傾向于把記錄日志當(dāng)作處理異常的方式。他們通常只是返回默認(rèn)值（一般是null,0或者空字符串），裝作什么也沒(méi)發(fā)生一樣。還有的時(shí)候，他們會(huì)先記錄異常，然后把異常包裝了下再拋出去：

log.error("IO exception", e);
throw new CustomException(e); 

這樣寫(xiě)通常會(huì)把棧信息打印兩次，因?yàn)椴东@了MyCustomException異常的地方也會(huì)再打印一次。日志記錄，或者包裝后再拋出去，不要同時(shí)使用，否則你的日志看起來(lái)會(huì)讓人很迷惑。

如果我們真的想記錄日志呢？由于某些原因（大概是不讀API和文檔？），大約有一半的日志記錄我認(rèn)為是錯(cuò)誤的。做個(gè)小測(cè)試，下面哪個(gè)日志語(yǔ)句能夠正確的打印空指針異常？

try {
 Integer x = null;
 ++x;
} catch (Exception e) {
 log.error(e); //A
 log.error(e, e); //B
 log.error("" + e); //C
 log.error(e.toString()); //D
 log.error(e.getMessage()); //E
 log.error(null, e); //F
 log.error("", e); //G
 log.error("{}", e); //H
 log.error("{}", e.getMessage()); //I
 log.error("Error reading configuration file: " + e); //J
 log.error("Error reading configuration file: " + e.getMessage()); //K
 log.error("Error reading configuration file", e); //L
}

很奇怪吧，只有G和L（這個(gè)更好）是對(duì)的！A和B在slf4j下面根本就編譯不過(guò)，其它的會(huì)把棧跟蹤信息給丟掉了或者打印了不正確的信息。比如，E什么也不打印，因?yàn)榭罩羔槷惓１旧頉](méi)有提供任何異常信息而棧信息又沒(méi)打印出來(lái) .記住，第一個(gè)參數(shù)通常都是文本信息，關(guān)于這個(gè)錯(cuò)誤本身的。不要把異常信息給寫(xiě)進(jìn)來(lái)，打印日志后它會(huì)自動(dòng)出來(lái)的，在棧信息的前面。不過(guò)想要打印這個(gè)，你當(dāng)然還得把異常傳到第二個(gè)參數(shù)里面才行。

日志應(yīng)當(dāng)可讀性強(qiáng)且易于解析

現(xiàn)在有兩組用戶(hù)對(duì)你的日志感興趣：我們?nèi)祟?lèi)（不管你同不同意，碼農(nóng)也是在這里邊），還有計(jì)算機(jī)（通常就是系統(tǒng)管理員寫(xiě)的shell腳本）。日志應(yīng)當(dāng)適合這兩種用戶(hù)來(lái)理解。如果有人在你后邊看你的程序的日志卻看到了這個(gè)：

那你肯定沒(méi)聽(tīng)從我的建議。日志應(yīng)該像代碼一樣易于閱讀和理解。

另一方面，如果你的程序每小時(shí)就生成了半GB的日志，沒(méi)有誰(shuí)或者任何圖形化的文本編輯器能把它們看完。這時(shí)候我們的老家伙們，grep,sed和awk這些上場(chǎng)的時(shí)候就來(lái)了。如果有可能的話，你記錄的日志最好能讓人和計(jì)算機(jī)都能看明白 ，不要將數(shù)字格式化，用一些能讓正則容易匹配的格式等等。如果不可能的，用兩個(gè)格式來(lái)打印數(shù)據(jù)：

log.debug("Request TTL set to: {} ({})", new Date(ttl), ttl);
// Request TTL set to: Wed Apr 28 20:14:12 CEST 2010 (1272478452437)
final String duration = DurationFormatUtils.formatDurationWords(durationMillis, true, true);
log.info("Importing took: {}ms ({})", durationMillis, duration);
//Importing took: 123456789ms (1 day 10 hours 17 minutes 36 seconds) 

計(jì)算機(jī)看到”ms after 1970 epoch“這樣的的時(shí)間格式會(huì)感謝你的，而人們則樂(lè)于看到”1天10小時(shí)17分36秒“這樣的東西。

總之，日志也可以寫(xiě)得像詩(shī)一樣優(yōu)雅，如果你愿意琢磨的話。

以上就是對(duì)java 日志調(diào)整輸出格式的資料整理，有興趣的朋友可以參考下。

最新評(píng)論