性能压测问题分析

 

记一次生产环境性能压测优化的经历

对线上服务进行性能压力测试的一次优化过程。
项目背景：
1.服务器的硬件配置(48核120G内存2T硬盘)；
2.网络部署结构，用户请求报文首先进入负载均衡Nginx，Nginx后端负载两台Tomcat。
现象描述：
对线上的两台服务器做性能压测时，发现单台Tomcat的QPS达到600左右处理业务就明显变慢，一次请求处理时间大约上升到七秒左右(正常情况下一秒内就处理完成)，给人的感觉就是Tomcat跑不动。
优化过程：
1.查看Tomcat和Nginx各自的log日志，发现Nginx的日志中有大量的“worker_connections are not enough while connecting to upstream”，错误信息已明确给出了提示，因此修改配置文件nginx.conf,修改为：

worker_processes  auto;
events {
    worker_connections  10240;
}

 

2.继续压测时，当QPS达到600时，发现Tomcat处理业务仍然很慢，查看ngxin的日志一切正常并无任何线索，因此，把重心转向Tomcat，查看Tomcat日志，发现日志打印的非常慢，特别是定位到两条相隔很近的日志间所需时间都在2秒左右，而且这两条日志在代码层面相隔很近，中间也无耗时的业务逻辑。
此时的第一反应是jvm的参数设置的不合理，于是就去查看gc的日志，并改动JVM的参数，但是多次调优JVM后QPS仍然未有明显提升。修改后的jvm参数：

JAVA_OPTS="-server -Xmx32g -Xms32g -Xmn12g -Xss256k -XX:SurvivorRatio=6 
-XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:MaxGCPauseMillis=n -XX:CMSInitiatingOccupancyFraction=60 -XX:CMSTriggerRatio=70 
-XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:/home/xiaoju/logs/stargate-service/gc/gc_${DT}.log -XX:+PrintHeapAtGC"

 

3.既然排除JVM和业务代码的原因，把目标又锁定在了日志框架上，我们的业务代码中引用了log4j(版本1.12.7)框架进行日志操作，在log4j的官网上找到了对性能影响的因素，见官网Performance菜单下的如下章节所示
Asynchronous Logging with Caller Location Information
也就是说如果在日志信息中打印location信息(例如：包名、类名、函数名称和行号)(即：在log4j的配置文件中，配置了%C or $class, %F or %file, %l or %location, %L or %line, %M or %method)，会严重影响log4j的性能。
跟踪log4j源码后发现，log4j为了拿到函数名称和行号信息，利用了异常机制，首先抛出一个异常，之后捕获异常并打印出异常信息的堆栈内容，再从堆栈内容中解析出行号，代码截取如下：

/**
     Set the location information for this logging event. The collected
     information is cached for future use.
   */
  public LocationInfo getLocationInformation() {
    if(locationInfo == null) {
      locationInfo = new LocationInfo(new Throwable(), fqnOfCategoryClass);
    }
    return locationInfo;
  }

 

我们知道，Java的异常机制很耗性能(注意：如果单纯的是new异常并抛出并未耗性能，如果对异常栈进行操作，如打印输出则很耗性能)，因此我们将log4j的配置文件去掉了函数名称和行号打印后，性能QPS立马提升到了2500。
4.在log4j的配置文件中去掉log4j的location信息后，继续压力测试，待QPS达到2500后服务器又会报服务超时的错误，通过看log4j官网文档中的性能章节，发现console对性能的影响也会非常大，因此在log4j的配置文件中又将console关闭了，继续压测后QPS性能达到8000左右了。
5.在log4j的配置文件中关闭location信息和关闭console后，继续压力测试进行优化，发现日志文件的大小也会影响到性能，建议控制日志文件的大小或者采用日志追加的方式；同时将日志改为异步打印也会有性能提升有所帮助。（在我们测试的过程中，日志文件大小和异步打印，对性能的提升有限，不如去掉location信息和关闭console那么明显）。

总结：
1.Java语言不像C语言或PHP语言，对于行号获取有宏定义__LINE__,可以很方便的获取到行号信息，而Java语言中并未有这样的宏定义，因此为了获取到行号信息，Java只能从线程池栈或异常栈中获取，为了获得异常栈信息，又只能构造异常并抛异常，依次来拿到栈信息。即：在Java语言中，凡是涉及到行号信息的获取，只能通过构造异常new Throwable()抛出，之后在函数内部通过异常或上层捕获异常来拿到栈信息，从栈信息中解析出行号信息，因此在Java中凡是涉及到行号信息的获取操作，都非常的耗性能，这一点尤其要注意。
2.log4j影响性能的程度依次为：日志的location信息(如:行号函数名) > console(关闭日志输出到控制台) > 异步打印 > 日志文件的大小(日志追加模式)。线上环境如果对性能有一定要求的话，建议关闭location和console控制台。

附录：
JVM的优化，JVM调优一般来说都是出问题或告警的时候注意进行优化，这块可谓”水无常形 兵无常势”,具体问题具体分析。
回收器的选择：
- CMS
- G1
关键参数
– 决定Heap大小:-xms(最小) -xmx(最大) –xmn(年轻代大小)(建议-xms=-xmx) ，初始堆的大小==可调堆最大值，避免堆动荡
● 取决与操作系统位数和CPU能力
● 过小则GC频繁，过大则GC中断时间过长，注意GC发生时业务代码会出现暂停一会，即：Stop the world。
– Eden/From/To：决定YounGC，如：-XX:SurvivorRatio
– 新生代存活周期：决定FullGC，如：–XX:MaxTenuringThreshold
新生代/旧生代
– 避免新生代设置过小
● 频繁YoungGC
● 大对象,From/To不足拿Old增长快，FullGC
– 避免新生代设置过大
● 旧生代变小，频繁FullGC
● 新生代变大，YoungGC更耗时
– 对于我们组大部分系统，可以分配 ： 新生代:Heap=33%，即Young:Old=1:2

-XX:NewRatio=4:设置年轻代（包括Eden和两个Survivor区）与年老代的比值（除去持久代），设置为4，则年轻代与年老代所占比值为1：4，年轻代占整个堆栈的1/5。
-XX:SurvivorRatio=4：设置年轻代中Eden区与Survivor区的大小比值，设置为4，则两个Survivor区与一个Eden区的比值为2:4，一个Survivor区占整个年轻代的1/6，Eden区占整个年轻代的4/6。

供参考：
1.GC专家系列3-GC调优 https://segmentfault.com/a/1190000004303843
2.JVM GC中Stop the world案例实战 https://blog.csdn.net/sinat_25306771/article/details/52374498
3.从实际案例聊聊Java应用的GC优化 https://tech.meituan.com/2017/12/29/jvm-optimize.html
4.垃圾回收算法 https://blog.csdn.net/d6619309/article/details/53358250
5.关于Jvm知识看这一篇就够了https://zhuanlan.zhihu.com/p/34426768?group_id=956114978579750912