JVM 线上排查实战(二):ps 说它占 66% CPU,其实它早睡着了 —— 找烧 CPU 线程的四个坑

这个系列

「JVM 线上排查实战」共五篇,每篇都在真机上跑、JDK 8 和 JDK 17 两个版本都贴输出:

1. (一)先把 JVM 看清楚:进程、参数、默认值
2. (二)CPU 飙高:找到那个线程 —— 本篇
3. (三)线程卡住:死锁、BLOCKED、线程池打满
4. (四)内存:OOM 了先干什么
5. (五)GC 日志:从 JDK 8 升 17,老启动参数会让进程直接起不来

实测环境同第一篇:CentOS 7.9(4 核)· JDK 1.8.0_381 装在 /opt/jdk8 · JDK 17.0.8 装在 /usr/java。top / ps 来自系统自带的 procps-ng 3.3.10。

先说结论

• 经典流程 top -Hp → printf '%x' → jstack 里找 nid=0x… 在 8 和 17 上都成立,本篇两版本都实跑了一遍
• 四个坑:①线程池的线程名在 top/ps 里被截成 15 个字符,三个线程长得一模一样;②**ps 的 %CPU 是线程一辈子的平均值**,一个已经睡着的线程能显示 66.5%;③jstack 里的 RUNNABLE 不等于在烧 CPU;④ JDK 17 的 jstack 每个线程自带 cpu=,但那是累计值,要隔几秒抓两次做差
• ps -L --sort=-pcpu 在 CentOS 7 自带的 procps-ng 3.3.10 上排序没有生效,要自己接 sort

---

1. 实验程序 ✅

一个进程里放四种线程,覆盖排查时最容易看错的几种状态:

import java.net.ServerSocket;

public class Busy {
    static volatile long sink;

    public static void main(String[] args) throws Exception {
        // 1. 一直在烧 CPU 的线程
        new Thread(() -> { long x = 0; while (true) { x += System.nanoTime() % 7; sink = x; } }, "busy-worker").start();
        // 2. 先猛烧 8 秒,然后睡下去 —— 累计 CPU 高,但此刻不占 CPU
        new Thread(() -> {
            long end = System.currentTimeMillis() + 8000, x = 0;
            while (System.currentTimeMillis() < end) { x += System.nanoTime() % 7; sink = x; }
            try { Thread.sleep(Long.MAX_VALUE); } catch (InterruptedException e) { }
        }, "burst-then-idle").start();
        // 3. 阻塞在 accept 上 —— 线程状态是 RUNNABLE,但不耗 CPU
        new Thread(() -> {
            try (ServerSocket ss = new ServerSocket(18080)) { ss.accept(); } catch (Exception e) { }
        }, "socket-accept").start();
        // 4. 一直在睡
        new Thread(() -> { try { Thread.sleep(Long.MAX_VALUE); } catch (InterruptedException e) { } }, "idle-sleeper").start();
        Thread.sleep(Long.MAX_VALUE);
    }
}

另一个模拟线程池:三个线程都叫 http-nio-8080-exec-N(Tomcat 默认的线程名格式),只有 exec-2 在烧 CPU:

public class Pool {
    static volatile long sink;
    public static void main(String[] args) throws Exception {
        for (int i = 1; i <= 3; i++) {
            final boolean busy = (i == 2);   // 只有 exec-2 在烧 CPU
            new Thread(() -> {
                if (busy) { long x = 0; while (true) { x += System.nanoTime() % 7; sink = x; } }
                try { Thread.sleep(Long.MAX_VALUE); } catch (InterruptedException e) { }
            }, "http-nio-8080-exec-" + i).start();
        }
        Thread.sleep(Long.MAX_VALUE);
    }
}

两个程序都用 JDK 8 的 javac 编译,同一份 class 分别用 8 和 17 跑。

---

2. 经典流程:top → 16 进制 → jstack ✅

以 Pool 为例。

2.1 top -Hp <pid>:看这个进程里哪个线程在烧

-H 按线程显示。下面是 top -Hp <pid> -b -d 2 -n 2 的第二帧(本文统一取刷新间隔 2 秒之后的那一帧):

JDK 8:

   PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
 41222 root      20   0 2737844  29212  11228 R 99.9  0.8   0:08.09 http-nio-8+
 41221 root      20   0 2737844  29212  11228 S  0.0  0.8   0:00.00 http-nio-8+
 41223 root      20   0 2737844  29212  11228 S  0.0  0.8   0:00.00 http-nio-8+

JDK 17:

   PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
 41518 root      20   0 3220140  28976  11992 R 99.9  0.8   0:08.12 http-nio-8+
 41517 root      20   0 3220140  28976  11992 S  0.0  0.8   0:00.00 http-nio-8+
 41519 root      20   0 3220140  28976  11992 S  0.0  0.8   0:00.00 http-nio-8+

PID 那一列在 -H 模式下是线程号。最忙的线程:JDK 8 是 41222,JDK 17 是 41518。

2.2 转 16 进制

printf '%x\n' 41222

得到 a106(JDK 17 那个 41518 是 a22e)。jstack 里的 nid 就是这个线程号的 16 进制。

2.3 在 jstack 里找 nid=0x…

jstack <pid> | grep -A3 "nid=0xa106 "

JDK 8:

"http-nio-8080-exec-2" #10 prio=5 os_prio=0 tid=0x00007fcb74164000 nid=0xa106 runnable [0x00007fcb64af9000]
   java.lang.Thread.State: RUNNABLE
	at Pool.lambda$main$0(Pool.java:7)
	at Pool$$Lambda$1/471910020.run(Unknown Source)

JDK 17:

"http-nio-8080-exec-2" #14 prio=5 os_prio=0 cpu=10468.88ms elapsed=10.47s tid=0x00007f7e840d2120 nid=0xa22e runnable  [0x00007f7e8863a000]
   java.lang.Thread.State: RUNNABLE
	at Pool.lambda$main$0(Pool.java:7)
	at Pool$$Lambda$1/0x00007f7e10000a08.run(Unknown Source)

Pool.java:7 就是那行 while (true)。定位到代码行,这个流程就走完了。

⚠️ grep 的时候在十六进制后面带个空格("nid=0xa106 "),否则 0xa10 会同时命中 0xa106、0xa10f 之类。

jcmd <pid> Thread.print 输出的是同一份线程栈,JDK 17 下同一行:

"http-nio-8080-exec-2" #14 prio=5 os_prio=0 cpu=10533.33ms elapsed=10.54s tid=0x00007f7e840d2120 nid=0xa22e runnable  [0x00007f7e8863a000]

---

3. 坑一:线程名被截成 15 个字符 ✅

上面 top 的 COMMAND 列里三个线程都是 http-nio-8+ —— 那是 top 列宽不够截的。换 ps 看完整的:

JDK 8:

   TID %CPU COMMAND
 41221  0.0 http-nio-8080-e
 41222  101 http-nio-8080-e
 41223  0.0 http-nio-8080-e

JDK 17:

 41517  0.0 http-nio-8080-e
 41518  101 http-nio-8080-e
 41519  0.0 http-nio-8080-e

ps 也只给到 http-nio-8080-e,正好 15 个字符 —— Linux 给线程起的名字最长就这么长,exec-1、exec-2、exec-3 的区别全在被截掉的部分里。

好消息是:在 JDK 8u381 和 17.0.8 上,Java 线程名都会同步成 Linux 线程名(top 里直接看得到 busy-worker、VM Thread、GC Thread#0),所以短名字的线程可以直接从 top 认出来。 但线程池、框架线程的名字普遍超过 15 个字符 —— 别拿 COMMAND 列认线程,一律用线程号转 16 进制去对 nid。

---

4. 坑二:ps 的 %CPU 是一辈子的平均值 ✅

用 Busy 程序,启动约 12 秒后同时看 ps 和 top(JDK 8):

---- ps -L 按 %CPU 排序(生命周期平均)
 42187 99.5 00:00:11 busy-worker
 42188 66.5 00:00:07 burst-then-idle
 42173  0.2 00:00:00 java
---- top -H 第二帧(最近 2 秒)
   PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
 42187 root      20   0 2806548  31852  11540 R 99.9  0.8   0:14.11 busy-worker
 42188 root      20   0 2806548  31852  11540 S  0.0  0.8   0:07.98 burst-then+

burst-then-idle 在前 8 秒猛烧,之后一直在睡:

• ps 显示 66.5% —— 它的算法是「累计 CPU 时间 ÷ 线程活了多久」,约 8 秒 ÷ 约 12 秒
• top 显示 0.0%、状态 S(睡眠) —— 它看的是最近一个刷新间隔

问「现在是谁在烧 CPU」,用 top,不用 ps。 用 ps 会把一个早就闲下来的线程当成凶手,而那段栈里看到的只是它在 sleep。

---

5. 坑三:ps -L --sort=-pcpu 没有按 CPU 排序 ✅

直觉写法:

ps -Lp <pid> -o tid,pcpu,comm --sort=-pcpu | head

在 CentOS 7 自带的 procps-ng 3.3.10 上,JDK 8 进程的实际输出前 3 行:

   TID %CPU COMMAND
 41205  0.0 java
 41207  0.3 java

烧到 101% 的 41222 不在前面 —— 输出是按线程号排的,--sort=-pcpu 在 -L 模式下没起作用(JDK 17 进程上结果一样)。接 head 就把真凶截掉了。

能用的写法:

ps -Lp <pid> -o tid,pcpu,comm --no-headers | sort -k2 -nr | head -3

 41222  101 http-nio-8080-e
 41207  0.3 java
 41218  0.1 C1 CompilerThre

用 ps 排序时,先看一眼输出是不是真的按 %CPU 降序。 而且就算排对了,它排的也是坑二里说的「一辈子平均值」。

---

6. 坑四:RUNNABLE 不等于在烧 CPU ✅

Busy 程序 JDK 8 的 jstack:

"socket-accept" #11 prio=5 os_prio=0 tid=0x00007f45881bd800 nid=0x9acb runnable [0x00007f45730ef000]
   java.lang.Thread.State: RUNNABLE
--
"busy-worker" #9 prio=5 os_prio=0 tid=0x00007f45881ba000 nid=0x9ac9 runnable [0x00007f45732f1000]
   java.lang.Thread.State: RUNNABLE

两个都是 RUNNABLE,但 socket-accept 阻塞在 accept() 上等连接,几乎不耗 CPU(下一节 JDK 17 的读数:12.58ms)。等网络 IO、等 socket 读的线程在 Java 层面都显示 RUNNABLE。

所以不能拿「jstack 里 RUNNABLE 的线程」当烧 CPU 的线程。 在 JDK 8 上,光看 jstack 分不出这两个 —— 必须先用 top -Hp 拿到线程号。

---

7. JDK 17:jstack 每个线程自带 cpu=,但它是累计值 ✅

JDK 17 的 jstack 每一行多了 cpu= 和 elapsed=(JDK 8 没有,上面 8 的输出里可以对照)。同一个 Busy 程序,隔 5 秒抓两次:

第一次:

"busy-worker" #13 prio=5 os_prio=0 cpu=14292.00ms elapsed=14.30s tid=0x00007f20b40e1db0 nid=0x9c9b runnable  [0x00007f209cbbc000]
"burst-then-idle" #14 prio=5 os_prio=0 cpu=7997.26ms elapsed=14.30s tid=0x00007f20b40e2ec0 nid=0x9c9c waiting on condition  [0x00007f209cabc000]
"socket-accept" #15 prio=5 os_prio=0 cpu=12.58ms elapsed=14.30s tid=0x00007f20b40e41c0 nid=0x9c9d runnable  [0x00007f209c9bb000]
"idle-sleeper" #16 prio=5 os_prio=0 cpu=0.10ms elapsed=14.29s tid=0x00007f20b40e53b0 nid=0x9c9e waiting on condition  [0x00007f209c8ba000]

第二次(5 秒后):

"busy-worker" #13 prio=5 os_prio=0 cpu=19375.82ms elapsed=19.38s tid=0x00007f20b40e1db0 nid=0x9c9b runnable  [0x00007f209cbbc000]
"burst-then-idle" #14 prio=5 os_prio=0 cpu=7997.26ms elapsed=19.38s tid=0x00007f20b40e2ec0 nid=0x9c9c waiting on condition  [0x00007f209cabc000]
"socket-accept" #15 prio=5 os_prio=0 cpu=12.58ms elapsed=19.38s tid=0x00007f20b40e41c0 nid=0x9c9d runnable  [0x00007f209c9bb000]
"idle-sleeper" #16 prio=5 os_prio=0 cpu=0.10ms elapsed=19.38s tid=0x00007f20b40e53b0 nid=0x9c9e waiting on condition  [0x00007f209c8ba000]

做差:

线程	两次 cpu= 之差	这 5.08 秒里的 CPU
busy-worker	19375.82 − 14292.00 = 5083.82ms	≈ 100%(一个核)
burst-then-idle	7997.26 − 7997.26 = 0	0
socket-accept	0	0
idle-sleeper	0	0

• 只看一次:burst-then-idle 的 7997ms 排第二 —— 和坑二一样的错,累计值会把早就闲下来的线程排到前面
• 做差之后:只有 busy-worker 在涨,一目了然;socket-accept 虽然是 RUNNABLE,但 cpu= 一动不动(坑四的答案)

这条路线不需要 top,也不需要换算 16 进制 —— 只要能跑 jstack/jcmd 就行。Windows 上的 JDK 17 同样有这个字段(我在 17.0.4.1 上看到了同样的 cpu=)。

---

8. 如果烧 CPU 的是 GC 线程 ✅

top -H 前排如果不是业务线程,而是 GC / VM 线程,问题在内存分配,不在某一行业务代码。构造一个:堆只给 64M,先占住约 80% 的已用内存,再不停分配短命的 32KB 数组:

import java.util.ArrayList;
import java.util.List;

public class GcStorm {
    static volatile Object sink;
    public static void main(String[] args) throws Exception {
        List<byte[]> live = new ArrayList<>();
        long max = Runtime.getRuntime().maxMemory();
        while (Runtime.getRuntime().totalMemory() - Runtime.getRuntime().freeMemory() < max * 0.8) {
            live.add(new byte[64 * 1024]);
        }
        System.out.println("retained " + live.size() + " x 64KB");
        while (true) {
            sink = new byte[32 * 1024];
        }
    }
}

java -Xmx64m GcStorm 跑 10 秒后,JDK 8 的 top -Hp 第二帧:

   PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
 47712 root      20   0 2470224  75116  11452 R 56.0  1.9   0:06.91 java
 47720 root      20   0 2470224  75116  11452 S 15.5  1.9   0:01.88 VM Thread
 47717 root      20   0 2470224  75116  11452 S 14.0  1.9   0:01.49 GC task th+
 47716 root      20   0 2470224  75116  11452 S 13.5  1.9   0:01.51 GC task th+
 47719 root      20   0 2470224  75116  11452 S 12.5  1.9   0:01.52 GC task th+
 47718 root      20   0 2470224  75116  11452 R 11.0  1.9   0:01.53 GC task th+

VM Thread 加 4 个 GC task thread 合计约 66%,比业务线程(56%)还多。拿 jstat -gcutil <pid> 1000 印证:

  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT   
  6.25   6.25  99.97   0.90  51.26  51.74  10604    3.775   154    0.172    3.947
  6.25   0.00   0.00   0.90  51.26  51.74  11404    4.096   154    0.172    4.268
  6.25   0.00   0.00   0.90  51.26  51.74  12339    4.385   154    0.172    4.557

YGC(Young GC 次数)每秒涨 800~935 次。这时去 jstack 里找「烧 CPU 的业务代码」是找错了方向 —— 该查的是谁在疯狂分配对象(第四、五篇)。

同一个程序在 JDK 17(G1)上,GC 线程在 top 里没那么显眼:

   PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
 48075 root      20   0 3019040  91412  12868 R 83.5  2.4   0:10.44 java
 48081 root      20   0 3019040  91412  12868 S  5.5  2.4   0:00.59 VM Thread
 48076 root      20   0 3019040  91412  12868 S  3.0  2.4   0:00.35 GC Thread#0
 48093 root      20   0 3019040  91412  12868 R  3.0  2.4   0:00.40 GC Thread#1

  S0     S1     E      O      M     CCS    YGC     YGCT     FGC    FGCT     CGC    CGCT       GCT   
  0.00   3.13  51.28   8.27  27.57   2.59   4932     1.327     0     0.000    90     0.012     1.339
  0.00   3.13  28.21   8.27  27.57   2.59   5330     1.424     0     0.000    90     0.012     1.437
  0.00   3.13  94.79   8.27  27.57   2.59   5749     1.494     0     0.000    90     0.012     1.506

Young GC 每秒仍有约 400 次,但 GC 线程在 top 里只有 3%~5.5% —— 在 17 上光看 top 容易漏掉 GC 这个因素,jstat 要一起看。 两版本的 GC 线程名也不同:8 是 GC task thread#N (ParallelGC),17 是 GC Thread#N、G1 Conc#N、G1 Refine#N 等。

顺带一个坑:main 线程在 top 里叫 java

上面两段 top 里排第一、名字叫 java 的线程是谁?换算线程号去 jstack 里对:

JDK 8(47712 = 0xba60):

"main" #1 prio=5 os_prio=0 tid=0x00007fa074009800 nid=0xba60 waiting on condition [0x00007fa07bef5000]
   java.lang.Thread.State: RUNNABLE
	at GcStorm.main(GcStorm.java:15)

JDK 17(48075 = 0xbbcb):

"main" #1 prio=5 os_prio=0 cpu=12544.21ms elapsed=14.53s tid=0x00007f25cc023b00 nid=0xbbcb waiting on condition  [0x00007f25d37ef000]
   java.lang.Thread.State: RUNNABLE
	at GcStorm.main(GcStorm.java:15)

是 main 线程。 两个版本都一样:别的 Java 线程在 top 里显示自己的名字,main 线程显示成 java。看到一个叫 java 的线程在烧 CPU,别当成 JVM 内部线程跳过去。

9. 本篇速查

步骤	命令	注意
找最忙的线程(此刻)	top -Hp <pid>	看第二帧;COMMAND 列的线程名最多 15 个字符,别靠它认线程
线程号转 16 进制	printf '%x\n' <tid>
对到线程栈	jstack <pid> | grep -A3 "nid=0x<hex> "	十六进制后带空格防误命中
用 ps 排序	ps -Lp <pid> -o tid,pcpu,comm --no-headers | sort -k2 -nr	procps-ng 3.3.10 上 --sort=-pcpu 没生效;而且 %CPU 是一辈子的平均值
JDK 17 不用 top	隔几秒 jstack 两次,对 cpu= 做差	单次读数是累计值
判断是不是 GC	看最忙线程是不是 GC / VM 线程,同时跑 jstat -gcutil <pid> 1000	17 上 GC 线程在 top 里不显眼;名叫 java 的线程是 main

下一篇

(三)线程卡住:死锁、BLOCKED、线程池打满 —— CPU 不高但请求不返回时,线程栈里各是什么样子,两版本实跑。