printStackTrace()造成的性能瓶頸

一 背景

　　在一次活動前的壓測中，發現一個服務（平響為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），從而造成了服務的性能瓶頸。