這是2023年的第89篇文章
( 本文閱讀時間:15分鐘 )
程式記錄日誌的過程,就是將需要記錄的內容寫入到磁碟檔案中的過程。與生活的物流場景類似,好比是一車貨物透過一套運輸體系運送至目的地的過程,然而在這套物流體系中,我們往往不需要自己完成整套打包、上車、運輸、卸貨等全套流程,只需要將包打好之後交由專業的物流公司即可。對於我們今天所要描述的日誌場景而言,日誌內容是需要運送的貨物,日誌框架就是物流公司,而目的地就是磁碟上的檔案(或其他日誌收集伺服器)。在 Java 的語言體系中,針對日誌處理很早有了很好的日誌框架 log4j、 logback以及 jul(Java Util Logging) 等,這些框架替我們隱藏了日誌記錄的技術細節,程式設計師只需要使用 Logger這一個工具類,即可高效的完成業務日誌的記錄,如下面程式碼所示:Logger logger = LogFactory.getLogger("PoweredByEDAS");
String product = "EDAS";
logger.info("This is powered by product: " + product);
這一篇文章是想透過幾個技術點來說明日誌記錄過程中的效能實踐,計算機領域的效能往往都遵循著冰山法則,即你能看得見的、程式設計師能感知的只是其中的一小部分,還有大量的細節隱藏在冰山之下,如下圖所示:簡單針對上圖做一個說明:當程式設計師在業務程式碼中透過 logger.info的方式對日誌內容進行輸出後,日誌的目的地是磁碟,而在最終將日誌內容刷入磁碟之前,它需要經過日誌框架、JVM、Linux 檔案系統的層層處理。這就好比在物流運輸過程中,期間有多個經停站點,在某些站點可能還需要進行換乘。運輸中用到的整個交通體系(車、司機、道路等)就是我們圖中的所畫的“日誌通道”。根據這個圖,也給出了我們進行系統性最佳化的思路,即:避免通道擁塞、減少看得見的業務開銷、躲開看不見的系統開銷。交通體系中,避免通道擁塞的思路主要是兩個:1) 儘量控制運輸流量 ,2) 最佳化整個交通運輸體系(修更多的道路,增加更多的資訊化技術等等)。在日誌輸出場景中,程式設計師能控制的主要是業務日誌的內容和日誌策略的配置,還有相當一部分能力依賴底層基礎設施的效能。針對程式設計師能控制的,我們儘量最佳化;而對於我們無法控制的,我們儘量解耦。這是我們這一章節闡述的主要思路。直觀來說,日誌內容越大,對整個系統會造成一些更大的壓力。為了量化差別,我們進行了下面的測試對比:第一組,我們僅僅將不同日誌大小寫入記憶體。第二組中,我們將不同的日誌大小寫入磁碟檔案。寫入記憶體我們使用了 Log4j 中的 CountingNoOp Appender ,他的作用是在進行日誌的正式輸出時,僅僅對輸出的日誌做計數統計,這樣的一種測試方式,從某種程度上能衡量出來單純日誌框架的處理效率。<Appenders> <CountingNoOp name="NoOp"> </CountingNoOp></Appenders>
在下圖所呈現的測試結果中,我們可以看到,即使不進行刷盤的動作,寫入的吞吐量隨著內容的大小而明顯下降在另外一組的測試中,我們再將不同日誌大小的內容寫入檔案,再做類似的對比,從實驗結果來看我們能得出兩個簡單的結論:- 與只寫入記憶體的吞吐量相比,二者的吞吐量隨著日誌內容的變大差距越來越大。
- 同時隨著輸出內容的數量變多,在磁碟場景下呈現明顯的下滑趨勢,隨著內容的增多,呈現逐漸趨平的趨勢。
上圖中的測試資料是我們從一個 IO 裝置提供了 400MB/s 左右的速度中獲得;在 IO 沒有被用滿的情況下,增加寫入內容尚能提升整體的寫入量,但是一旦達到裝置的瓶頸。繼續寫入將造成寫入的堆積。不過兩組資料均能得出相同的結論,即:更大的日誌文字內容,只會導致更差的處理時間。類比到生活中運輸的場景,如果我們要運輸的貨物非常大的時候,那麼就需要我們的貨車具備更大空間的、更強的動力,而且運輸速度也會更慢。同時過重的貨物會有動力失調,輪胎爆胎等風險。為了提高運輸效率和健康度,就應該儘量避免運超大型的貨物。從我們的日誌場景出發,過大的日誌會同樣會在在 CPU、記憶體、IO 等資源上均會對系統產生不同程度的衝擊。壓縮Logger輸出:
在獲取一個 Logger 進行日誌輸出時,大多數程式設計師的程式設計習慣是直接使用 Class 物件進行獲取,參見如下的程式碼片段:package com.alibabacloud.edas.demo;
public class PoweredByEdas {
private static Logger logger = LogFactory.getLogger(
ProweredByEdas.class);
public void execute() {
String product = "EDAS";
logger.info("Prowered by " + product);
}
}
而在進行日誌輸出時,如果 logger 是 Class 將預設輸出對應它所對應的 FQCN,即:com.alibabacloud.edas.demo.PoweredByEdas其實我們可以使用 logger 的 re-format 方式,將其進行壓縮,比如,在 logback 中使用 %logger{5} 或 %c{5} 精簡後,logger 在輸出時將壓縮成為c.a.e.d.PoweredByEdas,平均每條日誌將減少 19 字元。
2023-11-11 16:14:36.790 INFO [com.alibabacloud.edas.demo.PoweredByEdas] Prowered by EDAS
2023-11-11 16:24:44.879 INFO [c.a.e.d.PoweredByEdas] Prowered by EDAS
不過這種日誌處理由於做字串的拆分和擷取,會額外耗費一定的 CPU,如果是計算密集型的業務(CPU 佔用本來就很高的情況下)則不建議生產使用。
壓縮異常輸出
異常資訊的記錄,是我們的系統線上上出現問題或者故障時的一個重要的排查依據,他的全面與否很多時候直接影響了問題解決的效率,然而過多的異常資訊記錄,往往容易把真正有用的資訊進行覆蓋。而當我們將系統中丟擲的異常拆開來看的時候,不難看出通篇的堆疊資訊中,能對自己排查問題產生幫助的資訊,往往只有幾行,如下圖所示:根據筆者自己的經驗,在將異常直接進行列印輸出之前,我們可以嘗試將重新遍歷異常堆疊,將資訊重新整理之後再輸出,具體實踐可參考以下幾點:- 保留棧頂的幾幀:棧頂往往包含的是最為關鍵的資訊,是案發的第一現場,他的資訊完整性顯得尤為重要。
- 保留業務棧幀:在 Java 語言中,大家會遵循給業務程式碼一個單獨包名的實踐,此時我們可以利用包名進行棧幀的過濾和保留操作。
- 抽樣列印全棧資訊:這裡可以根據具體的業務情況而定,需要將全棧資訊進行隨機輸出的原因是有的時候可能會追蹤到一些系統級別的 BUG 或想了解他的一些機制。全棧資訊的輸出有助於問題的追根溯源。
壓縮異常不僅能帶來效能上的提升,而且還能節省大量的儲存空間。如果說上面提到的減少內容是把承載的貨物減輕的話,那麼針對通道的最佳化思路就是最佳化交通運輸的整體效率;站在應用的角度上思考,通道的最佳化,和系統執行時的狀態、以及所使用框架的實現方式有著莫大的關係,言下之意就是有著很大一部分的內容不受程式設計人員的控制。對於不受控制的部分,我們的思路是最大限度解耦底層的實現,具體思路是兩個:- 在進行日誌內容寫入時,透過非同步緩衝區解耦業務程式碼到通道(從日誌框架 到 JVM 到 作業系統 FileSystem)的瓶頸。
- 在進行檔案內容落盤時,透過大檔案切分成小檔案的方式,儘量解耦硬體級別的瓶頸。
使用非同步日誌
由於非同步的方式是業務程式碼先把日誌內容放入一個緩衝區,再由專門的執行緒非同步刷入到檔案系統中,這樣可以最大限度確保業務的吞吐不受底層框架的影響。但是是否所有日誌都適合非同步的策略這個需要根據業務場景進行區分:常規業務日誌如遇到日誌丟棄的場景可能對於業務影響不會太大,但是有的場景是必須做到嚴格資料一致,比如 RocketMQ 的 Commit Log,因為一條日誌代表著一條完整的業務訊息的投遞情況,他必須和業務狀態的返回做到嚴格一致,這種情況非同步方式就不是一個好的選擇;在 Log4j 中,他也提供了兩種方式,一種是細粒度的 Appender 級別的配置,一種是全域性的配置;下圖展示的是三種策略對於效能吞吐的影響:簡單解讀上圖:首先,同步寫入的效能在所有場景中都是最低的,這個和我們常規的認知是一致的;而AsyncLogger (藍色柱狀圖) 的 TPS 卻能隨著 Worker 的增加而增加,但 AsyncAppender只能持平 。這一點和我們常規的認知有些出入,帶著這個疑慮,我們下面稍微深入的探究一下。
下面是 AsyncAppender 的配置方式,框架提供了更多的引數來做更多精細化的控制,核心引數解讀如下:- shutdownTimeout:等待worker執行緒處理日誌的時間,預設為0,表示無限等待;
- bufferSize:緩衝佇列的大小,預設為1024;
- blocking:是否採用阻塞式,預設為true。當佇列滿時,會同步等待。
<Async name="Async"> <AppenderRef ref="RollingRandomAccessFile"/> <shutdownTimeout>500</shutdownTimeout> <bufferSize>1024</bufferSize> <blocking>true</blocking></Async>
簡單解讀其設計意圖:框架會先提供一個系統緩衝區來快取即將寫入的內容,但是當緩衝區滿時,框架還提供了兩種策略進行選擇,第一種是直接丟棄,第二種是進行等待,但是具體等待多長時間也依然可以配置。
與 AsyncAppender 相比,其使用上也更為簡單,只需要透過設定啟動引數-Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector便可全域性啟用非同步日誌。同樣,AsyncLogger 也會有緩衝區的大小的設定,預設是 256K 。當超出緩衝區大小時,可以使用丟棄策略。可以透過配置引數-Dlog4j2.asyncQueueFullPolicy=discard和-Dlog4j2.discardThreshold=INFO 來明確指定丟棄哪一級別的日誌。值得一提的是,AsyncLogger 使用了 LMAX Disruptor的高效能佇列,這是為什麼 AsyncLogger 相比於 AsyncAppender 在單執行緒吞吐和多執行緒併發方面具有更好的效能的關鍵。LMAX Disruptor為什麼相比阻塞佇列效能能隨執行緒數擴充套件,主要有三點:首先,解決了偽共享問題;其次,無鎖的佇列設計,只需CAS的開銷;最後,需要明確的,對比的是該日誌場景下的佇列效能。<dependency> <groupId>com.lmax</groupId> <artifactId>disruptor</artifactId></dependency>
與 Log4j 一樣,Logback 也有著類似的策略,這裡我們就不再贅述它的具體使用方式,下面的表格中,我們總結了在各種策略下的優缺點,希望在大家進行選型時能有所幫助:
| | | | |
| | | | |
| 易用,只需jvm引數-Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector即可啟用 | 配置較為複雜,需要配置多個AsyncAppender | 配置較為複雜,需要配置多個AsyncAppender | |
| | | | |
| | | | |
| Appender中ThreadLocal相關的pattern、filter異常 | Appender中ThreadLocal相關的pattern、filter異常 | Appender中ThreadLocal相關的pattern、filter異常 | |
| | | | |
| XxFileAppender指定immediateFlush為false | XxFileAppender指定immediateFlush為false | XxFileAppender指定immediateFlush為false | XxFileAppender指定immediateFlush為true |
| 設定丟棄策略-Dlog4j2.asyncQueueFullPolicy=discard和-Dlog4j2.discardThreshold=INFO | 設定丟棄策略-Dlog4j2.asyncQueueFullPolicy=discard和-Dlog4j2.discardThreshold=INFO | | |
使用滾動日誌
對於作業系統而言,小檔案的處理相比於大檔案,從系統資源角度,大檔案往往意味著更多的記憶體佔用,更多的 I/O 操作、更苛刻的磁碟空間、更多的匯流排頻寬等等,當任意方資源出現瓶頸時,還會帶來更多的 CPU 使用進而造成系統更高的 Load。而小檔案除了在上述資源角度帶來更好的最佳化空間之外,還在運維管理上提供了更多便利,如:使用更小的磁碟、儘早歸檔、儘早清理磁碟空間等等。在生產實踐中,適當使用滾動日誌,是一項極為可觀的實踐,下面的例子是在 log4j 中的的配置片段,配置內容為在時間上以天滾動,大小上按 100MB 滾動,最多保留 5 個檔案的策略來對日誌檔案進行滾動:<RollingRandomAccessFile name="RollingRandomAccessFile" fileName="logs/app.log" filePattern="powered_by/edas-%d{MM-dd-yyyy}-%i.log"> <PatternLayout> <Pattern>${commonPattern}</Pattern> </PatternLayout> <Policies> <TimeBasedTriggeringPolicy /> <SizeBasedTriggeringPolicy size="100 MB"/> </Policies> <DefaultRolloverStrategy> <max>5</max> </DefaultRolloverStrategy></RollingRandomAccessFile>
看得見的業務開銷,就好比是在運輸途中的貨物,我們期望打包裝車的貨物是最終都會使用到的;即確定能上車才進行打包,確定最終要運輸才裝車。在日誌輸出的場景中,我們也分為兩部分來闡述:在一些需要記錄詳細日誌內容的場景中,往往需要根據上下文中的某些引數再進行全量資訊的獲取(如:查詢資料庫),這樣的動作暗含這一次開銷很大的呼叫開銷,這個時候我們推薦使用"logger.isXXEnabled()"來進行控制。既確定對應的日誌 Level 滿足所需才開啟對應的查詢,參考下面的程式碼所呈現的方式:
log.debug("Powered by {}", getProductInfoByCode("EDAS"));
if (log.isDebugEnabled()) {
log.debug("Powered by {}", getProductInfoByCode("EDAS"));
}
上面的邏輯雖然簡單,原理也簡單易懂,但是我們很多的客戶因為這樣的程式碼太多而帶來的效能退化案例不在少數,一個很典型的例子就是JSON序列化大的物件,究其原因程式碼往往是在日常迭代中對於工程實施沒有規範,Code Review 流程的缺失而導致惡化。與上面的 Case 類似,這個實踐也簡單有效。使用引數佔位符方式,有兩個好處。首先,它更容易編寫,對於記錄內容的句子完整性和可讀性上相比直接拼接字串會友好很多;其次,由於它生成內容延遲的特性,可以保證在需要真實輸出時,才對內容進行填充,這樣無形之中就節省了很多的開銷。程式碼樣例如下:String product = "EDAS";
log.debug("Powered by {}", product);
log.debug("Powered by " + product);
不過可能有的同學心中會有一個疑慮:如果日誌級別為 “DEBUG”,他帶來的效能開銷難道不是一樣(或更差)的嗎?帶著這個疑慮,我們使用 log4j 這個框架針對性的做了一個測試,測試效果如下圖所示:上圖的測試結果,能得出以下兩個結論:1)在輸出字元較短時,字串拼接比佔位符快,因佔位符方式需要執行佔位符掃描替換過程。2)但是隨著輸出字元越來越大,佔位符反過來比字串拼接更快,而且越長的字串快的越多。原因是針對長字元的輸出,日誌框架會有針對性的最佳化。在 log4j2 中,它使用 ThreadLocal 快取並複用了StringBuilder 物件,無需每次都為大的 StringBuilder 構建一個大物件。而字串拼接則每次都建立新的StringBuilder 物件。繼續類比到貨物運輸的場景,看不見的系統開銷,就好比是整車中的資產折舊,道路狀況與司機駕駛習慣造成的綜合油耗。在計算機軟體中,我們常說的系統開銷為主要資源的開銷(計算、記憶體、磁碟、網路等),在這篇文章中,我們主要從記憶體與計算兩個角度闡述:4.1 避免多餘的記憶體資源(Garbage Free)
"Garbage Free" 也叫做 "No GC",即不產生 GC;這是 log4j2 中新引入的一項記憶體最佳化技術,設計目標是減少對垃圾回收(GC)的壓力,他的實現原理比較簡單:透過重複利用物件來避免不必要的物件建立。實現方式包括將需要重複利用的物件放置於執行緒的 ThreadLocal 中,或者重複利用 ByteBuffer 來避免建立不必要的字串物件。透過這個兩個技術手段避免 GC 的開銷後,它能夠顯著降低延遲。官方提供的效能測試結果對比如下:需要注意的是,傳統的 J2EE Web 應用程式的場景中,會有熱載入的訴求,由於 Garbage Free 會快取很多大的 StringBuilder 在 ThreadLocal 中,這在程式熱載入時可能會造成潛在的記憶體洩漏。因此當檢測到是 J2EE Web 應用程式時,log4j2 會預設禁用這項技術。如需強制開啟,可在啟動引數中加入 -Dlog4j2.enable.threadlocals=true -Dlog4j2.enable.direct.encoders=true。日誌輸出時的後設資料資訊列印是指在進行內容輸出時,將程式執行時的與相關程式碼資訊進行輸出,這些內容包括:類名稱、檔名、方法名、行號等。以獲取行號為例,下圖展示了在不同的日誌框架下使用行號輸出與不使用的效能差異。圖中很清晰的展示了幾乎所有的框架在進行行號輸出時效能的急劇下降:我們的疑問是:Why?以 Log4j2 為例,在進行 Location 計算時,是透過構建一個 Throwable 的方式拿到堆疊之後,然後再反向尋找與 Logger 同名的類所在的棧幀,再進行 Location 的獲取。這個過程光聽聽是不是就好感人?感興趣的同學可以查閱對應的程式碼,如下:
public StackTraceElement calcLocation(final String fqcnOfLogger) {
if (fqcnOfLogger == null) {
return null;
}
final StackTraceElement[] stackTrace = new Throwable().getStackTrace();
boolean found = false;
for (int i = 0; i < stackTrace.length; i++) {
final String className = stackTrace[i].getClassName();
if (fqcnOfLogger.equals(className)) {
found = true;
continue;
}
if (found && !fqcnOfLogger.equals(className)) {
return stackTrace[i];
}
}
return null;
}
本文是從 EDAS 團隊在客戶服務的過程中將日誌配置相關的工單答疑整理輸出,嘗試給出幾條 JAVA 日誌的經驗實踐。受限於筆者自身的知識面,可能無法一一列舉出所有的有效能影響的因素,如果您有其他額外的補充,歡迎留言與我們交流。[02] Log4j 配置
[03] Logback 配置
[03] EDAS 執行時日誌動態調整
來自 “ ITPUB部落格 ” ,連結:https://blog.itpub.net/70024420/viewspace-3000234/,如需轉載,請註明出處,否則將追究法律責任。