《Netty 高性能网络编程》13.3 线程栈、JFR 与连接诊断

本节目标：按「连接 → 线程 → 内存 → JFR」的固定顺序排查 linkd-v2 的卡顿与堆积，能读懂 netstat 的队列字段、EventLoop 的阻塞栈，并知道 JFR 在什么情况下什么也录不到。
适用版本：JDK 25 + Netty 4.2.19.Final；macOS 命令为本机实测，Linux 只写部署侧差异。

承接的问题

13.1 回答「谁没 release」，13.2 回答「池子里囤了多少」。这两节都是账本，前提是你已经知道该看内存。真实的告警往往只有一句「9090 的接口变慢」或者「连接数飙升」，既没有栈也没有指标。

顺序很重要。先看内存会得到一个「堆很正常」的结论，然后卡住；先 dump 堆会 STW 几秒，把现场搅乱。linkd-v2 的排查单固定为四步，每一步都有明确的判据和停止条件：

macOS 的连接统计按本节给出的 netstat 与 lsof 用法，不要照搬 Linux 的命令。下面所有输出都是本机跑出来的，标注为「本机输出」；linkd-v2 现网上的进程名、端口和 PID 会不同，按同样的字段读。

第一步：连接层，先看队列再看状态

lsof 回答「谁在监听、还有哪些已建立的连接」：

lsof -nP -iTCP:19095

本机输出（临时起了一个只监听不回数据的进程，端口用 19095；把端口换成 9090 就是 linkd-v2 的用法）：

COMMAND   PID         USER   FD   TYPE             DEVICE SIZE/OFF NODE NAME
Python  93079 bingrong.yan    3u  IPv4 0x6a6b05126d230996      0t0  TCP 127.0.0.1:19095 (LISTEN)
Python  93079 bingrong.yan    4u  IPv4 0x44d5fe76c1b8fb17      0t0  TCP 127.0.0.1:19095->127.0.0.1:62402 (ESTABLISHED)

两行分别是监听 fd 和一条已建立连接。lsof 的价值在「进程与 fd 的对应」：确认 9090 到底被哪个进程持有，是不是有残留的旧实例；同名服务起了两份时，lsof 会给出两个 PID，而客户端只会连到其中一个。它不告诉你队列有多深，也不告诉你应用有没有在读，这两件事要看 netstat。

netstat 的关键字段是 Recv-Q 与 Send-Q。本机输出（同一个进程，客户端灌了约 3 MB 数据，服务端始终不读）：

tcp4  2384788      0  127.0.0.1.19095   127.0.0.1.62402   ESTABLISHED   4778728        0
tcp4        0 701100  127.0.0.1.62402   127.0.0.1.19095   FIN_WAIT_1          0  3085888
tcp4        0      0  127.0.0.1.19095         *.*         LISTEN              0        0

（保留前六列与收发字节两列，进程列与 options 列略去。）

判读分三列：

• 服务端那条 ESTABLISHED 的 Recv-Q=2384788：约 2.3 MB 数据已经到达内核接收缓冲区，应用一次都没读。Netty 侧对应的是 AUTO_READ 被关掉、handler 卡住、或者事件循环根本没轮到这条连接。
• 客户端那条 FIN_WAIT_1 的 Send-Q=701100：对端窗口被塞满，发送缓冲区还压着 700 KB 发不出去。这是「服务端不读」在客户端一侧的镜像，不是客户端网络差。
• LISTEN 行的 Recv-Q/Send-Q 在 macOS 上显示为 0，不能用来读 accept 队列深度；判断 accept 是否堵住要看「已建立但应用没 accept」的连接数，以及线程栈里有没有 accept 调用。

连接堆积的另一种形态是 accept 队列满。本机用 listen(5) 且不 accept 的进程复现，30 次连接只有 5 次成功，其余在 1 秒超时：

connected 5 failed 25

此时 netstat 里能看到 5 条服务端侧连接，客户端关闭后停在 CLOSE_WAIT：

tcp4  0  0  127.0.0.1.19100  127.0.0.1.51624  CLOSE_WAIT    Python:97830
tcp4  0  0  127.0.0.1.51624  127.0.0.1.19100  FIN_WAIT_2    :97833
（另外 4 对同形态的连接省略）
tcp4  0  0  127.0.0.1.19100        *.*        LISTEN        Python:97830

CLOSE_WAIT 堆在服务端，说明内核已经完成握手、对端也关了，但应用没有调用 close()。Netty 里对应两种情况：ServerBootstrap 的 childHandler 抛异常导致 channel 没有正常关闭，或者 accept 出来的连接没有被注册进 ConnectionRegistry，失去了统一关闭的入口。看到大量 CLOSE_WAIT 先查 exceptionCaught 有没有只记日志不 close()。

第二步：线程层，找被占住的 EventLoop

jcmd <pid> Thread.print 与 jstack <pid> 输出等价，前者不用记 jstack 的路径；-l 会额外打印 java.util.concurrent 的锁信息。本机对一个复现程序执行（线程名与 linkd-v2 的 EventLoop 一致，栈里的类名是复现用的）：

jcmd 91593 Thread.print -l

本机输出（节选）：

"nioEventLoopGroup-2-1" #25 [26883] prio=5 os_prio=31 cpu=0.13ms elapsed=2.82s tid=0x0000000a750e7800 nid=26883 waiting on condition  [0x0000000171d1e000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleepNanos0(java.base@25.0.5/Native Method)
	at java.lang.Thread.sleepNanos(java.base@25.0.5/Thread.java:509)
	at java.lang.Thread.sleep(java.base@25.0.5/Thread.java:540)
	at BlockedLoop.blockingLookup(BlockedLoop.java:28)
	at BlockedLoop.channelRead(BlockedLoop.java:22)
	- locked <0x000000035fc17fb8> (a java.lang.Object)
	at BlockedLoop.eventLoopOne(BlockedLoop.java:13)
	at java.lang.Thread.runWith(java.base@25.0.5/Thread.java:1487)

这段栈说明三件事：

• 线程名是 nioEventLoopGroup-2-1，说明它属于 worker 组。一个 Channel 终身绑定一个 EventLoop，这条线程被占住，挂在它上面的所有连接一起停摆。
• 状态是 TIMED_WAITING (sleeping)，栈里有 Thread.sleep，而且是从 channelRead 一路调用下来的。业务代码在 EventLoop 线程里做了阻塞调用，这是 Netty 里最典型的错误，虚拟线程或线程池都不能自动救它。
• - locked <0x...> 表示这个线程还持有一把对象锁。如果它睡在锁里，别的 EventLoop 也会跟着卡。

第二条栈是同一把锁造成的排队：

"nioEventLoopGroup-2-2" #26 [43267] prio=5 os_prio=31 cpu=0.09ms elapsed=2.82s tid=0x0000000a758d4000 nid=43267 waiting for monitor entry  [0x0000000171f2a000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at BlockedLoop.channelRead(BlockedLoop.java:22)
	- waiting to lock <0x000000035fc17fb8> (a java.lang.Object)

BLOCKED (on object monitor) 且有 waiting to lock，与上一条的 locked 是同一个地址，锁竞争关系一目了然。判读 EventLoop 栈时按这个顺序看：

1. 数一数 worker 组里有多少线程处于 RUNNABLE 之外的业务栈。全部 EventLoop 都不在 selector 上等待，说明整个 worker 组被占满。
2. 看栈顶是不是 Thread.sleep、阻塞式 socket 读、JDBC、加解密的 native 调用。这些都不该出现在 EventLoop 线程上。
3. 看锁地址有没有成对出现，一把锁串起多个 EventLoop，问题会从一条连接扩散到整个组。
4. 如果栈里只有 NioEventLoop.run → Selector.select，说明线程在等 IO，问题不在这里，回到第一步看连接。

jstack 的输出头两行是时间和 VM 版本，本机验证 JDK 25 仍然可用：

2026-10-28 19:36:10
Full thread dump OpenJDK 64-Bit Server VM (25.0.5+8-LTS mixed mode, sharing)

线上执行时把输出重定向到文件，不要只截几行贴到聊天窗口；EventLoop 的栈要整组看，单条容易误判。

第三步：内存层，先分堆内堆外

GC.heap_info 给的是堆的视角：

jcmd 94266 GC.heap_info

本机输出（-Xms256m -Xmx256m）：

94266:
garbage-first heap   total reserved 262144K, committed 262144K, used 85118K [0x00000007f0000000, 0x0000000800000000)
 region size 1024K, 2 young (2048K), 0 survivors (0K)

读法：committed 262144K 是已经向系统要到的堆，used 85118K 是其中活着的部分，region size 1024K 是 G1 的 region 大小。used 远低于 committed，说明堆不紧张，GC 也不是瓶颈。

这一步最常见的误判是「堆很健康，所以不是内存问题」。13.2 已经证明 Netty 的池化直接内存在 JVM 账本里几乎不可见：64 MiB 的分配只让 BufferPoolMXBean 的 direct 池多出 1 个字节。所以堆内看完必须补一眼 metric() 的 usedDirectMemory，否则会漏掉整个直接内存。

两个视角的对应关系：

第四步：JFR，先确认它真的在录

JFR 适合回答「过去一分钟里，时间花在哪些阻塞上」。启动一次限时录制：

jcmd <pid> JFR.start name=diag settings=profile duration=60s filename=/tmp/diag.jfr

录制结束后用 jfr summary 看事件计数。这里有个必须先知道的坑：在本机 JDK 25 的 default 与 profile 配置里，jdk.SocketRead 都没有打开。本机对一段持续做 socket 读的程序录制 5 秒，summary 里该事件为 0：

 jdk.SocketRead                              0             0
 jdk.SocketWrite                             0             0

要拿到它，先用 jfr configure 生成一份打开该事件的配置：

jfr configure --input profile --output /tmp/sock.jfc \
  "jdk.SocketRead#enabled=true" "jdk.SocketRead#threshold=0 ms"

本机输出：

Configuration written successfully to:
/tmp/sock.jfc

再用 settings=/tmp/sock.jfc 启动录制，就能看到单次读的耗时与栈：

jdk.SocketRead {
  startTime = 19:34:54.445 (2026-10-28)
  duration = 203 ms
  host = "127.0.0.1"
  address = "127.0.0.1"
  port = 19099
  timeout = 0 s
  bytesRead = 1 byte
  endOfStream = false
  eventThread = "main" (javaThreadId = 3)
  stackTrace = [
    SocketReadDemo2.main(String[]) line: 10
  ]
}

duration=203 ms 加 eventThread=main 就能定位「谁在读、读了多久」。放到 linkd-v2 上，把 eventThread 换成 nioEventLoopGroup-* 就是一条 EventLoop 被 IO 拖住的直接证据。

JFR 的边界比它的功能更值得记住：事件在阻塞结束时才写出。本机对一个 Thread.sleep(600_000) 的线程录 7 秒，jfr print --events jdk.ThreadSleep 输出为空；同类阻塞要等线程醒来才有记录。所以「现在卡住了」要用线程栈，「过去卡过多少次」才用 JFR。两者不能互相替代。

在 linkd-v2 里落地

第一步到第四步在一个脚本里固定下来，输出按时间戳归档，避免现场被后续操作覆盖：

#!/usr/bin/env bash
set -euo pipefail
pid="${1:?usage: diag.sh <pid> [port]}"
port="${2:-9090}"
out="diag-$(date +%Y%m%d-%H%M%S)"
mkdir -p "$out"
lsof -nP -iTCP:"$port" > "$out/lsof.txt" 2>&1 || true
netstat -anv -p tcp > "$out/netstat.txt" 2>&1 || true
jcmd "$pid" Thread.print -l > "$out/threads.txt" 2>&1
jcmd "$pid" GC.heap_info > "$out/heap.txt" 2>&1
jcmd "$pid" JFR.start name=diag settings=profile duration=60s \
  filename="$out/diag.jfr" > "$out/jfr-start.txt" 2>&1
echo "collected into $out"

脚本只采集，不做判断；判断靠上面四步的判据。JFR.start 是异步的，60 秒后录制自动落盘到 $out/diag.jfr，脚本不用等。netstat 的输出在 macOS 上很长，归档后再按端口过滤。

第二步的「EventLoop 被占用」还可以在代码里留一个低成本探针。SlowHandlerWatch 放在业务 handler 之前，只统计同步段耗时：

package com.plume.linkd.v2.server;

import io.netty.channel.ChannelHandler;
import io.netty.channel.ChannelHandlerContext;
import io.netty.channel.ChannelInboundHandlerAdapter;

@ChannelHandler.Sharable
public final class SlowHandlerWatch extends ChannelInboundHandlerAdapter {

    private static final System.Logger LOG =
            System.getLogger(SlowHandlerWatch.class.getName());
    private static final long WARN_NANOS = 20_000_000L;

    @Override
    public void channelRead(ChannelHandlerContext ctx, Object msg) {
        long start = System.nanoTime();
        try {
            ctx.fireChannelRead(msg);
        } finally {
            long cost = System.nanoTime() - start;
            if (cost > WARN_NANOS) {
                LOG.log(System.Logger.Level.WARNING,
                        "slow channelRead cost={0}ms thread={1} channel={2}",
                        cost / 1_000_000, Thread.currentThread().getName(),
                        ctx.channel().id().asShortText());
            }
        }
    }
}

ctx.fireChannelRead(msg) 把消息交给下一个入站 handler，所有权随之下移，这里不 release，否则下游会拿到失效缓冲区。20 ms 是起点，要按压测的正常分位调整；日志只在该阈值以上才写，避免正常请求把磁盘打满。

它有一个明确的盲区：只能测同步段。下游 handler 如果切到别的线程异步处理，这里量到的只是「投递耗时」，真正的慢发生在别处。看到 slow channelRead 里的线程名是 nioEventLoopGroup-* 才是 EventLoop 被占；如果线程名是业务线程池，问题不在 EventLoop。

常见错误与边界

错误一：一上来就 dump 堆。 堆 dump 会 STW 并写出与堆等大的文件，几 GB 的堆能把一次 30 秒的抖动放大成几分钟。顺序是连接、线程、内存、JFR，堆 dump 放在有明确堆内证据之后。

错误二：在 EventLoop 线程里执行诊断命令。 在 handler 里调 jcmd、读 /proc、做 lsof，等于自己制造一次阻塞。诊断命令从运维终端执行，代码里只留 SlowHandlerWatch 这种纳秒级计时。

错误三：把 TIMED_WAITING 当死锁。 线程池空闲、Selector.select 等待、定时任务等待都会是 TIMED_WAITING。死锁的判据是 BLOCKED 加锁地址互相等待，或者 jstack 末尾的 Found one Java-level deadlock。单看状态会误报。

错误四：JFR 录了 5 秒就下结论。 周期性任务、连接建立抖动、长尾请求都可能在 5 秒窗口外。抓「已经发生」的问题，窗口至少覆盖一个完整业务周期，linkd-v2 的巡检默认 60 秒。

错误五：以为 Recv-Q 大就是网络问题。 本机输出里 Recv-Q=2384788 是应用不读，不是链路丢包。链路问题看重传与 Send-Q 的增长，应用问题看 Recv-Q 是否只涨不降。

边界一：macOS 与 Linux 的命令不等价。 macOS 用 netstat -anv -p tcp、lsof -nP -iTCP:9090、vmmap <pid>；Linux 侧对应 netstat -anp、lsof、/proc/<pid>/smaps。不要把 macOS 的输出格式当成 Linux 的字段位置，两者列顺序不同。

边界二：采样线程栈会漏掉短阻塞。 手工 dump 是单点快照，几十毫秒的阻塞大概率抓不到。这类问题靠 SlowHandlerWatch 的阈值日志或 JFR 的聚合事件，不靠反复 dump。

小结

• 排查顺序固定为连接、线程、内存、JFR；顺序错了会把现场搅乱，还会得到「一切正常」的错误结论。
• lsof 确认端口归属与连接清单，netstat 的 Recv-Q 看应用有没有读、Send-Q 看数据压没压住；macOS 的 LISTEN 行不显示 accept 队列深度。
• jcmd Thread.print 与 jstack 等价；EventLoop 栈里出现 Thread.sleep、同步 IO、BLOCKED 等待锁，就是线程被占的直接证据。
• GC.heap_info 只覆盖堆，直接内存要看 13.2 的 metric()；堆健康不代表内存没问题。
• 本机 JDK 25 的 JFR 配置不记录 jdk.SocketRead，要用 jfr configure 显式打开；而且事件在阻塞结束时才写出，抓不到「此刻正卡住」。
• linkd-v2 用 diag.sh 固定采集、用 SlowHandlerWatch 留下同步段耗时，两者都不改业务语义。

到这里，泄漏、内存、连接与线程四条线都有了可执行的检查手段。下一章把这些手段变成参数基线：水位、缓冲区、线程数各自定在什么位置，以及怎么用压测验证。

阅读导航：上一节：13.2 堆外内存与 PoolArena 指标 · 下一节：14.1 参数基线：水位、缓冲区、线程数 。