某日,运维同学反馈生产环境有故障,某个JVM进程CPU负载一直居高不下。登入服务器用 top -c 命令查看如下:
top - 00:37:39 up 48 days, 10:41, 5 users, load average: 3.34, 3.18, 3.10
Tasks: 166 total, 1 running, 165 sleeping, 0 stopped, 0 zombie
Cpu0 : 0.7%us, 0.3%sy, 0.0%ni, 99.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu1 :100.0%us, 0.0%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu2 : 1.3%us, 0.3%sy, 0.0%ni, 98.3%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu3 : 0.3%us, 0.0%sy, 0.0%ni, 99.7%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 16332280k total, 15744336k used, 587944k free, 200632k buffers
Swap: 8191992k total, 408724k used, 7783268k free, 7201204k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
9702 bb 20 0 2898m 348m 14m S 100.6 2.2 01:47.18 java -server -Xms512M -Xmx512M -Xmn192M -Xss256k -XX:PermSize=64M -XX:MaxPermSize=128M -verbose:
从输出结果看,CPU load 达到3以上,服务器是4核机器,负载已经不低了。进程ID为9720的进程CPU占用率超过100%。
定位故障的思路
首先找出问题进程内CPU占用率高的线程
再通过线程栈信息找出该线程当时在运行的问题代码段
定位故障的步骤
3.1 用top命令查找进程内导致CPU占用率高的线程
先祭出第一招, top命令加上 -H -b 两个选项:-H 可以查看由某个进程启动的所有线程,-b 选项指定以批处理模式输出结果 。具体命令如下:
top -Hbp 9702
top - 00:38:54 up 48 days, 10:43, 5 users, load average: 0.81, 0.36, 0.16
Tasks: 38 total, 1 running, 37 sleeping, 0 stopped, 0 zombie
Cpu(s): 3.5%us, 1.4%sy, 0.0%ni, 94.5%id, 0.3%wa, 0.0%hi, 0.2%si, 0.0%st
Mem: 16332280k total, 15744500k used, 587780k free, 200632k buffers
Swap: 8191992k total, 408724k used, 7783268k free, 7201392k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
10007 bb 20 0 2898m 348m 14m R 100.5 2.2 1:41.31 java
9702 bb 20 0 2898m 348m 14m S 0.0 2.2 0:00.00 java
9705 bb 20 0 2898m 348m 14m S 0.0 2.2 0:06.44 java
9706 bb 20 0 2898m 348m 14m S 0.0 2.2 0:00.11 java
9707 bb 20 0 2898m 348m 14m S 0.0 2.2 0:00.11 java
9708 bb 20 0 2898m 348m 14m S 0.0 2.2 0:00.11 java
9709 bb 20 0 2898m 348m 14m S 0.0 2.2 0:00.10 java
9710 bb 20 0 2898m 348m 14m S 0.0 2.2 0:00.00 java
9711 bb 20 0 2898m 348m 14m S 0.0 2.2 0:00.07 java
9712 bb 20 0 2898m 348m 14m S 0.0 2.2 0:00.03 java
9713 bb 20 0 2898m 348m 14m S 0.0 2.2 0:00.03 java
9714 bb 20 0 2898m 348m 14m S 0.0 2.2 0:00.00 java
9715 bb 20 0 2898m 348m 14m S 0.0 2.2 0:00.00 java
9716 bb 20 0 2898m 348m 14m S 0.0 2.2 0:05.60 java
输出结果里的PID其实是线程ID,可以看到线程ID为10007的线程CPU占用率为100.5%,它就是罪魁祸首。上面的命令可以再优化下:查出CPU占用率超过某个值的所有线程,例如超过50%,如下:
top -Hbp 9702 | awk '/java/ && $9>50'
3.2 用JVM命令 jstack 精确定位出问题的代码段
第二招,用jstack 命令dump出线程栈信息,可以直接定位到出问题的代码段。这里也分两步。第一步把上面的线程ID 10007 转化为十六进制:
$ printf "%x\n" 10007
2717
因为jstack输出的线程栈信息中,线程ID是以十六进制展示的。