事件驱动代码的调试艺术：当回调成为迷宫

事件驱动程序最难调的地方，从来不是某一个 API，而是因果链被拆散了。一次请求可能先在用户态进入 reactor/proactor 主循环，再在内核里排队，然后由 worker、软中断、超时器、回调或 CQE 一步步推进。epoll 把“什么时候可读”与“真正读数据”分成两段，io_uring 又把“提交”和“完成”拆到共享 ring 与完成队列中。代码越追求吞吐和低延迟，现场越容易碎，线上事故就越难靠单步调试解决。

这篇文章是一份线上排障手册：先看症状与收敛范围，再看应用日志与 trace，然后下探到 syscall、tracepoint、eBPF、profiling，最后才到 sanitizer、重放与离线复盘。排障顺序应该一层层缩小问题空间，而不是一开始就 attach GDB 或猜内核 bug。

TL;DR — 30 秒速查

先收敛症状和影响范围（日志 + metrics）

用 req_id / trace_id 在应用日志或 OTel span 里定位卡在哪个阶段

strace -tt -T / perf trace 验证 syscall 边界；io_uring 要用 bpftrace tracepoint

perf record -g + 火焰图看 CPU 热点与 off-CPU 瓶颈

ASan / TSan / rr 在测试环境钉死内存与竞态 bug

没有 req_id？先走 strace + FD 关联（见 Section 10 降级路径）。

0. 线上先怎么查

线上事故先做的是收敛，不是证明自己懂多少工具。对事件驱动程序，建议按下面的顺序推进。

先收敛症状和范围。确认是延迟飙升、超时、错误码异常、吞吐下降、CPU 飙高、FD 泄漏，还是单个 worker 卡死。确认影响范围是全部实例、单个 pod、某个机房、某类请求，还是只发生在 io_uring / epoll 某条路径上。
再看应用日志和 trace。优先找 req_id、trace_id、fd、op、state、错误码分布，以及队列深度、超时比例、重试次数这些结构化字段。没有统一请求身份时，后面的系统层观测几乎都会变成猜谜。
然后看 syscall 与 tracepoint。对 epoll 先用 strace / perf trace 验证系统调用边界；对 io_uring 则尽快切到 tracepoint、bpftrace、BCC 或内核事件，因为 strace 只能看到 io_uring_enter 这种入口，无法解释具体请求语义。
再看 profiler 与内核侧热点。确认延迟到底耗在用户态状态机、锁竞争、软中断、调度延迟、系统调用、内核 worker，还是日志和对象管理本身。这里适合 perf、continuous profiling、off-CPU 分析。
最后才做高侵入性的动作。Sanitizer、rr、最小复现、回放、canary、影子流量、压测环境复盘，应该放在已经有较强假设之后，不要把线上实例本身当实验场。

一句话概括这条顺序：先回答“哪里坏了”，再回答“哪一层坏了”，最后才回答“具体哪一行代码写坏了”。

0.1 一开始不要做什么

下面几件事在线上都很常见，但通常不是第一步。

不要一上来就 attach GDB 到高流量生产实例。它可能冻结线程、放大锁竞争、改变时序，甚至让原本偶发的问题彻底消失。
不要先猜内核 bug。绝大多数 io_uring / epoll 事故最后都能归到请求状态机、资源所有权、取消竞争、超时策略、缓冲区生命周期或观测缺失，而不是“内核随机坏了”。
不要先看最后一个崩溃点。事件驱动 bug 经常是几十毫秒前的一次状态迁移或一次错误回收导致的，最终崩溃栈只是在替根因背锅。
不要一次把所有工具全开。高噪声日志、全量 syscall trace、全量 eBPF 探针、采样 profiler 同时打开，只会把现场弄脏。
不要只盯 FD 或指针值。FD 会复用，指针会被对象池重复使用；没有稳定 req_id 时，跨层排障很难闭环。

0.2 值班时的最小动作列表

如果你在值班，先完成下面这份最小检查清单。

记录事故开始时间、影响实例、影响比例、最明显的错误码与现象。
抓一份最近 5 到 15 分钟的结构化日志样本，按 req_id 或接口名聚类。
看 trace 或请求生命周期日志，确认是卡在 submit、等待完成、超时、取消、回收，还是卡在某个锁或队列水位。
看机器或 pod 级 CPU、负载、context switch、run queue、网络丢包、FD 数和内存曲线。
再决定是进入 syscall / tracepoint 路径，还是进入 profiler / replay / sanitizer 路径。

这张图的意思很简单：排障应该从低风险、低侵入、强收敛的观测开始，逐层下钻，而不是反过来。

1. 事件驱动 bug 的五类典型模式

Section 0 讲了排障顺序，这里聚焦代码层面：哪些写法最容易在 epoll / io_uring 程序里制造难以排查的 bug。

控制流分裂。主循环、回调、定时器、异步完成、重试分支散落在多个函数里，调用栈只能看到当前切片。
时间敏感。bug 只在特定 interleaving 下出现，例如“删除事件后还有 ready 未消费”或“cancel 发出时原请求刚好完成”。
观测点错位。strace 看到的是 syscall 边界，应用日志看到的是用户态状态机，内核 tracepoint 看到的是执行事件，三者天然不在同一平面上。
数据所有权复杂。对象池、固定缓冲区、引用计数、intrusive list、共享 ring 都会让生命周期变得脆弱；错误经常不在当场崩溃，而是稍后在无关路径上崩。
性能与正确性交织。错误的唤醒策略、批处理阈值、锁竞争、过量日志或错误的 backpressure，既可能表现为性能问题，也可能伪装成超时或丢事件。

下面这个极简版 epoll 代码至少埋了两个陷阱——你能一眼看出来吗？

struct conn {
    int fd;
    int closed;
    char buf[4096];
    size_t used;
};

static void handle_read(struct conn *c) {
    ssize_t n = read(c->fd, c->buf + c->used, sizeof(c->buf) - c->used);
    if (n == 0) {
        close(c->fd);
        free(c);          /* ← 陷阱：释放后 loop_once 的后续迭代仍可能访问 c */
        return;
    }
    if (n < 0) {
        if (errno == EAGAIN || errno == EWOULDBLOCK) {
            return;
        }
        close(c->fd);
        free(c);
        return;
    }
    c->used += (size_t)n;
}

static void loop_once(int epfd) {
    struct epoll_event evs[128];
    int n = epoll_wait(epfd, evs, 128, 1000);
    for (int i = 0; i < n; ++i) {
        struct conn *c = evs[i].data.ptr;
        handle_read(c);   /* ← 陷阱：c 可能在上一次迭代中已被 free */
    }
}

陷阱 1：handle_read 里 close(fd) + free(c) 之后，loop_once 的 for 循环仍然可能在后续迭代中拿到同一个 c（如果 epoll_wait 在同一批返回了该 FD 的多个事件）。陷阱 2：关闭连接前没有 EPOLL_CTL_DEL，如果另一路写回调也持有 c，evs[i].data.ptr 将变成悬空指针。

这两个陷阱代表了事件驱动 bug 的共同特征：最终崩溃栈在替根因背锅，真正的问题藏在更早的一次状态迁移或资源回收里。排障的第一步永远是还原“请求从创建到回收的最小时间线”。

2. GDB 高级调试技巧

很多人说 GDB 不适合事件驱动程序，这只说对了一半。普通单步确实会把人困死在回调迷宫里，但 GDB 仍然擅长回答几个关键问题：对象是谁分配的、谁最后一次写了它、哪个线程提交了请求、哪个线程回收了上下文、异常状态第一次出现在哪里。

先用保留栈结构的编译参数。

cc -Og -g3 -fno-omit-frame-pointer -Wall -Wextra -o server server.c
ulimit -c unlimited
gdb ./server core

线上如果已经有 core，先看 core，别急着 live attach。

2.1 用条件断点抓第一个非法状态

事件驱动程序里最有价值的断点通常不是“进入函数就停”，而是“状态刚要非法时才停”。

break handle_read if c == 0 || c->closed != 0
commands
  printf "bad conn=%p fd=%d closed=%d\n", c, c ? c->fd : -1, c ? c->closed : -1
  bt
  continue
end

对 io_uring，更常见的是对 CQE 错误码、状态转换或某个 req_id 下断点。

break process_cqe if cqe->res < 0
break transition if req->id == 18192

2.2 watchpoint 抓谁写坏了状态

如果你怀疑对象被提前回收、被错误复用，或者状态字段被意外覆盖，硬件 watchpoint 往往比大量日志更快。

watch -location req->state
watch -location req->refcnt
watch -location req->magic

这招对排查“对象池复用过早”“user_data 被二次写入”“引用计数突然归零”特别有效。代价是慢，所以更适合在复现环境、core 复盘或 rr 回放里使用。

2.3 跟线程、跟事件，而不是跟函数

在复杂 reactor/proactor 中，重点不是函数调用链有多深，而是谁提交、谁完成、谁回收。GDB 里应该围绕线程和请求来观察。

info threads
thread apply all bt
set print thread-events off

如果程序已经有请求 ID，可以直接在断点动作里打印：

break submit_req
commands
  printf "submit tid=%ld req_id=%lu fd=%d state=%d\n",
         (long)pthread_self(), req->id, req->fd, req->state
  continue
end

2.4 用 rr 重放真正的竞态现场

rr 对“能复现但复现率不高”的用户态问题非常有效。它把一次真实执行录下来，之后可以反向执行、查最后一次写入、回退到关键分支之前重看现场。

rr record ./server --config debug.toml
rr replay

下面是一个完整的排查 session，演示如何从“发现 req->magic 损坏”反向追踪到写坏它的代码：

(rr) run
# 程序崩溃在 process_cqe()，req->magic == 0xdeadbeef
(rr) print req->magic
$1 = 0xdeadbeef

# 设置硬件 watchpoint，监控 magic 字段
(rr) watch -location req->magic
Hardware watchpoint 1: -location req->magic

# 反向执行，直到 magic 上一次被写入
(rr) reverse-continue
Hardware watchpoint 1: -location req->magic
Old value = 0xdeadbeef
New value = 0x12345678     # ← magic 原本的合法值
0x00401a3c in free_request (req=0x...) at server.c:142

# 这一帧就是破坏现场的代码
(rr) bt
#0  free_request (req=0x...) at server.c:142
#1  on_timeout (req=0x...) at server.c:87
#2  timer_callback (...) at server.c:210

# 查看当时的事件编号，可以和其他线程时间线交叉对比
(rr) when
Current event: 18724
(rr) print req->state
$2 = ST_CANCELLING

这段 session 说明了三件事：rr 不需要提前猜哪里出错；reverse-continue 配合 watchpoint 直接带你到最后一次修改目标内存的位置；when 给出的事件编号可以跨线程交叉对比。对 use-after-free、竞态顺序漂移、非法状态迁移，这几乎是最直接的定位手段。

3. 系统调用追踪：strace 的能与不能

strace 的价值，在于把“程序以为自己做了什么”和“内核实际看到了什么”对齐。对 epoll 程序，它非常适合回答这几个问题：FD 是否设成了非阻塞、是否漏了 EPOLL_CTL_MOD、是不是在错误的时机阻塞在 read、超时参数是不是写错了。

例如追踪一个 epoll 服务器：

strace -ff -tt -T -y -yy -s 128 ./epoll_server 2>&1 | tee /tmp/epoll.trace

几个参数很实用。

-ff 按线程或进程拆分输出。
-tt 打印高精度时间戳，便于和应用日志、trace 对表。
-T 显示 syscall 耗时。
-y -yy 显示 FD 指向的文件或 socket 信息。
-s 128 尽量避免字符串参数被截断。

如果只关心事件相关系统调用，可以先收窄范围：

strace -ff -tt -e trace=epoll_ctl,epoll_wait,read,write,close ./epoll_server

3.1 io_uring 下要理解 strace 的边界

io_uring 调试时，strace 仍然有价值，但它更像入口检查器，而不是完整语义解释器。你能看到 io_uring_setup、io_uring_enter、io_uring_register、mmap，但看不到每个 SQE 的业务含义，因为请求已经写进共享 ring 里了。

strace -ff -tt -e trace=io_uring_setup,io_uring_enter,io_uring_register,mmap ./uring_server

你可能只会看到：

io_uring_enter(3, 8, 1, IORING_ENTER_GETEVENTS, NULL, 0) = 1

这并不能告诉你这 8 个 SQE 分别是什么操作。所以对 io_uring，strace 主要用于回答：setup 是否成功、register 是否失败、enter 是否过于频繁、是否被 EINTR 打断、是否存在异常重试。真正的语义分析要交给 tracepoint 与应用层请求日志。

3.2 perf trace 可以作为更轻的一层

当你需要比 strace 更轻量的 syscall 级摘要，perf trace 很适合第一轮线上筛查。

sudo perf trace -e io_uring:*,syscalls:sys_enter_epoll_wait,syscalls:sys_exit_epoll_wait ./server

它不一定能替代 strace，但在“我要先看大体时间线，不想让探针太重”的阶段很有价值。

4. eBPF/bpftrace：事件驱动代码的线上主战场

如果只能保留一类动态观测工具给事件驱动程序，我会选 eBPF。原因很简单：它能把你带到 syscall 之下、内核执行之中，而且通常足够低开销，适合在线上或准线上验证假设。对 io_uring 尤其如此，因为内核已经暴露了丰富的 tracepoint；对 epoll，你也可以从网络栈、调度、软中断、wake-up、锁等待这些侧面观察它的真实形态。

先列出可用的 io_uring tracepoint：

sudo bpftrace -l 'tracepoint:io_uring:*'

4.1 用 bpftrace 统计 opcode、错误码和延迟

先看提交的 opcode 分布，确认服务到底在忙什么：

sudo bpftrace -e '
tracepoint:io_uring:io_uring_submit_sqe
{
  @[args->opcode] = count();
}
'

输出的 opcode 是数字，对照内核头文件查名称：grep IORING_OP_ /usr/include/linux/io_uring.h。常用值：0=NOP, 1=READV, 2=WRITEV, 11=TIMEOUT, 13=ACCEPT, 14=ASYNC_CANCEL, 22=READ, 23=WRITE, 26=SEND, 27=RECV。

如果怀疑大量请求在失败或取消，可以统计返回值：

sudo bpftrace -e '
tracepoint:io_uring:io_uring_complete
{
  @[args->res] = count();
}
'

更进一步，可以按 user_data 记录从提交到完成的粗粒度延迟：

sudo bpftrace -e '
tracepoint:io_uring:io_uring_submit_sqe
{
  @start[args->user_data] = nsecs;
}

tracepoint:io_uring:io_uring_complete
/@start[args->user_data]/
{
  @lat_us = hist((nsecs - @start[args->user_data]) / 1000);
  delete(@start[args->user_data]);
}
'

如果你在调 epoll，也可以从调度和网络栈侧面看“为什么应用层老说超时”：

sudo bpftrace -e 'tracepoint:sched:sched_wakeup { @[comm] = count(); }'
sudo bpftrace -e 'tracepoint:sched:sched_switch { @[kstack] = count(); }'

4.2 追踪取消竞争这类时间窗口 bug

事件驱动里最难抓的，往往是看似随机、实则高度时序化的问题。比如一个 io_uring 请求超时后应用发出 cancel，但原请求恰好在这时完成，于是你在用户态看到的是“cancel 失败”加“旧 CQE 仍然到达”的组合。如果回收路径写得草率，就会出现 FD 提前关闭、对象二次释放、状态机跳变等后果。

下面是一段故意写得过于乐观的示例：

enum req_state {
    REQ_SUBMITTED,
    REQ_CANCELLING,
    REQ_DONE,
};

struct request {
    uint64_t id;
    int fd;
    enum req_state state;
    int refcnt;
};

static void on_timeout(struct request *req) {
    req->state = REQ_CANCELLING;
    submit_cancel(req->id);
    close(req->fd);   /* 错误：这里假设 cancel 一定成功 */
    free(req);
}

这类 bug 最适合用 tracepoint 与应用日志双向夹击：应用层打印 req_id、fd、状态迁移，内核侧记录 submit、complete、cancel 的时间顺序。只要看到 complete 在 cancel 之后仍然到达，而用户态已经回收对象，根因就已经非常清楚了。这个竞争的完整状态跳转可参考 Section 9.5 的 cancel/complete 状态机图。

4.3 BCC 适合做现成的延迟与 off-CPU 分析

bpftrace 适合快速试探，复杂场景可以切到 BCC 的现成工具，例如：

sudo /usr/share/bcc/tools/runqlat
sudo /usr/share/bcc/tools/offcputime -f 5
sudo /usr/share/bcc/tools/tcptop

runqlat 适合确认线程是不是没拿到 CPU，offcputime 适合确认线程到底睡在锁、futex 还是 I/O 等待上，tcptop 适合看网络层是不是已经开始拥塞或重传。很多“事件没到”的表象，最后都不是 poller 本身的问题。

4.4 Kubernetes 场景下的现代在线工具

如果你的事件驱动服务跑在 Kubernetes 里，传统做法往往是先进容器、再抓日志、再猜网络或内核层发生了什么。现在有更高效的工具可以选择，前提是要和场景匹配。

Pixie 适合“应用没预埋足够观测，但我要快速看到请求、网络、SQL、错误分布”的场景。它基于 eBPF 自动采集，不要求你先把应用重编译成有 trace 的版本。对于还没接好 OTel、但需要先快速收敛线上范围的服务，Pixie 很适合作为第一轮聚焦工具。

Inspektor Gadget 更适合“我已经知道问题比较靠近内核或容器运行时，需要更细颗粒度地看 TCP drop、调度、文件系统、OOM、profile”的场景。它不是拿来替代应用日志的，而是拿来避免你在 kube node 上手工拼一堆 eBPF 命令。

这两类工具都不是为了堆名词，而是为了回答不同的问题：Pixie 更偏“快速看服务行为”，Inspektor Gadget 更偏“快速看节点和容器内核行为”。

5. perf 与 continuous profiling

很多事件驱动事故最初常表现为尾延迟抖动、CPU 飙升、吞吐下降、上下文切换异常或某条 worker 线程异常忙碌，而不是崩溃。perf 在这里既是性能工具，也是正确性线索收集器。你需要回答的问题是：CPU 时间花在用户态状态机、系统调用、锁竞争、软中断、调度还是日志与对象管理本身？

先做基本采样：

sudo perf record -F 199 -g -- ./uring_server
sudo perf report

如果怀疑调度、锁或上下文切换，配合 stat 和 sched 更直接：

sudo perf stat -e context-switches,cpu-migrations,page-faults,cycles,instructions ./uring_server
sudo perf sched record ./uring_server
sudo perf sched latency

5.1 火焰图比热点列表更能看出结构性错误

很多人看 perf report 时只盯第一名函数，但事件驱动程序更应该看调用形态。比如 CPU 大头如果落在 malloc、free、memcpy、哈希查找、日志格式化上，说明你以为在优化 I/O，实际却在对象管理上浪费时间。若热点集中在 io_uring_enter、ep_poll、schedule、futex_wait 或某把自旋锁，问题就更靠近同步与内核边界。

把采样结果转成火焰图通常更直观：

sudo perf script > /tmp/out.perf
git clone https://github.com/brendangregg/FlameGraph /tmp/FlameGraph
/tmp/FlameGraph/stackcollapse-perf.pl /tmp/out.perf | /tmp/FlameGraph/flamegraph.pl > /tmp/flame.svg

5.2 continuous profiling 适合看线上长期漂移

perf 更适合一次性深挖，continuous profiling 则适合看线上服务在小时级、天级的长期漂移。对事件驱动程序，特别值得看的是：

某个版本上线后，CPU 热点是否从业务逻辑漂移到日志、锁或 ring 管理。
某个接口的 off-CPU 时间是否持续升高，暗示锁等待、调度或 I/O 等待变严重。
某类请求在高峰期是否出现稳定的栈形态变化，说明问题并非偶发，而是结构性退化。

Grafana Pyroscope 适合已经在 Grafana 体系里，想把 profile 与 metrics、logs、traces 放在一起看的团队。它更像长期观测平台，而不是一次性定位工具。

Parca 更适合希望用持续采样方式观察生产服务 CPU/内存 profile 的场景，尤其适合服务规模较大、要跨版本看回归趋势的时候。它不能替代一次精确的 perf record，但能告诉你“问题从什么时候开始出现，是否只在某批机器上出现”。

6. 请求身份与状态机设计

工具只能放大事实，不能弥补结构缺陷。很多事件驱动系统难调的根本原因是业务状态、资源所有权、日志字段和观测点混在一起，没有形成可验证的结构。想让线上排障真的可操作，先把请求身份和状态机设计好。

6.1 每个请求必须有稳定身份

不要让日志里只有 FD、指针和“read callback enter”这种模糊描述。FD 会复用，指针会释放后重分配，回调名称更没有区分度。应该给每个请求、连接或操作一个单调递增的 ID，并在创建、提交、重试、取消、完成、回收这些节点统一打印。

struct request {
    uint64_t id;
    int fd;
    int op;
    int state;
};

static void req_log(const char *phase, const struct request *req, int res) {
    fprintf(stderr,
            "phase=%s req=%lu fd=%d op=%d state=%d res=%d\n",
            phase, req->id, req->fd, req->op, req->state, res);
}

对 io_uring，最好把 req->id 直接编码进 sqe->user_data。这样 GDB、日志、bpftrace、perf trace 和 OTel span 至少能围绕同一个请求聚合。

6.2 状态机要显式

很多“偶发 bug”本质上只是状态机没有写出来。与其让请求在多个回调里靠布尔变量和注释隐式跳转，不如明确列出状态，并在开发期对非法迁移直接中止。

enum state {
    ST_INIT,
    ST_SUBMITTED,
    ST_CANCELLING,
    ST_COMPLETING,
    ST_DONE,
    ST_RECLAIMED,
};

static void transition(struct request *req, enum state from, enum state to) {
    if (req->state != from) {
        fprintf(stderr, "invalid transition req=%lu %d->%d current=%d\n",
                req->id, from, to, req->state);
        abort();
    }
    req->state = to;
}

事件驱动 bug 越往后拖，现场越脏，所以开发期宁可因为非法迁移直接 abort()，也不要“先容错跑过去”。

7. OpenTelemetry 与观测实战

请求身份和状态机解决了“怎么写”的问题，线上排障还需要“怎么看”。OpenTelemetry 可以把请求在用户态状态机里的每一步串成 trace，和内核侧观测拼成完整时间线。

7.1 把应用层请求时间线补齐

对事件驱动服务，span 的重点是把请求身份和状态挂完整，而不只是追求调用链的形式。

C/C++ 项目接入 OpenTelemetry SDK 最小依赖如下（以 CMake + vcpkg 为例）：

# vcpkg 安装
vcpkg install opentelemetry-cpp

# CMakeLists.txt
find_package(opentelemetry-cpp CONFIG REQUIRED)
target_link_libraries(your_target PRIVATE
    opentelemetry-cpp::trace
    opentelemetry-cpp::ostream_span_exporter  # 调试用
    opentelemetry-cpp::otlp_grpc_exporter     # 接 Collector 用
)

如果没有 vcpkg，也可以从源码构建 opentelemetry-cpp。

下面给一个最小示例，展示如何为请求创建 span，并把 req_id、fd、op、state 挂到 attributes 上：

#include <stdint.h>
#include <string>
#include <opentelemetry/trace/provider.h>
#include <opentelemetry/trace/scope.h>

namespace trace = opentelemetry::trace;

enum req_state {
    ST_INIT,
    ST_SUBMITTED,
    ST_CANCELLING,
    ST_DONE,
};

struct request {
    uint64_t id;
    int fd;
    int op;
    req_state state;
    opentelemetry::nostd::shared_ptr<trace::Span> span;
};

static auto tracer =
    trace::Provider::GetTracerProvider()->GetTracer("uring-server", "1.0");

static const char *state_name(req_state state) {
    switch (state) {
    case ST_INIT: return "init";
    case ST_SUBMITTED: return "submitted";
    case ST_CANCELLING: return "cancelling";
    case ST_DONE: return "done";
    default: return "unknown";
    }
}

static void req_span_start(struct request *req) {
    req->span = tracer->StartSpan("event.request");
    req->span->SetAttribute("req.id", static_cast<int64_t>(req->id));
    req->span->SetAttribute("fd", req->fd);
    req->span->SetAttribute("op", req->op);
    req->span->SetAttribute("state", std::string(state_name(req->state)));
    req->span->AddEvent("req.created");
}

static void req_span_transition(struct request *req, req_state next, int result) {
    req->state = next;
    req->span->SetAttribute("state", std::string(state_name(req->state)));
    req->span->SetAttribute("last.result", result);
    req->span->AddEvent("req.transition", {
        {"req.id", static_cast<int64_t>(req->id)},
        {"fd", req->fd},
        {"op", req->op},
        {"state", std::string(state_name(req->state))}
    });
}

static void req_span_finish(struct request *req, int cqe_res) {
    req->span->SetAttribute("cqe.res", cqe_res);
    req->span->AddEvent("req.complete");
    req->span->End();
}

这段示例里最关键的不是 SDK 调用本身，而是四件事。

一开始就生成请求 span，不要等到出错了才补日志。
req_id、fd、op、state 这些字段要贯穿 span 生命周期，而不是只打在某个错误日志里。
状态迁移要用 AddEvent 记录，而不是只改内存里的枚举值。
完成时把 cqe.res、错误码、取消结果等收口到 span 上，方便与系统层时间线对表。

7.2 怎么把应用层 span 与内核层观测结合起来

只接 OTel 还不够。线上真正有价值的是把应用层 span 与内核层或系统层观测拼成一张图，而不是让 trace、日志、bpftrace 三套系统各说各话。

比较稳妥的做法是：

把 req_id 编进 sqe->user_data，让内核 tracepoint 能直接看到同一个请求身份。
在应用日志里同时打印 req_id、trace_id、span_id、fd、state。
在 bpftrace 或 BCC 输出里优先打印 user_data、pid、tid、时间戳。
在 profiler 或 continuous profiling 里按 worker 线程、队列、请求类别聚合，避免只有全局 CPU 视图。

例如下面这个脚本就能把 user_data 与内核完成事件对上：

sudo bpftrace -e '
tracepoint:io_uring:io_uring_complete
{
  printf("ts=%llu pid=%d tid=%d user_data=%llu res=%d\n",
         nsecs, pid, tid, args->user_data, args->res);
}
'

如果你的应用日志里已经把 req_id=18192 trace_id=... span_id=... 打出来，而 user_data 正好也是 18192，那么你就能把“应用层在什么时候进入 cancelling”和“内核在什么时候真正 complete”放在一条时间线上，而不是两边各猜一次。

7.3 最小 OTel Collector 运行方式

要让这套东西在线上或准线上跑起来，至少需要一个最小的 OTel Collector。下面给一个足够小的配置，接 OTLP，再把 traces 打到本地 debug exporter。

receivers:
  otlp:
    protocols:
      grpc:
      http:

processors:
  batch:

exporters:
  debug:
    verbosity: detailed

service:
  pipelines:
    traces:
      receivers: [otlp]
      processors: [batch]
      exporters: [debug]

本地或测试环境最小运行方式：

docker run --rm \
  -p 4317:4317 -p 4318:4318 \
  -v "$PWD/otelcol.yaml:/etc/otelcol-contrib/config.yaml" \
  otel/opentelemetry-collector-contrib:0.122.1

如果服务要通过 OTLP 导出，至少要把 endpoint 配好：

export OTEL_EXPORTER_OTLP_ENDPOINT=http://127.0.0.1:4317
export OTEL_SERVICE_NAME=uring-echo

调试阶段先把 traces 导到本地 debug exporter 或 Jaeger/Tempo 即可；重点不是平台多豪华，而是让请求时间线真正落地。

7.4 为调试保留低成本开关

建议至少保留这些可动态打开的开关：

请求生命周期日志。
关键队列长度、水位线、批处理大小统计。
关键状态机断言。
每秒错误码与超时分布。
单请求采样追踪，例如只追某个 req_id。
OTel span 采样率的动态调节，避免事故时只能在“全量太重”和“完全没有”之间二选一。

这些开关的价值是：出事故时你不需要大改代码，就能把“系统整体异常”收束成“某类请求、某个阶段、某条线程”的局部异常。

8. 内存与并发错误检测

事件驱动程序的内存与并发问题尤其隐蔽，因为对象常在多个回调之间流转，生命周期跨越多个 poll 周期。单靠日志很难确认 use-after-free、越界写、双重释放、数据竞争这些问题，必须借助专门工具，而且这些工具更适合放在复现环境、canary 或离线回放里，而不是直接砸向主生产实例。

8.1 AddressSanitizer 优先级最高

AddressSanitizer 几乎应该是 C/C++ 事件驱动程序的默认调试构建。它对 use-after-free、heap-buffer-overflow、stack-use-after-return 的定位速度非常快。

cc -O1 -g -fsanitize=address -fno-omit-frame-pointer -o server_asan server.c
ASAN_OPTIONS=detect_leaks=1:abort_on_error=1 ./server_asan

如果你怀疑对象池或复用缓冲区把内存写坏了，ASan 往往是最快给出准确信息的工具。

8.2 ThreadSanitizer 专抓看起来像偶发的问题

多线程 event loop、一个线程 submit 一个线程 reap、后台定时器线程参与取消，这些结构很容易引入真正的数据竞争。ThreadSanitizer 能直接指出未同步的读写位置。

cc -O1 -g -fsanitize=thread -fno-omit-frame-pointer -pthread -o server_tsan server.c
TSAN_OPTIONS=halt_on_error=1 ./server_tsan

TSan 开销很大，而且会改变时序，所以更适合测试环境和最小复现程序，而不是直接套在线上二进制上。

8.3 Valgrind 仍然适合慢病排查

Valgrind 比 ASan 慢得多，但在某些环境无法重编译、或者你需要更完整的泄漏和未初始化读取报告时仍然很好用。

valgrind --tool=memcheck --leak-check=full --track-origins=yes ./server

它不适合高负载网络基准，但对“长时间运行后 RSS 稳步上升”“某条错误路径泄漏请求对象”“低频未初始化读取”这种慢病仍然有价值。

8.4 一段典型并发错误示例

下面的示例更贴近事件驱动的实际场景：一个线程提交 SQE，另一个线程收割 CQE，共享的 inflight 数组和 request 结构体没有任何同步。

#include <liburing.h>
#include <pthread.h>
#include <stdlib.h>

struct request {
    uint64_t id;
    int fd;
    int state;
};

struct io_ctx {
    struct io_uring ring;
    struct request *inflight[1024];
    int nr_inflight;
};

/* 线程 A：提交 SQE */
void *submit_thread(void *arg) {
    struct io_ctx *ctx = arg;
    struct io_uring_sqe *sqe = io_uring_get_sqe(&ctx->ring);
    struct request *req = calloc(1, sizeof(*req));
    req->state = 1; /* ST_SUBMITTED */
    ctx->inflight[ctx->nr_inflight++] = req;  /* 未加锁 */
    io_uring_sqe_set_data(sqe, req);
    io_uring_submit(&ctx->ring);
    return NULL;
}

/* 线程 B：收割 CQE */
void *reap_thread(void *arg) {
    struct io_ctx *ctx = arg;
    struct io_uring_cqe *cqe;
    io_uring_wait_cqe(&ctx->ring, &cqe);
    struct request *req = io_uring_cqe_get_data(cqe);
    req->state = 3; /* ST_DONE —— 未加锁 */
    io_uring_cqe_seen(&ctx->ring, cqe);
    free(req);
    return NULL;
}

TSan 会直接标记 nr_inflight 的竞争写和 req->state 的竞争读写。在事件驱动服务中，这类错误常表现为“偶发丢请求”或“CQE 收到后 req 已被另一个线程回收”。

9. 实战案例：从线上症状到根因

下面给一个接近真实线上故障的案例。场景是一个 io_uring 回显服务，为了处理读超时，给每个 read 请求都挂了 timeout；一旦超时，应用就发 cancel 并立即关闭连接。线上表现是：少量连接会出现响应写到错误客户端、偶发 EBADF、极少数情况下进程崩溃在已经释放的请求对象上。

9.1 先收敛症状

第一轮不要上来跑 ASan，而是先看症状是不是已经能说明问题在“回收早于完成”。应用日志样本：

phase=submit req=18192 fd=87 op=READ state=1 res=0
phase=timeout req=18192 fd=87 op=READ state=1 res=-110
phase=reclaim req=18192 fd=87 op=READ state=4 res=0
phase=complete req=18192 fd=87 op=READ state=4 res=128

单看这几行就已经很可疑：reclaim 出现在 complete 之前。

如果服务已经接了 OTel，这个时候 span 上通常也会出现类似顺序：req.transition -> cancelling、req.reclaim、随后才是 req.complete。这说明应用层时间线已经和正确的资源回收顺序相矛盾。

9.2 第二轮：strace 证明最外层入口正常

strace 显示 io_uring_setup、io_uring_enter 都成功，没有权限或参数层面的明显错误，也没有大量 EINTR。这一步的结论不是“没问题”，而是“问题不在最外层入口”。

strace -ff -tt -e trace=io_uring_setup,io_uring_enter,close ./uring_echo

9.3 第三轮：bpftrace 看到 cancel 与 complete 交错

通过 tracepoint 记录同一个 user_data 的提交与完成顺序，确认有一部分请求在 cancel 之后仍然完成：

sudo bpftrace -e '
tracepoint:io_uring:io_uring_submit_sqe
{ printf("submit user_data=%llu opcode=%d\n", args->user_data, args->opcode); }

tracepoint:io_uring:io_uring_complete
{ printf("complete user_data=%llu res=%d\n", args->user_data, args->res); }
'

这一步说明内核行为完全合理，真正错误在应用层：应用把“已经发出 cancel”误当成“请求已不可能完成”。

9.4 第四轮：ASan 钉死 use-after-free

在测试环境切 ASan 版本跑压测，很快命中：

cc -O1 -g -fsanitize=address -fno-omit-frame-pointer -o uring_echo_asan uring_echo.c
./uring_echo_asan

ASan 报告显示 process_cqe() 在读取已经释放的 struct request。这与日志、OTel 时间线和 eBPF 观察完全吻合。

9.5 根因代码与修复方式

根因代码通常比想象中更朴素：

static void on_timeout(struct request *req) {
    req->state = ST_CANCELLING;
    submit_cancel(req->id);
    close(req->fd);
    free(req);
}

static void process_cqe(struct io_uring_cqe *cqe) {
    struct request *req = decode_user_data(cqe->user_data);
    req->result = cqe->res;
    finish_request(req);
}

问题不在 cancel 本身，而在于 timeout 路径和 completion 路径都以为自己拥有最终回收权。

这张图要表达的重点只有一个：ST_CANCELLING 不是“已经结束”，而只是“已经发出了取消请求，正在等待最终事实落地”。真正能决定是否关闭 FD、是否释放请求对象的，永远是后续到达的 CQE 和引用计数归零这两个条件，而不是 timeout 回调自身。

修复要点只有三个。

timeout 路径只把状态改成 ST_CANCELLING，不直接关闭 FD，不释放请求。
只有真正收到 CQE，且引用计数归零后，才执行最终回收。
cancel 成功、失败、-EALREADY 都统一收敛到“等原始 CQE 或 cancel CQE 抵达后再决定”。

修复后的核心逻辑：

static void on_timeout(struct request *req) {
    transition(req, ST_SUBMITTED, ST_CANCELLING);
    req_get(req);
    submit_cancel(req->id);
}

static void process_cqe(struct io_uring_cqe *cqe) {
    struct request *req = decode_user_data(cqe->user_data);
    req->result = cqe->res;
    req->state = ST_DONE;
    maybe_close_fd(req);
    req_put(req);
}

上面用到的 req_get、req_put、maybe_close_fd 实现如下：

static void req_get(struct request *req) {
    req->refcnt++;
}

static void req_put(struct request *req) {
    if (--req->refcnt == 0) {
        free(req);
    }
}

static void maybe_close_fd(struct request *req) {
    if (req->fd >= 0) {
        close(req->fd);
        req->fd = -1;
    }
}

req_get / req_put 的作用是让 timeout 和 completion 两条路径共享对象所有权——谁最后一个 req_put 谁负责释放，不再争抢。maybe_close_fd 保证 FD 只关一次，后续路径拿到 -1 就知道已经清理过了。

这类修复做完后，验证不应该只看“能不能通”，而要按层次确认：日志顺序正常、OTel span 顺序正常、eBPF 看不到异常交错、ASan/TSan 不再报错、性能没有被修复动作拖垮。 ### 9.6 案例二：epoll FD 复用导致写到错误客户端

另一个常见线上事故类型完全不涉及取消竞争，但同样是事件驱动特有的。

症状：偶发客户端收到不属于自己的响应数据；日志里偶尔出现 EBADF 或 EPIPE；极低概率 crash。

排查过程：

应用日志发现同一个 FD 号在很短时间内出现了两个不同 req_id 的日志——说明 FD 被复用了。
strace 确认 close(87) 之后紧接着 accept() = 87，内核把同一个号分配给了新连接。
但旧连接的 epoll_event 里仍然挂着旧的 struct conn *，epoll_wait 随后返回了这个过期指针。

根因代码：

static void close_conn(struct conn *c) {
    close(c->fd);
    free(c);
    /* 漏了 epoll_ctl(epfd, EPOLL_CTL_DEL, c->fd, NULL); */
}

close() 确实会自动把 FD 从 epoll 里删除——但仅限于该 FD 是对应文件描述的最后一个引用。如果 dup() 或 fork() 产生了副本，close() 不会触发 epoll 删除。更关键的是，在 close() 和 accept() 之间如果 FD 号被复用，epoll_wait 在同一轮可能仍然返回旧事件。

修复：先 EPOLL_CTL_DEL，再 close，再 free。

static void close_conn(int epfd, struct conn *c) {
    epoll_ctl(epfd, EPOLL_CTL_DEL, c->fd, NULL);
    close(c->fd);
    c->fd = -1;
    free(c);
}

这个案例和 cancel/complete 竞争的共同教训是：事件驱动程序里，资源回收的顺序就是正确性本身。关错了顺序，后果不是立刻崩溃，而是数据静默发错——这往往比崩溃更危险。 ## 10. 调试工具选择决策表

最后给一张更适合线上场景的决策表。事件驱动程序的问题很多，不需要每次把工具全上；关键是按问题类型选第一把刀。

如果应用完全没有 req_id、没有结构化日志、没有 OTel？ 这在老服务中很常见。降级路径是：先用 strace -ff -tt -T -y 拿到 FD 级别的系统调用时间线，配合 lsof / /proc/<pid>/fd 确认 FD 对应的 socket 或文件；再用 bpftrace tracepoint 拿到内核侧事件顺序；最后用 perf record 抓 CPU 热点。这条路比有 OTel 时慢得多，但至少能开始收敛。事后应尽快补上请求级观测点，避免下次还要重复这套体力活。

问题现象	首选工具	为什么先用它	什么时候切换
先要收敛影响范围、看请求在哪个阶段卡住	OpenTelemetry + 结构化日志	先补齐应用层时间线，最快知道卡在 submit、wait、timeout、cancel 还是 reclaim	应用层看不出根因时，下钻 syscall 与 eBPF
进程崩溃、core 明确	GDB	先拿到现场栈、线程、局部变量	现场不稳定或偶发时切到 `rr`
偶发 use-after-free、顺序相关 bug	`rr`	可重放、可反向执行，适合追最后一次写入	若怀疑调度或内核时序，补 eBPF
怀疑 syscall 参数或时序错了	`strace` / `perf trace`	先验证程序到底调用了什么	若进入 `io_uring` 语义盲区，切 `bpftrace`
怀疑 `io_uring` 请求类型、错误码、延迟分布异常	`bpftrace`	tracepoint 离真实执行更近，在线成本低	需要更复杂脚本或现成工具时切 BCC / Gadget
怀疑 Kubernetes 节点、容器网络、内核层异常	Pixie / Inspektor Gadget	更快收敛 pod、node、内核维度问题，减少手工登机与拼探针	聚焦到单机后转 `bpftrace`、`perf`
怀疑 CPU 热点、上下文切换、锁竞争	`perf`	同时看性能与结构性异常	需要长期趋势和版本对比时补 Pyroscope / Parca
想看线上长期热点漂移与回归	Pyroscope / Parca	continuous profiling 适合看小时级、天级趋势，而不是一次性抓包	需要精确现场时再做 `perf record`
怀疑 use-after-free、越界、双重释放	AddressSanitizer	命中快、定位准	无法重编译时退回 Valgrind
怀疑数据竞争、跨线程状态损坏	ThreadSanitizer	直接指出未同步读写	时序变化太大时辅以日志与 `rr`
怀疑设计层面“代码本身难调”	状态机重构 + 请求级观测点补齐	工具只能放大现象，不能替代结构化设计	应尽早做，不要等线上事故后补

真正成熟的调试流程一定是分层的：先看症状与收敛范围，再看日志和 trace，然后看 syscall / tracepoint，再看 profiler，最后才上 sanitizer、重放与离线复盘。这样每一步都在缩小问题空间，而不是把所有输出混在一起互相猜测。

对 epoll 与 io_uring 这类事件驱动程序而言，调试能力本身就是架构能力的一部分。谁能把请求身份、状态机、所有权、观测点设计清楚，谁就能在线上更快地区分“内核没做”“用户态做错”“只是还没看到”这三类完全不同的问题。

参考链接

上一篇: 08-golang-integration.md - Go 如何集成 io_uring：从 CGO 封装到纯 Go 实现返回 io_uring 系列索引

目录