转载

利用jstack定位典型性能问题实例

此文已由作者朱笑天授权网易云社区发布。

欢迎访问网易云社区，了解更多网易技术产品运营经验。

问题的起因是笔者在一轮性能测试的中，发现某协议的响应时间很长，去观察哨兵监控里的javamethod监控可以看到以下结果：

利用jstack定位典型性能问题实例

onMessage是该协议的总入口，可以看到该协议平均耗时为352.11ms，观察其他耗时方法可以看到updateUserForeignId耗时307.75ms，那么可以认为该方法的响应时间慢是该协议的最主要性能瓶颈，这时候我们应该看看该方法究竟做了哪些操作导致响应时间过长：

利用jstack定位典型性能问题实例

从哨兵监控中可以看到userStorage.updateUserForeignId方法耗时122.86ms，userStorage.updateForeignIdPegging方法耗时71.33ms，这两个方法有成为了SessionProcessHelper.updateUserForeignId方法的主要耗时点，基于对代码的熟悉程度xxxStroge方法都是一些数据库的操作，那么现在可以初步的认为数据库的相关操作可能是问题的根源所在，为了清楚的展示问题，我们先选择一个逻辑较简单的方法分析一下，从上面的哨兵方法监控里可以看到updateSession方法耗时34.88ms，查看该方法代码：

利用jstack定位典型性能问题实例

可以看到方法只是有一个简单的dao层的操作，通过查看dao层方法可知该方法仅仅是一个update操作，按常理来说这样的操作需要三十多毫秒的耗时，显然是偏长了，既然如此，我们继续求根溯源利用哨兵的mqlcolletor来验证一下该方法底层的sql操作究竟耗时多少毫秒。此处省略通过dao层方法查找sql语句的过程，直接来看结果：

利用jstack定位典型性能问题实例

从这里可以看到底层sql响应时间是1.62ms，而dao层方法耗时高达34.88ms，这里显然有问题的，这里我们首先需要排查一下压测机，数据库的各资源指标是否到达瓶颈(在之前的性能测试中发现过类似的问题最后发现是数据库机器的磁盘util接近100%，该机器性能较差导致出现该问题，后期更换数据库机器解决了问题)，通过检查这些指标可以发现cpu,内存，网络，磁盘各项指标均保持在正常水平。

问题到这里，貌似没有什么进展了，这时候就到了jstack登场了。在Java应用的性能测试中，很多性能问题可以通过观察线程堆栈来发现，Jstack是JVM自带dump线程堆栈的工具，很轻量易用，并且执行时不会对性能造成很大的影响。灵活的使用jstack可以发现很多隐秘的性能问题，是定位问题不可多得的好帮手。这里推荐一下我们组内小宝哥的一篇关于jstack使用姿势的一篇ks：巧用jstack定位性能问题

我们来jstack一下，查看在测试执行的过程中，各线程所做的操作和线程状态，可以看到以下状态：

利用jstack定位典型性能问题实例

在所有的24个线程中，多执行几次jstack可以发现大约有十个左右的线程处于waitting状态，该状态表明该线程正在执行obj.wait()方法，放弃了 Monitor，进入 “Wait Set”队列，为什么阻塞住呢，继续往下看堆栈信息，可以看到该线程正在做borrowobject操作，可以大概看到这里是一个数据库连接池的相关操作，具体到究竟是干什么的可以查看一些数据库连接池的资料： dbcp源码解读与对象池原理剖析

简单的说一下，数据库连接的使用过程：创建一个池对象工厂, 将该工厂注入到对象池中, 当要取池对象, 调用borrowObject, 当要归还池对象时, 调用returnObject, 销毁池对象调用clear(), 如果要连池对象工厂也一起销毁, 则调用close()。从这里可以很明显的看到该线程waitting的原因是没有获取到连接池里的连接对象，那么很容易就可以想象的到导致该问题的原因是数据库连接池比够用导致的，于是将连接池的大小从10修改到了50，继续执行一轮测试得到了以下结果：

利用jstack定位典型性能问题实例

可以看到updateSession方法从34.88ms下降到20.13ms，虽然耗时下降了14ms，但是距离sql耗时的1.64ms仍然有差距，沿着刚刚的思路，我们继续jstack一下，看看当前的线程状态又是如何：

利用jstack定位典型性能问题实例

在24个线程中平均下来会有十个左右的blocked状态，继续往下阅读可以发现，该线程是blocked在了log4j.Category.callAppenders上，显然可以发现这是个log4j的问题，那究竟为何会阻塞在这里呢，查看资料可以找到callAppenders的源码（具体的log4j相关资料可以看这里： Log4j 1.x版引发线程blocked死锁问题）：

/** 
     Call the appenders in the hierrachy starting at 
     this.  If no appenders could be found, emit a 
     warning. 
 
     
This method calls all the appenders inherited from the 
     hierarchy circumventing any evaluation of whether to log or not 
     to log the particular log request. 
 
     @param event the event to log.   
*/  
  public void callAppenders(LoggingEvent event) {  
    int writes = 0;  
  
    for(Category c = this; c != null; c=c.parent) {  
      // Protected against simultaneous call to addAppender, removeAppender,...  
      synchronized(c) {  
    if(c.aai != null) {  
      writes += c.aai.appendLoopOnAppenders(event);  
    }  
    if(!c.additive) {  
      break;  
    }  
      }  
    }  
  
    if(writes == 0) {  
      repository.emitNoAppenderWarning(this);  
    }  
  }复制代码

我们从上面可以看出在该方法中有个synchronized同步锁，同步锁就会导致线程竞争，那么在大并发情况下将会出现性能问题，同会引起线程BLOCKED问题。那么如何优化log4j使其执行时间尽量短，防止线程阻塞呢，推荐一下我们组候姐的一篇文章： log4j不同配置对性能的影响当前我们解决该问题的方式是去掉log4j配置文件中打印行号的选项，然后再执行一轮测试可以看到如下结果：利用jstack定位典型性能问题实例可以看到响应updateSession响应时间又下降了一半到了11.48ms的水平，优化到这里可以看到该dao层方法算是达到了一个正常水平，看总体的响应时间也从原先的352.11ms下降到109.19ms。可以认为解决了该协议的性能问题。总结下来，可以发现一个典型性能问题的分析思路：发现性能问题-->查看压测机，服务器，数据库资源指标是否达到瓶颈点-->结合哨兵找到主要耗时方法-->查看耗时方法的具体代码逻辑-->具体问题具体分析(这里是结合jstack查看堆栈信息)-->条件允许范围内优化问题并验证问题。