一 背景
在一次活動前的壓測中，發現一個服務（平響為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列印日志，當時做了下面三個嘗試：
- 從Logger改成asyncLogger，無效果；
- 減少日志量（只列印com.xxx.xxx包路徑下的日志），單實體QPS壓力升高到48后服務雪崩；
- 不列印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），從而造成了服務的并發瓶頸，
轉載請註明出處，本文鏈接：https://www.uj5u.com/houduan/180911.html
標籤：其他
上一篇：學習第56天