定位 CPU 高负载 Java 线程

常用命令

# 按照 CPU 使用率排序输出进程信息
ps -eo pid,ppid,%cpu,%mem,cmd --sort=-%cpu

# 监控对应 pid 进程下的所有线程按照 CPU 排序
top -Hp "$pid" -o %CPU 

# jstack 输出 JVM 堆栈信息
jstack $pid

演示事例

查看高负载 Java 进程获取到对应 pid

$ ps -eo pid,ppid,%cpu,%mem,cmd --sort=-%cpu
  PID  PPID %CPU %MEM CMD
 4432  4288  102  1.2 /usr/bin/qemu-x86_64 /usr/lib/jvm/java-1.8.0/bin/java java -cp mytomcat.jar co
 4288     0  0.2  0.2 /usr/bin/qemu-x86_64 /bin/bash /bin/bash
    1     0  0.0  0.1 /usr/bin/qemu-x86_64 /bin/sh /bin/sh /home/user/run.sh
   29     1  0.0  0.2 /usr/bin/qemu-x86_64 /usr/bin/sudo sudo /usr/sbin/sshd -D
   34    29  0.0  0.2 /usr/bin/qemu-x86_64 /usr/sbin/sshd /usr/sbin/sshd -D
   37     1  0.0  0.0 /usr/bin/qemu-x86_64 /usr/bin/tail tail -f /dev/null
  411     1  0.0  1.2 /usr/bin/qemu-x86_64 /usr/lib/jvm/java-1.8.0/bin/java java -cp mytomcat.jar co
 1892     0  0.0  0.2 /usr/bin/qemu-x86_64 /bin/bash /bin/bash
 3671     1  0.0  0.0 [java] <defunct>
 3759     1  0.0  0.0 [java] <defunct>
 3839     1  0.0  0.0 [jstack] <defunct>
 4017     1  0.0  0.0 [java] <defunct>
 4105     1  0.0  0.0 [java] <defunct>
 4466  1892  0.0  0.1 ps -eo pid,ppid,%cpu,%mem,cmd --sort=-%cpu

查看 pid 为 4432 进程的线程 CPU 占用情况

$ top -Hp 4432 -o %CPU -n 1

top - 09:30:22 up 1 day,  4:05,  0 users,  load average: 1.04, 1.62, 1.85
Threads:  16 total,   1 running,  15 sleeping,   0 stopped,   0 zombie
%Cpu(s): 25.8 us,  0.0 sy,  0.0 ni, 72.7 id,  0.0 wa,  0.0 hi,  1.5 si,  0.0 st
KiB Mem :  8039920 total,  5078924 free,   469100 used,  2491896 buff/cache
KiB Swap:  1048572 total,  1048572 free,        0 used.  6990084 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND                         
 4435 user      20   0 4585612  98712  17288 R 99.9  1.2   1:24.68 java                            
 4432 user      20   0 4585612  98712  17288 S  0.0  1.2   0:00.05 java                            
 4434 user      20   0 4585612  98712  17288 S  0.0  1.2   0:00.00 java                            
 4436 user      20   0 4585612  98712  17288 S  0.0  1.2   0:00.00 java                            
 4437 user      20   0 4585612  98712  17288 S  0.0  1.2   0:00.00 java                            
 4438 user      20   0 4585612  98712  17288 S  0.0  1.2   0:00.00 java                            
 4439 user      20   0 4585612  98712  17288 S  0.0  1.2   0:00.00 java                            
 4440 user      20   0 4585612  98712  17288 S  0.0  1.2   0:00.00 java                            
 4441 user      20   0 4585612  98712  17288 S  0.0  1.2   0:00.00 java                            
 4442 user      20   0 4585612  98712  17288 S  0.0  1.2   0:00.00 java                            
 4443 user      20   0 4585612  98712  17288 S  0.0  1.2   0:00.00 java                            
 4444 user      20   0 4585612  98712  17288 S  0.0  1.2   0:00.17 java                            
 4445 user      20   0 4585612  98712  17288 S  0.0  1.2   0:00.00 java                            
 4446 user      20   0 4585612  98712  17288 S  0.0  1.2   0:00.18 java                            
 4447 user      20   0 4585612  98712  17288 S  0.0  1.2   0:00.00 java                            
 4448 user      20   0 4585612  98712  17288 S  0.0  1.2   0:00.06 java 

可见该进程下 pid 为 4435 的线程 CPU 占用率最高将其换算为 16 进制 4435 = 0x1153

将 4432 堆栈信息导出并检索 4435 （jstack 导出的线程 id 是 16 进制）线程的调用情况

$ jstack 4432 > 4432.log
$ less 4432.log # /0x1153

定位到具体的线程调用情况

"main" #1 prio=5 os_prio=0 tid=0x0000004004009440 nid=0x1153 runnable [0x0000004002f36000]
   java.lang.Thread.State: RUNNABLE
        at com.ft.mytomcat.MyTomcat.main(MyTomcat.java:71)

定位到业务代码

利用 arthas

$ java -jar arthas-boot.jar 
[INFO] JAVA_HOME: /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.171-8.b10.el7_5.x86_64/jre
[INFO] arthas-boot version: 3.7.1
[INFO] Found existing java process, please choose one and input the serial number of the process, eg : 1. Then hit ENTER.
* [1]: 4432 com.ft.mytomcat.MyTomcat
1
[INFO] arthas home: /tmp
[INFO] Try to attach process 4432
Picked up JAVA_TOOL_OPTIONS: 
[INFO] Attach process 4432 success.
[INFO] arthas-client connect 127.0.0.1 3658
  ,---.  ,------. ,--------.,--.  ,--.  ,---.   ,---.                           
 /  O  \ |  .--. ''--.  .--'|  '--'  | /  O  \ '   .-'                          
|  .-.  ||  '--'.'   |  |   |  .--.  ||  .-.  |`.  `-.                          
|  | |  ||  |\  \    |  |   |  |  |  ||  | |  |.-'    |                         
`--' `--'`--' '--'   `--'   `--'  `--'`--' `--'`-----'                          

wiki       https://arthas.aliyun.com/doc                                        
tutorials  https://arthas.aliyun.com/doc/arthas-tutorials.html                  
version    3.7.1                                                                
main_class                                                                      
pid        4432                                                                 
time       2023-12-25 01:45:20                                                  

[arthas@4432]$ thread -n 1
"main" Id=1 cpuUsage=99.77% deltaTime=209ms time=11449914ms RUNNABLE
    at com.ft.mytomcat.MyTomcat.main(MyTomcat.java:71)

[arthas@4432]$ stop
Resetting all enhanced classes ...
Affect(class count: 0 , method count: 0) cost in 7 ms, listenerId: 0
Arthas Server is going to shutdown...
[arthas@4432]$ session (bb9f4723-d996-4309-868d-cdea6fa62cb4) is closed because server is going to shutdown.

使用完 arthas 记得 stop