系统运行缓慢，CPU 100%，以及Full GC次数过多问题的排查思路

一、系统运行缓慢导致系统不可用

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

二、Full GC（垃圾回收）次数过多

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

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

问题排查过程：

jstack可以定位到线程堆栈，根据堆栈信息我们可以定位到具体代码，所以它在JVM性能调优中使用得非常多。找出某个Java进程中最耗费CPU的Java线程并定位堆栈信息，用到的命令有ps、top、printf、jstack、grep。操作如下：
1.查询Java进程ID，如下图：

• 使用top命令查看系统CPU的占用情况，id为9的cpu使用率达到98%

 

 

•  使用 top -Hp 9 查看该进程的各个线程运行情况，通过jstack命令查看线程id为10的线程为什么耗费CPU最高。

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

•  使用   printf "%x\n"10

 

 

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

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

• 使用  stat -gcutil 9 1000 10  命令可以查看GC的情况，FGC指的是Full GC数量，这里高达6793，而且还在不断增长。

        从而进一步证实了是由于内存溢出导致的系统缓慢。那么这里确认了内存溢出，但是如何查看你是哪些对象导致的内存溢出呢，这个可以dump出内存日志，

        然后通过eclipse的mat工具进行查看，如下是其展示的一个对象树结构：

 

 

 

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

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

三、总结

简要的说，我们进行线上日志分析时，主要可以分为如下步骤：

• 通过top命令查看CPU情况，如果CPU比较高，则通过top -Hp <pid>命令查看当前进程的各个线程运行情况，找出CPU过高的线程之后，将其线程id转换为十六进制的表现形式，然后在jstack日志中查看该线程主要在进行的工作。这里又分为两种情况
  • 如果是正常的用户线程，则通过该线程的堆栈信息查看其具体是在哪处用户代码处运行比较消耗CPU；
  • 如果该线程是VM Thread，则通过jstat -gcutil <pid> <period> <times>命令监控当前系统的GC状况，然后通过jmap dump:format=b,file=<filepath> <pid>导出系统当前的内存数据。导出之后将内存情况放到eclipse的mat工具中进行分析即可得出内存中主要是什么对象比较消耗内存，进而可以处理相关代码；
• 如果通过top命令看到CPU并不高，并且系统内存占用率也比较低。此时就可以考虑是否是由于另外三种情况导致的问题。具体的可以根据具体情况分析：
  • 如果是接口调用比较耗时，并且是不定时出现，则可以通过压测的方式加大阻塞点出现的频率，从而通过jstack查看堆栈信息，找到阻塞点；
  • 如果是某个功能突然出现停滞的状况，这种情况也无法复现，此时可以通过多次导出jstack日志的方式对比哪些用户线程是一直都处于等待状态，这些线程就是可能存在问题的线程；
  • 如果通过jstack可以查看到死锁状态，则可以检查产生死锁的两个线程的具体阻塞点，从而处理相应的问题。