JVM进程CPU使用率异常排查

前言

在我们JVM进程运行过程中可能会出现占用CPU过高或者占用达到100%异常情况，如果没有解决思路看看这篇，会发现原来如此简单。

例子程序

下面是一个模拟线程占用CPU的例子程序，编译（javac HighCPUUsageSample.java）后执行（java HighCPUUsageSample）这个程序来启动一个JVM进程。

第三个线程会调用doSomethingWithProblem()方法不断的进行累加运算占用CPU到20%~50%。

因为只是为了模拟，所以没有让程序占用过多的CPU，可以长时间运行不用担心过多的影响服务器的其他进程。但本质上和模拟CPU占用100%是一样的。

import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import static java.util.concurrent.TimeUnit.SECONDS;

public class HighCPUUsageSample {

    private static final ExecutorService EXECUTOR = Executors.newFixedThreadPool(3);

    public static void main(String[] args) {
        EXECUTOR.submit(() -> repeat(false));
        EXECUTOR.submit(() -> repeat(false));
        EXECUTOR.submit(() -> repeat(true));
    }

    private static void repeat(boolean withProblem) {
        try {
            while (true) {
                if (withProblem) {
                    doSomethingWithProblem();
                } else {
                    doSomething();
                }
                SECONDS.sleep(1);
            }
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }

    /**
     * 普通方法，基本不占用CPU
     */
    private static void doSomething() {
        System.out.println(Thread.currentThread().getName() + " do something.");
    }

    /**
     * 从0累加到Integer.MAX_VALUE，来占用CPU
     */
    private static void doSomethingWithProblem() {
        long sum = 0;
        for (int i = 0; i < Integer.MAX_VALUE; i++) {
            sum += i;
        }
        System.out.println(Thread.currentThread().getName() + " sum is " + sum);
    }
}

排查过程

找出进程

执行top指令并按CPU使用率排序（键入大写的P）可以看到占用CPU占用过高的Java进程ID为19068，Ctrl+c退出top监控。

top指令执行后可以通过键入大写的P或M分别按CPU或内存的使用率进行排序。

top

找出线程

执行top -Hp <进程ID>找出进程中占用CPU过高的线程ID，Ctrl+c退出top监控。

top -Hp 19068

将线程ID转换成十六进制

可以通过科学计算器或者其他方式将这个十进制的ID转换成十六进制，也可以通过下面的Java中Integer的方法进行转换。转换的目的是让这个线程ID能和jstack输出的线程ID匹配上，因为jstack输出的是十六进制的线程ID。

System.out.println(Integer.toHexString(19080));

查看线程的运行状态

• jstack查看

jstack是JDK中自带的指令，通过jstack <Java进程ID>可以输出进程所有的线程信息。

jstack 19068

从下图可以看到线程名（pool-1-thread-3）、线程ID（nid=0x4a88）、线程运行状态（RUNNABLE），从输出的线程方法堆栈中可以看到我们模拟占用CPU的方法。

• jstack + grep查看

也可以在jstack指令后加上grep来过滤，只输出包含这个十六进制线程ID的信息，格式为jstack <进程ID> | grep <十六进制线程ID>。

但是这个输出信息没有包含运行状态和方法堆栈。

jstack 19068 | grep 4a88

• jstack输出到文件后查看

这种方式会将信息输出到指定的文件中，然后在文件中查找线程ID对应的内容，格式为jstack [进程ID] > [文件名]。

jstack 19068 > 19068.txt

总结

通过这个例子我们体会到排查的过程并不是很复杂，虽然只是个例子但实际情况下排查方式也差不多，只不过会有其他麻烦的地方。

一般这种占用CPU的线程状态肯定是RUNNABLE，不运行也不会占用CPU。

我们这个例子找出问题线程很容易的原因之一是方法是固定在一个线程里面执行，而实际生产环境一般是一个业务在线程中执行完后线程会被线程池回收，下次执行的时候会分配新的线程，所以线程ID是会一直变化的，没办法像我们这样可以一直查看，所以得在业务在线程中执行完之前就用jstack查看线程运行相关信息。不过CPU占用100%这种情况线程ID不会怎么变化，因为一般是长时间执行占用CPU无法退出导致的，比如死循环。

还有在最后分析线程运行信息的那一步会非常麻烦，因为我们事先并不知道是哪段程序有这个问题，而且实际情况代码量和方法调用链肯定非常的长。这种情况下我们只能从整体到局部逐步缩小排查范围，先确定问题出现的时间区间，再找出这段时间相关的服务更新记录，找出服务中变化的点，结合问题线程的相关信息逐步缩小定位问题。

另外jstack中有输出线程名字，如果我们给线程按业务取见名知意的线程名能够很好的帮助我们缩小问题所在的范围。这也是为什么建议不同类型的任务使用不同的线程池、给线程池取有意义的名字的原因。