推薦異步+隨機采樣打印日志，日志能少則少，而且只打印核心信息，切勿打印無用日志內容，切勿在循環中打日志。

摘要：推薦異步+隨機采樣打印日志，日志能少則少，而且只打印核心信息，切勿打印無用日志內容，切勿在循環中打日志。

綜述

??在任何系統中，日志對服務的重要性不言而喻，它是反映系統運行情況的重要依據；它輕巧、簡單，與我們形影不離，使得我們在排查問題時無需絞盡腦汁。被線上服務問題毒打過的人都認可日志的重要性，但看似不起眼的日志，卻是一把雙刃劍，隱藏著各式各樣的“坑”，如果使用不當，不僅不能助我們一臂之力，反而會成為服務“殺手”，所以，你知道有哪些場景可能導致性能問題嗎？今天樓蘭胡楊和各位老鐵聊聊高并發系統下 Java 日志性能那些事，同時提供一套異步+隨機采樣方案能讓程序與日志“和諧共處”。

日志打印流程

??Java 日志打印對服務的影響包括多種因素，例如日志級別、日志輸出目標和日志格式等。下面的流程圖展示了 Java 日志打印的一般流程和對 CPU 的影響。

日志打印流程

??根據以上流程圖可以得出以下結論：

• Java 日志打印會增加代碼的執行時間，因為需要執行額外的日志打印語句。

• 日志級別的選擇會影響 CPU 的占用率。較低的日志級別（如 INFO 或 DEBUG）會導致更多的日志打印語句被執行，增加 CPU 的負擔。

• 日志輸出目標的選擇也會影響 CPU 的占用率。將日志輸出到控制臺會導致額外的 I/O 操作，增加 CPU 的負擔。

??日志格式的復雜程度也會影響 CPU 的占用率。使用更復雜的日志格式可能會導致更多的字符串操作，增加 CPU 的負擔。

不合理的書寫方法

??本章節我將介紹過往線上遇到的日志問題，并逐個剖析問題根因。不同場景的日志書寫格式：

// 格式1
log.debug("User id = " + userId);

// 格式2
if (log.isdebugEnable()) {
    log.debug("User id = " + userId);
}

// 格式3
log.debug("User msg {}!", JSON.toJSONString(user));

// 格式4，既然加了開關，說明是核心日志，打印info級別
if (日志開關已開啟) {
  log.info("User msg {}!", JSON.toJSONString(user));
}

??如上四種寫法，我相信大家或多或少都在項目代碼中看到過，那么它們之間有什么區別？對性能會造成什么影響？如果此時關閉 DEBUG 級別日志，差異就顯露出來了。

格式1 即使它不輸出日志，依然需要執行字符串拼接，屬于資源浪費。

格式2 缺點是需要加入額外的判斷邏輯，增加了廢代碼，一點不優雅。

格式3 缺點是仍然需要根據系統配置的日志級別判斷是否打印日志，并且需要提前序列化對象為JSON字符串，但是，不需要拼接字符串。

格式4 推薦在高并發系統中使用，優點是根據Boolean類型日志開關判斷是否走日志打印邏輯，開關關閉時，不必校驗是否需要打印日志。

線上環境打印大量日志消耗性能

??盡量多的日志，能夠把用戶的請求串起來，更容易斷定出問題的代碼位置。對于業務龐雜的分布式系統，任何日志的缺失對于程序員定位問題都是極大的障礙。所以，被線上問題折磨過的的程序員在開發代碼過程中，為了以后線上出現問題能盡快定位問題并修復，肯定會設置合理的日志級別，而且只打印剛需日志。

??提問：為何 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 日志量也不容小覷，假設線上出現大量異常數據，或者下游大量超時，瞬時會產生大量 ERROR 日志，此時還是會把磁盤 I/O 壓滿，導致用戶線程 Block 住，最終導致 CPU 使用率快速增長。

最佳實踐

去掉不必要的異常堆棧信息

??對于顯而易見的異常就不要打印堆棧，省點性能，任何事一旦邂逅高并發，意義就不一樣了。

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不合法，在這種情況下，可以去掉不必要打印的異常堆棧信息，直接打印自定義異常信息。

異步隨機采樣打印日志

??生產環境，尤其是 QPS 高的服務，小編推薦大家采用【異步+隨機采樣】打印策略，異步打印就不解釋了，隨機采樣可以根據每次請求的唯一標識，如訂單ID、用戶ID+當前時間戳或者每次訪問的請求ID等，隨機打印32%或者50%等。當然開啟異步打印有丟失日志的風險，比如服務器被強行終止時，沒有來得及打印的日志就會丟失，但是，這些丟失的日志相對于QPS>100的整體日志而言，可以忽略不計。

優化日志的輸出格式

??我們看下不同日志輸出模式的區別：

// 格式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

??各屬性解釋如下：

%C - 調用者的類名（速度慢，不推薦使用）
%F - 調用者的文件名（速度極慢，不推薦使用）
%l - 調用者的函數名、文件名、行號（極度不推薦，非常耗性能）
%L - 調用者的行號（速度極慢，不推薦使用）
%M - 調用者的函數名（速度極慢，不推薦使用）

??例如，log4j 為了拿到函數名稱和行號信息，利用了異常機制，首先拋出一個異常，之后捕獲異常并打印出異常信息的堆棧內容，再從堆棧內容中解析出行號。而實現源碼中增加了鎖的獲取及解析過程，高并發下，性能損耗可想而知。

配置日志打印開關|done

??動態調整日志級別是常規操作，不做介紹，它既滿足可隨時查看 INFO日志的訴求，又能滿足不需要時可動態關閉的訴求，而且不影響服務性能。借鑒此設計思想，小編推薦老鐵們自定義日志打印開關。如果需要排查問題，開啟相關日志的開關，定位到問題后再關閉開關：

if (日志開關已開啟) {
  log.info("User msg {}!", JSON.toJSONString(user));
}

??優點是避免JSON 序列化或者字符串拼接，而且可以減少不必要的磁盤I/O操作造成的性能損耗。

總結與展望

??小編在此帶你了解了日志在日常軟件服務中常見的問題，以及對應的解決方法。切記，簡單的東西 + 高并發 = 不簡單！要對服務穩定性保持敬畏之心！

??能讀到結尾說明你真是鐵粉了，有任何問題請私信或者評論，我看到了一定會第一時間回復。“點贊背后有感動，轉發背后有收獲，評論背后有認同，關注背后有價值。”如果你覺得本人提供的內容解決了你的問題，麻煩點贊、轉發和關注，這是對我默默前行的最大鼓勵，感謝支持！

Reference

• https://blog.csdn.net/weixin_43975482/article/details/126647980