【工作中问题解决实践十二】线上如何排查CPU100%的情况

当我们把服务发布到服务器器，可能会因为一些问题造成我们的服务器CPU被打满甚至超过100%，那如果我们想知道到底上在做什么操作导致CPU持续过高呢？因为在线上只能通过日志看问题，或者排查到哪个进程或者哪个线程持续占用CPU。然后才能找到具体问题在哪里才能进行解决，具体排查过程

排查过程

无论是什么原因导致的，一定会体现在具体的进程和线程上，所以开始从进程入手，找到最大的线程

执行top -c命令：查看所有进程占系统CPU的排序。极大可能排第一个的就是咱们的java进程（COMMAND列）。PID那一列就是进程号。可以看到，有一个 Java 程序此时 CPU 占用量达到了 98.8%，此时我们可以复制该进程 id9，并且使用如下命令查看该进程的各个线程运行情况 找高CPU进程

top - 08:31:10 up 30 min,  0 users,  load average: 0.73, 0.58, 0.34
KiB Mem:   2046460 total,  1923864 used,   122596 free,    14388 buffers
KiB Swap:  1048572 total,        0 used,  1048572 free.  1192352 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
    9 root      20   0 2557160 288976  15812 S  98.0 14.1   0:42.60 java

执行top -Hp 进程号命令：查看java进程下的所有线程占CPU的情况。top -Hp PID 9，可以看到，在进程为 9 的 Java 程序中各个线程的 CPU 占用情况，接下来我们可以通过 jstack 命令查看线程 id 为 10 的线程为什么耗费 CPU 最高 找高CPU线程

top - 08:31:16 up 30 min,  0 users,  load average: 0.75, 0.59, 0.35
Threads:  11 total,   1 running,  10 sleeping,   0 stopped,   0 zombie
%Cpu(s):  3.5 us,  0.6 sy,  0.0 ni, 95.9 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem:   2046460 total,  1924856 used,   121604 free,    14396 buffers
KiB Swap:  1048572 total,        0 used,  1048572 free.  1192532 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
   10 root      20   0 2557160 289824  15872 R 79.3 14.2   0:41.49 java
   11 root      20   0 2557160 289824  15872 S 13.2 14.2   0:06.78 java

执行printf "%x\n 10命令：后续查看线程堆栈信息展示的都是十六进制，为了找到咱们的线程堆栈信息，咱们需要把线程号转成16进制。例如,printf "%x\n 10打印：a，那么在jstack中线程号就是0xa.转换获取操作系统线程ID
执行 jstack 进程号 | grep 线程ID 查找某进程下线程ID（jstack堆栈信息中的nid）=0xa的线程状态。如果"VM Thread" os_prio=0 tid=0x00007f871806e000 nid=0xa runnable，第一个双引号圈起来的就是线程名，如果是VM Thread这就是虚拟机GC回收线程了获取该进程快照并grep到该线程，查看线程状态

"main" #1 prio=5 os_prio=0 tid=0x00007f8718009800 nid=0xb runnable [0x00007f871fe41000]
   java.lang.Thread.State: RUNNABLE
    at com.aibaobei.chapter2.eg2.UserDemo.main(UserDemo.java:9)

"VM Thread" os_prio=0 tid=0x00007f871806e000 nid=0xa runnable

执行jstat -gcutil 进程号统计间隔毫秒统计次数（缺省代表一致统计），查看某进程GC持续变化情况，如果发现返回中FGC很大且一直增大确认Full GC 也可以使用jmap -heap 进程ID查看一下进程的堆内从是不是要溢出了，特别是老年代内从使用情况一般是达到阈值(具体看垃圾回收器和启动时配置的阈值)就会进程Full GC。【如果是虚拟机线程】统计gc情况，判断是否是full GC过多

root@8d36124607a0:/# jstat -gcutil 9 1000 10
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
  0.00   0.00   0.00  75.07  59.09  59.60   3259    0.919  6517    7.715    8.635
  0.00   0.00   0.00   0.08  59.09  59.60   3306    0.930  6611    7.822    8.752
  0.00   0.00   0.00   0.08  59.09  59.60   3351    0.943  6701    7.924    8.867
  0.00   0.00   0.00   0.08  59.09  59.60   3397    0.955  6793    8.029    8.984

执行jmap -dump:format=b,file=filename 进程ID”，导出某进程下内存heap输出到文件中。可以通过mat工具查看内存中有哪些对象比较多。公司封装后，我们用的命令是heap dump【如果是虚拟机线程】heap dump下虚拟机快照，查看对象树判断

不同的问题结论排查到同的阶段就会有结论

问题定位

针对以上各个步骤，大致排查到某些步骤后就可以大致定位具体原因了

1 内存消耗过大，导致Full GC次数过多

一直排查，执行了步骤1-5：

【步骤2明确为虚拟机线程】多个线程的CPU都超过了100%，通过jstack命令可以看到这些线程主要是垃圾回收线程
【步骤5查看GC情况】通过jstat命令监控GC情况，可以看到Full GC次数非常多，并且次数在不断增加。

确定是Full GC, 接下来找到具体原因：

【步骤6查看堆Dump文件】使用MAT工具分析，如果生成大量的对象，导致内存溢出，查看具体内存对象占用情况。
如果对象占用不算高，但是Full GC次数还是比较多，此时可能是代码中手动调用 System.gc()导致GC次数过多，这可以通过添加 -XX:+DisableExplicitGC来禁用JVM对显示GC的响应。

2 代码中有大量消耗CPU的操作，导致CPU过高，系统运行缓慢

一直排查，执行了步骤1-4：

【步骤2明确为非虚拟机线程】
【步骤4查看线程快照情况】可直接定位到代码行。问题原因有某些复杂算法，甚至算法BUG，无限循环递归等。

3 由于锁使用不当，导致死锁

一直排查，执行了步骤1-4：

【步骤2明确为非虚拟机线程】
【步骤4查看线程快照情况】如果有死锁，会直接提示。关键字：deadlock 会打印出业务死锁的位置

在这里插入图片描述

4 不定期出现的接口耗时现象

对于这种情况，比较典型的例子就是，我们某个接口访问经常需要 2~3s 才能返回。这是比较麻烦的一种情况，因为一般来说，其消耗的 CPU 不多，而且占用的内存也不高，也就是说，我们通过【1-4】排查是无法解决这种问题的。而且由于这样的接口耗时比较大的问题是不定时出现的，这就导致了我们在通过 jstack 命令即使得到了线程访问的堆栈信息，我们也没法判断具体哪个线程是正在执行比较耗时操作的线程。对于不定时出现的接口耗时比较严重的问题，我们的定位思路基本如下：首先找到该接口，通过压测工具不断加大访问力度，如果说该接口中有某个位置是比较耗时的，由于我们的访问的频率非常高，那么大多数的线程最终都将阻塞于该阻塞点。

通过压测工具不断加大接口访问力度
一直排查，执行了步骤1-4：查看线程快照信息，大量线程都会阻塞在该点

"http-nio-8080-exec-4" #31 daemon prio=5 os_prio=31 tid=0x00007fd08d0fa000 nid=0x6403 waiting on condition [0x00007000033db000]

   java.lang.Thread.State: TIMED_WAITING (sleeping)-》期限等待

    at java.lang.Thread.sleep(Native Method)

    at java.lang.Thread.sleep(Thread.java:340)

    at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)

    at com.*.user.controller.UserController.detail(UserController.java:18)-》业务代码阻塞点