一 背景
在一次版本上线前的压测中,发现相比于旧版本300ms左右的平响,新版本已经达到了2000ms几乎快超时的平响,造成单台容器原本预期100TPS降到了只有20TPS,通过分析javacore文件发现很多BLOCKED线程,考虑BLOCKED线程出现的可能性,同步锁锁等待和内存资源不足。
由于笔者对于初步定位到问题的代码块自认为比较熟悉,不涉及同步锁锁等待,首先考虑内存资源不足,刚好有问题的代码块存在新建较多List的处理,参考了博文[2]之后,加上List的显式回收,再压测,结果并没有好转,具体再看BLOCKED线程信息,发现很多线程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)
再回到问题代码块,发现有个异常分支有个孤零零的e.printStackTrace()
try{
....
}catch(Exception e){
e.printStackTrace();
}
二 分析
分析线程信息,类Throwable的653行,printStackTrace()方法会对标准错误输出流(System.err)加同步锁(synchronized)。到这里,性能瓶颈的原因找到了!
建议参考:
- 《java中e.printStackTrace()不要使用,请使用logger记录
》https://blog.csdn.net/qq_28929589/article/details/82495193 - 《把list清空和赋值null对内存释放的区别》https://blog.csdn.net/qq_39019865/article/details/80702667