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

在某项目的第一轮性能测试的中，发现某协议响应时间很长，经过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倍，虽然用户量小的时候，体现不出打的性能瓶颈，若是并发量大，这种性能优化的效果仍是很明显

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