java大量的print影响性能吗_printStackTrace()造成的性能瓶颈

一 背景

在一次活动前的压测中，发现一个服务(平响为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未成功(机器权限问题，阻塞未解决)。

错判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)，从而造成了服务的性能瓶颈。