jdk自带压测工具_记一次压测优化

最近针对一个比较重要的服务做了下压测，记录了下优化的过程以及所需要的工具介绍。

压测工具：JMeter

分析工具：top、vmstat、Arthas、show-busy-java-threads.sh、MAT

压测数据：100并发，总计20W数据

宿主服务器：CPU12核，被测服务部署在docker

Web服务器：Springboot内嵌tomcat(默认200线程数未作调整，真实业务场景可适时调整)

JDK：1.8

垃圾回收器：Parallel Scavenge + Parallel Old

日志组件：log4j2 INFO级别

调用图例：

case	内存	能耗大户1	能耗大户2	能耗大户3	TPS
case1	1G	RSA	DES	日志脱敏	230
case2	4G	RSA	DES	日志脱敏	500
case3	4G	RSA	DES	/	1400
case4	4G	RSA	DES	日志脱敏V2	600
case5	4G	/	/	/	1900

具体case问题分析

case1

从上图可以看出，老生代在1G内存的情况下占用了683M使用率达到了92.85%，GC的次数和耗时简直没法看了，从而导致系统的tps无法上去。

case2

根据case1的分析，先做内存的扩容，Xms(最小堆内存)和Xmx(最大堆内存)设置为4G

此时GC已经不是大问题了

FullGC一轮压测不触发，只会触发YoungGC，耗时比较理想。

测试过程中，通过show-busy-java-threads.sh命令，基于jstack获取最繁忙的N个调用栈并输出到文件，发现在日志脱敏的代码中使用了SimpleDateFormat影响了性能

"Log4j2-TF-8-AsyncLoggerConfig-6" Id=19 cpuUsage=12% RUNNABLE    at java.util.GregorianCalendar.getJulianCalendarSystem(GregorianCalendar.java:2989)    at java.util.GregorianCalendar.computeTime(GregorianCalendar.java:2720)    at java.util.Calendar.updateTime(Calendar.java:3353)    at java.util.Calendar.getTimeInMillis(Calendar.java:1782)    at java.util.Calendar.getTime(Calendar.java:1755)    at java.text.SimpleDateFormat.parse(SimpleDateFormat.java:1532)    at java.text.DateFormat.parse(DateFormat.java:364)    at com.xxx.converter.pattern.xxx.xxx(xxx.java:106)    at com.xxx.converter.pattern.xxx.xxx(xxx.java:40)    at com.xxx.converter.log4j2.xxx.format(xxx.java:53)

case3

基于case2的分析，先把日志脱敏去除来验证我们的想法，此时堆内存还是4G，不过修改了年轻代Xmn2G(经过观察老年代使用率一直不高故缩小老年代大小)，果然TPS上去了，此处的max耗时主要来源于跨服务调用时的不稳定，不然TPS还可以稍微高一点，并且可以看到前年轻代的GC次数也少了总GC耗时也减少了(每一次的年轻代GC同样会造成stop the world，少见GC就意味着减少被动的上下文切换)

case4

基于case3的结果，准备稍微优化一把脱敏工具，优化完毕再跑，跑的过程中发现TPS降至600，故继续使用

show-busy-java-threads.sh命令进行抓取繁忙线程栈

问题栈如下，在做脱敏时会获取整行日志然后做正则匹配需要脱敏的数据进行脱敏，故相当消耗性能

"Log4j2-TF-8-AsyncLoggerConfig-6" Id=19 cpuUsage=11% RUNNABLE    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3797)    at java.util.regex.Pattern$Curly.match(Pattern.java:4227)    at java.util.regex.Pattern$Branch.match(Pattern.java:4604)    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4658)    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4717)    at java.util.regex.Pattern$CharProperty.match(Pattern.java:3777)    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4658)    at java.util.regex.Pattern$Start.match(Pattern.java:3461)    at java.util.regex.Matcher.search(Matcher.java:1248)    at java.util.regex.Matcher.find(Matcher.java:637)    at com.xxx.converter.pattern.xxx.xxx(xxx.java:50)    at com.xxx.converter.log4j2.xxx.format(xxx.java:48)    at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:38)

此处忘记截图了emmm~~

case5

由于上面的问题短时间内暂不去解决，在后续测试中先去除日志脱敏jar，那么生下来影响TPS的就是DES加密算法和RSA加签了，目前为了适配老服务，对外无缝切换故暂时不切换性能比较好的AES等加密算法，故在本轮测试过程中先去除RSA和DES加密，看看纯业务逻辑处理能达到多少TPS

从下图可以看，如果耗时能控制在40~50左右的话，TPS上1900是没有问题的

后记:

整个压测过程中CPU使用率都还是比较高的，load有时到达30几，这些都有进一步优化的空间。

load高的问题主要还是RSA和DES中核心代码使用了synchronized的对象锁和方法锁导致对系统mutex锁的竞争，每一次的抢锁都会造成用户态到内核态的切换这些都会对CPU造成比较大的负担。

工具分析侧重点:

• top: cpu使用率，load

• vmstat: 上下文切换、空闲率

• Arthas: 应用级别各种监控

• show-busy-java-threads.sh: 繁忙线程栈获取

• MAT: heapdump分析(结合Arthas heapdump食用更香)