Logging最佳實踐

#意識

ASAP (As Soon As Possible)原則

當線上出現詭異問題，

當你意識到靠現有的日志無法定位問題時，

當現象難以在你的開發環境重制時，

請不要執著于枯坐肉眼看代碼，

因為：

一）不一定是你代碼邏輯問題，可能是髒資料造成的，是老業務資料造成的，是分布式環境造成的，是其他子系統造成的；

二）線上業務處于不穩定中，條件不允許問題定位無限期。

此時，請立即在問題相關的調用鍊條上，一次性：

在函數的入口和出口列印日志，同時列印輸入、輸出參數catch(){……}裡列印stacktrace，同時列印try塊中關鍵變量的值（避免你發現某個異常是問題第一原因，卻不知道是什麼變量傳入導緻的）

與其他子產品互動的接口入口處列印輸入參數，即，解決線上問題歸根結底要靠log、a lot of log output！

在logging的力度上切勿猶猶豫豫，我們的工程師習慣于吝啬地找兩個函數列印日志、打包部署一把、沒看出來、再找幾個函數列印、再部署、等着現象重制再觀察、……，一來二去時間流逝，閑庭信步，從客服知道的小事故變成了全國皆知的大事故。

是以，再強調一遍：在你的調用鍊條上，逐層調用的函數入口和出口都列印詳細日志，不怕多隻怕少，然後部署，等待現象重制，畢其功于一役！

我們要記錄什麼？

1）完成某項操作所需的時間

通過它可以跟蹤為什麼系統響應變慢或者太快，處理完一個incoming request所耗費的時間，精确到毫秒，執行資料庫查詢的時間，從磁盤或者存儲媒體擷取資料的時間等等

2）異常和堆棧跟蹤

3）Sessions

知道一個問題是由誰引起的非常重要，是以在日志中使用會話辨別符就變得必不可少。它可以簡單到是一個 IP 位址或者是一個更複雜的 UUID，隻要能區分不同的請求者就足夠。

4）版本号

#工具

推薦的Java Logging架構

1）log4j：我們的配置是，

log4j.appender.CONSOLE.layout.ConversionPattern=[%-d{yyyy-MM-dd HH:mm:ss.SSS}] [%p] [%c] [%m]%n；

%p是日志優先級，%c是類目名，%m是輸出資訊，%n是回車換行符。

2）logback：log4j建立人Ceki Gülcü後續推出了SLF4J+logback。SLF4J(Simple Logging Facade for Java)作為commons-logging的替代，為各種logging APIs提供了一個簡單的統一接口，使得最終使用者能夠在部署的時候配置所希望的logging APIs的實作。logback勝在性能，據稱“某些關鍵操作，比如判定是否記錄一條日志語句的操作，其性能得到了顯著的提高。這個操作在logback中需要3納秒，而在 log4j 中則需要30納 秒。 logback 建立記錄器（logger）的速度也更快：13毫秒，而在 log4j 中需要23毫秒。更重要的是，它擷取已存在的記錄器隻需94納秒， 而 log4j 需要2234納秒，時間減少到了1/23。跟java.util.logging(JUL)相比性能提高也是顯著的”。

#配置

不要随便從網上找一個log4j的配置檔案，請确認你了解每一個配置項

我們既然輸出日志，自然期望在面對“這個問題是否從過去幾天開始出現？”這樣的疑問時，不至于發現你的rollingPolicy錯誤設定導緻隻能看到最近幾小時的日志，或者日志發生時間沒有精确到毫秒。

#理念

可用grep抽取的日志：獨立的行！

我們總是希望能用grep處理日志檔案。這意味着：一個日志條目永遠不應該跨多行，除非你是堆棧列印。

我們會用grep問日志什麼問題呢？如：

用手機号13910**下單的顧客最近三天内都來自于哪些IP？

浏覽位址是?from=kfapi的顧客，但referral卻是搜尋引擎域名，最近三天有多少次？

最近一周内，訂單中心執行的所有事務，耗時最長的一次是多長時間？

××××的接口是否真的于18:00發送了一個請求，我們收到的參數是什麼？

確定你的日志能回答這樣的問題。

不同關注領域寫不同的日志檔案

當通路和調用極其頻繁，有時候你會發現把你的工程裡什麼資訊都列印到一個日志檔案裡，會讓你看得頭昏腦脹。

最簡單的示範就是Apache的通路日志和錯誤日志是分開的。

同樣，你也可以把更加安靜的事件（偶爾出現）與更加喧鬧的事件分開存儲。

如，對外的開放平台可以列印三種日志檔案：connection log（建立連結和關閉連結，附帶接入參數），message log（内部調用鍊），stacktrace log（異常的堆棧列印）。

#具體實作

至少精确到毫秒

日志必須包含時間戳，精确到至少毫秒級。

如果隻是記錄到秒級，我們曾明知代碼因缺乏并發控制而産生BUG，卻隻能郁悶地看着精确到秒級的日志。

對Java來說，最好配置為：yyyy-MM-dd/HH:mm:ss.SSS。

請盡可能列印明确的會話辨別

日志條目裡列印一個會話辨別（A certain session identifier），當有許多并發請求打過來時，你就能基于此字段過濾 client 了。比如，我們日志會補充列印一個浏覽器 cookies 裡種下的 UUID 。

log4j的isDebugEnabled判斷

如果列印資訊是常量字元串或簡單字元串拼接，那麼不需要if ( log.isDebugEnabled() )。

如果你拼裝的動作比較耗資源，請用if ( log.isDebugEnabled() )。

如有可能，請将性能資料标準化輸出

這樣更友善grep或hadoop做性能資料抽取和挖掘，進而能很輕松地轉換為圖形監控。

比如，訂單中心的性能資料格式為：樹枝标志 目前節點起始時間 [目前節點持續時間, 目前節點自身消耗時間, 在父節點中所占的時間比例]

哪些位置需要部署性能檢測點

（1）通路資料庫的dao層；

（2）通路外部資源的ext層；

（3）通路mq的方法；

（4）等等，一切不在你自己負責的工程掌握的部分（外部），或一切你認為自己工程的性能危險點，都需要加入性能監控日志。

#Sample

一個好的啟動日志 [外鍊圖檔轉存失敗,源站可能有防盜鍊機制,建議将圖檔儲存下來直接上傳(img-GFZqKEOC-1664280573192)

列印了應用的版本号，用戶端的會話辨別，關鍵步驟的執行時長。

一個好的堆棧跟蹤日志 [外鍊圖檔轉存失敗,源站可能有防盜鍊機制,建議将圖檔儲存下來直接上傳(img-xDHVnPjU-1664280573193)