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

来源:https://www.cnblogs.com/gugujifly/archive/2022/09/05/16658733.html
-Advertisement-
Play Games

日誌對程式的重要性不言而喻，輕巧、簡單、無需費腦，程式代碼中隨處可見，幫助我們排查定位一個有一個問題問題。但看似不起眼的日誌，卻隱藏著各式各樣的“坑”，如果使用不當，不僅不能幫助我們，反而會成為服務“殺手”。 本文主要介紹生產環境日誌使用不當導致的“坑”及避坑指北，高併發系統下尤為明顯。同時提供一套... ...


引言

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

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

避坑指北

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

不規範的日誌書寫格式

場景

// 格式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 日誌，尤其在高峰期，大量的日誌磁碟寫入，極具消耗服務性能。
那這就變成了博弈論，日誌多了好排查問題，但是服務性能被“吃了”，日誌少了服務穩定性沒啥影響了，但是排查問題難了，程式員“苦”啊。
image.png
提問：為何 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

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

如下是比較影響性能的參數配置，請大家酌情配置：

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

解決方案——日誌級別動態調整

項目代碼需要列印大量 INFO級別日誌，以支持問題定位及測試排查等。但這些大量的 INFO日誌對生產環境是無效的，大量的日誌會吃掉 CPU 性能，此時需要能動態調整日誌級別，既滿足可隨時查看 INFO日誌，又能滿足不需要時可動態關閉，不影響服務性能需要。

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

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

總結與展望

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

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


您的分享是我們最大的動力!

-Advertisement-
Play Games
更多相關文章
  • Java---多線程入門
    前置知識 什麼是進程，什麼又是線程？咱不是講系統，簡單說下，知道個大概就好了。 進程：一個可執行文件執行的過程。 線程：操作系統能夠進行運算調度的最小單位。它被包含在進程之中，是進程中的實際運作單位。一條線程指的是進程中一個單一順序的控制流，一個進程中可以併發多個線程，每條線程並行執行不同的任務 什 ...
  • 使用 Mypy 檢查 30 萬行 Python 代碼，總結出 3 大痛點與 6 個技巧！
    Spring(三)——AOP 概念 什麼是AOP （1）面向切麵編程（方面），利用 AOP 可以對業務邏輯的各個部分進行隔離，從而使得業務邏輯各部分之間的耦合度降低，提高程式的可重用性，同時提高了開發的效率。 （2）通俗描述：不通過修改源代碼方式，在主幹功能裡面添加新功能 AOP底層原理 JDK動態 ...
  • day33-線程基礎03
    線程基礎03 6.用戶線程和守護線程 用戶線程：也叫工作線程，當線程的任務執行完或者通知方法結束。平時用到的普通線程均是用戶線程，當在Java程式中創建一個線程，它就被稱為用戶線程 守護線程（Daemon）：一般是為工作線程服務的，當所有的用戶線程結束，守護線程自動結束 常見的守護線程：垃圾回收機制 ...
  • 彩虹女神躍長空,Go語言進階之Go語言高性能Web框架Iris項目實戰-項目結構優化EP05
    前文再續，上一回我們完成了用戶管理模塊的CURD(增刪改查)功能，功能層面，無甚大觀，但有一個結構性的缺陷顯而易見，那就是項目結構過度耦合，項目的耦合性(Coupling)，也叫耦合度，進而言之，模塊之間的關係，是對項目結構中各模塊間相互聯繫緊密程度的一種量化。耦合的強弱取決於模塊間調用的複雜性、調 ...
  • Rust 如何實現 async/await
    非同步編程在 Rust 中的地位非常高，很多 crate 尤其是多IO操作的都使用了 async/await. 首先弄清楚非同步編程的幾個基本概念： Future Future 代表一個可在未來某個時候獲取返回值的 task，為了獲取這個 task 的執行狀況，Future 提供了一個函數用於判斷該 t ...
  • Caffeine緩存框架入門學習
    引入依賴 <dependency> <groupId>com.github.ben-manes.caffeine</groupId> <artifactId>caffeine</artifactId> <version>2.5.5</version> </dependency> 基礎創建方式 Cac ...
  • 用Python做一個中秋搶購月餅的腳本
    序言 每逢佳節倍思親，想買個東西給家裡，結果發現手速不夠，網速不夠快，沒有時間下單等等各種原因導致最後想買的東西售罄了… 甚至跟你一起搶購的可能是腳本，太真實了！ 今天就給大家分享一個python版搶購月餅的腳本，我們要用魔法打敗魔法！話不多說，直接開搞！ 準備工作 今天要用的是一個測試工具的庫：S ...
  • 如何高效解決 C++記憶體問題，Apache Doris 實踐之路｜技術解析
    摘要：經常有朋友問，學 Python 面向對象時，翻閱別人代碼，會發現一個 super() 函數，那這個函數的作用到底是什麼？ 本文分享自華為雲社區《Python 中的 super 函數怎麼學，怎麼解？》，作者：夢想橡皮擦。 實戰場景 經常有朋友問，學 Python 面向對象時，翻閱別人代碼，會發現 ...
一周排行
    -Advertisement-
    Play Games
  • 移動開發（一）：使用.NET MAUI開發第一個安卓APP
    移動開發（一）：使用.NET MAUI開發第一個安卓APP 對於工作多年的C#程式員來說，近來想嘗試開發一款安卓APP，考慮了很久最終選擇使用.NET MAUI這個微軟官方的框架來嘗試體驗開發安卓APP，畢竟是使用Visual Studio開發工具，使用起來也比較的順手，結合微軟官方的教程進行了安卓 ...
  • wpf ToggleButton選中效果和一個登錄界面
    前言 QuestPDF 是一個開源 .NET 庫，用於生成 PDF 文檔。使用了C# Fluent API方式可簡化開發、減少錯誤並提高工作效率。利用它可以輕鬆生成 PDF 報告、發票、導出文件等。 項目介紹 QuestPDF 是一個革命性的開源 .NET 庫，它徹底改變了我們生成 PDF 文檔的方 ...
  • 彈幕樹洞項目功能新增篇
    項目地址 項目後端地址： https://github.com/ZyPLJ/ZYTteeHole 項目前端頁面地址： ZyPLJ/TreeHoleVue (github.com) https://github.com/ZyPLJ/TreeHoleVue 目前項目測試訪問地址： http://tree ...
  • 第27篇 sqlserver2022詳細安裝步驟
    話不多說，直接開乾 一.下載 1.官方鏈接下載： https://www.microsoft.com/zh-cn/sql-server/sql-server-downloads 2.在下載目錄中找到下麵這個小的安裝包 SQL2022-SSEI-Dev.exe，運行開始下載SQL server； 二. ...
  • .NET 開源高性能 MQTT 類庫
    前言 隨著物聯網（IoT）技術的迅猛發展，MQTT（消息隊列遙測傳輸）協議憑藉其輕量級和高效性，已成為眾多物聯網應用的首選通信標準。 MQTTnet 作為一個高性能的 .NET 開源庫，為 .NET 平臺上的 MQTT 客戶端與伺服器開發提供了強大的支持。 本文將全面介紹 MQTTnet 的核心功能 ...
  • Serilog文檔翻譯系列（六） - 可用的接收器、增強器、格式化輸出
    Serilog支持多種接收器用於日誌存儲，增強器用於添加屬性，LogContext管理動態屬性，支持多種輸出格式包括純文本、JSON及ExpressionTemplate。還提供了自定義格式化選項，適用於不同需求。 ...
  • 警惕 Visual Studio 屬性求值副作用導致邏輯不符合預期
    目錄簡介獲取 HTML 文檔解析 HTML 文檔測試參考文章 簡介 動態內容網站使用 JavaScript 腳本動態檢索和渲染數據，爬取信息時需要模擬瀏覽器行為，否則獲取到的源碼基本是空的。 本文使用的爬取步驟如下： 使用 Selenium 獲取渲染後的 HTML 文檔 使用 HtmlAgility ...
  • [使用目前最新版]HybridCLR6.9.0+YooAsset2.2.4實現純C# Unity熱更新方案 (一)
    1.前言 什麼是熱更新 游戲或者軟體更新時，無需重新下載客戶端進行安裝，而是在應用程式啟動的情況下，在內部進行資源或者代碼更新 Unity目前常用熱更新解決方案 HybridCLR，Xlua，ILRuntime等 Unity目前常用資源管理解決方案 AssetBundles，Addressable， ...
  • 在 ASP.NET Core Web API 中使用操作篩選器統一處理通用操作
    本文章主要是在C# ASP.NET Core Web API框架實現向手機發送驗證碼簡訊功能。這裡我選擇是一個互億無線簡訊驗證碼平臺，其實像阿裡雲，騰訊雲上面也可以。 首先我們先去 互億無線 https://www.ihuyi.com/api/sms.html 去註冊一個賬號 註冊完成賬號後，它會送 ...
  • 第28篇 如何.net中實現高效可靠數據同步api
    通過以下方式可以高效，並保證數據同步的可靠性 1.API設計 使用RESTful設計，確保API端點明確，並使用適當的HTTP方法（如POST用於創建，PUT用於更新）。 設計清晰的請求和響應模型，以確保客戶端能夠理解預期格式。 2.數據驗證 在伺服器端進行嚴格的數據驗證，確保接收到的數據符合預期格 ...
所有分類