CPU飙高、内存飙高、频繁FULLGC、程序越来越慢的排查思路（top jstack jstat jmap）

个人思路，出现CPU飙高、内存飙高、频繁FULLGC、程序越来越慢的问题，先dump线程、内存日志。

一、dump的方式

1.用jstack、jstate、jmap

（1）top

首先使用top命令查看当前系统哪个进程占用的CPU/内存最高

可以用shift+P根据CPU使用率排序

shift+m根据内存占用排序

得到该有问题的进程ID，也就是上述操作中显示的PID。

比如PID=11225

top命令详解在另外一篇博客中有写

（2）top -Hp 11225

查看该进程内哪个线程的CPU/内存最高

得到该有问题的线程ID，也就是上述操作中显示的PID。

比如PID=10

（3） jstack -l pid >> threaddumppid.log   

（每隔5sdump一次，共dump 4-5次，如果每次dump下来都用同样的问题，基本可确定该问题存在）

jstack 命令dump并查看进程id 为 11225 的所有的线程信息

jstack命令用法

Usage:
    jstack [-l] <pid>
        (to connect to running process) 连接活动线程
    jstack -F [-m] [-l] <pid>
        (to connect to a hung process) 连接阻塞线程
    jstack [-m] [-l] <executable> <core>
        (to connect to a core file) 连接dump的文件
    jstack [-m] [-l] [server_id@]<remote server IP or hostname>
        (to connect to a remote debug server) 连接远程服务器

Options:
    -F  to force a thread dump. Use when jstack <pid> does not respond (process is hung)
    -m  to print both java and native frames (mixed mode)
    -l  long listing. Prints additional information about locks
    -h or -help to print this help message

jstack统计线程数

jstack -l 28367 | grep 'java.lang.Thread.State' | wc -l

 注意： jstack 命令展示的结果中，线程 id 都转换成了十六进制形式。

线程id在jstack文件中叫nid

如何把线程ID转换成十六进制的

printf "%x\n" 11225

关于jstack dump下来的线程文件的具体分析，我另外一篇博客有

【二十二】Java多线程之线程转储和分析（jstack）

 （4）jstat -gcutil <pid>

使用Jstat命令查看新生代、老年代、永久代是使用情况、各代GC次数和耗时

看有没有频繁GC

关于该命令的详细解释在另外一篇博客

Java之jstat命令内存统计

（5）jmap -dump:format=b,file=XXXmemoryDump.txt pid

使用jmap命令dump内存文件，用MAT工具分析

关于该命令详细的解释在另外一骗

Java之jmap命令内存详情

 2.arthas

也能用arthas作为工具查看 dump 线程和内存的文件

具体使用另外一篇讲

二、分析思路

该部分大多数是参考的：https://blog.csdn.net/lucky_ykcul/article/details/94580325

线上常见系统变慢甚至导致系统不可用的原因：

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

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

下面3种情况CPU并不一定会飙高、内存也并不一定会飙高，不一定导致系统不可用

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

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

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

1.Full GC 次数过多

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

特征：

1）线上多个线程的 CPU 都超高(超过80%)，通过 jstack 命令可以看到这些线程主要是垃圾回收线程（名字叫VM Thread）。

2）通过 jstat 命令（jstat -gcutil pid 1000 10）监控 GC 情况，可以看到 Full GC 次数非常多，并且次数在不断增加。

那么多半是内存溢出了，

通过jmap -heap pid 看内存（新生代、老年代、永久代）占用情况

通过jmap -histro pid 看哪个类的对象特别大

通过jmap -dump:format=b,file=XXX.txt pid 得到内存文件用MAT工具做分析，基本上就能确定内存中主要是哪个对象比较消耗内存，然后找到该对象的创建位置，进行处理即可。

 dump下来的内存文件中会打印GC的原因，比如System.gc() 是显示调用导致的、Allocation Failure是 JVM 主动发起的。

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

1.代码中一次获取了大量的对象，导致内存溢出，此时可以通过 Eclipse 的 Mat 工具查看内存中有哪些对象比较多。

2.内存占用不高，但是 Full GC 次数还是比较多，此时可能是显示的 System.gc() 调用导致 GC 次数过多，这可以通过添加 -XX:+DisableExplicitGC 来禁用 JVM 对显示 GC 的响应。

 2.CPU 过高

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

查看方式其实与上面的非常类似：

1.top 命令查看当前 CPU 消耗过高的进程是哪个，从而得到进程 id；

2.通过 top -Hp 来查看该进程中有哪些线程 CPU 过高，一般超过 80% 就是比较高的，80% 左右是合理情况。这样我们就能得到 CPU 消耗比较高的线程 id。

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

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

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

而如果是代码中有比较耗时的计算，那么我们得到的就是一个线程的具体堆栈信息，根据堆栈信息，直接定位到代码的哪个类的哪 行，查看代码中具体是什么原因导致计算量如此之高。

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

对于这种情况，比较典型的例子就是，我们某个接口访问经常需要 2~3s 才能返回。

这是比较麻烦的一种情况，一般来说，其消耗的 CPU 不多，而且占用的内存也不高，通过上述两种方式进行排查是无法解决这种问题的。而且接口耗时比较大的问题是不定时出现的，通过 jstack 命令即使得到了线程访问的堆栈信息，也没法判断具体哪个线程是正在执行比较耗时操作的线程。

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

1.首先找到该接口，通过压测工具不断加大访问力度。

如果说该接口中有某个位置是比较耗时的，由于我们的访问的频率非常高，那么大多数的线程最终都将阻塞于该阻塞点。

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

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

“http-nio-8080-exec-2” #29 daemon prio=5 os_prio=31 tid=0x00007fd08cb26000 nid=0x9603 waiting on condition [0x00007000031d5000]
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.aibaobei.user.controller.UserController.detail(UserController.java:18)

“http-nio-8080-exec-3” #30 daemon prio=5 os_prio=31 tid=0x00007fd08cb27000 nid=0x6203 waiting on condition [0x00007000032d8000]
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.aibaobei.user.controller.UserController.detail(UserController.java:18)

“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.aibaobei.user.controller.UserController.detail(UserController.java:18)

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

4.某个线程进入 WAITING 状态

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

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

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

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

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

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

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

①通过 grep 在 jstack 日志中找出所有的处于 TIMED_WAITING 状态的线程，将其导出到某个文件中，如 a1.log，如下是一个导出的日志文件示例：
“Attach Listener” #13 daemon prio=9 os_prio=31 tid=0x00007fe690064000 nid=0xd07 waiting on condition [0x0000000000000000]
“DestroyJavaVM” #12 prio=5 os_prio=31 tid=0x00007fe690066000 nid=0x2603 waiting on condition [0x0000000000000000]
“Thread-0” #11 prio=5 os_prio=31 tid=0x00007fe690065000 nid=0x5a03 waiting on condition [0x0000700003ad4000]
“C1 CompilerThread3” #9 daemon prio=9 os_prio=31 tid=0x00007fe68c00a000 nid=0xa903 waiting on condition [0x0000000000000000]

②等待一段时间之后，比如 10s，再次对 jstack 日志进行 grep，将其导出到另一个文件，如 a2.log，结果如下所示：
“DestroyJavaVM” #12 prio=5 os_prio=31 tid=0x00007fe690066000 nid=0x2603 waiting on condition [0x0000000000000000]
“Thread-0” #11 prio=5 os_prio=31 tid=0x00007fe690065000 nid=0x5a03 waiting on condition [0x0000700003ad4000]
“VM Periodic Task Thread” os_prio=31 tid=0x00007fe68d114000 nid=0xa803 waiting on condition

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

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

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

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

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

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

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

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

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

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

“Thread-0” #11 prio=5 os_prio=31 tid=0x00007f9de08c7000 nid=0x5603 waiting on condition [0x0000700001f89000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:304)
at com.aibaobei.chapter2.eg4.SyncTask.lambda$main0 ( S y n c T a s k . j a v a : 8 ) a t c o m . a i b a o b e i . c h a p t e r 2. e g 4. S y n c T a s k 0(SyncTask.java:8) at com.aibaobei.chapter2.eg4.SyncTask0(SyncTask.java:8)atcom.aibaobei.chapter2.eg4.SyncTask$Lambda$1/1791741888.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)

5.死锁

这个看我另外一篇写的详细的例子

【二十二】Java多线程之线程转储和分析（jstack详解、以死锁例子分析jstack dump下来的线程文件）