Java应用CPU飙升和死锁排查实战教程

引言

在日常开发中，我们可能会遇到Java应用CPU飙升和死锁的问题。本文将通过实际案例，为大家介绍如何排查这些问题

Java应用CPU飙升和死锁排查步骤

先执行top命令，找到CPU占用比较高的进程
再执行jstack 进程id > dump.txt
找到进程中CPU占用比较高的线程，线程id转16进制
到dump.txt文件中根据线程id查看线程的具体状态即可

下面我们使用简单的例子检验排查步骤

首先我们先写两个Demo模拟CPU飙升和死锁的情况，启动SpringBoot项目发送Http请求触发这个两个接口，其中loop接口触发了两次，达到更好演示CPU飙升的效果。

package your.controller;

import lombok.extern.slf4j.Slf4j;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

import java.util.concurrent.TimeUnit;

@RestController
@Slf4j
public class CpuController {

    private Object lock1 = new Object();
    private Object lock2 = new Object();


    @GetMapping("loop")
    public String loop() {
        log.warn("loop start");
        while (true) {}
    }

    @GetMapping("deadlock")
    public String deadlock() {
        log.warn("deadlock start");
        new Thread(()->{
            synchronized (lock1) {
                try {
                    TimeUnit.SECONDS.sleep(1);
                } catch (InterruptedException e) {}
                synchronized (lock2) {
                    log.info("thread1 over");
                }
            }
        }).start();

        new Thread(()->{
            synchronized (lock2) {
                try {
                    TimeUnit.SECONDS.sleep(1);
                } catch (InterruptedException e) {}
                synchronized (lock1) {
                    log.info("thread2 over");
                }
            }
        }).start();

        return "ok";
    }


}

步骤一：先执行`top`命令，找到CPU占用比较高的进程

在这里插入图片描述
可以看到进程号为 279738 的应用占用CPU较高。

步骤二：再执行`jstack 进程id > dump.txt`生成线程快照

在此例子中执行：jstack 279738 > dump.txt
在这里插入图片描述

步骤三：找到进程中CPU占用比较高的线程，线程id转16进制

在此例子中执行：top -p 279738 -H，可以看到279758和279761这两个线程占用CPU较高（由于之前触发了两次loop接口，所有这两个线程占用较高）
在这里插入图片描述
因为dump文件的线程ID是使用16进制表示的，所以再执行：printf "%x" 279758，将10进制转成16进制，是 444ce

步骤四：到dump.txt文件中根据线程id查看线程的具体状态即可

在这里插入图片描述
可以看出线程状态是RUNNABLE，并且运行到了20行

at com.example.demo.controller.CpuController.loop(CpuController.java:20)

回到代码分析，确实是在第20行发生了死循环。
在这里插入图片描述

在dump文件的末尾可以看到死锁的情况
在这里插入图片描述


Found one Java-level deadlock:
=============================
"Thread-8":
  waiting to lock monitor 0x00007f71340066d8 (object 0x00000000e2eba7e0, a java.lang.Object),
  which is held by "Thread-6"
"Thread-6":
  waiting to lock monitor 0x00007f714001fad8 (object 0x00000000e2eba7d0, a java.lang.Object),
  which is held by "Thread-5"
"Thread-5":
  waiting to lock monitor 0x00007f71340066d8 (object 0x00000000e2eba7e0, a java.lang.Object),
  which is held by "Thread-6"

Java stack information for the threads listed above:
===================================================
"Thread-8":
	at com.example.demo.controller.CpuController.lambda$deadlock$1(CpuController.java:40)
	- waiting to lock <0x00000000e2eba7e0> (a java.lang.Object)
	at com.example.demo.controller.CpuController$$Lambda$475/725445379.run(Unknown Source)
	at java.lang.Thread.run(Thread.java:748)
"Thread-6":
	at com.example.demo.controller.CpuController.lambda$deadlock$1(CpuController.java:43)
	- waiting to lock <0x00000000e2eba7d0> (a java.lang.Object)
	- locked <0x00000000e2eba7e0> (a java.lang.Object)
	at com.example.demo.controller.CpuController$$Lambda$475/725445379.run(Unknown Source)
	at java.lang.Thread.run(Thread.java:748)
"Thread-5":
	at com.example.demo.controller.CpuController.lambda$deadlock$0(CpuController.java:32)
	- waiting to lock <0x00000000e2eba7e0> (a java.lang.Object)
	- locked <0x00000000e2eba7d0> (a java.lang.Object)
	at com.example.demo.controller.CpuController$$Lambda$474/637174220.run(Unknown Source)
	at java.lang.Thread.run(Thread.java:748)

Found 1 deadlock.

可以看出Thread-8想要得到Thread-6的资源，Thread-6想要得到Thread-5的资源，Thread-5想要得到Thread-6的资源，回到代码可以看出死锁的具体位置。
在这里插入图片描述
按照上述排查步骤，我们成功地找到了导致CPU飙升和死锁的原因。在实际操作中，我们可以根据这些信息对代码进行优化，解决性能问题。