面试官：如果你们的系统 CPU 突然飙升且 GC 频繁，如何排查？

数据与人 2021-12-27

1527

本文主要针对系统运行缓慢、CPU 100%以及Full GC次数过多的问题，定位出问题点，进而提供解决该问题的思路。

下面我们就通过查看系统日志来一步步分析造成这种问题的几种原因。

1. Full GC次数过多

主要有如下两个特征：

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

如下是系统CPU较高的一个示例：

top：

可以看到，有一个进程id 为9的
Java程序此时CPU占用量达到了98.8%，查看该进程的各个线程运行情况：

top -Hp 9

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

通过jstack命令查看线程id为 10
的线程为什么耗费CPU最高。

需要注意的是，在jsatck命令展示的结果中，线程id都转换成了十六进制形式。可以用如下命令查看转换结果，也可以找一个科学计算器进行转换：

root@a39de7e7934b:/# printf "%x\n" 10a

这里打印结果说明该线程在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的情况：

上述日志Full GC数量高达6793，而且还在不断增长。从而进一步证实了是由于内存溢出导致的系统缓慢。

确认了内存溢出，但是如何查看你是哪些对象导致的内存溢出呢，这个可以dump出内存日志，然后通过eclipse的mat工具进行查看

如下是其展示的一个对象树结构：

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

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

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

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

比如这里第一次GC是由于 System.gc()
的显示调用导致的，而第二次GC则是JVM主动发起的。总结来说，对于Full GC次数过多，主要有以下两种原因：

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

2. CPU过高

我们平常也经常遇到比较耗时的计算，导致CPU过高的情况。

通过 top
命令查看当前CPU消耗过高的进程是哪个，从而得到进程id；然后通过 top-Hp
来查看该进程中有哪些线程CPU过高，一般超过80%就是比较高的，这样我们就能得到CPU消耗比较高的线程id。

接着通过该 线程id的十六进制表示
在 jstack
日志中查看当前线程具体的堆栈信息。

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

如果是Full GC次数过多，那么通过 jstack
得到的线程信息会是类似于VM Thread之类的线程，而如果是代码中有比较耗时的计算，那么我们得到的就是一个线程的具体堆栈信息。

如下是一个代码中有比较耗时的计算，导致CPU过高的线程信息：

可以看到，在请求UserController的时候，由于该Controller进行了一个比较耗时的调用，导致该线程的CPU一直处于100%。

我们可以根据堆栈信息，直接定位到UserController的34行，查看代码中具体是什么原因导致计算量如此之高。

3. 不定期出现的接口耗时现象

这种情况比较麻烦，一般来说，其消耗的CPU不多，占用的内存也不高，也就是说，我们通过之前两种方式进行排查是无法解决这种问题的。

对于不定时出现的接口耗时比较严重的问题，我们的定位思路基本如下：

首先找到该接口，通过压测工具不断加大访问力度，如果说该接口中有某个位置是比较耗时的，由于我们的访问的频率非常高，那么大多数的线程最终都将阻塞于该阻塞点。

这样通过多个线程具有相同的堆栈日志，我们基本上就可以定位到该接口中比较耗时的代码的位置。

如下是一个代码中有比较耗时的阻塞操作通过压测工具得到的线程堆栈日志：

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

4. 某个线程进入WAITING状态

这种情况不常见，其具有一定的“不可复现性”，因而我们在排查的时候是非常难以发现的。

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

当时我们是通过CountDownLatch控制多个线程连接并导出用户的gmail邮箱数据，这其中有一个线程连接上了用户邮箱，但是连接被服务器挂起了，导致该线程一直在等待服务器的响应。最终导致我们的主线程和其余几个线程都处于WAITING状态。

对于这样的问题，查看过jstack日志的读者应该都知道，正常情况下，线上大多数线程都是处于 TIMED_WAITING
状态，而我们这里出问题的线程所处的状态与其是一模一样的，这就非常容易混淆我们的判断。

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

通过grep在jstack日志中找出所有的处于 TIMED_WAITING状态的线程，将其导出到某个文件中，如a1.log
等待一段时间之后，比如10s，再次对jstack日志进行grep，将其导出到另一个文件，如a2.log
重复步骤2，待导出3~4个文件之后，我们对导出的文件进行对比，找出其中在这几个文件中一直都存在的用户线程，这个线程基本上就可以确认是包含了处于等待状态有问题的线程。
经过排查得到这些线程之后，我们可以继续对其堆栈信息进行排查，如果该线程本身就应该处于等待状态，比如用户创建的线程池中处于空闲状态的线程，那么这种线程的堆栈信息中是不会包含用户自定义的类的。这些都可以排除掉，而剩下的线程基本上就可以确认是我们要找的有问题的线程。通过其堆栈信息，我们就可以得出具体是在哪个位置的代码导致该线程处于等待状态了。

需要说明的是，我们在判断是否为用户线程时，可以通过线程最前面的线程名来判断，因为一般的框架的线程命名都是非常规范的，我们通过线程名就可以直接判断得出该线程是某些框架中的线程，这种线程基本上可以排除掉。

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

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

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

5. 死锁

死锁很容易发现，因为 jstack
可以帮助我们检查死锁，并且在日志中打印具体的死锁线程信息。

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

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

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

来源：
https://my.oschina.net/zhangxufeng/blog/3017521

觉得本文有用，请转发、点赞或点击“在看”
聚焦技术与人文，分享干货，共同成长
更多内容请关注“数据与人”

面试

文章转载自数据与人，如果涉嫌侵权，请发送邮件至：contact@modb.pro进行举报，并提供相关证据，一经查实，墨天轮将立刻删除相关内容。