记一次 JVM CPU 使用率飙高问题的排查过程

问题现象

首先，我们一起看看通过 VisualVM 监控到的机器 CPU 使用率图：

cpu-usage

如上图所示，在 下午3:45 分之前，CPU 的使用率明显飙高，最高飙到近 100%，为什么会出现这样的现象呢？

排查过程

Step 1：使用top命令，查询资源占用情况：

top

如上图所示，显示了服务器当前的资源占用情况，其中PID为5456的进程占用的资源最多。

在这里，我们也使用top -p PID命令，查询指定PID的资源占用情况：

top-p

Step 2：使用ps -mp PID -o THREAD,tid,time命令，查询该进程的线程情况：

ps

在这里，我们也使用ps -mp PID -o THREAD,tid,time | sort -rn命令，将该进程下的线程按资源使用情况倒序展示：

ps-sort

Step 3：使用printf "%xn" PID命令，将PID转为十六进制的TID：

printf

在这里，我们之所以需要将PID转为十六进制是因为在堆栈信息中，PID是以十六进制形式存在的。

Step 4：使用jstack PID | grep TID -A 100命令，查询堆栈信息：

jstack

如上图所示，显示该进程下多个线程均处于TIMED_WAITING状态。

虽然线程处于WAITING或者TIMED_WAITING状态都不会消耗 CPU，但是线程频繁的挂起和唤醒却会消耗 CPU，而且代价高昂。

而上面之所以会出现 CPU 使用率飙高的情况，则是因为有人在做压测。

特别地，在 mock 底层接口的时候，使用了类似TimeUnit.SECONDS.sleep(1)这样的语句。

至于为何在 下午3:45 分之后，CPU 的使用率降下来了，则是因为停止了压测。

除此之外，我们还可以使用jinfo和jstat命令来查询 Java 进程的启动参数以及 GC 情况：

• 使用jinfo PID命令，查询启动参数：

jinfo

如上图所示，使用该命令我们主要是为了查询启动参数，如初始化堆大小、垃圾回收器等配置。

• 使用jstat -gcutil PID 1000命令，查询 GC 情况：

jstat

如上图所示，显示了PID为20567的 Java 进程每秒的 GC 情况，其中1000表示 GC 状态的更新频率，单位为毫秒。