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)。非常顺利,性能瓶颈的原因找到了!
image.png


但是,为什么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算法等),无效果。
image.png
image.png
image.png

错判3、log4j的bug
Remote debug到测试环境上,在Throwable.printStackTrace()处断点,发现必现异常(ArrayIndexOutOfBoundsException:4)。于是使用关键字log4j+ArrayIndexOutOfBoundsException搜了下,找到log4j2的官方issue(https://issues.apache.org/jir...),不太对,继续浏览该关键字其他的bug issue,没有找到答案,想着要不提一个bug?但升级log4j的版本到2.13后无效果。

柳暗花明
再次Remote debug到测试环境上,一步一步调试,发现会进入一些非本工程的代码且出现单词trace,想起来之前看到的通过字节码注入方式(jar包)打印trace日志的方案,怀疑是trace包内数组越界后catch异常同时e.printStackTrace()。最后找到trace包的提供者验证了该怀疑:
image.png

三 结论

通过字节码注入方式打印trace日志的jar包有一个数组越界的bug:

ThreadContext.put("XXX", ids[4]); // 数组ids大小为4

此处会抛出ArrayIndexOutOfBoundsException,该异常被catch后调用了e.printStackTrace(),而Throwable.printStackTrace()方法会对标准错误输出流(System.err)加同步锁(synchronized),从而造成了服务的性能瓶颈。

阅读 978
9 声望
0 粉丝
0 条评论
你知道吗?

9 声望
0 粉丝
文章目录
宣传栏