Jstack CPU过高问题分析及定位
前面我们讲解了Jstack命令可以排查死锁问题，通过jstack日志，我们看到了线程之间相互持有，造成死锁，并且能够顺利的定位到死锁，看到代码的位置解决死锁问题，死锁是造成系统停顿时间久的问题之一，但是系统停顿的问题有很多种，今天我们分析下CPU过高的问题定位
学习了这篇文章后，在项目生产环境上，如果遇到CPU问题很高，让我们排查下原因，就不会无从下手了
1.CPU过高问题分析
真正的项目中，CPU过高时，尽量让运维配置下脚本，在CPU超过多少的时候就自动打印线程堆栈信息，有了堆栈信息我们才能分析那时刻，到底在干什么，什么导致CPU过高
下面，我们编写一个程序，来模拟一下CPU问题过高，然后通过Jstack命令，快速定位到CPU过高的问题，解决问题
场景如下:
- 开启2个线程，每个线程里面都在循环运算
- 运算就会导致CPU升高，这时候检测下CPU的信息
- CPU升高后，我们执行Jstack命令，打印线程堆栈信息
- 然后定位问题，解决问题
本次环境我们要执行一些Linux 命令，windows 环境不行，所以我们这次在虚拟机中执行本次操作，需要把程序打包，然后放到linux服务器上执行，然后执行命令 定位问题， 步骤如下
top
top -Hp pid
printf %x xxx jstack -F -l pid
jstack -l [PID] >/tmp/log.txt
分析堆栈信息
1.1 程序代码及打包install
依旧是通过 TestController启动运行计算程序，代码如下
package com.jzj.jvmtest.font;
import com.jzj.jvmtest.mythread.MyTask;
import lombok.extern.slf4j.Slf4j;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
@RestController
@Slf4j
public class TestController {
/**
* 新建一个固定大小的线程池
*/
private static ExecutorService executorService = Executors.newFixedThreadPool(5);
public static Object TEST_LOCK = new Object();
@GetMapping("/ping")
private String ping() {
return "pong";
}
@GetMapping("/cpu")
private String cpu() {
MyTask task1 = new MyTask();
MyTask task2 = new MyTask();
executorService.execute(task1);
executorService.execute(task2);
return "ok";
}
}
然后这里面有两个MyTask 线程信息，代码如下
package com.jzj.jvmtest.mythread;
import static com.jzj.jvmtest.font.TestController.TEST_LOCK;
public class MyTask implements Runnable {
public void run() {
synchronized (TEST_LOCK) {
//线程开始计算sum， 累加，消耗CPU
long sum = 0L;
while (true) {
sum += 1;
}
}
}
}
通过线程池 来开启线程
MyTask task1 = new MyTask();
MyTask task2 = new MyTask();
executorService.execute(task1);
executorService.execute(task2);
SpringBoot启动后，我们通过 curl 127.0.0.1:8078/temp/cpu 来执行程序，让cpu跑起来
1.2 复制jar包到linux， 执行
我们把Jar包复制到Linux 服务器，然后执行Jar包
Linux环境下 启动Jar包
java -jar demo-0.0.1-SNAPSHOT.jar
[jzj@localhost jzjtest]$ pwd
/home/jzj/jzjtest
[jzj@localhost jzjtest]$ ll
总用量 18856
-rwxrw-rw-. 1 jzj jzj 19308165 4月 26 2023 demo-0.0.1-SNAPSHOT.jar
[jzj@localhost jzjtest]$
[jzj@localhost jzjtest]$ java -jar demo-0.0.1-SNAPSHOT.jar
启动成功， 端口 8078
测试 TestController， 执行 curl 127.0.0.1:8078/temp/ping, 返回pong
[jzj@localhost jzjtest]$ curl 127.0.0.1:8078/ping
pong
[jzj@localhost jzjtest]$
查看 java进程 , demo 进程PID 是6380
[jzj@localhost jzjtest]$ ps -ef |grep java
jzj 6380 5714 2 01:14 pts/1 00:00:05 java -jar demo-0.0.1-SNAPSHOT.jar
jzj 6652 6407 0 01:18 pts/2 00:00:00 grep --color=auto java
[jzj@localhost jzjtest]$
[jzj@localhost jzjtest]$ jps
6380 jar
6671 Jps
2.启动模拟程序， 升高CPU
执行 curl 127.0.0.1:8078/cpu, 让线程开始计算，模拟CPU升高 [jzj@localhost jzjtest]
2.1 top 命令查看进程 最高消耗CPU的进程
此刻， 我们利用top命令来定位CPU 升高的问题 ， 我们解析下 top 打印进程信息及cpu信息
- CPU 的load average 负载时0.95 也就是 95%
- 此刻 一共 1个任务在running， 210个线程 sleep
- 进程最高的 进程PID时 7198
top - 01:40:27 up 3:48, 4 users, load average: 1.50, 1.37, 1.05
Tasks: 210 total, 3 running, 207 sleeping, 0 stopped, 0 zombie
%Cpu(s): 99.7 us, 0.3 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 1863004 total, 132724 free, 1073776 used, 656504 buff/cache
KiB Swap: 2097148 total, 2096884 free, 264 used. 574696 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
7198 jzj 20 0 2502788 119248 13556 S 98.7 6.4 3:16.74 java
1516 root 20 0 415924 137764 60148 S 0.7 7.4 0:36.55 X
2195 jzj 20 0 3130516 300892 93748 S 0.3 16.2 1:41.85 gnome-shell
1 root 20 0 128600 7256 4220 S 0.0 0.4 0:02.03 systemd
2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd
4 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0H
2.2 top -Hp pid 查看进程中最高的线程
打印进程 7198 中最高的线程信息, 我们可以看到
- 进程内，CPU的 98.7 消耗都是7154的 线程ID消耗的
[jzj@localhost jzjtest]$ top -Hp 7198
top - 01:40:38 up 3:48, 4 users, load average: 1.43, 1.35, 1.05
Threads: 19 total, 1 running, 18 sleeping, 0 stopped, 0 zombie
%Cpu(s):100.0 us, 0.0 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 1863004 total, 132972 free, 1073528 used, 656504 buff/cache
KiB Swap: 2097148 total, 2096884 free, 264 used. 574944 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
7574 jzj 20 0 2502788 119248 13556 R 93.3 6.4 3:21.92 pool-1-thread-1
7198 jzj 20 0 2502788 119248 13556 S 0.0 6.4 0:00.00 java
7199 jzj 20 0 2502788 119248 13556 S 0.0 6.4 0:01.94 java
7200 jzj 20 0 2502788 119248 13556 S 0.0 6.4 0:00.11 VM Thread
2.3 printf %x 线程ID 把它转换为16进制
我们看到 7574 的线程，消耗最高， 但是7574在 jstack日志中是以 16进制形式展示的，所以我们要做下转换
[jzj@localhost jzjtest]
2.4 jstack -F -l pid > a.txt 打印堆栈日志
我们使用命令 jstack -F -l 7574 > a.txt 打印堆栈日志
[jzj@localhost jzjtest]$ jstack -F -l 7574 >a.txt
sun.jvm.hotspot.debugger.DebuggerException: sun.jvm.hotspot.debugger.DebuggerException: get_thread_regs failed for a lwp
at sun.jvm.hotspot.debugger.linux.LinuxDebuggerLocal$LinuxDebuggerLocalWorkerThread.execute(LinuxDebuggerLocal.java:163)
at sun.jvm.hotspot.debugger.linux.LinuxDebuggerLocal.getThreadIntegerRegisterSet(LinuxDebuggerLocal.java:482)
at sun.jvm.hotspot.runtime.JavaThread.getCurrentFrameGuess(JavaThread.java:256)
at sun.jvm.hotspot.runtime.JavaThread.getLastJavaVFrameDbg(JavaThread.java:218)
at sun.jvm.hotspot.tools.StackTrace.run(StackTrace.java:86)
at sun.jvm.hotspot.tools.StackTrace.run(StackTrace.java:45)
3.分析jstack日志
打开刚才 另存为的a.txt日志
查看分析日志, 我们重点关注 7574 这个线程的
ttaching to process ID 7574, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.362-b08
Deadlock Detection:
No deadlocks found.
Thread 7576: (state = BLOCKED)
Error occurred during stack walking:
Locked ownable synchronizers:
- None
Thread 7575: (state = BLOCKED)
Error occurred during stack walking:
Locked ownable synchronizers:
- <0x00000000e4036668>, (a java/util/concurrent/ThreadPoolExecutor$Worker)
Thread 7574: (state = IN_JAVA)
- com.jzj.jvmtest.mythread.MyTask.run() @bci=12, line=12 (Compiled frame; information may be imprecise)
- java.util.concurrent.ThreadPoolExecutor.runWorker(java.util.concurrent.ThreadPoolExecutor$Worker) @bci=95, line=1149 (Interpreted frame)
- java.util.concurrent.ThreadPoolExecutor$Worker.run() @bci=5, line=624 (Interpreted frame)
- java.lang.Thread.run() @bci=11, line=750 (Interpreted frame)
Locked ownable synchronizers:
- <0x00000000e401d538>, (a java/util/concurrent/ThreadPoolExecutor$Worker)
Thread 7573: (state = BLOCKED)
Error occurred during stack walking:
Locked ownable synchronizers:
- None
Thread 7199: (state = BLOCKED)
Error occurred during stack walking:
我们找到 7574线程 ,分析如下
Thread 7574: (state = IN_JAVA)
- com.jzj.jvmtest.mythread.MyTask.run() @bci=12, line=12 (Compiled frame; information may be imprecise)
- java.util.concurrent.ThreadPoolExecutor.runWorker(java.util.concurrent.ThreadPoolExecutor$Worker) @bci=95, line=1149 (Interpreted frame)
- java.util.concurrent.ThreadPoolExecutor$Worker.run() @bci=5, line=624 (Interpreted frame)
- java.lang.Thread.run() @bci=11, line=750 (Interpreted frame)
- 7574 线程
- com.jzj.jvmtest.mythread.MyTask.run() 出问题的地方在这里
- 定位问题 线程出现了问题，消耗CPU最高
- 如果没有显示 7574线程，我们可以用内存地址
- 比如 之前的 printf %x 7574 = 1d96
- 用 1d96 在 jstack日志中 查看线程相关信息
本文我们 在Linux环境下，模拟了程序，进行了CPU过高的时候，如何通过top命令和jstack命令定位问题，并且进行了实战，帮助大家快速的解决CPU过高的问题，但是jstack命令也不是无敌的，有时候单纯的靠jstack，在实际项目中是无法定位问题的
