分布式鍊路追蹤技術：編寫出“可觀測”的系統日志

今天我将帶你從編寫日志的工具、編寫日志的方式，以及日志編寫後的管理，就像是購物的售前、售中、售後，這 3 個方面來講解，怎麼樣才可以寫出更具有“可觀測性”的日志内容。

日志架構

在編寫日志之前，咱們先來了解一下有哪些日志架構可以協助我們編寫日志。

在介紹日志架構之前，我需要說明一下，如果你仍在使用 System.out.println、Exception.printStackTrace 或類似的控制台輸出日志的方式，我推薦你改用第三方日志架構編寫。這種控制台輸出的方式，可以從它們的源碼了解到它們是線程同步的，大量使用這種方式，會對程式性能造成嚴重的影響，因為它們同一時間隻能有一個線程在進行執行。

日志架構在系統中一般分為 2 種類型：日志實作架構和日志接口架構。下面我會對它們分别說明。

日志實作架構

顧名思義，就是日志的實作方，每個架構都提供自己的日志管理和寫入的方式。Java 中的日志架構很不統一，這裡我就以認知度最高的 3 個項目來說明。

1. log4j 1.x：2001 年釋出，後來成為 Apache 基金會的頂級項目。log4j 1.x 當年可以說是基本都在使用的日志實作架構，即便到了現在，仍有很多項目在使用它。log4j 1.x 使用起來确實很友善，但是 1.x 版本在高并發的情況下，存在比較嚴重的鎖競争關系，會導緻性能不能得到有效的發揮；
2. logback：log4j 1.x 創始人的另一個項目。它提供了更加高效的寫入性能，據官方說明是 log4j 1.x 性能的 10 倍，以及更多的功能，比如異步日志。
3. log4j 2.x：随着 logback 流行，log4j 1.x 的開發人員也想跟上步伐，于是推出了一套新的日志架構，号稱比 logback 更快。log4j 2.x 借鑒了很多 logback 中的想法和功能，并解決了 log4j 1.x 架構上存在的一些問題。同時，它采用 Disruptor 來進行異步日志，相比較 Java 自帶的隊列，它提供了更高效且更完整的隊列實作方案。

對于這三種架構，目前市面上都有在用，但是大多是 logback 和 log4j 2.x。雖然異步日志的效率 logback 和 log4j 2.x 相差無幾，但 log4j 2.x 仍有些微弱的優勢。

日志接口架構

可以看到，Java 中是存在多種不同日志架構的實作的，這就會造成 2 個問題：

1. 多架構協作：在一個項目中，不光有你的代碼，還有各種各樣的架構代碼，比如分布式協調會用到 Zookeeper、Curator；RPC 通信會用到 Dubbo、Thrift。為了友善開發，業務系統中往往內建了許多第三方架構。我們需要日志來了解各個第三方架構之間的協作狀态，這些第三方架構又依賴于各個日志架構進行輸出。這時候如果直接使用像 logback、log4j 這樣的日志架構，豈不是業務系統要接入每個日志架構？
2. 不同架構競争：如果要引入多個日志架構，我們還需要考慮各個架構的輸出位置。要是多個日志架構同時寫入一個日志檔案，還會涉及競争問題，導緻性能無法發揮。

由此就出現了面向接口的日志架構，它提供了統一的 API。開發人員在編寫代碼的時候，直接使用這套面向接口的日志架構，當業務項目人員在使用時，隻需要選擇好實作架構，就可以統一日志實作架構。

目前使用最為廣泛的日志接口架構是 SLF4J，出自 logback 的開發者，目前基本已經形成規範。SLF4J 提供了動态占位符的功能，大大提高了程式的性能，無須開發人員再對參數資訊進行拼接。

比如預設情況下程式是 info 級别的，在原先的代碼方式中想要進行日志輸出需要自行拼接字元串：

logger.debug("使用者" + userId + "開始下單:" + orderNo + ",請求資訊:" + Gson.toJson(req));
           

這會産生一個問題，系統中如果存在大量類似的代碼，同時系統隻輸出 info 及 info 以上級别的日志，那麼，在輸出 debug 日志時會産生大量的字元串，而并不會輸出 debug 日志，最後造成字元串不停地拼接，浪費系統性能。此時，SLF4J 就可以使用占位符的功能編寫日志，比如像下面這樣：

logger.debug("使用者{}開始下單:{},請求資訊:", userId, orderNo,  Gson.toJson(req));
           

通過這樣的形式，SLF4J 就可以根據日志等級判斷，隻對符合要求的日志進行資料拼接和列印。

有些時候日志輸出需要進行數值計算，或者 JSON 轉換，此時就需要一定的計算任務。但方法調用如果被當作參數傳遞的話一樣會被執行，是以 Java8 中 SLF4J 還可以通過 Supplier 來傳遞。如下所示：

logger.debug("使用者{}開始下單:{},請求資訊:", userId, orderNo, () -> Gson.toJson(req))
           

可以看到，SLF4J 不僅為我們制定了一套面向接口開發的方式，還為我們明确了如何有效地編寫日志。這也是為什麼越來越多人喜歡用 SLF4J。

日志編寫方式

在詳細介紹了我們在開發時需要使用的日志架構後，我将正式展開我們的标題：“如何編寫‘可觀測’的日志？”我會從日志編寫位置、寫入性能、占位符、可讀性、關鍵資訊隐蔽、減少代碼位置資訊的輸出、檔案分類、和日志 review 這 8 個點來講解，并将它們分成了 2 個方向：

• 日志開發時（前 5 項）：怎麼樣寫出更有效率的日志？
• 日志完成後（後 3 項）：上線前後有哪些需要注意的？

日志編寫位置

日志編寫的位置可以說是重中之重，好的日志位置可以幫你解決問題，也可以讓你更加了解代碼的運作情況。我總結了幾點比較重要的編寫日志的位置，以供參考。

1. 系統/應用啟動和參數變更：當系統啟動時，可以将相關的參數資訊進行列印，以便出現問題時，更準确地查詢原因；參數資訊可能并不存儲在本地，需要通過配置中心擷取，而參數資訊有變更時，也需要将變更後的内容輸出在日志中。
2. 關鍵操作節點：最典型的就是在關鍵位置添加日志，記錄使用者進行的某個操作。當出現問題時，你可以通過這個位置的日志了解到使用者的操作。同樣你也可以在系統進行某些操作時添加日志，比如你準備啟動某個線程池來進行資料處理時，可以加上日志便于以後分析問題。
3. 大型任務進度上報：當系統在處理某個比較大型的任務時，可以在這個過程中增加相關的日志來表明任務處理的進度，防止因為長時間沒有處理而無法得知程式執行的狀态，比如在檔案下載下傳時，可以按照百分比來定時/定次地上報資料。
4. 異常：當程式出現異常時，我們通常是通過 try-catch 來記錄當時的情況，然後以日志的形式表現出來。如果是通過 try-catch 處理，你需要注意日志編寫的位置。如果你需要将日志在本層抛出，則不需要進行日志記錄，否則會出現日志重複的問題。如果你除了異常以外還需要記錄其他的内容，則可以通過定制異常資訊來實作。

寫入性能

日志的寫入性能則會受到如下 5 個因素的影響：

1. 日志編寫位置：日志編寫的位置在程式中十分重要，如果在 for 循環中編寫，因為這個循環會持續很多次，那麼就會産生大量的日志記錄。此時可以考慮一下，這個日志的記錄是否有必要。
2. 日志數量：如果你大量地編寫日志，那麼日志的品質一定會降低。同時，大量的日志會讓你很難去檢視問題，反而成了一種負擔。在高通路量時，過多的日志也會影響程式的執行效率。
3. 日志編寫等級：我在上一節中講過，日志等級很容易被濫用，不正确的日志等級會導緻我們查詢問題的時間增加。
4. 日志輸出級别：這裡指的是對于配置日志輸出級别的選擇。線上上環境，不建議使用 debug 級别，因為線上一直有請求，debug 級别會輸出大量的基礎和請求資訊，極其浪費資源，是以建議開啟 info 或者以上。
5. 無用輸出參數：不對大字段、無用字段輸出，因為這很影響程式執行效率和日志的内容。我曾遇到一個案例，A 同學線上上列印了一個完整的 HTML 内容，導緻當日的部分日志内容錯亂，部分日志無法檢索，原因就在于 HTML 存在多行内容導緻無法解析的問題。當開發人員到線上伺服器上檢視時，日志檔案的大小已經擴大了 3 倍。

好的日志一定是便于你去排查問題的。在編寫日志時你一定要思考這個日志可以幫你做什麼。

占位符

在介紹日志接口架構時我提到過，在日志編寫時盡可能地選擇基于占位符的編寫方式。這裡我會告訴你為什麼要用占位符：

1. 節約性能。在生成較進階别的日志時，低級别的日志會不停疊加字元串而占用過多的記憶體、CPU 資源，導緻性能浪費。
2. 便于編寫。先确認日志所想要表達的内容，再确認你所需要編寫的參數，這樣在寫日志時，目的也會更加明确。
3. 便于檢視。在代碼 review 時，更友善檢視日志想表達的意思，而不會被日志的參數打亂。

可讀性

日志的可讀性也是日志編寫的關鍵之一。一個好的日志就像一篇好的文章，能讓你很快了解到這個日志中的關鍵資訊。我在工作中發現很多人寫的日志都是無意義的，根本無法幫你定位問題的根源，比如像下面的這段代碼：

boolean success = doSomeThing(); 
if (success) { 
    logger.info("資料儲存成功！"); 
}
           

這段代碼乍一看似乎沒什麼問題，但是運作後系統會大量地輸出“資料儲存成功！”的消息，這個輸出和沒有是一樣的，起不到任何的作用。

我總結了幾點在日志中容易遺漏的資訊：

1. 會話辨別：目前操作的使用者和與目前請求相關的資訊，類似 Session。當出現問題/檢視行為時，可以根據這個值來快速識别到相關的日志。
2. 請求辨別：每個請求都擁有一個唯一的辨別，這樣在檢視問題時，我們隻需要檢視這一個請求中的所有日志即可。一般我們會配合鍊路追蹤系統一同使用，因為後者可以實作跨應用的日志追蹤，進而幫助我們過濾掉不相關的資訊。
3. 參數資訊：在日志中增加參數資訊能幫你了解到，是什麼情況下産生的問題，這樣你也很容易複現問題，以及辨識錯誤的原因。
4. 發生資料的結果：和參數資訊互相對應，一個是執行前，一個是執行後。發生資料的結果可以幫你了解程式執行的結果，出錯時也是很重要的參考條件。

關鍵資訊隐蔽

對于關鍵的資訊不顯示或者進行掩碼顯示，以免資訊被盜取後出現資料内容洩漏。推特在 2018 年曾将使用者的密碼列印在日志中，這一行為洩露了 3.3 億人的密碼。

減少代碼位置資訊的輸出

如果不是必要，盡量不要在日志格式中輸出目前日志所在的代碼行和方法名稱資訊。如果你看過 logback，log4j 的源碼你就知道，這都是通過擷取目前線程堆棧快照資訊來進行實作的，這種實作方式會極大地影響程式執行的效率。

在 log4j 的文檔中有這樣一段話：“使用同步方式進行擷取位置資訊會慢 1.3 到 5 倍，如果是使用異步日志，因為會涉及跨線程擷取位置資訊，會慢 30 到 100 倍。原文： https://logging.apache.org/log4j/2.0/manual/async.html#Location。

是以，關閉代碼位置資訊的輸出可以節省系統資源的使用，提升性能。

檔案分類

檔案分類可以幫助你提高檢索日志資訊時的效率。将不同的業務邏輯按照不同的日志檔案來分類，可以保證你看到的資訊都是和這個功能相關的，不會被其他的日志幹擾。這也是在大型系統中經常會使用到的功能。

比如拉勾的單點登入系統，就會将使用者的極驗驗證功能和登入驗證功能拆成兩個單獨的日志檔案，當出現問題時，可以根據相關功能的日志來快速篩查問題，減少了篩選所需的時間。

日志 review

每一次功能上線後，除了要對業務功能進行回歸，還要對日志進行觀察，确認日志内容的輸出情況，比如日志内容是否符合預期，會不會有不合适的地方？

好的日志不是一次就能寫好的，一定是要和代碼一樣不停地疊代，才能寫出更友善處理問題，也更具有可讀性的日志。

日志管理

就像店家在賣出商品後還要負責其售後，編寫完日志，對于它的管理也是十分重要的。好的日志管理方式可以提高閱讀日志的效率，而這需要開發人員和運維人員共同協作。

日志格式

日志的格式布局會影響運維人員将這些日志内容收集與管理的效率。如果編寫者和管理者能夠通過協商，規定出一套完整的日志格式，這樣就能在排查問題時事半功倍。

我會簡單介紹幾點在日志編寫時需要注意的事項：

1. 系統之間格式保持一緻：每個應用在日志格式上盡量保持統一，這樣，運維人員在進行日志收集時，就可以采用統一的日志模闆來收集和格式化内容，減少雙方的溝通成本。
2. 不編寫多行的日志内容：除了異常堆棧資訊，不對日志内容進行多行的輸出，多行的内容十分不便于資料解析，可能會出現生成多條日志的情況。
3. 不要使用日志中的常見内容來分割：如果采用日志中常見的内容來分割，會在格式解析時出現問題，比如使用者 ID 中的空格就是比較常見的内容。

日志歸檔

日志歸檔是一件很重要的事情。如果你将日志内容全部寫到一個檔案中，這個日志檔案會變得越來越煩冗，不利于日志的收集和檢視。

一般情況下，我們會對日志按照日期來歸檔，每天生成一個日志檔案，這樣在日志備份和恢複時，可以按照日期來進行。如果感覺天級别的日志仍然太大了，可以考慮按照小時細分。

結語

今天我們了解了日志編寫的工具、日志編寫需要注意的 8 個事項以及日志管理的方式，有哪些是你原來犯過的錯誤，又有哪些是你原來沒有想到的呢？歡迎你在留言區分享與讨論。希望你在日後的日志編寫中可以注意到這些問題。