在一次活动前的压测中，发现一个服务（平响为250ms左右）存在性能瓶颈，单实例的QPS压力从20升高到40后服务就雪崩了（平响急剧升高）。
通过命令查看线程信息，发现很多线程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）！
分析命令查出的线程信息，类Throwable的653行，printStackTrace()方法会对标准错误输出流（System.err）加同步锁（synchronized）。非常顺利，性能瓶颈的原因找到了！
----------------------------------但是，为什么logger.info会进入到Throwable.printStackTrace()呢？错判1、jstack
怀疑命令查出的线程信息有问题，尝试用命令，提示错误信息"well-known file is not secure"，搜了下是由于进程的所有者与执行jstack命令的用户不一致，使用sudo未成功（机器权限问题，阻塞未解决）。分析Throwable.printStackTrace()的上一行堆栈信息（类Logger的144行、类AbstractLogger的1992/1998行），怀疑是GC导致（历史经验，但讲不通），查看服务雪崩时的GC日志，发现确实GC频繁，搜了下CMS GC的相关文章，尝试修改JVM参数（内存大小、GC算法等），无效果。
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），从而造成了服务的性能瓶颈。
京公网安备 11010802041100号