一次性搞清楚线上CPU100%，频繁FullGC排查套路

处理过线上问题的同学基本上都会遇到系统突然运行缓慢，CPU100%，以及FullGC次数过多的问题。

当然，这些问题最终导致的直观现象就是系统运行缓慢，并且有大量的报警。

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

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

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

代码中某个位置读取数据量较大，导致系统内存耗尽，从而导致FullGC次数过多，系统缓慢。

代码中有比较耗CPU的操作，导致CPU过高，系统运行缓慢。

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

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

代码某个位置有阻塞性的操作，导致该功能调用整体比较耗时，但出现是比较随机的。

某个线程由于某种原因而进入WAITING状态，此时该功能整体不可用，但是无法复现。

由于锁使用不当，导致多个线程进入死锁状态，从而导致系统整体比较缓慢。

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

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

FullGC次数过多

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

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

线上多个线程的CPU都超过了100%，通过jstack命令可以看到这些线程主要是垃圾回收线程。

通过jstat命令监控GC情况，可以看到FullGC次数非常多，并且次数在不断增加。

首先我们可以使用top命令查看系统CPU的占用情况，如下是系统CPU较高的一个示例：

top-08:31:10up30min,0users,loadaverage:0.73,0.58,0.34KiBMem:2046460total,1923864used,122596free,14388buffersKiBSwap:1048572total,0used,1048572%CPU%MEMTIME+:42.60java

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

top-Hp9

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

top-08:31:16up30min,0users,loadaverage:0.75,0.59,0.35Threads:11total,1running,10sleeping,0stopped,0zombie%Cpu(s):3.5us,0.6sy,0.0ni,95.9id,0.0wa,0.0hi,0.0si,0.0stKiBMem:2046460total,1924856used,121604free,14396buffersKiBSwap:1048572total,0used,1048572%CPU%MEMTIME+:41.49:06.78java

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

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

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

root@a39de7e7934b:/1prio=5os_prio=0tid=0x00007f8718009800nid=0xbrunnable[0x00007f871fe41000]:(:9)"VMThread"os_prio=0tid=0x00007f871806e000nid=0xarunnable

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

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

我们通过如下命令可以查看GC的情况：

root@8d36124607a0:/29daemonprio=5os_prio=31tid=0x00007fd08cb26000nid=0x9603waitingoncondition[0x00007000031d5000]:TIMED_WAITING(sleeping)(NativeMethod)(:340)(:386)(:18)"http-nio-8080-exec-3"31daemonprio=5os_prio=31tid=0x00007fd08d0fa000nid=0x6403waitingoncondition[0x00007000033db000]:TIMED_WAITING(sleeping)(NativeMethod)(:340)(:386)(:18)

从上面的日志你可以看出，这里有多个线程都阻塞在了UserController的第18行，说明这是一个阻塞点，也就是导致该接口比较缓慢的原因。

某个线程进入WAITING状态

对于这种情况，这是比较罕见的一种情况，但是也是有可能出现的，而且由于其具有一定的“不可复现性”，因而我们在排查的时候是非常难以发现的。

笔者曾经就遇到过类似的这种情况，具体的场景是，在使用CountDownLatch时，由于需要每一个并行的任务都执行完成之后才会唤醒主线程往下执行。

而当时我们是通过CountDownLatch控制多个线程连接并导出用户的Gmail邮箱数据，这其中有一个线程连接上了用户邮箱，但是连接被服务器挂起了，导致该线程一直在等待服务器的响应。

最终导致我们的主线程和其余几个线程都处于WAITING状态。

对于这样的问题，查看过jstack日志的读者应该都知道，正常情况下，线上大多数线程都是处于TIMED_WAITING状态。

而我们这里出问题的线程所处的状态与其是一模一样的，这就非常容易混淆我们的判断。

解决这个问题的思路主要如下：

①通过grep在jstack日志中找出所有的处于TIMED_WAITING状态的线程，将其导出到某个文件中，如，如下是一个导出的日志文件示例：

"AttachListener"12prio=5os_prio=31tid=0x00007fe690066000nid=0x2603waitingoncondition[0x0000000000000000]"Thread-0"9daemonprio=9os_prio=31tid=0x00007fe68c00a000nid=0xa903waitingoncondition[0x0000000000000000]

②等待一段时间之后，比如10s，再次对jstack日志进行grep，将其导出到另一个文件，如，结果如下所示：

"DestroyJavaVM"11prio=5os_prio=31tid=0x00007fe690065000nid=0x5a03waitingoncondition[0x0000700003ad4000]"VMPeriodicTaskThread"os_prio=31tid=0x00007fe68d114000nid=0xa803waitingoncondition

③重复步骤2，待导出3~4个文件之后，我们对导出的文件进行对比，找出其中在这几个文件中一直都存在的用户线程。

这个线程基本上就可以确认是包含了处于等待状态有问题的线程。因为正常的请求线程是不会在20~30s之后还是处于等待状态的。

④经过排查得到这些线程之后，我们可以继续对其堆栈信息进行排查，如果该线程本身就应该处于等待状态，比如用户创建的线程池中处于空闲状态的线程，那么这种线程的堆栈信息中是不会包含用户自定义的类的。

这些都可以排除掉，而剩下的线程基本上就可以确认是我们要找的有问题的线程。

通过其堆栈信息，我们就可以得出具体是在哪个位置的代码导致该线程处于等待状态了。

这里需要说明的是，我们在判断是否为用户线程时，可以通过线程最前面的线程名来判断，因为一般的框架的线程命名都是非常规范的。

我们通过线程名就可以直接判断得出该线程是某些框架中的线程，这种线程基本上可以排除掉。

而剩余的，比如上面的Thread-0，以及我们可以辨别的自定义线程名，这些都是我们需要排查的对象。

经过上面的方式进行排查之后，我们基本上就可以得出这里的Thread-0就是我们要找的线程，通过查看其堆栈信息，我们就可以得到具体是在哪个位置导致其处于等待状态了。

如下示例中则是在SyncTask的第8行导致该线程进入等待了：

"Thread-0"#11prio=5os_prio=31tid=0x00007f9de08c7000nid=0x5603waitingoncondition[0x0000700001f89000]:WAITING(parking)(NativeMethod)(:304)$main$0(:8)$Lambda$1/1791741888.run(UnknownSource)(:748)

死锁

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

如下是一个产生死锁的一个jstack日志示例：

可以看到，在jstack日志的底部，其直接帮我们分析了日志中存在哪些死锁，以及每个死锁的线程堆栈信息。

这里我们有两个用户线程分别在等待对方释放锁，而被阻塞的位置都是在ConnectTask的第5行，此时我们就可以直接定位到该位置，并且进行代码分析，从而找到产生死锁的原因。

小结

本文主要讲解了线上可能出现的五种导致系统缓慢的情况，详细分析了每种情况产生时的现象，已经根据现象我们可以通过哪些方式定位得到是这种原因导致的系统缓慢。

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

①通过top命令查看CPU情况，如果CPU比较高，则通过top-Hp命令查看当前进程的各个线程运行情况。

找出CPU过高的线程之后，将其线程id转换为十六进制的表现形式，然后在jstack日志中查看该线程主要在进行的工作。

这里又分为两种情况：

如果是正常的用户线程，则通过该线程的堆栈信息查看其具体是在哪处用户代码处运行比较消耗CPU。

如果该线程是VMThread，则通过jstat-gcutil命令监控当前系统的GC状况。

然后通过jmapdump:format=b,file=导出系统当前的内存数据。

导出之后将内存情况放到Eclipse的Mat工具中进行分析即可得出内存中主要是什么对象比较消耗内存，进而可以处理相关代码。

②如果通过top命令看到CPU并不高，并且系统内存占用率也比较低。此时就可以考虑是否是由于另外三种情况导致的问题。

具体的可以根据具体情况分析：

如果是接口调用比较耗时，并且是不定时出现，则可以通过压测的方式加大阻塞点出现的频率，从而通过jstack查看堆栈信息，找到阻塞点。

如果是某个功能突然出现停滞的状况，这种情况也无法复现，此时可以通过多次导出jstack日志的方式对比哪些用户线程是一直都处于等待状态，这些线程就是可能存在问题的线程。

如果通过jstack可以查看到死锁状态，则可以检查产生死锁的两个线程的具体阻塞点，从而处理相应的问题。

本文主要是提出了五种常见的导致线上功能缓慢的问题，以及排查思路。当然，线上的问题出现的形式是多种多样的，也不一定局限于这几种情况。

如果我们能够仔细分析这些问题出现的场景，就可以根据具体情况具体分析，从而解决相应的问题。