JVM调优+性能测试——2一次压力测试问题定位

今天有点空闲，便对程序作了一次压力测试。

系统Centos7.6, jdk1.8，jvm配置:JAVA_MAX_PERM_MEM="256m" JAVA_MAX_MEM="256m", 使用JMetter做并发模拟。

刚开始200个并发，程序OK，在大概13秒之内全部成功。当叠加到600个并发时，程序死掉了，http请求无响应，不出所料，有问题是正常的。接下来记录一下排查过程。

首先拿到程序的pid,然后执行top -Hp 6966  【6966为pid】

  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND                                                                                
 6971 root      20   0 6518996 690984  35232 R 71.6  0.9 172:59.03 java                                                                                   
 6974 root      20   0 6518996 690984  35232 R 70.3  0.9 173:20.36 java                                                                                   
 6968 root      20   0 6518996 690984  35232 R 70.0  0.9 173:15.19 java                                                                                   
 6969 root      20   0 6518996 690984  35232 R 66.3  0.9 172:47.05 java                                                                                   
 6975 root      20   0 6518996 690984  35232 R 65.7  0.9 172:52.02 java                                                                                   
 6970 root      20   0 6518996 690984  35232 R 65.3  0.9 173:27.50 java                                                                                   
 6972 root      20   0 6518996 690984  35232 R 64.4  0.9 173:17.92 java                                                                                   
 6973 root      20   0 6518996 690984  35232 R 63.0  0.9 173:14.25 java

可以看到进程中有8个线程的CPU占用持续很高，可以看出这几个线程很可能就是导致问题的原因。

我们可以使用jdk自带的 jstack 命令导出线程日志查看

jstack 6966 > /home/yrm_jstack.log

在jstack导出的日志中，线程是十六进制的，所以需要将6971转换为16进制   printf %x 6975

[root@host bin]# printf %x 6975
1b3f[root@host bin]# 

查看输出的log日志发现 nid=0x1b3f 是JVM 的GC线程

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f2fb0023000 nid=0x1b38 runnable 

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007f2fb0025000 nid=0x1b39 runnable 

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007f2fb0026800 nid=0x1b3a runnable 

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007f2fb0028800 nid=0x1b3b runnable 

"GC task thread#4 (ParallelGC)" os_prio=0 tid=0x00007f2fb002a800 nid=0x1b3c runnable 

"GC task thread#5 (ParallelGC)" os_prio=0 tid=0x00007f2fb002c000 nid=0x1b3d runnable 

"GC task thread#6 (ParallelGC)" os_prio=0 tid=0x00007f2fb002e000 nid=0x1b3e runnable 

"GC task thread#7 (ParallelGC)" os_prio=0 tid=0x00007f2fb0030000 nid=0x1b3f runnable 

使用jstat -gcutil 6966 【6966为进程pid】

[root@host bin]# jstat -gcutil 6966
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT   
  0.00   0.00 100.00  99.94  92.25  87.04     50    1.207 48109 20534.744 20535.951

可以看出Eden Space、 Old Space内存使用情况几乎100%运行

导出dump文件 jmap -dump:format=b,file=/home/yrm_dump 6966

[root@host bin]# jmap -dump:format=b,file=/home/yrm_dump 6966
Dumping heap to /home/yrm_dump ...
Heap dump file created
[root@host bin]# 

可以看出，不是自身代码导致GC阻塞。测试之前我将jvm参数设置成了：JAVA_MAX_PERM_MEM="128m" JAVA_MAX_MEM="256m"，这里调整为1024之后，并发量可以达到2000

哦，JMetter已经执行了。。。。。。。。。。。。。。。。。。。。。。。。。。。