主頁 > 後端開發 > 性能調優——小小的log大大的坑

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

2022-09-06 09:47:16 後端開發

引言

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

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

避坑指北

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

不規范的日志書寫格式

場景

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

轉載請註明出處，本文鏈接：https://www.uj5u.com/houduan/504207.html

標籤：其他

上一篇：Python學習：基礎練習題

下一篇：想了解Python中的super 函式么

標籤雲
其他(157675) Python(38076) JavaScript(25376) Java(17977) C(15215) 區塊鏈(8255) C＃(7972) AI(7469) 爪哇(7425) MySQL(7132) html(6777) 基礎類(6313) sql(6102) 熊猫(6058) PHP(5869) 数组(5741) R(5409) Linux(5327) 反应(5209) 腳本語言(PerlPython)(5129) 非技術區(4971) Android(4554) 数据框(4311) css(4259) 节点.js(4032) C語言(3288) json(3245) 列表(3129) 扑(3119) C++語言(3117) 安卓(2998) 打字稿(2995) VBA(2789) Java相關(2746) 疑難問題(2699) 细绳(2522) 單片機工控(2479) iOS(2429) ASP.NET(2402) MongoDB(2323) 麻木的(2285) 正则表达式(2254) 字典(2211) 循环(2198) 迅速(2185) 擅长(2169) 镖(2155) 功能(1967) .NET技术(1958) Web開發(1951) python-3.x(1918) HtmlCss(1915) 弹簧靴(1913) C++(1909) xml(1889) PostgreSQL(1872) .NETCore(1853) 谷歌表格(1846) Unity3D(1843) for循环(1842)

熱門瀏覽
  • 【C++】Microsoft C++、C 和匯編程式檔案

    ......

    uj5u.com 2020-09-10 00:57:23 more
  • 例外宣告

    相比于斷言適用于排除邏輯上不可能存在的狀態，例外通常是用于邏輯上可能發生的錯誤。 例外宣告 Item 1：當函式不可能拋出例外或不能接受拋出例外時，使用noexcept 理由 如果不打算拋出例外的話，程式就會認為無法處理這種錯誤，并且應當盡早終止，如此可以有效地阻止例外的傳播與擴散。 示例 //不可 ......

    uj5u.com 2020-09-10 00:57:27 more
  • Codeforces 1400E Clear the Multiset(貪心 + 分治)

    鏈接：https://codeforces.com/problemset/problem/1400/E 來源：Codeforces 思路：給你一個陣列，現在你可以進行兩種操作，操作1：將一段沒有 0 的區間進行減一的操作，操作2：將 i 位置上的元素歸零。最終問：將這個陣列的全部元素歸零后操作的最少 ......

    uj5u.com 2020-09-10 00:57:30 more
  • UVA11610 【Reverse Prime】

    本人看到此題沒有翻譯，就附帶了一個自己的翻譯版本 思考 這一題，它的第一個要求是找出所有 $7$ 位反向質數及其質因數的個數。 我們應該需要質數篩篩選1~$10^{7}$的所有數，這里就不慢慢介紹了。但是，重讀題，我們突然發現反向質數都是 $7$ 位，而將它反過來后的數字卻是 $6$ 位數，這就說明 ......

    uj5u.com 2020-09-10 00:57:36 more
  • 統計區間素數數量

    1 #pragma GCC optimize(2) 2 #include <bits/stdc++.h> 3 using namespace std; 4 bool isprime[1000000010]; 5 vector<int> prime; 6 inline int getlist(int ......

    uj5u.com 2020-09-10 00:57:47 more
  • C/C++編程筆記：C++中的 const 變數詳解，教你正確認識const用法

    1、C中的const 1、區域const變數存放在堆疊區中，會分配記憶體（也就是說可以通過地址間接修改變數的值）。測驗代碼如下： 運行結果： 2、全域const變數存放在只讀資料段（不能通過地址修改，會發生寫入錯誤）， 默認為外部聯編，可以給其他源檔案使用（需要用extern關鍵字修飾） 運行結果： ......

    uj5u.com 2020-09-10 00:58:04 more
  • 【C++犯錯記錄】VS2019 MFC添加資源不懂如何修改資源宏ID

    1. 首先在資源視圖中，添加資源 2. 點擊新添加的資源，復制自動生成的ID 3. 在解決方案資源管理器中找到Resource.h檔案，編輯，使用整個專案搜索和替換的方式快速替換 宏宣告 4. Ctrl+Shift+F 全域搜索，點擊查找全部，然后逐個替換 5. 為什么使用搜索替換而不使用屬性視窗直 ......

    uj5u.com 2020-09-10 00:59:11 more
  • 【C++犯錯記錄】VS2019 MFC不懂的批量添加資源

    1. 打開資源頭檔案Resource.h，在其中預先定義好宏 ID（不清楚其實ID值應該設定多少，可以先新建一個相同的資源項，再在這個資源的ID值的基礎上遞增即可） 2. 在資源視圖中選中專案資源，按F7編輯資源檔案，按 ID 型別 相對路徑的形式添加 資源。（別忘了先把檔案拷貝到專案中的res檔案 ......

    uj5u.com 2020-09-10 01:00:19 more
  • C/C++編程筆記：關于C++的參考型別，專供新手入門使用

    今天要講的是C++中我最喜歡的一個用法——參考，也叫別名。 參考就是給一個變數名取一個變數名，方便我們間接地使用這個變數。我們可以給一個變數創建N個參考，這N + 1個變數共享了同一塊記憶體區域。(參考型別的變數會占用記憶體空間，占用的記憶體空間的大小和指標型別的大小是相同的。雖然參考是一個物件的別名，但 ......

    uj5u.com 2020-09-10 01:00:22 more
  • 【C/C++編程筆記】從頭開始學習C ++：初學者完整指南

    眾所周知，C ++的學習曲線陡峭，但是花時間學習這種語言將為您的職業帶來奇跡，并使您與其他開發人員區分開。您會更輕松地學習新語言，形成真正的解決問題的技能，并在編程的基礎上打下堅實的基礎。 C ++將幫助您養成良好的編程習慣（即清晰一致的編碼風格，在撰寫代碼時注釋代碼，并限制類內部的可見性），并且由 ......

    uj5u.com 2020-09-10 01:00:41 more
最新发布
  • Rust中的智能指標:Box<T> Rc<T> Arc<T> Cell<T> RefCell<T> Weak

    Rust中的智能指標是什么 智能指標（smart pointers）是一類資料結構，是擁有資料所有權和額外功能的指標。是指標的進一步發展 指標（pointer）是一個包含記憶體地址的變數的通用概念。這個地址參考，或 ” 指向”（points at）一些其 他資料 。參考以 & 符號為標志并借用了他們所 ......

    uj5u.com 2023-04-20 07:24:10 more
  • Java的值傳遞和參考傳遞

    值傳遞不會改變本身，參考傳遞（如果傳遞的值需要實體化到堆里）如果發生修改了會改變本身。 1.基本資料型別都是值傳遞 package com.example.basic; public class Test { public static void main(String[] args) { int ......

    uj5u.com 2023-04-20 07:24:04 more
  • [2]SpinalHDL教程——Scala簡單入門

    第一個 Scala 程式 shell里面輸入 $ scala scala> 1 + 1 res0: Int = 2 scala> println("Hello World!") Hello World! 檔案形式 object HelloWorld { /* 這是我的第一個 Scala 程式 * 以 ......

    uj5u.com 2023-04-20 07:23:58 more
  • 理解函式指標和回呼函式

    理解 函式指標 指向函式的指標。比如： 理解函式指標的偽代碼 void (*p)(int type, char *data); // 定義一個函式指標p void func(int type, char *data); // 宣告一個函式func p = func; // 將指標p指向函式func ......

    uj5u.com 2023-04-20 07:23:52 more
  • Django筆記二十五之資料庫函式之日期函式

    本文首發于公眾號：Hunter后端 原文鏈接：Django筆記二十五之資料庫函式之日期函式 日期函式主要介紹兩個大類，Extract() 和 Trunc() Extract() 函式作用是提取日期，比如我們可以提取一個日期欄位的年份，月份，日等資料 Trunc() 的作用則是截取，比如 2022-0 ......

    uj5u.com 2023-04-20 07:23:45 more
  • 一天吃透JVM面試八股文

    什么是JVM？ JVM，全稱Java Virtual Machine（Java虛擬機），是通過在實際的計算機上仿真模擬各種計算機功能來實作的。由一套位元組碼指令集、一組暫存器、一個堆疊、一個垃圾回收堆和一個存盤方法域等組成。JVM屏蔽了與作業系統平臺相關的資訊，使得Java程式只需要生成在Java虛擬機 ......

    uj5u.com 2023-04-20 07:23:31 more
  • 使用Java接入小程式訂閱訊息！

    更新完微信服務號的模板訊息之后，我又趕緊把微信小程式的訂閱訊息給實作了！之前我一直以為微信小程式也是要企業才能申請，沒想到小程式個人就能申請。 訊息推送平臺🔥推送下發【郵件】【短信】【微信服務號】【微信小程式】【企業微信】【釘釘】等訊息型別。 https://gitee.com/zhongfuch ......

    uj5u.com 2023-04-20 07:22:59 more
  • java -- 緩沖流、轉換流、序列化流

    緩沖流 緩沖流, 也叫高效流, 按照資料型別分類： 位元組緩沖流：BufferedInputStream，BufferedOutputStream 字符緩沖流：BufferedReader，BufferedWriter 緩沖流的基本原理，是在創建流物件時，會創建一個內置的默認大小的緩沖區陣列，通過緩沖 ......

    uj5u.com 2023-04-20 07:22:49 more
  • Java-SpringBoot-Range請求頭設定實作視頻分段傳輸

    老實說，人太懶了，現在基本都不喜歡寫筆記了，但是網上有關Range請求頭的文章都太水了 下面是抄的一段StackOverflow的代碼...自己大修改過的，寫的注釋挺全的，應該直接看得懂，就不解釋了 寫的不好...只是希望能給視頻網站開發的新手一點點幫助吧. 業務場景：視頻分段傳輸、視頻多段傳輸（理 ......

    uj5u.com 2023-04-20 07:22:42 more
  • Windows 10開發教程_編程入門自學教程_菜鳥教程-免費教程分享

    教程簡介 Windows 10開發入門教程 - 從簡單的步驟了解Windows 10開發，從基本到高級概念，包括簡介，UWP，第一個應用程式，商店，XAML控制元件，資料系結，XAML性能，自適應設計，自適應UI，自適應代碼，檔案管理，SQLite資料庫，應用程式到應用程式通信，應用程式本地化，應用程式 ......

    uj5u.com 2023-04-20 07:22:35 more

Copyright © 2010-2020 有解無憂