性能优化案例（2019-案例78）-接口性能耗时问题分析

Posted 2022-11-25 qmfsun

在某项目的第一轮性能测试的中，发现某协议响应时间很长，通过javamethod监控相关接口的调用耗时的时候监控结果如下：

onMessage是该协议的总入口，可以看到该协议平均耗时为352.11ms，观察其他耗时方法可以看到updateUserForeignId耗时307.75ms，

那么可以认为该方法的响应时间慢是该协议的最主要性能瓶颈，这时候我们应该看看该方法究竟做了哪些操作导致响应时间过长：

从监控中可以看到userStorage.updateUserForeignId方法耗时122.86ms，userStorage.updateForeignIdPegging方法耗时71.33ms，

这两个方法有成为了SessionProcessHelper.updateUserForeignId方法的主要耗时点，基于对代码的熟悉程度xxxStroge方法都是一些数据库的操作，

那么现在可以初步的认为数据库的相关操作可能是问题的根源所在，为了清楚的展示问题，我们先选择一个逻辑较简单的方法分析一下，从上面的方法监控里可以看到updateSession方法耗时34.88ms，查看该方法代码：

可以看到方法只是有一个简单的dao层的操作，通过查看dao层方法可知该方法仅仅是一个update操作，按常理来说这样的操作需要三十多毫秒的耗时，显然是偏长了，既然如此，

我们继续求根溯源利用哨兵的mqlcolletor来验证一下该方法底层的sql操作究竟耗时多少毫秒。此处省略通过dao层方法查找sql语句的过程，直接来看结果：

从这里可以看到底层sql响应时间是1.62ms，而dao层方法耗时高达34.88ms，这里显然有问题的，这里我们首先需要排查一下压测机，数据库的各资源指标是否到达瓶颈(在之前的性能测试中发现过类似的问题最后发现是数据库机器的磁盘util接近100%，

该机器性能较差导致出现该问题，后期更换数据库机器解决了问题)，通过检查这些指标可以发现cpu,内存，网络，磁盘各项指标均保持在正常水平。

问题到这里，貌似没有什么进展了，这时候就到了jstack登场了。在Java应用的性能测试中，很多性能问题可以通过观察线程堆栈来发现，Jstack是JVM自带dump线程堆栈的工具，很轻量易用，并且执行时不会对性能造成很大的影响。

灵活的使用jstack可以发现很多隐秘的性能问题，是定位问题不可多得的好帮手。我们来jstack一下，查看在测试执行的过程中，各线程所做的操作和线程状态，可以看到以下状态：

在所有的24个线程中，多执行几次jstack可以发现大约有十个左右的线程处于waitting状态，该状态表明该线程正在执行obj.wait()方法，放弃了 Monitor，进入 “Wait Set”队列，为什么阻塞住呢，继续往下看堆栈信息，

可以看到该线程正在做borrowobject操作，可以大概看到这里是一个数据库连接池的相关操作，具体到究竟是干什么的可以查看一些数据库连接池的资料：dbcp源码解读与对象池原理剖析     https://blog.csdn.net/suixinm/article/details/41761019

简单的说一下，数据库连接的使用过程：创建一个池对象工厂, 将该工厂注入到对象池中, 当要取池对象, 调用borrowObject, 当要归还池对象时, 调用returnObject, 销毁池对象调用clear(), 如果要连池对象工厂也一起销毁, 则调用close()。

从这里可以很明显的看到该线程waitting的原因是没有获取到连接池里的连接对象，那么很容易就可以想象的到导致该问题的原因是数据库连接池比够用导致的，于是将连接池的大小从10修改到了50，继续执行一轮测试得到了以下结果：

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

在24个线程中平均下来会有十个左右的blocked状态，继续往下阅读可以发现，该线程是blocked在了log4j.Category.callAppenders上，显然可以发现这是个log4j的问题，那究竟为何会阻塞在这里呢，

查看资料可以找到callAppenders的源码（具体的log4j相关资料可以看这里：Log4j 1.x版引发线程blocked死锁问题）：https://www.iteye.com/blog/zl378837964-2373591

/** 
     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配置文件中打印行号的选项，然后再执行一轮测试可以看到如下结果：

其实这个案例的优化主要体现在接口耗时上面的优化，从最初的接口耗时352ms优化到了109ms，性能提升了接近3倍，虽然用户量小的时候，体现不出打的性能瓶颈，如果并发量大，这种性能优化的效果还是很明显

其实性能优化的重点是分析解决性能瓶颈，而作为专业的性能测试需要辅助开发定位和性能瓶颈卡在哪里，进而指导开发解决问题