关于线上问题CPU100%，频繁FullGC排查套路

因为之前在项目中有过类似的经历，最近想总结一些相关的知识点。如果是线上环境，其实我们可以依赖阿里开源的arthas来进行跟踪，快速入门 | arthas。基于常规的情况下，我们在测试环境可以采用原生的一些Java自带的命令和工具进行问题的跟踪和排查。

本文主要针对系统运行缓慢这一问题，提供该问题的排查思路，从而定位出问题的代码点，进而提供解决该问题的思路。

对于线上系统突然产生的运行缓慢问题，如果该问题导致线上系统不可用，那么首先需要做的就是，导出 jstack 和内存信息，然后重启系统，尽快保证系统的可用性。

这种情况可能的原因主要有两种：

• 代码中某个位置读取数据量较大，导致系统内存耗尽，从而导致 Full GC 次数过多，系统缓慢。
• 代码中有比较耗 CPU 的操作，导致 CPU 过高，系统运行缓慢。

相对来说，这是出现频率最高的两种线上问题，而且它们会直接导致系统不可用。

另外有几种情况也会导致某个功能运行缓慢，但是不至于导致系统不可用：

• 代码某个位置有阻塞性的操作，导致该功能调用整体比较耗时，但出现是比较随机的。
• 某个线程由于某种原因而进入 WAITING 状态，此时该功能整体不可用，但是无法复现。
• 由于锁使用不当，导致多个线程进入死锁状态，从而导致系统整体比较缓慢。

对于这三种情况，通过查看 CPU 和系统内存情况是无法查看出具体问题的，因为它们相对来说都是具有一定阻塞性操作，CPU 和系统内存使用情况都不高，但是功能却很慢。

下面我们就通过查看系统日志来一步一步甄别上述几种问题

Full GC 次数过多

相对来说，这种情况是最容易出现的，尤其是新功能上线时。

对于 Full GC 较多的情况，其主要有如下两个特征：

• 线上多个线程的 CPU 都超过了 100%，通过 jstack 命令可以看到这些线程主要是垃圾回收线程。
• 通过 jstat 命令监控 GC 情况，可以看到 Full GC 次数非常多，并且次数在不断增加。

首先我们可以使用 top 命令查看系统 CPU 的占用情况，如下是系统 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 

 可以看到，有一个 Java 程序此时 CPU 占用量达到了 98%，此时我们可以复制该进程 id9，并且使用如下命令查看该进程的各个线程运行情况

top -Hp 9 

该进程下的各个线程运行情况如下： 

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 

可以看到，在进程为 9 的 Java 程序中各个线程的 CPU 占用情况，接下来我们可以通过 jstack 命令查看线程 id 为 10 的线程为什么耗费 CPU 最高。

需要注意的是，在 jsatck 命令展示的结果中，线程 id 都转换成了十六进制形式。

可以用如下命令查看转换结果，也可以找一个科学计算器进行转换：

printf "%x" 10

然后通过 jstack 9 |grep a -A 200 

 这里打印结果说明该线程在 jstack 中的展现形式为 0xa，通过 jstack 命令我们可以看到如下信息：

"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

 

这里的 VM Thread 一行的最后显示 nid=0xa，这里 nid 的意思就是操作系统线程 id 的意思，而 VM Thread 指的就是垃圾回收的线程。

这里我们基本上可以确定，当前系统缓慢的原因主要是垃圾回收过于频繁，导致 GC 停顿时间较长。

我们通过如下命令可以查看 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 

 

可以看到，这里 FGC 指的是 Full GC 数量，这里高达 6793，而且还在不断增长。从而进一步证实了是由于内存溢出导致的系统缓慢。

那么这里确认了内存溢出，但是如何查看你是哪些对象导致的内存溢出呢，这个可以 Dump 出内存日志，然后通过 Eclipse 的 Mat 工具进行查看。(也可以用jvisualVM)

 

 

经过 Mat 工具分析之后，我们基本上就能确定内存中主要是哪个对象比较消耗内存，然后找到该对象的创建位置，进行处理即可。

这里主要是 PrintStream 最多，但是我们也可以看到，其内存消耗量只有 12.2%。

也就是说，其还不足以导致大量的 Full GC，此时我们需要考虑另外一种情况，就是代码或者第三方依赖的包中有显示的 System.gc() 调用。

这种情况我们查看 Dump 内存得到的文件即可判断，因为其会打印 GC 原因：

[Full GC (System.gc()) [Tenured: 262546K->262546K(349568K), 0.0014879 secs] 262546K->262546K(506816K), [Metaspace: 3109K->3109K(1056768K)], 0.0015151 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[GC (Allocation Failure) [DefNew: 2795K->0K(157248K), 0.0001504 secs][Tenured: 262546K->402K(349568K), 0.0012949 secs] 265342K->402K(506816K), [Metaspace: 3109K->3109K(1056768K)], 0.0014699 secs] [Times: user=0.00

 

比如这里第一次 GC 是由于 System.gc() 的显示调用导致的，而第二次 GC 则是 JVM 主动发起的。

总结来说，对于 Full GC 次数过多，主要有以下两种原因：

• 代码中一次获取了大量的对象，导致内存溢出，此时可以通过 Eclipse 的 Mat 工具查看内存中有哪些对象比较多。
• 内存占用不高，但是 Full GC 次数还是比较多，此时可能是显示的 System.gc() 调用导致 GC 次数过多，这可以通过添加 -XX:+DisableExplicitGC 来禁用 JVM 对显示 GC 的响应。

CPU 过高 

在前面第一点中，我们讲到，CPU 过高可能是系统频繁的进行 Full GC，导致系统缓慢。

而我们平常也肯定能遇到比较耗时的计算，导致 CPU 过高的情况，此时查看方式其实与上面的非常类似。

首先我们通过 top 命令查看当前 CPU 消耗过高的进程是哪个，从而得到进程 id;然后通过 top -Hp 来查看该进程中有哪些线程 CPU 过高，一般超过 80% 就是比较高的，80% 左右是合理情况。

这样我们就能得到 CPU 消耗比较高的线程 id。接着通过该线程 id 的十六进制表示在 jstack 日志中查看当前线程具体的堆栈信息。

在这里我们就可以区分导致 CPU 过高的原因具体是 Full GC 次数过多还是代码中有比较耗时的计算了。

如果是 Full GC 次数过多，那么通过 jstack 得到的线程信息会是类似于 VM Thread 之类的线程。

而如果是代码中有比较耗时的计算，那么我们得到的就是一个线程的具体堆栈信息。

基本的排查思路和上面的步骤类似。

死锁

对于死锁，这种情况基本上很容易发现，因为 jstack 可以帮助我们检查死锁，并且在日志中打印具体的死锁线程信息。

 

总结：

通常的排查步骤如下:

• 1 通过 top 命令找到消耗 cpu 高的进程 id 号 pid
• 2 根据 pid 找到消耗 cpu 资源比较高的线程 id
• 3 对当前的线程做 stack,输出前进程的所有堆栈信息
• 4 将第 2 步中得到的线程 id 转换成 16 进制进得到结果
• 5 根据相应的线程 id 在堆栈信息中找到相关的内容
• 6 解读对应的堆栈信息，定位代码位置并排查问题原因

 一般情况下，基本没有哪家公司允许线上排除问题的，从线上摘掉有问题的服务进行操作观察处理。所以还是考虑一些开源工具