用JAVA日誌來寫詩

工欲善其事，必先利其器

不少程序員可能都忘了記錄應用程序的行爲是一件多麼重要的事，當遇到多線程環境下高壓力致使的併發bug時，你就能體會到記錄log的重要性。

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

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

他可能都沒有意識到應用程序的日誌在維護，調優和故障識別中的重要性。
我認爲slf4j是最好的日誌API，最主要是由於它支持一個很棒的模式注入的方式：

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

log4j的話你只能這樣：

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

這樣寫不只更囉嗦和可讀性差，並且字符串拼接影響效率（當這個級別並不須要輸出的時候）。

slf4j引入了{}注入特性，而且因爲避免了每次都進行字符串拼接，toString方法不會被調用，也再也不須要加上isDebugEnabled了。

slf4j是外觀模式的一種應用，它只是一個門面。具體實現的話我推薦logback框架，以前已經作過一次廣告了，而不是已經很完備的log4j。它有許多頗有意思的特性，和log4j不一樣的是，它還在積極的開發完善中。

還有一個要推薦的工具是perf4j：

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

就比如log4j是System.out.println的一種更好的替換方式同樣，perf4j更像是System.currentTimeMillis()的替代。

我已經在一個項目中引入了perf4j，並在高負載的狀況下觀察它的表現。管理員和企業用戶都被這個小工具提供的漂亮的圖表驚呆了。

咱們能夠隨時查看性能問題。perf4j應該專門開一篇文章來說，如今的話能夠先看下它的開發者指南。

還有一個Ceki Gülcü（log4j,slf4j和logback工程的建立者）提供了一個簡單的方法供咱們移除對commons-logging的依賴。

不要忘了日誌級別

每次你要加一行日誌的時候，你都會想，這裏該用哪一種日誌級別？大概有90%的程序員都不太注意這個問題，都是用一個級別來記錄日誌，一般不是INFO就是DEBUG。爲何？

日誌框架和System.out相比有兩大優點：分類和級別。二者可讓你能夠選擇性的過濾日誌，永久的或者只是在排查錯誤的時候。

• ERROR 發生了嚴重的錯誤，必須立刻處理。這種級別的錯誤是任何系統都沒法容忍的。好比：空指針異常，數據庫不可用，關鍵路徑的用例沒法繼續執行。
• WARN 還會繼續執行後面的流程，但應該引發重視。其實在這裏我但願有兩種級別：一個是存在解決方案的明顯的問題（好比，"當前數據不可用，使用緩存數據"），另外一個是潛在的問題和建議（好比「程序運行在開發模式下」或者「管理控制檯的密碼不夠安全」）。應用程序能夠容忍這些信息，不過它們應該被檢查及修復。
• DEBUG 開發人員關注的事。後面我會講到什麼樣的東西應該記錄到這個級別。
• TRACE 更爲詳盡的信息，只是開發階段使用。在產品上線以後的一小段時間內你可能還須要關注下這些信息，不過這些日誌記錄只是臨時性的，最終應該關掉。DEBUG和TRACE的區別很難區分，不過若是你加了一行日誌，在開發測試完後又刪了它的話，這條日誌就應該是TRACE級別的。

上面的列表只是一個建議，你能夠根據本身的規則來記錄日誌，但最好要有必定的規則。我我的的經驗是：在代碼層面不要進行日誌過濾，而是用正確的日誌級別可以快速的過濾出想要的信息，這樣能節省你不少時間。

最後要說的就是這個臭名昭著的is*Enabled的條件語句了。有的人喜歡把每第二天志前加上這個：

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

我的認爲，應該避免在代碼里加入這個亂哄哄的東西。性能看起來沒有什麼提高（尤爲是用了slf4j以後）,更像是過早的優化。還有，沒發現這麼作有點多餘麼？不多有時候是明確須要這種顯式的判斷語句的，除非咱們證實構造日誌消息自己開銷太大。否則的話，該怎麼記就怎麼記，讓日誌框架去操心這個吧。

你清楚你在記錄什麼嗎？

每次你寫下一行日誌，花點時間看看你到底在日誌文件裏打印了些什麼。讀一遍你的日誌，找出異常的地方。首先，至少要避免空指針異常：

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

你確認過request不是null了嗎？

記錄集合也是一個大坑。若是你用Hibernate從數據庫裏獲取領域對象的集合的時候,不當心寫成了這樣：

log.debug("Returning users: {}", users);

slf4j只會在這條語句確實會打印的時候調用toString方法，固然這個很酷。不過若是內存溢出了，N+1選擇問題，線程餓死，延遲初始化異常，日誌存儲空間用完了...這些都有可能發生。

最好的方式是隻記錄對象的ID（或者只記錄集合的大小）。不過收集ID須要對每一個對象調用getId方法，這個在Java裏可真不是件簡單的事。Groovy有個很棒的展開操做符（users*.id）,在Java裏咱們能夠用Commons Beanutils庫來模擬下：

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

collect方法大概是這麼實現的：

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

最後要說的是，toString方法可能沒有正確的實現或者使用。

首先，爲了記錄日誌，爲每一個類建立一個toString的作法比比皆是，最好用 ToStringBuilder來生成（不過不是它的反射實現的那個版本）。

第二，注意數組和非典型的集合。數組和一些另類的集合的toString實現可能沒有挨個調用每一個元素的toString方法。可使用JDK提供的Arrays#deepToString方法。常常檢查一下你本身打印的日誌，看有沒有格式異常的一些信息。

避免反作用

日誌打印通常對程序的性能沒有太大影響。最近我一個朋友在一些特殊的平臺上運行的一個系統拋出了Hibernate的LazyInitializationException異常。你可能從這已經猜到了，當會話鏈接進來的時候，一些日誌打印致使延遲初始化的集合被加載。在這種狀況下，把日誌級別提升了，集合也就再也不被初始化了。若是你不知道這些上下文信息，你得花多長時間來發現這個BUG。

另外一個反作用就是影響程序的運行速度。快速回答一下這個問題：若是日誌打印的過多或者沒有正確的使用toString和字符串拼接，日誌打印就會對性能產生負面影響。能有多大？好吧，我曾經見過一個程序每15分鐘就重啓一次，由於太多的日誌致使的線程餓死。這就是反作用！從個人經驗來看，一小時打印百來兆差很少就是上限了。

固然若是因爲日誌打印異常致使的業務進程停止，這個反作用就大了。我常常見到有人爲了不這個而這麼寫：

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

這是段真實的代碼，可是爲了讓世界清淨點，請不要這麼寫。

描述要清晰

每一個日誌記錄都會包含數據和描述。看下這個例子：

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

當在一個陌生的系統裏排查錯誤的時候，你更但願看到哪一種日誌？相信我，上面這些例子都很常見。還有一個反面模式：

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

在這個警告日誌里加上消息類型，消息ID等等這些難道很困難嗎？我是知道發生錯誤了，不過究竟是什麼錯誤？上下文信息是什麼？

第三個反面例子是「魔法日誌」。一個真實的例子：團隊裏的不少程序員都知道，3個&號後面跟着！號再跟着一個#號，再跟着一個僞隨機數的日誌意味着」ID爲XYZ的消息收到了」。沒人願意改這個日誌，某人敲下鍵盤，選中某個惟一的」&&&!#」字符串，他就能很快找到想要的信息。

結果是，整個日誌文件看起來像一大串隨機字符。有人不由會懷疑這是否是一個perl程序。

日誌文件應當是可讀性強的，清晰的，自描述的。不要用一些魔數，記錄值，數字，ID還有它們的上下文。記錄處理的數據以及它的含義。記錄程序正在幹些什麼。好的日誌應該是程序代碼的一份好的文檔。

我有提過不要打印密碼還有我的信息嗎？相信沒有這麼傻的程序員。

調整你的格式

日誌格式是個頗有用的工具，無形中在日誌添加了頗有價值的上下文信息。不過你應該想清楚，在你的格式中包含什麼樣的信息。好比說，在每小時循環寫入的日誌中記錄日期是沒有意義的，由於你的日誌名就已經包含了這個信息。相反的，若是你沒記錄線程名的話當兩個線程並行的工做的時候，你就沒法經過日誌跟蹤線程了——日誌已經重疊到一塊兒了。在單線程的應用程序中，這樣作沒問題，不過那個已是過去的事兒了。

從個人經驗來看，理想的日誌格式應當包括（固然除了日誌信息自己了）：當前時間（無日期，毫秒級精度），日誌級別，線程名，簡單的日誌名稱（不用全稱）還有消息。在logback裏會是這樣的：

<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> 

文件名，類名，行號，都不用列進來，儘管它們看起來頗有用。我還在代碼裏見過空的日誌記錄：

log.info("");
由於程序員認爲行號會做爲日誌格式的一部分，而且他知道若是空日誌消息出如今這個文件的67行的話，意味着這個用戶是認證過的。不只這樣，記錄類名方法名，或者行號對性能都有很大的影響。

日誌框架的一個比較高級的特性是診斷上下文映射（Mapped Diagnostic Context）。MDC只是一個線程本地的一個map。你能夠把任何鍵值對放到這個map裏，這樣的話這個線程的全部日誌記錄都能從這個map裏取到相應的信息做爲輸出格式的一部分。

記錄方法的參數和返回值

若是你在開發階段發現了一個BUG，你一般會用調試器來跟蹤具體的緣由。如今假設不讓你用調試器了，好比，由於這個BUG幾天前在用戶的環境裏出現了，你能拿到的只有一些日誌。你能從中發現些什麼？

若是你遵循打印每一個方法的入參和出參這個簡單的原則，你根本不須要調試器。固然每一個方法可能訪問外部系統，阻塞，等待，等等，這些都應該考慮進來。就參考如下這個格式就好：

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;
}

因爲你在方法的開始和結束都記錄了日誌，因此你能夠人工找出效率不高的代碼，甚至還能夠檢測到可能會引發死鎖和飢餓的誘因——你只需看一下「Entering」後面是否是沒有」Leaving「就明白了。若是你的方法名的含義很清晰，清日誌將是一件愉快的事情。一樣的，分析異常也更得更簡單了，由於你知道每一步都在幹些什麼。代碼裏要記錄的方法不少的話，能夠用AOP切面來完成。這樣減小了重複的代碼，不過使用它得特別當心，不注意的話可能會致使輸出大量的日誌。

這種日誌最合適的級別就是DEBUG和TRACE了。若是你發現某個方法調用 的太頻繁，記錄它的日誌可能會影響性能的話，只須要調低它的日誌級別就能夠了，或者把日誌直接刪了（或者整個方法調用只留一個？）不過日誌多了總比少了要強。把日誌記錄當成單元測試來看，你的代碼應該佈滿了日誌就像它的單元測試處處都是同樣。系統沒有任何一部分是徹底不須要日誌的。記住，有時候要知道你的系統是否是正常工做，你只能查看不斷刷屏的日誌。

觀察外部系統

這條建議和前面的有些不一樣：若是你和一個外部系統通訊的話，記得記錄下你的系統傳出和讀入的數據。系統集成是一件苦差事，而診斷兩個應用間的問題(想像下不一樣的公司，環境，技術團隊）尤爲困難。最近咱們發現記錄完整的消息內容，包括Apache CXF的SOAP和HTTP頭，在系統的集成和測試階段很是有效。

這樣作開銷很大，若是影響到了性能的話，你只能把日誌關了。不過這樣你的系統可能跑的很快，掛的也很快，你還無能爲力？當和外部系統進行集成的時候，你只能格外當心並作好犧牲必定開銷的準備。若是你運氣夠好，系統集成由ESB處理了，那在總線把請求和響應給記錄下來就最好不過了。能夠參考下Mule的這個日誌組件。

有時候和外部系統交換的數據量決定了你不可能什麼都記下來。另外一方面，在測試階段和發佈初期，最好把全部東西都記到日誌裏，作好犧牲性能的準備。能夠經過調整日誌級別來完成這個。看下下面這個小技巧：

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

若是這個logger是配置成DEBUG級別，它會打印完整的請求ID的集合。若是它配置成了打印INFO信息的話，就只會輸出集合的大小。你可能會問我是否是忘了isInfoEnabled條件了，看下第二點建議吧。這裏還有一個值得注意的是ID的集合不能爲null。儘管在DEBUG下，它爲NULL也能正常打印，可是當配置成INFO的時候一個大大的空指針。還記得第4點建議中提到的反作用吧？

正確的記錄異常

首先，不要記錄異常，讓框架或者容器來幹這個。固然有一個例外：若是你從遠程服務中拋出了異常（RMI，EJB等），異常會被序列化，確保它們能返回給客戶端 （API中的一部分）。否則的話，客戶端會收到NoClassDefFoundError或者別的古怪的異常，而不是真正的錯誤信息。

異常記錄是日誌記錄的最重要的職責之一，不過不少程序員都傾向於把記錄日誌看成處理異常的方式。他們一般只是返回默認值（通常是null,0或者空字符串），裝做什麼也沒發生同樣。還有的時候，他們會先記錄異常，而後把異常包裝了下再拋出去：

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

這樣寫一般會把棧信息打印兩次，由於捕獲了MyCustomException異常的地方也會再打印一次。日誌記錄，或者包裝後再拋出去，不要同時使用，不然你的日誌看起來會讓人很迷惑。

若是咱們真的想記錄日誌呢？因爲某些緣由（大概是不讀API和文檔？），大約有一半的日誌記錄我認爲是錯誤的。作個小測試，下面哪一個日誌語句可以正確的打印空指針異常？

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（這個更好）是對的！A和B在slf4j下面根本就編譯不過，其它的會把棧跟蹤信息給丟掉了或者打印了不正確的信息。好比，E什麼也不打印，由於空指針異常自己沒有提供任何異常信息而棧信息又沒打印出來 .記住，第一個參數一般都是文本信息，關於這個錯誤自己的。不要把異常信息給寫進來，打印日誌後它會自動出來的，在棧信息的前面。不過想要打印這個，你固然還得把異常傳到第二個參數裏面才行。

日誌應當可讀性強且易於解析

如今有兩組用戶對你的日誌感興趣：咱們人類（無論你同不一樣意，碼農也是在這裏邊），還有計算機（一般就是系統管理員寫的shell腳本）。日誌應當適合這兩種用戶來理解。若是有人在你後邊看你的程序的日誌卻看到了這個：

那你確定沒遵從個人建議。日誌應該像代碼同樣易於閱讀和理解。

另外一方面，若是你的程序每小時就生成了半GB的日誌，沒有誰或者任何圖形化的文本編輯器能把它們看完。這時候咱們的老傢伙們，grep,sed和awk這些上場的時候就來了。若是有可能的話，你記錄的日誌最好能讓人和計算機都能看明白 ，不要將數字格式化，用一些能讓正則容易匹配的格式等等。若是不可能的，用兩個格式來打印數據：

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) 

計算機看到」ms after 1970 epoch「這樣的的時間格式會感謝你的，而人們則樂於看到」1天10小時17分36秒「這樣的東西。

總之，日誌也能夠寫得像詩同樣優雅，若是你願意琢磨的話。