CPU 占用过高，如何排查？

测试代码

死循环，一直打印数字

package com.test.high;

public class CPUHigh {
    public static void main(String[] args) {
        long count = 0;
        while (true){
            System.out.println(count++);
        }
    }
}

排查步骤

top 查看，哪一个进程 CPU 使用高

%Cpu(s): 10.8 us, 12.3 sy,  0.0 ni, 76.8 id,  0.0 wa,  0.0 hi,  0.2 si,  0.0 st
KiB Mem :  1863020 total,  1266812 free,   224332 used,   371876 buff/cache
KiB Swap:  2097148 total,  2097148 free,        0 used.  1485416 avail Mem

   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
  2291 root      20   0 2692708  47004  12396 S  41.2  2.5   0:55.56 java
  2059 root      20   0  158944   5780   4428 S   3.3  0.3   0:07.02 sshd
  2333 root      20   0  161972   2196   1552 R   0.7  0.1   0:00.03 top
    13 root      rt   0       0      0      0 S   0.3  

可以看到 pid = 2291 这个进程 CPU 使用率高。

ps -ef | grep java

如果能确定是 java 程序可以直接使用 jps -l，查找哪一个 java 进程。

[root@s101 program]# ps -ef | grep java
root       2291   2062 40 20:59 pts/1    00:01:18 java com.test.high.CPUHigh
root       2349   2025  0 21:02 pts/0    00:00:00 grep --color=auto java

ps -mp pid -o THREAD,tid,time

查看该进程中哪一个线程占用 CPU 时长较长。

[root@s101 program]# ps -mp 2291 -o THREAD,tid,time
USER     %CPU PRI SCNT WCHAN  USER SYSTEM    TID     TIME
root     40.2   -    - -         -      -      - 00:01:24
root      0.0  19    - futex_    -      -   2291 00:00:00
root     39.5  19    - -         -      -   2292 00:01:22
root      0.0  19    - futex_    -      -   2293 00:00:00
root      0.0  19    - futex_    -      -   2294 00:00:00
root      0.0  19    - futex_    -      -   2295 00:00:00
root      0.0  19    - futex_    -      -   2296 00:00:00
root      0.0  19    - futex_    -      -   2297 00:00:00
root      0.0  19    - futex_    -      -   2298 00:00:00
root      0.1  19    - futex_    -      -   2299 00:00:00
root      0.0  19    - futex_    -      -   2300 00:00:00
root      0.0  19    - futex_    -      -   2301 00:00:00
root      0.4  19    - futex_    -      -   2302 00:00:00

可以看到 tid = 2292 这个线程占用 CPU 较长。
tid = 2292 = 0x8f4

jstack pid | grep tid(hex) -A100

注意： jstack 中 tid 使用的是十六进制。

[root@s101 program]# jstack 2291 | grep 8f4 -A100
"main" #1 prio=5 os_prio=0 tid=0x00007f903404b800 nid=0x8f4 runnable [0x00007f903e385000]
   java.lang.Thread.State: RUNNABLE
        at java.io.FileOutputStream.writeBytes(Native Method)
        at java.io.FileOutputStream.write(FileOutputStream.java:326)
        at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
        at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
        - locked <0x00000000e38431e0> (a java.io.BufferedOutputStream)
        at java.io.PrintStream.write(PrintStream.java:482)
        - locked <0x00000000e3805138> (a java.io.PrintStream)
        at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
        at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
        at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
        - locked <0x00000000e38050f0> (a java.io.OutputStreamWriter)
        at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
        at java.io.PrintStream.newLine(PrintStream.java:546)
        - locked <0x00000000e3805138> (a java.io.PrintStream)
        at java.io.PrintStream.println(PrintStream.java:751)
        - locked <0x00000000e3805138> (a java.io.PrintStream)
        at com.test.high.CPUHigh.main(CPUHigh.java:7)

"VM Thread" os_prio=0 tid=0x00007f90340d1800 nid=0x8f7 runnable

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f903405e000 nid=0x8f5 runnable

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007f9034060000 nid=0x8f6 runnable

"VM Periodic Task Thread" os_prio=0 tid=0x00007f903413d000 nid=0x8fe waiting on condition

JNI global references: 5

References

1. cpu 占用过高排查