技術文章 » 效能調優——小小的log大大的坑

效能調優——小小的log大大的坑

2022-09-05 18:00:47

引言

「只有被線上服務問題毒打過的人才明白紀錄檔有多重要！」
我先說結論，誰贊成，誰反對？如果你深有同感，那恭喜你是個社會人了：）

紀錄檔對程式的重要性不言而喻，輕巧、簡單、無需費腦，程式程式碼中隨處可見，幫助我們排查定位一個有一個問題問題。但看似不起眼的紀錄檔，卻隱藏著各式各樣的「坑」，如果使用不當，不僅不能幫助我們，反而會成為服務「殺手」。
本文主要介紹生產環境紀錄檔使用不當導致的「坑」及避坑指北，高並行系統下尤為明顯。同時提供一套實現方案能讓程式與紀錄檔「和諧共處」。

避坑指北

本章節我將介紹過往線上遇到的紀錄檔問題，並逐個剖析問題根因。

不規範的紀錄檔書寫格式

場景

// 格式1
log.debug("get user" + uid + " from DB is Empty!");

// 格式2
if (log.isdebugEnable()) {
    log.debug("get user" + uid + " from DB is Empty!");
}

// 格式3
log.debug("get user {} from DB is Empty!", uid);

如上三種寫法，我相信大家或多或少都在專案程式碼中看到過，那麼他們之前有區別呢，會對效能造成什麼影響？
如果此時關閉 DEBUG 紀錄檔級別，差異就出現了，格式1 依然還是要執行字串拼接，即使它不輸出紀錄檔，屬於浪費。

格式2 的缺點就是就在於需要加入額外的判斷邏輯，增加了廢程式碼，一點都不優雅。
所以推薦格式3，只有在執行時才會動態的拼接，關閉相應紀錄檔級別後，不會有任何效能損耗。

生產列印大量紀錄檔消耗效能

儘量多的紀錄檔，能夠把使用者的請求串起來，更容易斷定出問題的程式碼位置。由於當前分散式系統，且業務龐雜，任何紀錄檔的缺失對於程式設計師定位問題都是極大的障礙。所以，吃過生產問題苦的程式設計師，在開發程式碼過程中，肯定是儘量多打紀錄檔。
為了以後線上出現問題能儘快定位問題並修復，程式設計師在程式設計實現階段，就會盡量多打關鍵紀錄檔。那上線後是能快速定位問題了，但是緊接著又會有新的挑戰：隨著業務的快速發展，使用者存取不斷增多，系統壓力越來越大，此時線上大量的 INFO 紀錄檔，尤其在高峰期，大量的紀錄檔磁碟寫入，極具消耗服務效能。
那這就變成了博弈論，紀錄檔多了好排查問題，但是服務效能被「吃了」，紀錄檔少了服務穩定性沒啥影響了，但是排查問題難了，程式設計師「苦」啊。

提問：為何 INFO 紀錄檔打多了，效能會受損（此時 CPU 使用率很高）？

根因一：同步列印紀錄檔磁碟 I/O 成為瓶頸，導致大量執行緒 Block

可以想象，如果紀錄檔都輸出到同一個紀錄檔檔案時，此時有多個執行緒都往檔案裡面寫，是不是就亂了套了。那解決的辦法就是加鎖，保證紀錄檔檔案輸出不會錯亂，如果是在高峰期，鎖的爭搶無疑是最耗效能的。當有一個執行緒搶到鎖後，其他的執行緒只能 Block 等待，嚴重拖垮使用者執行緒，表現就是上游呼叫超時，使用者感覺卡頓。

如下是執行緒卡在寫檔案時的堆疊

Stack Trace is:
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.logging.log4j.core.appender.OutputStreamManager.writeBytes(OutputStreamManager.java:352)
- waiting to lock <0x000000063d668298> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager)
at org.apache.logging.log4j.core.layout.TextEncoderHelper.writeEncodedText(TextEncoderHelper.java:96)
at org.apache.logging.log4j.core.layout.TextEncoderHelper.encodeText(TextEncoderHelper.java:65)
at org.apache.logging.log4j.core.layout.StringBuilderEncoder.encode(StringBuilderEncoder.java:68)
at org.apache.logging.log4j.core.layout.StringBuilderEncoder.encode(StringBuilderEncoder.java:32)
at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:228)
.....

那麼是否線上減少 INFO 紀錄檔就沒問題了呢？同樣的，ERROR 紀錄檔量也不容小覷，假設線上出現大量異常資料，或者下游大量超時，瞬時會產生大量 ERROR 紀錄檔，此時還是會把磁碟 I/O 壓滿，導致使用者執行緒 Block 住。

提問：假設不關心 INFO 排查問題，是不是生產只列印 ERROR 紀錄檔就沒效能問題了？

根因二：高並行下紀錄檔列印異常堆疊造成執行緒 Block

有次線上下游出現大量超時，異常都被我們的服務捕獲了，慶幸的是容災設計時預計到會有這種問題發生，做了兜底值邏輯，本來慶幸沒啥影響是，伺服器開始「教做人」了。線上監控開始報警， CPU 使用率增長過快，CPU 一路直接增到 90%+ ，此時緊急擴容止損，並找一臺拉下流量，拉取堆疊。
Dump 下來的執行緒堆疊檢視後，結合火焰退分析，大部分現成都卡在如下堆疊位置：

Stack Trace is:
java.lang.Thread.State: BLOCKED (on object monitor)
at java.lang.ClassLoader.loadClass(ClassLoader.java:404)
- waiting to lock <0x000000064c514c88> (a java.lang.Object)
at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:349)
at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
at org.apache.logging.log4j.core.impl.ThrowableProxyHelper.loadClass(ThrowableProxyHelper.java:205)
at org.apache.logging.log4j.core.impl.ThrowableProxyHelper.toExtendedStackTrace(ThrowableProxyHelper.java:112)
at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:112)
at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:96)
at org.apache.logging.log4j.core.impl.Log4jLogEvent.getThrownProxy(Log4jLogEvent.java:629)
...

此處堆疊較長，大部分現場全部 Block 在 java.lang.ClassLoader.loadClass，而且往下盤堆疊發現都是因為這行程式碼觸發的

at org.apache.logging.slf4j.Log4jLogger.error(Log4jLogger.java:319)

// 對應的業務程式碼為
log.error("ds fetcher get error", e);

啊這。。。就很離譜，你打個紀錄檔為何會載入類呢？載入類為何會 Block 這麼多執行緒呢？
一番查閱分析後，得出如下結論：

  • 使用 Log4j 的 Logger.error 去列印異常堆疊的時候，為了列印出堆疊中類的位置資訊，需要使用 Classloader進行類載入；
  • Classloader載入是執行緒安全的，雖然並行載入可以提高載入不同類的效率，但是多執行緒載入相同的類時，還是需要互相同步等待，尤其當不同的執行緒列印的異常堆疊完全相同時，就會增加執行緒 Block 的風險，而 Classloader 去載入一個無法載入的類時，效率會急劇下降，使執行緒Block的情況進一步惡化；
  • 因為反射呼叫效率問題，JDK 對反射呼叫進行了優化，動態生成 Java 類進行方法呼叫，替換原來的 native 呼叫，而生成的動態類是由 DelegatingClassLoader 進行載入的，不能被其他的 Classloader 載入，異常堆疊中有反射優化的動態類，在高並行的條件下，就非常容易產生執行緒 Block 的情況。

結合上文堆疊，卡在此處就很明清晰了：

  • 大量的執行緒湧進，導致下游的服務超時，使得超時異常堆疊頻繁列印，堆疊的每一層，需要通過反射去拿對應的類、版本、行數等資訊，loadClass 是需要同步等待的，一個執行緒加鎖，導致大部分執行緒 block 住等待類載入成功，影響效能。
  • 講道理，即使大部分執行緒等待一個執行緒 loadClass，也只是一瞬間的卡頓，為何這個報錯這會一直 loadClass類呢？結合上述結論分析程式程式碼，得出：此處執行緒內的請求下游服務邏輯包含 Groovy 指令碼執行邏輯，屬於動態類生成，上文結論三表明，動態類在高並行情況下，無法被log4j正確反射載入到，那麼堆疊反射又要用，進入了死迴圈，越來越多的執行緒只能加入等待，block 住。

最佳實踐

1. 去掉不必要的異常堆疊列印

明顯知道的異常，就不要列印堆疊，省點效能吧，任何事+高並行，意義就不一樣了：）

try {
    System.out.println(Integer.parseInt(number) + 100);
} catch (Exception e) {
    // 改進前
    log.error("parse int error : " + number, e);
    // 改進後
    log.error("parse int error : " + number);
}

如果Integer.parseInt發生異常，導致異常原因肯定是出入的number不合法，在這種情況下，列印異常堆疊完全沒有必要，可以去掉堆疊的列印。

2. 將堆疊資訊轉換為字串再列印

public static String stacktraceToString(Throwable throwable) {
    StringWriter stringWriter = new StringWriter();
    throwable.printStackTrace(new PrintWriter(stringWriter));
    return stringWriter.toString();
}

log.error得出的堆疊資訊會更加完善，JDK 的版本，Class 的路徑資訊，jar 包中的類還會列印 jar 的名稱和版本資訊，這些都是去載入類反射得來的資訊，極大的損耗效能。
呼叫 stacktraceToString 將異常堆疊轉換為字串，相對來說，確實了一些版本和 jar 的後設資料資訊，此時需要你自己決策取捨，到底是否有必要列印出這些資訊（比如類衝突排查基於版本還是很有用的）。

3. 禁用反射優化

使用 Log4j 列印堆疊資訊，如果堆疊中有反射優化生成的動態代理類，這個代理類不能被其它的Classloader載入，這個時候列印堆疊，會嚴重影響執行效率。但是禁用反射優化也會有副作用，導致反射執行的效率降低。

4.非同步列印紀錄檔

生產環境，尤其是 QPS 高的服務，一定要開啟非同步列印，當然開啟非同步列印，有一定丟失紀錄檔的可能，比如伺服器強行「殺死」，這也是一個取捨的過程。

5. 紀錄檔的輸出格式

我們看戲紀錄檔輸出格式區別

// 格式1
[%d{yyyy/MM/dd HH:mm:ss.SSS}[%X{traceId}] %t [%p] %C{1} (%F:%M:%L) %msg%n

// 格式2
[%d{yy-MM-dd.HH:mm:ss.SSS}] [%thread]  [%-5p %-22c{0} -] %m%n

官網也有明確的效能對比提示，如果使用瞭如下欄位輸出，將極大的損耗效能

 %C or $class, %F or %file, %l or %location, %L or %line, %M or %method


log4j 為了拿到函數名稱和行號資訊，利用了異常機制，首先丟擲一個異常，之後捕獲異常並列印出異常資訊的堆疊內容，再從堆疊內容中解析出行號。而實現原始碼中增加了鎖的獲取及解析過程，高並行下，效能損耗可想而知。

如下是比較影響效能的引數設定，請大家酌情設定：

%C - 呼叫者的類名(速度慢,不推薦使用)
%F - 呼叫者的檔名(速度極慢,不推薦使用)
%l - 呼叫者的函數名、檔名、行號(極度不推薦，非常耗效能)
%L - 呼叫者的行號(速度極慢,不推薦使用)
%M - 呼叫者的函數名(速度極慢,不推薦使用)

解決方案——紀錄檔級別動態調整

專案程式碼需要列印大量 INFO級別紀錄檔，以支援問題定位及測試排查等。但這些大量的 INFO紀錄檔對生產環境是無效的，大量的紀錄檔會吃掉 CPU 效能，此時需要能動態調整紀錄檔級別，既滿足可隨時檢視 INFO紀錄檔，又能滿足不需要時可動態關閉，不影響服務效能需要。

方案：結合 Apollo 及 log4j2 特性，從 api層面，動態且細粒度的控制全域性或單個 Class 檔案內的紀錄檔級別。優勢是隨時生效，生產排查問題，可指定開啟單個 class 檔案紀錄檔級別，排查完後可隨時關閉。

限於本篇篇幅，具體實現程式碼就不貼出了，其實實現很簡單，就是巧妙的運用 Apollo 的動態通知機制去重置紀錄檔級別，如果大家感興趣的話，可以私信或者留言我，我開一篇文章專門來詳細講解如何實現。

總結與展望

本篇帶你瞭解了紀錄檔在日常軟體服務中常見的問題，以及對應的解決方法。切記，簡單的東西 + 高並行 = 不簡單！要對生產保持敬畏之心！

能讀到結尾說明你真是鐵粉了，有任何問題請私信或者評論，我看到了一定會第一時間回覆。如果你覺得本人分享的內容夠「幹」，麻煩點贊、關注、轉發，這是對我最大鼓勵，感謝支援！
希望我分享的文章能夠給每一位讀者帶來幫助！個人技術部落格：https://jifuwei.github.io/