轉自：用JAVA日志來寫詩
工欲善其事，必先利其器
很多程式員可能都忘了記錄應用程式的行為是一件多麼重要的事，當遇到多線程環境下高壓力導緻的并發bug時，你就能體會到記錄log的重要性。
有的人很高興的就在代碼裡加上了這麼句：
他可能都沒有意識到應用程式的日志在維護，調優和故障識别中的重要性。
我認為slf4j是最好的日志API，最主要是因為它支援一個很棒的模式注入的方式：
log4j的話你隻能這樣：
這樣寫不僅更啰嗦和可讀性差，而且字元串拼接影響效率（當這個級别并不需要輸出的時候）。
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
上面的清單隻是一個建議，你可以根據自己的規則來記錄日志，但最好要有一定的規則。我個人的經驗是：在代碼層面不要進行日志過濾，而是用正确的日志級别能夠快速的過濾出想要的資訊，這樣能節省你很多時間。
最後要說的就是這個臭名昭著的is*Enabled的條件語句了。有的人喜歡把每次日志前加上這個：
if(log.isDebugEnabled())
log.debug("Place for your commercial");
個人認為，應該避免在代碼裡加入這個亂哄哄的東西。性能看起來沒有什麼提升（尤其是用了slf4j之後）,更像是過早的優化。還有，沒發現這麼做有點多餘麼？很少有時候是明确需要這種顯式的判斷語句的，除非我們證明構造日志消息本身開銷太大。不然的話，該怎麼記就怎麼記，讓日志架構去操心這個吧。
你清楚你在記錄什麼嗎？
每次你寫下一行日志，花點時間看看你到底在日志檔案裡列印了些什麼。讀一遍你的日志，找出異常的地方。首先，至少要避免空指針異常：
你确認過request不是null了嗎？
記錄集合也是一個大坑。如果你用Hibernate從資料庫裡擷取領域對象的集合的時候,不小心寫成了這樣：
slf4j隻會在這條語句确實會列印的時候調用toString方法，當然這個很酷。不過如果記憶體溢出了，N+1選擇問題，線程餓死，延遲初始化異常，日志存儲空間用完了…這些都有可能發生。
最好的方式是隻記錄對象的ID（或者隻記錄集合的大小）。不過收集ID需要對每個對象調用getId方法，這個在Java裡可真不是件簡單的事。Groovy有個很棒的展開操作符（users*.id）,在Java裡我們可以用Commons Beanutils庫來模拟下：
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秒“這樣的東西。
總之，日志也可以寫得像詩一樣優雅，如果你願意琢磨的話。
![九、設計模式以及查找、排序算法[圖]](data:image/gif;base64,R0lGODlhAQABAIAAAP///wAAACwAAAAAAQABAAACAkQBADs=)