一次由日志引起的严重性能问题的排查过程

一 现象描述

 

新系统上线后运行正常，但忽然有一天客户反馈登陆出现很慢的状况。那就先重现客户的问题，在测试环境，单笔测试系统登陆发现响应时间在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配置文件，添加缓冲配置项；