第17章 Runtime 可观测性：Metrics、tracing 与 tokio-console

"If you can't measure it, you can't improve it." —— Peter Drucker "对 async runtime 来说，这句话更严厉：连 bug 都找不到。" —— 笔者

本章要点

• 三层可观测性：RuntimeMetrics（数字——聚合态、每秒一次）+ tracing（事件——细粒度、每次 span 进出）+ tokio-console（状态——实时面板、live task 快照）
• RuntimeMetrics 30+ 项指标：worker 级（park / poll / steal / overflow / local_queue_depth）+ blocking pool（num_blocking_threads / idle / queue_depth）+ IO driver（ready_count / fd_registered）——每项对应一个真实优化场景
• #[instrument] 的魔法：宏展开后把函数体包进一个 instrumented future、在每次 poll 前 span.enter()、poll 后 span.exit()——让 await 不破坏 span 栈
• tokio-console 背后：通过 Trace::capture 劫持 Waker、在下次 poll 时抓 live 的 backtrace——不停服就能看到每个 task 正卡在哪一行
• 生产黄金三元组：Prometheus 抓 Metrics + Jaeger 收 tracing + tokio-console 做 live debug——三者齐备、bug 无处藏身

17.0 为什么可观测性是运行时的一等公民

上一章结尾埋了一个伏笔："看得见才能调得动"。本章就把这句话兑现。

想象你接手一个生产服务、QPS 掉到了平时的 1/3——延迟没涨、错误率没涨，就是吞吐不见了。如果你只能看日志，几乎没有办法诊断：日志只告诉你请求进了出了、不告诉你 task 在哪一步被 schedule 失败、worker 有没有被堵、blocking pool 有没有排队。

async runtime 的最大诊断难点是"状态极度弥散"：几千个 task 分布在几个 worker、几十个 blocking thread、几百个 fd 上，每个都有自己的微观状态机——没有工具把这些状态收集起来，你就是盲人摸象。

Tokio 从一开始就知道这件事。从 2020 年的 0.3 版本引入 tracing 支持、到 2022 年 tokio-console 1.0、再到 1.30+ 的 RuntimeMetrics 全面开放——每一个 Tokio 大版本都在加强可观测性。今天你拿到的 1.40 已经是一个完整的工具链。本章带你走一遍。

17.1 RuntimeMetrics：30+ 个数字描绘的运行时肖像

先上源码。tokio/src/runtime/metrics/runtime.rs：

pub struct RuntimeMetrics {
    handle: Handle,
}

就一个 Handle 包装——所有数据现场去读。这样的设计决策意味深远：

• 读取开销极低：不持有快照、直接读 runtime 里的 atomic 计数器——一次读 ≈ 一次 atomic load ≈ 1-5 纳秒；
• 数据永远实时：没有"上次 snapshot"和"当前"的差异；
• 代价：要保证 runtime 里每个被观测的状态都是 atomic——源码里你会看到大量 AtomicU64、AtomicUsize。

核心指标地图

全局级（stable，不需要 tokio_unstable）：

• num_workers(): worker 线程数（= Builder 里设的 worker_threads）；
• num_alive_tasks(): 当前存活的 task 数。

全局级（unstable）：

• num_blocking_threads(): blocking pool 现有线程数；
• num_idle_blocking_threads(): 其中 idle 的数量；
• spawned_tasks_count(): runtime 启动以来累计 spawn 数；
• remote_schedule_count(): 从非 worker 线程调 spawn 的次数（含 blocking pool）；
• budget_forced_yield_count(): coop budget 用完强制 yield 的次数；
• injection_queue_depth(): 全局注入队列当前长度；
• blocking_queue_depth(): blocking pool 队列当前长度。

每个 worker 级：

• worker_park_count(i): worker i park（睡眠）的次数；
• worker_poll_count(i): poll 的次数；
• worker_steal_count(i): 从别人那里 steal 来的 task 数；
• worker_overflow_count(i): 本地 queue 满、溢出到全局 inject 的次数；
• worker_local_queue_depth(i): 当前本地 queue 长度；
• worker_mean_poll_time(i): 平均每次 poll 耗时；
• worker_total_busy_duration(i): worker 累计"非 park" 时间。

I/O driver 级：

• io_driver_fd_registered_count(): 注册过的 fd 总数；
• io_driver_fd_deregistered_count(): 注销过的；
• io_driver_ready_count(): readiness 事件总数。

指标如何映射到真实问题

单个数字没用、配对比较才能诊断。下面这张表是我压测调优多年攒下的经验：

观察	可能诊断
worker_poll_count 高、worker_mean_poll_time 低	每个 poll 很快、但 poll 次数多——task 被 wake 过频、可能存在"虚假唤醒"（比如某个 channel 每次收都 wake 但实际没数据）
worker_mean_poll_time > 100us	某些 task 每次 poll 都重（CPU 计算）——应该 spawn_blocking 或改算法
worker_steal_count 总和接近 spawned_tasks_count	负载严重不均——几乎所有任务都需要 steal 才能跑、初始分配分布差
worker_overflow_count > 0 且持续增加	本地 queue 被打满（默认 256）——spawn 洪峰，考虑限速或加 worker
injection_queue_depth > num_workers	全局 inject 堆积——worker 消化不过来、增加 worker 或分流
blocking_queue_depth > 0 且增加	blocking pool 积压——上一章讲的场景，CPU 密集错用 spawn_blocking
io_driver_ready_count 大幅高于 QPS	epoll 被频繁唤醒但没真实 IO——可能是某个 socket 在 spurious wakeup
budget_forced_yield_count 持续增加	有 hot task 在 CPU 上霸占——scheduler coop 机制在介入、但说明 task 本身不礼让

这张表比任何抽象文档都实用。把它打印贴在显示器边上、出了性能问题先看这几个数。

17.2 把 Metrics 连到 Prometheus

实际生产里你不会 println! 这些数字、你会按固定频率把它们导出到 Prometheus。基本 pattern：

let metrics = tokio::runtime::Handle::current().metrics();
let workers = metrics.num_workers();

// 每 10 秒采样一次，挂到 prometheus gauge
tokio::spawn(async move {
    let mut ticker = tokio::time::interval(Duration::from_secs(10));
    loop {
        ticker.tick().await;
        TOKIO_ALIVE_TASKS.set(metrics.num_alive_tasks() as i64);
        TOKIO_BLOCKING_QUEUE.set(metrics.blocking_queue_depth() as i64);
        for w in 0..workers {
            TOKIO_WORKER_POLL
                .with_label_values(&[&w.to_string()])
                .set(metrics.worker_poll_count(w) as i64);
        }
    }
});

关键是——这个采样 task 本身跑在同一个 runtime 里、不能 block 太久。10 秒一次、每次几微秒、完全可以忽略。不要每秒 100 次采样每个 worker 10 个指标——会把 runtime 的 overhead 从 0.1% 抬到 5%。

17.3 tracing：span 和 event 的双层模型

RuntimeMetrics 给你数字、tracing 给你叙事——"某个请求经历了什么、在哪一步慢了多久"。

tracing 的核心抽象两个：

• Span：有开始和结束的时间段——"我在处理请求 X"；
• Event：一个瞬间——"我刚收到了某个值"。

use tracing::{info, instrument};

#[instrument(fields(user_id = %req.user_id))]
async fn handle(req: Request) -> Response {
    info!("start processing");
    let user = fetch_user(req.user_id).await?;
    info!(?user, "user loaded");
    let resp = do_work(user).await?;
    info!("done");
    resp
}

#[instrument] 干什么？宏展开后：

1. 在函数进入时创建一个 span（名字默认是函数名、带上 fields 里声明的字段）；
2. 把函数体包进一个 wrapper future（有点像 Future combinator）；
3. 每次 poll wrapper 时——先 span.enter()（把 span 设为当前 thread 的 active）、poll 内部 future、再 span.exit()；
4. 函数返回时 drop span。

为什么 #[instrument] 这么重要

手动 span.enter() + await 会出 bug——因为 await 是一个让出点、_guard 保持的"当前 span"会被带到 await 之后的另一个 poll 里去、但此时可能是另一个 task 在跑！这正是官方文档警告的那句话："Span::enter may produce incorrect traces if the returned drop guard is held across an await point."

#[instrument] 通过每次 poll 都重新 enter / exit避开了这个坑——span 和 future 的生命周期绑定、而不是和线程的"某一段时间"绑定。这是 async 语境下 tracing 的核心正确姿态。

Subscriber：数据收到哪里去

tracing 本身不决定日志打到哪、去不去 Jaeger——那是 Subscriber 的职责。常见组合：

• tracing-subscriber::fmt：格式化打到 stdout——开发用；
• tracing-subscriber::EnvFilter：按 RUST_LOG 过滤级别；
• tracing-opentelemetry：把 span 导出到 OpenTelemetry collector（Jaeger / Tempo / SigNoz）——生产分布式追踪首选；
• tracing-bunyan-formatter：JSON 结构化日志——ELK stack 配套。

一套典型生产配置：

use tracing_subscriber::{layer::SubscriberExt, Registry};
let registry = Registry::default()
    .with(tracing_subscriber::EnvFilter::from_default_env())
    .with(tracing_opentelemetry::layer().with_tracer(otel_tracer))
    .with(tracing_subscriber::fmt::layer().json());
tracing::subscriber::set_global_default(registry)?;

一行代码 + 一个全局默认 → 所有 info! / error! / span 都会被这几个 layer 处理。这种"分层订阅"的设计让 tracing 生态极其灵活——换一个输出目的地只改配置、不改业务代码。

17.4 tokio-console：live task 的 X 光

Metrics 给你聚合数字、tracing 给你历史轨迹、但"此刻某个 task 卡在哪一行"谁告诉你？tokio-console。

启动方式简单：

// Cargo.toml: console-subscriber = "0.4"
// 需要 RUSTFLAGS="--cfg tokio_unstable"
console_subscriber::init();

在终端里跑 tokio-console、就能看到一个动态面板：所有 live task 的状态、多久没被 poll、在哪一行卡住、当前 span 是什么。像 top 命令但对象是 task。

背后的 taskdump 机制

tokio-console 的核心能力依赖一个 Tokio 里 unstable 的 API——Handle::dump()。源码在 tokio/src/runtime/task/trace/mod.rs。

关键技术：劫持 Waker 注入 trace 上下文。当你调 dump()，Tokio 会：

1. 把 runtime 里 alive 的 task 全部 collect 到一张 list；
2. 对每个 task，设置一个"tracing 模式"标志；
3. 强行 schedule 这些 task（通过内部的 notify 机制）；
4. 下一次 poll 时、task 运行到某个关键点（比如 await）——触发 trace_leaf()、捕获当前调用栈；
5. trace_leaf 返回 Poll::Pending 并 defer waker——task 没真正跑、只是"路过让 Tokio 抓一把 backtrace"。

if did_trace {
    context::with_scheduler(|scheduler| {
        // ... 记录 trace ...
        s.defer.defer(cx.waker());
    });
    Poll::Pending
}

这个机制的精妙之处：不需要停 runtime、不需要 ptrace、不需要修改 task 结构——利用 Future 本身的 poll-reenter 语义就把所有 live task 的栈抓下来了。这是 Tokio 把"把 async 结构变成第一公民"思想贯彻到底的结果：既然 Future 的 poll 是可重入的、那就用这个重入捕获状态。

你能在 tokio-console 里看到什么

• 每个 task 的 ID + 名字 + 当前 state（running / idle / ready）；
• Task 上一次 poll 的时长、总 poll 次数、总被 wake 次数；
• Task 当前所在的 .await 对应的源代码行（带上 backtrace）；
• Resource（Mutex、Semaphore、channel）的等待者列表；
• 自己调 warn() 打标记——发现某个 task 异常时留给后来人看。

这个工具对诊断"task 泄漏"、"某个 task 被某个锁挂死"、"某个 task 长期不 yield"的价值无可替代。上一章讲的 JoinSet 内存泄漏故事、用 tokio-console 五分钟就定位了——肉眼看到面板上有几十万个 task 名字都是 process()、立刻知道是哪段 spawn 没清理。

17.5 三层一体：一次真实 bug 诊断的流水账

来一个完整诊断流程——某服务"偶尔"5 秒无响应：

Step 1（Metrics 发现异常）：Grafana 上看到 worker_poll_count 每 5 分钟会有一个 5 秒长的水平段——这段时间 runtime 几乎不 poll。

Step 2（关联其他 Metrics）：那 5 秒里 num_alive_tasks 曲线还在涨、blocking_queue_depth 也在涨——task 进来了但不被处理。worker_park_count 没跳——worker 没睡，在干活。干什么活？

Step 3（tracing 找范围）：grep Jaeger 里那几秒的 span——发现某个 process_batch span 的 duration 恰好 5 秒。而这个函数正常时间是 50 毫秒。猜测：某个 batch 里有超大数据、同步处理卡 CPU。

Step 4（tokio-console live 抓）：下次重现时开 tokio-console——看到一个 task 的"上次 poll 时长"是 4.8 秒、backtrace 停在 serde_json::to_vec(&huge_struct)。

真相大白：有个边界 case 下 huge_struct 变得巨大（几 MB）、to_vec 在 worker 上同步跑了 5 秒、把整个 worker 卡死——期间其他 task 要么堵在这个 worker、要么要 steal 到别的 worker（短暂缓解，但最终还是波及）。

修复：把 to_vec 包进 spawn_blocking。上线后 Grafana 曲线再没出现过水平段。

这个案例的教训：Metrics 发现"什么时候慢"、tracing 发现"哪个函数慢"、tokio-console 发现"慢在哪一行"——三者各司其职、缺一不可。

17.5½ 一些 Metrics 使用的实战微技巧

把这些集中讲出来、都是踩过坑的：

微技巧 1：用 diff 而不是 raw 值做告警

spawned_tasks_count 是累计值——告警配"瞬时值 > 10000"毫无意义（上线一周所有正常进程都会超）。应该每分钟记一次差值、告警"每分钟新增 > 50000"——才是真正的"突发 spawn 洪峰"信号。Prometheus 的 rate() 函数就是为这个设计的。

微技巧 2：per-worker 曲线分别画

不要把所有 worker 的 worker_poll_count 加总成一条曲线。分开画——你会看到"负载是否均衡"的真相。理想情况下 8 条曲线应该几乎重合、如果某条明显比其他高（或低）——scheduler 负载分布有问题、可能是某个 task 有线程亲和性、或是 work-stealing 没起作用。

微技巧 3：histogram 的 bucket 配置

poll_count_histogram_* API 允许你看 "poll 耗时的分布直方图"——但你得先在 Builder 里 enable 它、默认关（因为有额外 overhead）：

Builder::new_multi_thread()
    .enable_metrics_poll_count_histogram()
    .metrics_poll_count_histogram_scale(HistogramScale::Log)
    .metrics_poll_count_histogram_buckets(10)
    .build()?;

log scale 比 linear 好——poll 耗时分布通常是重尾（99% 的 poll <10us、但 tail 拖到 100ms），linear bucket 会把 99% 挤到一个 bucket 里、看不出分布。

微技巧 4：worker_total_busy_duration 是"CPU 利用率"的分子

busy_duration(w) / wall_time 就是 worker w 的 CPU 利用率——不是整机 CPU 利用率、是 runtime 的利用率。低利用率 + 高延迟 = 瓶颈在 IO 或下游（worker 都在 park 等 IO）；高利用率 + 高延迟 = 瓶颈在 CPU（worker 忙不过来）。两者的优化方向完全相反。

微技巧 5：injection_queue_depth 的"持续 > 0" 才是问题

偶发 spike 到 1-2 个是正常（spawn 间隙本来就会短暂排队）。持续 > 10、且 worker 都忙——说明 worker 消化速度 < 外部注入速度、典型的"producer 快 consumer 慢"。这时候增加 worker 可能没用（CPU 本来就不够）、该考虑的是限速或分流。

17.6 和其他书的呼应

《Vue 3 设计与实现》第 17 章讲过 Vue 的 Devtools 通过全局钩子 __VUE_DEVTOOLS_GLOBAL_HOOK__ 把组件树、响应式依赖、事件流全部暴露——tokio-console 和它的设计哲学一模一样：runtime 自己提供钩子、外部工具消费。区别只是 Vue 的钩子走浏览器消息通道、tokio-console 走 gRPC。"observability 是运行时的 contract、不是外挂功能"——这是两个生态的共同共识。

《Rust 编译器与运行时揭秘》第 18 章讲过 rustc 的 -Z self-profile 如何在编译器内部插桩、把各阶段耗时写到 measureme 格式——#[instrument] 宏和那套机制异曲同工：编译期插入观测代码、运行期收集聚合。学会在两种"运行时"（rustc 和 tokio）里都用这种技术，是系统工程师的基本功。

**《vLLM 源码剖析》**里的 iteration_stats 记录每次调度循环的 batch 大小、token 数、latency——和 RuntimeMetrics 里 worker 级指标是同一个思路：调度器自己暴露足够多的内部状态、让调用方能看清自己"做了多少功"。这是所有严肃调度器共享的基础设施品质。

17.7 可观测性的心智模型：永远留足"下次调试"的空间

最后一条原则、实践里最值钱——今天加的每个 metric、每个 tracing span，都是在给"下次出事"的自己留路。

什么时候加观测？不是出 bug 才加——那时候场景已经消失了。而是"你觉得这段代码未来有可能成为瓶颈时"——比如新加的一段 spawn_blocking、一个 channel 的 buffer size、一个 select! 的多路分支——就地加一个 info! 或 gauge、成本几纳秒、未来救命无数次。

观测的反模式：

• 把所有 debug! 写到 info! 级别——日志量爆炸、找不到重点；
• 只加 metrics 不加 tracing——知道"什么时候"不知道"为什么"；
• 只加 tracing 不加 metrics——每个请求都清楚、但看不到聚合趋势；
• 上线后才 attach tokio-console——生产环境不开 tokio_unstable 就用不了。

正反结合：开发就上全套（fmt logs + jaeger dev env + console）、生产上 metrics + sampled tracing + console 预开但按需连。Tokio 官方的模板仓库里有标准配置、直接抄最省心。

一个补充：tracing 的"成本焦虑"通常被高估

很多人不敢在热路径写 info!——怕性能。实际上 tracing 的 runtime 成本分两层：

1. globally disabled level：如果当前 subscriber 不收这个 level，info! 宏展开后第一行就是 if Level::INFO > max_level() { return; }——开销 ≈ 一次原子读、几纳秒。
2. enabled level：要格式化、提交给 subscriber——微秒级。但热路径上通常不会开 info！

最佳实践：热路径用 debug! 或 trace!（默认关）、请求入口用 info! 、异常情况 warn!/error!。配合 EnvFilter 在问题重现时按需打开 debug——不重启、不用改代码。这才是 tracing 的真正威力：按需扩展观测精度。

tracing 这套设计和 linux 的 dmesg/ftrace/perf 是同一个哲学——零开销"关着的"诊断点、按需"打开"。学会这套思维、你的每个生产服务都会比对照组更容易排障。

17.7½ 把可观测性当"文化"而不是"工具"

说一个我反复观察到的团队级差异：同样的 Tokio、同样的 tracing、同样的 Grafana——A 团队一周定位完 bug、B 团队三个月还没找到。差别不在工具、在文化。

A 团队的特征：

• 每个 PR 的代码 review 会问"这段代码的观测点在哪"——和"这段代码有测试吗"一样重要；
• 线上事故后一定有"下次怎么更快发现"的复盘项——直接落成新 metric / 新 dashboard；
• on-call 手册里每个告警都链接到 runbook——不是"重启试试"、而是"先看 X 指标、再看 Y 面板"；
• 定期看 Grafana 不是出事才看——周会上过一遍关键曲线、长期趋势里藏着未来的坑。

B 团队的特征常常是反过来的：metrics 是"加了就好"、dashboard 没人看、告警大多数被静默、tracing 只在 dev 环境看过。出事了翻日志、翻代码、翻 git blame——花的时间全是工具本该替他们省的。

可观测性的终极价值不是帮你解决 bug、而是帮你用更少的 bug 运营系统——每条新加的 metric、每个新加的 span，都在训练整个团队对系统的直觉。而直觉，才是资深工程师的护城河。所以把这一章的工具用起来——工具是死的、文化是活的；只有把工具注入日常、可观测性才真正发挥作用。

最后一个建议：给每个 runtime 起个名字

默认的 worker 线程叫 tokio-runtime-worker——如果你进程里有多个 runtime（下一章话题），panic 时你看不出是哪个。永远用 Builder 的 .thread_name("my-service") 起显式名字：

Builder::new_multi_thread()
    .thread_name("api-server-worker")
    .build()?;

这个五个字符的改动，能在凌晨三点你看堆栈时省你两分钟——两分钟乘以一辈子的 on-call 次数、是非常可观的时间。运行时的可观测性、从一行名字开始。

17.7¾ 另一个常被遗忘的观测维度：panic 追踪

async 里最容易被忽视的观测漏洞是 panic 追踪。当一个 spawn 出去的 task panic 了、默认情况下 runtime 只会打印到 stderr——如果你的生产日志不收 stderr、或者 stderr 被 systemd journal 吞了但 log agent 没配——这次 panic 就无声无息丢了。JoinHandle await 时会得到 JoinError::panic(...)，但要主动检查。

正确的做法是在 spawn 边界包一层：

tokio::spawn(async move {
    let result = std::panic::AssertUnwindSafe(run()).catch_unwind().await;
    if let Err(payload) = result {
        tracing::error!(?payload, "task panicked");
        PANIC_COUNTER.inc();
    }
});

这样每次 panic 都会触发 error! 级日志、PANIC_COUNTER 上报 Prometheus、告警触发。很多团队在生产跑了一年才发现自己一直在丢 panic——一查日志才发现每天有几千条。这个黑洞，只有把 panic 当作"一等观测对象"才能堵住。

Tokio 1.40 还专门提供了 Builder::unhandled_panic(UnhandledPanic::ShutdownRuntime) 选项、可以在 panic 发生时整个 runtime 退出——这在对"任何 panic 都意味着状态不一致"的系统（比如交易、数据库）里非常有用：与其让 runtime 带着一个 corrupted task 继续跑几小时、不如立刻 crash 让 supervisor 重启。选择哪种策略取决于你的系统能不能容忍"部分失败"——对无状态服务可忍、对有状态服务多半不可忍。这也是"可观测性不止是看、也包含对异常的处置策略"的一个注脚。

17.8 本章小结

带走三件事：

1. 三层可观测性缺一不可——Metrics 给聚合数、tracing 给叙事、tokio-console 给 live 状态。三者分别对应"多慢、为什么慢、现在卡在哪"——生产诊断三大问
2. #[instrument] 宏的核心是每次 poll re-enter span——正确跨越 await 边界的唯一姿势。手动 span.enter() + await 在 async 里几乎必错
3. taskdump 利用 Future poll 可重入、劫持 Waker 抓 backtrace——零停服观测 live task。这是 Tokio 把 async 结构作为一等公民的又一个副产物

下一章进入跨 runtime 通信与多 runtime 架构——你会看到为什么"一个进程只有一个 Tokio runtime" 不再是唯一答案、什么时候该分 runtime、分 runtime 之间如何通信而不死锁。

---

延伸阅读

• Tokio 源码：tokio/src/runtime/metrics/runtime.rs
• Tokio 源码：tokio/src/runtime/task/trace/mod.rs
• tracing 官方文档
• tokio-console GitHub
• 《Vue 3 设计与实现》第 17 章：Devtools 钩子
• 《Rust 编译器与运行时揭秘》第 18 章：rustc self-profile 与 measureme