printStackTrace()造成的并发瓶颈

• 2020 年 10 月 19 日
• 筆記
• JAVA, log4j2, 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（//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