分布式鏈路追蹤技術:編寫出“可觀測”的系統日志
?有在用,但是大多是 logback 和 log4j 2.x。雖然異步日志的效率 logback 和 log4j 2.x 相差無幾,但 log4j 2.x 仍有些微弱的優勢。
日志接口框架
可以看到,Java 中是存在多種不同日志框架的實現的,這就會造成 2 個問題:
多框架協作:在一個項目中,不光有你的代碼,還有各種各樣的框架代碼,比如分布式協調會用到 Zookeeper、Curator;RPC 通信會用到 Dubbo、Thrift。為了方便開發,業務系統中往往集成了許多第三方框架。我們需要日志來了解各個第三方框架之間的協作狀態,這些第三方框架又依賴于各個日志框架進行輸出。這時候如果直接使用像 logback、log4j 這樣的日志框架,豈不是業務系統要接入每個日志框架?
不同框架競爭:如果要引入多個日志框架,我們還需要考慮各個框架的輸出位置。要是多個日志框架同時寫入一個日志文件,還會涉及競爭問題,導致性能無法發揮。
由此就出現了面向接口的日志框架,它提供了統一的 API。開發人員在編寫代碼的時候,直接使用這套面向接口的日志框架,當業務項目人員在使用時,只需要選擇好實現框架,就可以統一日志實現框架。
目前使用最為廣泛的日志接口框架是 SLF4J,出自 logback 的開發者,目前基本已經形成規范。SLF4J 提供了動態占位符的功能,大大提高了程序的性能,無須開發人員再對參數信息進行拼接。
比如默認情況下程序是 info 級別的,在原先的代碼方式中想要進行日志輸出需要自行拼接字符串:
這會產生一個問題,系統中如果存在大量類似的代碼,同時系統只輸出 info 及 info 以上級別的日志,那么,在輸出 debug 日志時會產生大量的字符串,而并不會輸出 debug 日志,最后造成字符串不停地拼接,浪費系統性能。此時,SLF4J 就可以使用占位符的功能編寫日志,比如像下面這樣:
通過這樣的形式,SLF4J 就可以根據日志等級判斷,只對符合要求的日志進行數據拼接和打印。
有些時候日志輸出需要進行數值計算,或者 JSON 轉換,此時就需要一定的計算任務。但方法調用如果被當作參數傳遞的話一樣會被執行,所以 Java8 中 SLF4J 還可以通過 Supplier 來傳遞。如下所示:
可以看到,SLF4J 不僅為我們制定了一套面向接口開發的方式,還為我們明確了如何有效地編寫日志。這也是為什么越來越多人喜歡用 SLF4J。
日志編寫方式
在詳細介紹了我們在開發時需要使用的日志框架后,我將正式展開我們的標題:“如何編寫‘可觀測’的日志?”我會從日志編寫位置、寫入性能、占位符、可讀性、關鍵信息隱蔽、減少代碼位置信息的輸出、文件分類、和日志 review 這 8 個點來講解,并將它們分成了 2 個方向:
日志開發時(前 5 項):怎么樣寫出更有效率的日志?
日志完成后(后 3 項):上線前后有哪些需要注意的?
日志編寫位置
日志編寫的位置可以說是重中之重,好的日志位置可以幫你解決問題,也可以讓你更加了解代碼的運行情況。我總結了幾點比較重要的編寫日志的位置,以供參考。
系統/應用啟動和參數變更:當系統啟動時,可以將相關的參數信息進行打印,以便出現問題時,更準確地查詢原因;參數信息可能并不存儲在本地,需要通過配置中心獲取,而參數信息有變更時,也需要將變更后的內容輸出在日志中。
關鍵操作節點:最典型的就是在關鍵位置添加日志,記錄用戶進行的某個操作。當出現問題時,你可以通過這個位置的日志了解到用戶的操作。同樣你也可以在系統進行某些操作時添加日志,比如你準備啟動某個線程池來進行數據處理時,可以加上日志便于以后分析問題。
大型任務進度上報:當系統在處理某個比較大型的任務時,可以在這個過程中增加相關的日志來表明任務處理的進度,防止因為長時間沒有處理而無法得知程序執行的狀態,比如在文件下載時,可以按照百分比來定時/定次地上報數據。
異常:當程序出現異常時,我們通常是通過 try-catch 來記錄當時的情況,然后以日志的形式表現出來。如果是通過 try-catch 處理,你需要注意日志編寫的位置。如果你需要將日志在本層拋出,則不需要進行日志記錄,否則會出現日志重復的問題。如果你除了異常以外還需要記錄其他的內容,則可以通過定制異常信息來實現。
寫入性能
日志的寫入性能則會受到如下 5 個因素的影響:
日志編寫位置:日志編寫的位置在程序中十分重要,如果在 for 循環中編寫,因為這個循環會持續很多次,那么就會產生大量的日志記錄。此時可以考慮一下,這個日志的記錄是否有必要。
日志數量:如果你大量地編寫日志,那么日志的質量一定會降低。同時,大量的日志會讓你很難去查看問題,反而成了一種負擔。在高訪問量時,過多的日志也會影響程序的執行效率。
日志編寫等級:我在上一節中講過,日志等級很容易被濫用,不正確的日志等級會導致我們查詢問題的時間增加。
日志輸出級別:這里指的是對于配置日志輸出級別的選擇。在線上環境,不建議使用 debug 級別,因為線上一直有請求,debug 級別會輸出大量的基礎和請求信息,極其浪費資源,因此建議開啟 info 或者以上。
無用輸出參數:不對大字段、無用字段輸出,因為這很影響程序執行效率和日志的內容。我曾遇到一個案例,A 同學在線上打印了一個完整的 HTML 內容,導致當日的部分日志內容錯亂,部分日志無法檢索,原因就在于 HTML 存在多行內容導致無法解析的問題。當開發人員到線上服務器上查看時,日志文件的大小已經擴大了 3 倍。
好的日志一定是便于你去排查問題的。在編寫日志時你一定要思考這個日志可以幫你做什么。
占位符
在介紹日志接口框架時我提到過,在日志編寫時盡可能地選擇基于占位符的編寫方式。這里我會告訴你為什么要用占位符:
- 節約性能。在生成較高級別的日志時,低級別的日志會不停疊加字符串而占用過多的內存、CPU 資源,導致性能浪費。
- 便于編寫。先確認日志所想要表達的內容,再確認你所需要編寫的參數,這樣在寫日志時,目的也會更加明確。
- 便于查看。在代碼 review 時,更方便查看日志想表達的意思,而不會被日志的參數打亂。
可讀性
日志的可讀性也是日志編寫的關鍵之一。一個好的日志就像一篇好的文章,能讓你很快了解到這個日志中的關鍵信息。我在工作中發現很多人寫的日志都是無意義的,根本無法幫你定位問題的根源,比如像下面的這段代碼:
這段代碼乍一看似乎沒什么問題,但是運行后系統會大量地輸出“數據保存成功!”的消息,這個輸出和沒有是一樣的,起不到任何的作用。
我總結了幾點在日志中容易遺漏的信息:
- 會話標識:當前操作的用戶和與當前請求相關的信息,類似 Session。當出現問題/查看行為時,可以根據這個值來快速識別到相關的日志。
- 請求標識:每個請求都擁有一個唯一的標識,這樣在查看問題時,我們只需要查看這一個請求中的所有日志即可。一般我們會配合鏈路追蹤系統一同使用,因為后者可以實現跨應用的日志追蹤,從而幫助我們過濾掉不相關的信息。
- 參數信息:在日志中增加參數信息能幫你了解到,是什么情況下產生的問題,這樣你也很容易復現問題,以及辨別錯誤的原因。
- 發生數據的結果:和參數信息相互對應,一個是執行前,一個是執行后。發生數據的結果可以幫你了解程序執行的結果,出錯時也是很重要的參考條件。
關鍵信息隱蔽
對于關鍵的信息不顯示或者進行掩碼顯示,以免信息被盜取后出現數據內容泄漏。推特在 2018 年曾將用戶打印在日志中,這一行為泄露了 3.3 億人。
減少代碼位置信息的輸出
如果不是必要,盡量不要在日志格式中輸出當前日志所在的代碼行和方法名稱信息。如果你看過 logback,log4j 的源碼你就知道,這都是通過獲取當前線程堆棧快照信息來進行實現的,這種實現方式會極大地影響程序執行的效率。
在 log4j 的文檔中有這樣一段話:“使用同步方式進行獲取位置信息會慢 1.3 到 5 倍,如果是使用異步日志,因為會涉及跨線程獲取位置信息,會慢 30 到 100 倍。原文:https://logging.apache.org/log4j/2.0/manual/async.html#Location。
所以,關閉代碼位置信息的輸出可以節省系統資源的使用,提升性能。
文件分類
文件分類可以幫助你提高檢索日志信息時的效率。將不同的業務邏輯按照不同的日志文件來分類,可以保證你看到的信息都是和這個功能相關的,不會被其他的日志干擾。這也是在大型系統中經常會使用到的功能。
比如拉勾的單點登錄系統,就會將用戶的極驗驗證功能和登錄驗證功能拆成兩個單獨的日志文件,當出現問題時,可以根據相關功能的日志來快速篩查問題,減少了篩選所需的時間。
日志 review
每一次功能上線后,除了要對業務功能進行回歸,還要對日志進行觀察,確認日志內容的輸出情況,比如日志內容是否符合預期,會不會有不合適的地方?
好的日志不是一次就能寫好的,一定是要和代碼一樣不停地迭代,才能寫出更方便處理問題,也更具有可讀性的日志。
日志管理
就像店家在賣出商品后還要負責其售后,編寫完日志,對于它的管理也是十分重要的。好的日志管理方式可以提高閱讀日志的效率,而這需要開發人員和運維人員共同協作。
日志格式
日志的格式布局會影響運維人員將這些日志內容收集與管理的效率。如果編寫者和管理者能夠通過協商,規定出一套完整的日志格式,這樣就能在排查問題時事半功倍。
我會簡單介紹幾點在日志編寫時需要注意的事項:
- 系統之間格式保持一致:每個應用在日志格式上盡量保持統一,這樣,運維人員在進行日志收集時,就可以采用統一的日志模板來收集和格式化內容,減少雙方的溝通成本。
- 不編寫多行的日志內容:除了異常堆棧信息,不對日志內容進行多行的輸出,多行的內容十分不便于數據解析,可能會出現生成多條日志的情況。
- 不要使用日志中的常見內容來分割:如果采用日志中常見的內容來分割,會在格式解析時出現問題,比如用戶 ID 中的空格就是比較常見的內容。
日志歸檔
日志歸檔是一件很重要的事情。如果你將日志內容全部寫到一個文件中,這個日志文件會變得越來越煩冗,不利于日志的收集和查看。
一般情況下,我們會對日志按照日期來歸檔,每天生成一個日志文件,這樣在日志備份和恢復時,可以按照日期來進行。如果感覺天級別的日志仍然太大了,可以考慮按照小時細分。
結語
今天我們了解了日志編寫的工具、日志編寫需要注意的 8 個事項以及日志管理的方式,有哪些是你原來犯過的錯誤,又有哪些是你原來沒有想到的呢?歡迎你在留言區分享與討論。希望你在日后的日志編寫中可以注意到這些問題。?