一次非典型的CPU告警的排查

最近线上频繁收到CPU超过阈值的告警, 很明显是哪里出了问题.
于是排查了一番, 到最后找到罪魁祸首的时候, 突然意识到这次是一次很有意思的"非典型"的CPU的问题, 所以这里特意记录一下.
为啥说它是非典型呢, 因为在我的经验里, 典型的CPU飙升通常都是业务代码里面有死循环, 或是某个RPC性能过低阻塞了大量线程等等,
而这次的CPU问题却是由GC引起的, 因吹斯汀
来看看排查过程

找出占用CPU的线程

top

首先肯定是先看哪些线程占用CPU最高, 这个可以使用top命令:

top -Hp $pid -b -n 1|sed -n "7,17p"

   PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND           
 94349 app     20   0 11.2g 5.0g  12m S 15.0 32.1 215:03.69 java              
 94357 app     20   0 11.2g 5.0g  12m S 15.0 32.1  88:22.39 java              
 94352 app     20   0 11.2g 5.0g  12m S 13.1 32.1 215:05.71 java              
 94350 app     20   0 11.2g 5.0g  12m S 11.2 32.1 215:04.86 java              
 94351 app     20   0 11.2g 5.0g  12m S 11.2 32.1 215:04.99 java              
 94935 app     20   0 11.2g 5.0g  12m S 11.2 32.1  63:11.75 java              
 94926 app     20   0 11.2g 5.0g  12m S  9.4 32.1  63:10.58 java              
 94927 app     20   0 11.2g 5.0g  12m S  5.6 32.1  63:06.89 java              
 94932 app     20   0 11.2g 5.0g  12m S  5.6 32.1  63:12.65 java              
 94939 app     20   0 11.2g 5.0g  12m S  5.6 32.1  63:01.75 java  

$pid是我们对应的java进程的进程ID, sed -n “7,17p” 是取第7到第17行, 因为前7行都是top命令的头部信息, 所以第7到第17行就是该线程下最耗CPU的前10个线程了.
其中第一列的"pid"就是JVM里面对应的线程ID, 我们只需要用线程ID在jstack里面找到对应的线程就知道是谁在搞鬼了.
不过需注意的是top命令中的PID是十进制的, 而jstack里面的线程ID是十六进制的, 所以我们还需要做一个工作, 就是把上面的PID转成十六进制, 这里我只转换了最耗CPU的前3个:

[app@linux-v-l-02:/app/tmp/]$printf '%x\n' 94349
1708d
[app@linux-v-l-02:/app/tmp/]$printf '%x\n' 94357
17095
[app@linux-v-l-02:/app/tmp/]$printf '%x\n' 94352
17090

jstack

现在我们已经知道消耗CPU的线程ID, 接着就要去看看这些线程ID对应的是什么线程.

首先使用jstack打出JVM里面的所有的线程信息:

[app@linux-v-l-02:/app/tmp/]jstack -l $pid >>/tmp/jstack.txt

值得一提的是, 由于JVM里面的线程一直在变化, 而TOP中的线程也一直在变化, 所以如果jstack命令和top命令是分开执行的话, 很有可能两者的线程ID会对应不上. 因此top命令和jstack命令最好是写好脚本一起执行. 其实我就是写脚本一起执行的~

接着, 看看1708d, 17095, 17090 这三个到底是什么线程:

[app@linux-v-l-02:/app/tmp/]$egrep "1708d|17095|17090" jstack.txt --color
"Gang worker#0 (Parallel GC Threads)" os_prio=0 tid=0x00007f4d4c023000 nid=0x1708d runnable 
"Gang worker#3 (Parallel GC Threads)" os_prio=0 tid=0x00007f4d4c028800 nid=0x17090 runnable 
"G1 Concurrent Refinement Thread#0" os_prio=0 tid=0x00007f4d4c032000 nid=0x17095 runnable 

上面的nid就是对应的十六进制的线程ID. 从jstack可以看出, 居然最耗CPU的线程都是一些GC线程.
对JVM的FULL GC我们是有监控的, 这个应用自从换了G1之后, 一般一周左右才会发生一次FULL GC, 所以我们一直都以为我们