一次由日志引发的严重性能问题的排查过程-创新互联

一 现象描述

新系统上线后运行正常，但突然有一天客户反馈登录出现很慢的情况。那就先重现客户的问题，在测试环境，单笔测试系统登录发现响应时间在100ms以内，数据上看还是不错的。但并发测试，结果竟然大跌眼镜，在并发100用户下，响应时间飙升到20s左右，这结果完全超越了预期，也重现了客户的问题，接下来就是排查问题、解决问题。。。。

二 问题排查

1.       问题是在多用户并发下出现的，当并发100用户时，从Jmeter console看，吞吐量仅仅为4/s。

此时机器cpu使用率仅2%左右，磁盘、网络都没发现异常，是什么原因导致请求响应时间达到20s左右呢？初步猜测是数据库层在并发下出现了锁，于是按这个思路，排查数据库层的情况。

2．再次并发测试，同时关注数据库是否发生锁表，从测试过程发现，未见锁表，从抓到awr报告中也未发现验证耗时的sql语句，排除了问题发生在数据库层的想法。

    既然数据库层没有问题，就要考虑中间件层了，系统采用java开发，tomcat作为应用服务器。于是，自然想到分析下系统进程的情况。

3． 再次并发测试，通过观察java进程各线程的运行情况，发现并发时，top显示没有线程是running的，隐隐之中，已经觉得离真相更近了一步。

并发时，居然没有线程在running，那它们在干什么呢？所以，需要排查下各个线程的状态。

4.  使用jstack将进程的各线程的运行状态输出到日志，以便后续分析。

   命令格式：jstack pid > stack.log

   查看日志，有重大发现，大量线程是blocked的状态，blcok的原因是在等待log相关的资源。

至此，已经基本判定引起问题的原因了，既然与日志有关，那就先将日志等级从debug调整为error，测试看下是否有变化。

5.  将日志等级从debug调整到error，再次并发测试，发现问题不在出现，tps上升到322/s左右，响应时间90%line在740毫秒，cpu使用到40%-50%，一切开始正常了。

6. 现在已经知道是由于日志配置导致的该问题，那么对日志配置再做一些测试看看情况。

首先日志输出使用的log4j，日志优先级从高到低分别是 ERROR、WARN、INFO、DEBUG。先前配置debug出现性能问题，现在配置error问题解决，再次尝试配 置info，测试也未发现问题，也就是说，该问题只有在debug配置下才会出现。经开发走读代码，发现在debug下才会记录线程打印出的日志。这也再次印证了，debug日志配置引起的问题。

实际系统发布是按info配置的，但是客户环境因人为调整了debug引起的，再次改到info问题就解决了。虽然现场问题暂时解决了，但为什么debug配置下引起该问题，需要进一步分析。

三 进一步分析

从线程日志可以看出调用了org.apache.log4j.Category.callAppenders方法，该方法中有synchronized同步锁，同步锁在并发条件下会导致线程竞争，引起线程BLOCKED问题。

因针对该问题的解决方法，尚未验证，提供以下类似问题的解决方法，供参考：

1.使用Apache log 解决这个问题，代码如下：

    private static final Log log = LogFactory.getLog("xxx");

2.  修改log4j配置文件，添加缓冲配置项；