printStackTrace()造成的併發瓶頸

hiwatershed發表於2020-10-19

一 背景

　　在一次活動前的壓測中，發現一個服務（平響為250ms左右）存在併發瓶頸，單例項的QPS壓力從20升高到40後服務就雪崩了（平響急劇升高）。

　　通過<jstack -F>命令檢視執行緒資訊，發現很多執行緒BLOCKED在列印日誌的地方：

Thread 39120: (state = BLOCKED)
 - java.lang.Throwable.printStackTrace(java.lang.Throwable$PrintStreamOrWriter) @bci=25, line=653 (Compiled frame)
 - java.lang.Throwable.printStackTrace(java.io.PrintStream) @bci=9, line=643 (Compiled frame)
 - java.lang.Throwable.printStackTrace() @bci=4, line=634 (Compiled frame)
 - org.apache.logging.log4j.core.Logger.logMessage(java.lang.String, org.apache.logging.log4j.Level, org.apache.logging.log4j.Marker, org.apache.logging.log4j.message.Message, java.lang.Throwable) @bci=103, line=144 (Interpreted frame)
 - org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(java.lang.String, org.apache.logging.log4j.Level, org.apache.logging.log4j.Marker, org.apache.logging.log4j.message.Message, java.lang.Throwable) @bci=8, line=2091 (Compiled frame)
 - org.apache.logging.log4j.spi.AbstractLogger.logMessage(java.lang.String, org.apache.logging.log4j.Level, org.apache.logging.log4j.Marker, java.lang.String, java.lang.Object[]) @bci=186, line=1999 (Interpreted frame)
 - org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(java.lang.String, org.apache.logging.log4j.Level, org.apache.logging.log4j.Marker, java.lang.String, java.lang.Object[]) @bci=21, line=1868 (Interpreted frame)
 - org.apache.logging.slf4j.Log4jLogger.info(java.lang.String, java.lang.Object) @bci=20, line=183 (Compiled frame)

　　該服務使用log4j-2.7列印日誌，當時做了下面三個嘗試：

  1. 從Logger改成asyncLogger，無效果；
  2. 減少日誌量（只列印com.xxx.xxx包路徑下的日誌），單例項QPS壓力升高到48後服務雪崩；
  3. 不列印info級別日誌，單例項QPS壓力到80服務依然正常；

　　很疑惑，為什麼日誌列印對服務效能的影響如此大？而且單例項的QPS壓力只有20也太小了（併發數只有5 = 20 / 1000ms / 250ms）！

二 排查

　　分析<jstack -F>命令查出的執行緒資訊，類Throwable的653行，printStackTrace()方法會對標準錯誤輸出流（System.err）加同步鎖（synchronized）。非常順利，併發瓶頸的原因找到了！

但是，為什麼logger.info會進入到Throwable.printStackTrace()呢？

錯判1、jstack

　　懷疑<jstack -F>命令查出的執行緒資訊有問題，嘗試用<jstack -l>命令，提示錯誤資訊"well-known file is not secure"，搜了下是由於<pid>程式的所有者與執行jstack命令的使用者不一致，使用sudo未成功（機器許可權問題，阻塞未解決）。

錯判2、GC

　　分析Throwable.printStackTrace()的上一行堆疊資訊（類Logger的144行、類AbstractLogger的1992/1998行），懷疑是GC導致（歷史經驗，但講不通），檢視服務雪崩時的GC日誌，發現確實GC頻繁，搜了下CMS GC的相關文章，嘗試修改JVM引數（記憶體大小、GC演算法等），無效果。

錯判3、log4j的bug

　　Remote debug到測試環境上，在Throwable.printStackTrace()處斷點，發現必現異常（ArrayIndexOutOfBoundsException:4）。於是使用關鍵字log4j+ArrayIndexOutOfBoundsException搜了下，找到log4j2的官方issue（https://issues.apache.org/jira/browse/LOG4J2-1542），不太對，繼續瀏覽該關鍵字其他的bug issue，沒有找到答案，想著要不提一個bug？但升級log4j的版本到2.13後無效果。

柳暗花明

　　再次Remote debug到測試環境上，一步一步除錯，發現會進入一些非本工程的程式碼且出現單詞trace，想起來之前看到的通過位元組碼注入方式（jar包）列印trace日誌的方案，懷疑是trace包內陣列越界後catch異常同時e.printStackTrace()。最後找到trace包的提供者驗證了該懷疑：

三 結論

通過位元組碼注入方式列印trace日誌的jar包有一個陣列越界的bug：

ThreadContext.put("XXX", ids[4]); // 陣列ids大小為4

　　此處會丟擲ArrayIndexOutOfBoundsException，該異常被catch後呼叫了e.printStackTrace()，而Throwable.printStackTrace()方法會對標準錯誤輸出流（System.err）加同步鎖（synchronized），從而造成了服務的併發瓶頸。

相關文章