数字看起来不对
主线位置:两条主线的读取端。数字本身是对的,是读的人按另一个定义去理解了它。
flowchart TB q1["busy_ratio 是 4.00"] --> a1["各 worker 之和 ÷ 墙钟"] q2["首次 poll 延迟多 200ms"] --> a2["从 instrument() 算起"] q3["slow_poll_ratio 是 NaN"] --> a3["区间里没有 poll:0 ÷ 0"] q4["直方图是空的"] --> a4["要 cfg,还要在 Builder 上打开"] q5["两个看板最大空闲不同"] --> a5["swap(0):谁先读谁拿走"] a1 --> f1["再除以 workers_count"] a2 --> f2["在 spawn 那一行 instrument"] a3 --> f3["导出前判断分母"] a4 --> f4["enable_metrics_poll_time_histogram"] a5 --> f5["一个 monitor 只开一个 intervals()"]
四个现象的机制都在前面讲过,这一页把它们放进一个程序里,每个都先跑出现象,再跑出修法。
use std::time::{Duration, Instant};
use tokio_metrics::{RuntimeMonitor, TaskMonitor};
fn spin(d: Duration) {
let t = Instant::now();
while t.elapsed() < d {}
}
#[tokio::main(flavor = "multi_thread", worker_threads = 4)]
async fn main() {
// 1. busy_ratio 是各 worker 之和 ÷ 墙钟
let rm = RuntimeMonitor::new(&tokio::runtime::Handle::current());
let mut ri = rm.intervals();
let hs: Vec<_> = (0..4).map(|_| tokio::spawn(async { spin(Duration::from_millis(300)) })).collect();
for h in hs {
h.await.unwrap();
}
let r = ri.next().unwrap();
println!("1 busy_ratio={:.2} per_worker={:.2}", r.busy_ratio(), r.busy_ratio() / r.workers_count as f64);
// 2. 首次 poll 延迟从 instrument() 算起
let late = TaskMonitor::new();
let fut = late.instrument(async {});
tokio::time::sleep(Duration::from_millis(200)).await;
tokio::spawn(fut).await.unwrap();
let at_spawn = TaskMonitor::new();
tokio::time::sleep(Duration::from_millis(200)).await;
tokio::spawn(at_spawn.instrument(async {})).await.unwrap();
println!(
"2 first_poll_delay instrument_early={:?} instrument_at_spawn={:?}",
late.cumulative().mean_first_poll_delay(),
at_spawn.cumulative().mean_first_poll_delay()
);
// 3. 区间里没有 poll:比率是 0/0
let quiet = TaskMonitor::new();
let mut qi = quiet.intervals();
qi.next();
let q = qi.next().unwrap();
let ratio = if q.total_poll_count == 0 { 0.0 } else { q.slow_poll_ratio() };
println!("3 polls={} slow_poll_ratio={} guarded={}", q.total_poll_count, q.slow_poll_ratio(), ratio);
// 4. 同一个 monitor 开两个 intervals()
let shared = TaskMonitor::new();
let mut a = shared.intervals();
let mut b = shared.intervals();
a.next();
b.next();
let h = tokio::spawn(shared.instrument(async {
tokio::time::sleep(Duration::from_millis(100)).await;
}));
h.await.unwrap();
let ma = a.next().unwrap();
let mb = b.next().unwrap();
println!(
"4 a: idled={} max_idle={:?} b: idled={} max_idle={:?}",
ma.total_idled_count, ma.max_idle_duration, mb.total_idled_count, mb.max_idle_duration
);
// 5. 直方图:要 tokio_unstable,还要在 Builder 上打开
#[cfg(tokio_unstable)]
{
let r = ri.next().unwrap();
println!("5 runtime from #[tokio::main]: polls={} buckets={}", r.total_polls_count, r.poll_time_histogram.buckets().len());
}
}
不带 cfg 连跑 5 次,其中一次:
1 busy_ratio=4.00 per_worker=1.00
2 first_poll_delay instrument_early=202.030875ms instrument_at_spawn=41.917µs
3 polls=0 slow_poll_ratio=NaN guarded=0
4 a: idled=1 max_idle=100.993709ms b: idled=1 max_idle=0ns
5 次里第 1、3 行完全相同,第 4 行的 b 每次都是 0ns;instrument_early 在 202.0–203.1ms,instrument_at_spawn 在 15–42µs,a 的 max_idle 在 101.0–103.0ms。带 RUSTFLAGS="--cfg tokio_unstable" 再跑,多出第 5 行:
5 runtime from #[tokio::main]: polls=4 buckets=0
busy_ratio() 返回 4.00
busy_ratio 的分子是所有 worker 忙碌时长之和,分母是一段墙钟时间,范围是 0 到 worker 数。4 个 worker 各忙满 300ms,1.2s ÷ 0.3s = 4.00。要「平均每个 worker 有多忙」的百分比,自己再除以 workers_count。看板上如果把它当 0 到 1 的比率画、设了「大于 0.9 告警」,4 个 worker 的服务在只用了不到四分之一算力时就会报警。
细节见 Worker 差分与 poll 时间直方图。那一页还讲了另一个让它「超标」的原因:tokio 只在 worker park 前和每 61 个 tick 提交一次计数,一次很长的 poll 会在结束后的那个区间里一次补上,单个区间的 max_busy_duration 可以大于区间本身的长度。在本站中实测里,2 个 worker 的服务在一次 1.8 秒的搜索重建后,1 秒的区间里 max_busy_duration 是 1403ms。
首次 poll 延迟比预期大几百毫秒
首次 poll 延迟 = 第一次 poll 的时刻 − instrumented_at,而 instrumented_at 是在 instrument() 被调用时记下的,不是 spawn 时。上面第 2 行,先 instrument 再等 200ms 才 spawn,这 200ms 全算进了首次 poll 延迟;同样等 200ms,但在 spawn 那一行才 instrument,延迟只有几十微秒。
常见的写法是先把一批 future 包好放进 Vec,再逐个 spawn,或者把包好的 future 交给一个有界队列、由消费者稍后 spawn。这两种情况下首次 poll 延迟量到的是「排队等着被 spawn」加上「被 spawn 之后等着被 poll」。如果想要的是后一段,就在 tokio::spawn(monitor.instrument(fut)) 这一行包;如果前一段也想要,那它正好量到了。机制见 Instrumented 与 instrument_poll 的「第一段:首次 poll 延迟」。
slow_poll_ratio 是 NaN,poll_time_histogram 是空的
两件事碰巧经常一起出现,原因不同。
NaN:slow_poll_ratio 是慢 poll 数 ÷ poll 总数,long_delay_ratio 是长排队数 ÷ 排队总数,都是浮点除法。intervals() 的某个区间里一次 poll 都没有(任务都在等外部,或者这个路由这段时间没人访问)就是 0.0 ÷ 0.0 = NaN;同一个区间里 8 个 mean_* 却返回 0,因为它们除以 0 时特意返回零(TaskMetrics 与派生指标)。有的看板把 NaN 画成断点,有的导出器拒收,metrics-rs 集成则原样导出 NaN(metrics-rs 与 metrique)。第 3 行的 guarded 是一种处理:分母为 0 时按 0 算;也可以跳过这个区间不导出,看你希望看板上「没有流量」显示成 0 还是空白。
空直方图:poll_time_histogram 要两样东西:编译时带 --cfg tokio_unstable(不带时字段本身不存在,见 E0609),以及建运行时时调 Builder::enable_metrics_poll_time_histogram()。#[tokio::main] 不会替你调,所以第 5 行有 poll 计数、桶数却是 0,不报错。自己建运行时并打开它:
// 只在 --cfg tokio_unstable 下有意义
let mut b = tokio::runtime::Builder::new_multi_thread();
b.worker_threads(2).enable_all();
if enable {
b.enable_metrics_poll_time_histogram();
}
let rt = b.build().unwrap();
let monitor = RuntimeMonitor::new(rt.handle());
enable_metrics_poll_time_histogram=false polls=10 buckets=0
enable_metrics_poll_time_histogram=true polls=10 buckets=10
默认是 10 个 100µs 宽的线性桶,900µs 以上都落进最后一个,看长尾要换成对数桶,见 Worker 差分与 poll 时间直方图 的「poll 时间直方图」一节。
两个看板的 max_idle_duration 对不上
第 4 行,同一个 monitor 开了两个 intervals():两边都看到了那次 100ms 的空闲(idled=1),但只有先 next() 的 a 拿到了最大空闲,b 是 0。计数和时长是每个迭代器各自记住上一次的读数做差,互不干扰;区间最大值做不了差,只能读一个「区间内」的原子变量再 swap(0) 清零,一个 monitor 只有这一份,谁先读谁拿走。
实际中的样子:一个后台任务每 10 秒 intervals() 打日志,同时 metrics-rs 的 reporter 自己也开了一个 intervals() 每 30 秒导出;或者两个看板各起一个采样任务。修法是一个 monitor 只开一个 intervals(),取到的 TaskMetrics 再分发给各个消费者(它实现了 Clone);或者需要两种周期时,一个用 intervals(),另一个用 cumulative() 自己做差,cumulative() 读的是全局最大值,不会清零。细节见 intervals:迭代器差分。
小结
busy_ratio范围是 0 到 worker 数,要百分比再除以workers_count;计数提交滞后会让单个区间更「超标」。- 首次 poll 延迟从
instrument()算起,包和spawn不在同一行时,中间的时间也算进去。 - 区间里没有 poll 时两个比率是 NaN,均值是 0;导出前判断分母。
poll_time_histogram要tokio_unstable加enable_metrics_poll_time_histogram(),#[tokio::main]不会打开它,空着也不报错。- 区间最大空闲靠
swap(0),同一个 monitor 的第二个intervals()读到 0;一个 monitor 只开一个。