它解决什么问题
主线位置:两条主线的动机。本页回答为什么要在任务外面包一层:只有包住任务,才能把一个任务的时间切成 poll、排队、空闲三段,再按任务的种类分开统计。
sequenceDiagram participant Q as 运行队列 participant W as worker 线程 participant I as Instrumented participant X as 外部(IO、定时器、别的线程) Q->>W: 取出任务 W->>I: poll Note over I: poll 时长:在 worker 上跑了多久 I-->>W: Pending Note over I,X: 空闲:上次 poll 结束到被唤醒 X->>I: wake I->>Q: 记下唤醒时刻,转给 tokio,任务进队列 Note over Q,I: 排队:被唤醒到下次被 poll Q->>W: 轮到它 W->>I: poll Note over W: 运行时主线:读 tokio 每个 worker 的累计计数器
问题:慢在哪一段
线上一个接口的 p99 变高了。可能的原因有三种,治法完全不同:
| 慢在哪 | 现象 | 治法 |
|---|---|---|
| 自己 poll 得慢 | 一次 poll 里做了重计算、同步 IO、拿了阻塞锁 | 挪进 spawn_blocking,或者拆小、中间让出 |
| 排队排得久 | 自己很快,但被唤醒之后迟迟轮不到;同一个 worker 上有别的任务在做上一种事 | 找出那个慢 poll 的任务;或者加 worker |
| 在等外部 | 数据库、下游服务、定时器本来就慢 | 和异步运行时无关,去看外部 |
请求级的耗时(日志里的 latency、tracing 的 span 时长)只给出三段的和。tokio 自己的 Handle::metrics() 能给出每个 worker 忙了多久、poll 了多少次,但那是整个运行时的数字:它说不出是哪一类任务慢,也说不出一个任务慢在哪一段。
tokio-metrics 的回答是在任务外面包一层:TaskMonitor::instrument(fut)。包过的 future 每次被 poll 都记下三个时刻,按 monitor 累加:一个路由一个 monitor,就能知道这个路由的任务平均每次 poll 多久、被唤醒后平均等多久、两次 poll 之间平均空闲多久。README 的说法是(README 第 28 行起):同一个 TaskMonitor 包住的任务把指标聚合到一起,要分开看就用不同的 monitor(原文写的是 separate TaskMetrics instances,按上下文指的是 TaskMonitor)。
实验:三种慢各落进一列
三类任务各 10 个,交错 spawn 在单线程运行时上:
cpu:一次 poll 忙等 3ms,代表「自己 poll 得慢」。io:sleep(10ms),代表「在等外部」。victim:把一件小事交给阻塞线程池(spawn_blocking),做完立刻从那个线程唤醒自己。它自己几乎不花时间,但和cpu挤在同一个线程上。
tokio-metrics = "=0.5.2"
tokio = { version = "=1.54.1", features = ["full"] }
use std::time::{Duration, Instant};
use tokio_metrics::{TaskMetrics, TaskMonitor};
fn spin(d: Duration) {
let t = Instant::now();
while t.elapsed() < d {}
}
fn show(name: &str, m: &TaskMetrics, wall: Duration) {
println!(
"{name:<5} wall={:>6.1?} poll={:>6.1?} idle={:>6.1?} sched={:>6.1?} slow_polls={} long_delays={}",
wall,
m.total_poll_duration / m.instrumented_count as u32,
m.total_idle_duration / m.instrumented_count as u32,
m.total_scheduled_duration / m.instrumented_count as u32,
m.total_slow_poll_count,
m.total_long_delay_count,
);
}
#[tokio::main(flavor = "current_thread")]
async fn main() {
let cpu = TaskMonitor::new(); // 自己算得慢
let io = TaskMonitor::new(); // 在等外部(这里用 sleep 代替)
let victim = TaskMonitor::new(); // 自己很快,但和 cpu 挤在同一个线程上
let start = Instant::now();
let mut handles = Vec::new();
for _ in 0..10 {
handles.push(tokio::spawn(cpu.instrument(async {
let t = Instant::now();
spin(Duration::from_millis(3));
t.elapsed()
})));
handles.push(tokio::spawn(io.instrument(async {
let t = Instant::now();
tokio::time::sleep(Duration::from_millis(10)).await;
t.elapsed()
})));
handles.push(tokio::spawn(victim.instrument(async {
let t = Instant::now();
// 交给阻塞线程池做一件小事;它做完时从另一个线程唤醒本任务
tokio::task::spawn_blocking(|| ()).await.unwrap();
t.elapsed()
})));
}
let mut walls = [Duration::ZERO; 3];
for (i, h) in handles.into_iter().enumerate() {
walls[i % 3] += h.await.unwrap();
}
println!("total {:?}", start.elapsed());
show("cpu", &cpu.cumulative(), walls[0] / 10);
show("io", &io.cumulative(), walls[1] / 10);
show("victm", &victim.cumulative(), walls[2] / 10);
}
wall 是任务自己量的从第一次被 poll 到完成的时间,其余几列是每个任务的平均值。连跑 5 次,各列的毫秒数一致,只有微秒级的数字在变,其中一次:
total 41.407583ms
cpu wall= 3.0ms poll= 3.0ms idle= 0.0ns sched= 0.0ns slow_polls=10 long_delays=0
io wall=16.4ms poll=566.0ns idle=16.4ms sched=954.0ns slow_polls=0 long_delays=0
victm wall=13.5ms poll= 5.0µs idle=10.7µs sched=13.5ms slow_polls=0 long_delays=9
三行各有一列独占了 wall:
cpu:poll=wall= 3.0ms。10 次 poll 全部超过默认的 50µs 阈值,slow_polls=10。victim:poll只有几微秒,sched却是 13.5ms。第 i 个victim被阻塞线程池唤醒后,要排在还没跑的cpu后面,平均前面还有 4.5 个,4.5 × 3ms = 13.5ms。最后一个victim后面没有cpu,所以 10 次排队里有 9 次超过默认的 50µs,long_delays=9。io:几乎全是idle。但它睡的是 10ms,idle是 16.4ms:多出来的 6ms 是定时器到期了却没人处理,单线程一直被cpu占着,驱动没机会查时间轮。woke_at记的是wake()被调用的那一刻,这段延误被算进了空闲而不是排队,包装 waker 一页专门讲这种边界。
单看请求耗时,io 和 victim 差不多慢;拆开之后,一个该去查外部依赖,一个该去找同一线程上的 cpu。这就是这个库的用途。
和别的工具的分工
tokio 自带的 Handle::metrics()
tokio 1.54.1 的 RuntimeMetrics 不需要 tokio_unstable 就能读 num_workers、num_alive_tasks、global_queue_depth,以及每个 worker 的忙碌时间、park 次数、park/unpark 次数(这三个包在 cfg_64bit_metrics! 里,要求平台有 64 位原子);poll 次数、窃取次数、本地队列深度等要 tokio_unstable。它们全是从运行时启动开始的累计值,而且都按 worker 或整个运行时统计。
tokio-metrics 和它的关系分两半:
- 运行时指标:本库不量任何新东西,只是把 tokio 的累计值定期读出来,做差得到「这个区间」的值,再把各 worker 的值求和、求最大最小,这是 02 运行时指标的内容。
- 任务指标:tokio 不提供按任务分组的数字(1.54.1 有
on_before_task_poll/on_after_task_poll两个钩子,但都要tokio_unstable,而且只给你回调,统计要自己写)。本库靠包 future 自己量,不需要tokio_unstable,在任何运行时上都能用。
tokio-console
README 的 Relation to Tokio Console 一节只有三句:
Currently, Tokio Console is primarily intended for **local** debugging. Tokio
metrics is intended to enable reporting of metrics in production to your
preferred tools. Longer term, it is likely that `tokio-metrics` will merge with
Tokio Console.
即:console 主要用于本地调试,本库用来把指标报给生产环境里你自己的看板工具,长期看两者可能合并。console 要求什么构建条件,见设计取舍的「与 tokio-console 的分工」;它的开销本卷没有测。
dial9
README 的 Relation to dial9 一节(0.5.1 加入):dial9 记录 tokio、操作系统和应用的事件,用来事后排查、找根因;本库把指标报给看板和告警。原话的最后两句是 tokio-metrics can tell you something is wrong. Dial9 can help tell you what is wrong. 本库告诉你出了问题,dial9 帮你找出是什么问题。
| 工具 | 产出 | 怎么拿到数据 | 典型用法 |
|---|---|---|---|
Handle::metrics() | 运行时 / worker 级累计值 | tokio 内部计数器 | 自己读、自己算 |
| tokio-metrics | 运行时区间值 + 按 monitor 分组的任务指标 | 读 tokio 计数器;包 future | 生产看板、告警 |
| tokio-console | 每个任务的实时状态 | tokio 的 tracing 事件 | 本地调试 |
| dial9 | 事件记录 | tokio、操作系统、应用事件 | 事后分析 |
后两行只按两份 README 的描述写,不展开。
小结
- 一个任务的墙钟时间 = poll + 排队 + 空闲(再加上首次 poll 之前的等待)。请求耗时只给出和,tokio 的运行时指标给不出按任务分组的数字。
- tokio-metrics 包住任务,按 monitor 累加三段时间;一类任务一个 monitor。
- 实验里三类任务各被一列独占:忙等的落在 poll,挤在同一线程上的落在排队,等定时器的落在空闲。
- 空闲和排队的分界是
wake()被调用的时刻;定时器到期但没人处理的那段时间算空闲。 - 本库的运行时指标只是把 tokio 的累计值做差;console 用于本地调试,dial9 用于事后找根因,本库用于生产看板。