效能調優——小小的log大大的坑
引言
“只有被線上服務問題毒打過的人才明白日誌有多重要!”
我先說結論,誰贊成,誰反對?如果你深有同感,那恭喜你是個社會人了:)
日誌對程式的重要性不言而喻,輕巧、簡單、無需費腦,程式程式碼中隨處可見,幫助我們排查定位一個有一個問題問題。但看似不起眼的日誌,卻隱藏著各式各樣的“坑”,如果使用不當,不僅不能幫助我們,反而會成為服務“殺手”。
本文主要介紹生產環境日誌使用不當導致的“坑”及避坑指北,高併發系統下尤為明顯。同時提供一套實現方案能讓程式與日誌“和諧共處”。
避坑指北
本章節我將介紹過往線上遇到的日誌問題,並逐個剖析問題根因。
不規範的日誌書寫格式
場景
// 格式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 的動態通知機制去重置日誌級別,如果大家感興趣的話,可以私信或者留言我,我開一篇文章專門來詳細講解如何實現。
總結與展望
本篇帶你瞭解了日誌在日常軟體服務中常見的問題,以及對應的解決方法。切記,簡單的東西 + 高併發 = 不簡單!要對生產保持敬畏之心!
能讀到結尾說明你真是鐵粉了,有任何問題請私信或者評論,我看到了一定會第一時間回覆。如果你覺得本人分享的內容夠“幹”,麻煩點贊、關注、轉發,這是對我最大鼓勵,感謝支援!
希望我分享的文章能夠給每一位讀者帶來幫助!個人技術部落格: http://jifuwei.github.io/
- 天翼雲全場景業務無縫替換至國產原生作業系統CTyunOS!
- 以羊了個羊為例,淺談小程式抓包與響應報文修改
- 這幾種常見的 JVM 調優場景,你知道嗎?
- 如此狂妄,自稱高效能佇列的Disruptor有啥來頭?
- 為什麼要學習GoF設計模式?
- 827. 最大人工島 : 簡單「並查集 列舉」運用題
- 手把手教你如何使用 Timestream 實現物聯網時序資料儲存和分析
- 850. 矩形面積 II : 掃描線模板題
- Java 併發程式設計解析 | 基於JDK原始碼解析Java領域中的併發鎖,我們可以從中學習到什麼內容?
- 【手把手】光說不練假把式,這篇全鏈路壓測實踐探索
- 大廠鍾愛的全鏈路壓測有什麼意義?四種壓測方案詳細對比分析
- 寫個續集,填坑來了!關於“Thread.sleep(0)這一行‘看似無用’的程式碼”裡面留下的坑。
- 857. 僱傭 K 名工人的最低成本 : 列舉 優先佇列(堆)運用題
- Vue3 實現一個自定義toast(小彈窗)
- 669. 修剪二叉搜尋樹 : 常規樹的遍歷與二叉樹性質
- 讀完 RocketMQ 原始碼,我學會了如何優雅的建立執行緒
- 效能調優——小小的log大大的坑
- 1582. 二進位制矩陣中的特殊位置 : 簡單模擬題
- elementui原始碼學習之仿寫一個el-switch
- 646. 最長數對鏈 : 常規貪心 DP 運用題