rt::tracing:给 spawn 出去的任务带上 span
主线位置:两条主线的旁路。hyper 和 hyper-util 在需要后台任务时调用
Executor::execute(见 Executor 与 Timer);这一页讲的是这些后台任务运行时,tracing 的「当前 span」是什么,以及那个 span 因此会活多久。
sequenceDiagram participant R as 请求 span 下的调用方 participant C as legacy Client participant E as Executor participant T as 连接任务 participant P as 池的清理任务 R->>C: request(进入请求 span) C->>E: execute(连接任务) Note over E: TokioExecutor(0.1.21):不带 span<br/>CurrentSpanExecutor:带上请求 span E->>T: spawn C->>E: execute(IdleTask) E->>P: spawn C-->>R: 响应,body 读完 Note over R: 0.1.21 TokioExecutor:请求 span 在这里关闭 P->>T: 空闲超时,连接被清掉,任务结束 Note over P: CurrentSpanExecutor:两个任务都结束,请求 span 才关闭
tracing 的 span 在最后一个句柄被 drop 时关闭。fut.instrument(span) 或 fut.in_current_span() 把一个 span 句柄放进 future 里,future 活多久,span 就至少开多久。后台任务往往比发起它的请求活得长,这一页的问题都从这里来。
0.1.21 的行为变化
TokioExecutor::execute 在 0.1.21:
fn execute(&self, fut: Fut) {
#[cfg(feature = "rt-tracing-exec-force")]
tokio::spawn(fut.in_current_span());
#[cfg(not(feature = "rt-tracing-exec-force"))]
tokio::spawn(fut);
}
0.1.20 的同一段是 #[cfg(feature = "tracing")]:只要打开 tracing feature,spawn 出去的任务就带上当前 span。这个行为是 0.1.11 加 tracing feature 时一起加的。0.1.21 的 CHANGELOG 把它去掉的理由写得很直接:
This caused issues for some users, due to background tasks keeping a span open for the duration of a long-lived connection.
改动是 #322。要临时恢复旧行为,打开 rt-tracing-exec-force(Cargo.toml 第 100 行),它不在 full 里,CHANGELOG 说它「will be removed in a future release」。CHANGELOG 里把执行器写成 rt::TokioExecutor<E>,实际的类型不带泛型参数。
注意 tracing 这个 feature 本身还在 full 里(第 97 行)。很多项目并没有自己打开它,而是被依赖里的某个 features = ["full"] 打开的,这时 0.1.20 → 0.1.21 的变化完全是被动的。本站就是这样,见 本站的出站客户端。
三个包装执行器
取代旧行为的是 rt::tracing 模块里的三个包装器,要 tracing feature,在 rt 下重新导出:
| 类型 | span 从哪来 | 什么时候取 |
|---|---|---|
CurrentSpanExecutor<E> | Span::current() | 每次 execute 时 |
WithSpanExecutor<E> | 构造时给定;current(inner) 取构造时的当前 span | 构造时,之后固定 |
MkSpanExecutor<E, F> | 闭包 F: Fn() -> Span 现造 | 每次 execute 时 |
三个实现都只有一两行,CurrentSpanExecutor 的:
impl<E, F> Executor<F> for CurrentSpanExecutor<E>
where
E: Executor<Instrumented<F>>,
F: Future,
{
fn execute(&self, future: F) {
self.inner.execute(future.in_current_span());
}
}
约束只有「内层执行器接受 Instrumented<F>」,没有 Send、'static,也不绑定 tokio。包 TokioExecutor 时,Send + 'static 由 TokioExecutor 自己的实现要求。CurrentSpanExecutor::new(TokioExecutor::new()) 就是旧行为,上游的 examples/client_tracing.rs 用的正是它:
let executor = {
// Propagate spans to spawned tasks.
use hyper_util::rt::{CurrentSpanExecutor, TokioExecutor};
let tokio = TokioExecutor::new();
CurrentSpanExecutor::new(tokio)
};
模块文档推荐的选择是「For most typical applications, CurrentSpanExecutor<E> should suffice」,并且点了名:OpenTelemetry 一类的 subscriber 可能要等 span 关闭才导出它里面的事件,这时把请求 span 交给长寿的后台任务就有问题。MkSpanExecutor 是给这种情况的:每个后台任务一个新的 span,用 follows_from 记下因果,而不是成为请求 span 的子 span、把它撑开:
let mk = || {
let span = info_span!("example");
span.follows_from(Span::current());
span
};
let executor = MkSpanExecutor::new(TokioExecutor::new(), mk);
哪些任务经过 Executor
这决定了「带上 span」影响的是哪些任务。
hyper 一侧只有 HTTP/2:服务端每个流一个任务,客户端的连接任务和每个请求的发送任务,表格见 Executor 与 Timer。HTTP/1 的连接不经过执行器,服务端的连接任务是你自己 tokio::spawn 的(axum::serve 也是),所以「HTTP/1 服务端的连接任务带不带 span」和这几个执行器无关。
hyper-util 的 legacy Client 有五处:
| 位置 | 任务 | 活多久 |
|---|---|---|
client.rs 第 552 行 | HTTP/2 连接任务 | 连接存在多久就多久 |
| 第 584 行 | HTTP/1 连接任务(with_upgrades()) | 同上,包括在池里空闲的时间 |
| 第 362 行 | on_idle:等 HTTP/1 连接可以回池 | 到响应 body 读完 |
| 第 446 行 | 赛跑输掉、在后台建完的新连接 | 到连接建完进池 |
pool.rs 第 459 行 | 池的清理任务 IdleTask | 0.1.21:到池子空了;0.1.20:到池子被 drop |
除了 on_idle,都比请求活得长。连接任务和 IdleTask 都是在第一个请求的调用栈里 spawn 的,这个请求的 span 就被它们带走了。
实验:请求 span 什么时候关闭
一个自己写的 tracing Layer:span 关闭时打印时刻,hyper-util 的每个事件打印它所在的 span。legacy Client 的 pool_idle_timeout 设成 1 秒并给 pool_timer(reqwest 默认也给了),在 info_span!("request") 里发一个请求、读完 body,然后等 3 秒再 drop Client。
hyper = { version = "1", features = ["full"] } # 1.12.0
hyper-util = { version = "=0.1.21", features = ["full"] }
tokio = { version = "=1.54.1", features = ["full"] }
tracing = "0.1"
tracing-subscriber = { version = "0.3", features = ["registry"] }
http-body-util = "0.1"
bytes = "1"
// Prints span closes and every hyper-util event with the spans it sits in.
struct Probe;
impl<S: Subscriber + for<'a> LookupSpan<'a>> Layer<S> for Probe {
fn on_close(&self, id: span::Id, ctx: Context<'_, S>) {
if let Some(s) = ctx.span(&id) { println!("{:>5}ms close span `{}`", ms(), s.name()); }
}
fn on_event(&self, e: &Event<'_>, ctx: Context<'_, S>) {
if !e.metadata().target().starts_with("hyper_util") { return; }
let mut m = Msg(String::new());
e.record(&mut m);
let scope: Vec<_> = ctx.event_scope(e).map(|s| s.from_root().map(|s| s.name()).collect()).unwrap_or_default();
println!("{:>5}ms event {:?} spans={scope:?}", ms(), m.0);
}
}
async fn run<E>(name: &str, exec: E, addr: std::net::SocketAddr)
where
E: hyper::rt::Executor<std::pin::Pin<Box<dyn std::future::Future<Output = ()> + Send>>> + Clone + Send + Sync + 'static,
{
println!("== {name}");
let client: Client<_, Empty<Bytes>> = Client::builder(exec)
.pool_idle_timeout(Duration::from_secs(1))
.pool_timer(TokioTimer::new())
.build_http();
let url: hyper::Uri = format!("http://{addr}/").parse().unwrap();
async {
let resp = client.get(url).await.unwrap();
resp.into_body().collect().await.unwrap();
println!("{:>5}ms response body read", ms());
}
.instrument(tracing::info_span!("request"))
.await;
tokio::time::sleep(Duration::from_secs(3)).await;
println!("{:>5}ms drop client", ms());
drop(client);
tokio::time::sleep(Duration::from_millis(200)).await;
}
// main: run("TokioExecutor", TokioExecutor::new(), ..) then
// run("CurrentSpanExecutor<TokioExecutor>", CurrentSpanExecutor::new(TokioExecutor::new()), ..)
0.1.21,两种执行器(建连接那几行事件两边相同,省略):
== TokioExecutor
2ms event "checkout waiting for idle connection: (\"http\", 127.0.0.1:50696)" spans=["request"]
...
5ms event "pooling idle connection for (\"http\", 127.0.0.1:50696)" spans=["request"]
5ms response body read
5ms close span `request`
1007ms event "idle interval checking for expired" spans=[]
1007ms event "idle interval evicting expired for (\"http\", 127.0.0.1:50696)" spans=[]
1007ms event "pool empty, canceling idle interval" spans=[]
1007ms server: connection closed
3007ms drop client
== CurrentSpanExecutor<TokioExecutor>
3209ms event "checkout waiting for idle connection: (\"http\", 127.0.0.1:50696)" spans=["request"]
...
3211ms event "pooling idle connection for (\"http\", 127.0.0.1:50696)" spans=["request"]
3211ms response body read
4212ms event "idle interval checking for expired" spans=["request"]
4212ms event "idle interval evicting expired for (\"http\", 127.0.0.1:50696)" spans=["request"]
4212ms event "pool empty, canceling idle interval" spans=["request"]
4213ms close span `request`
4213ms server: connection closed
6212ms drop client
同一个实验换成 hyper-util 0.1.20(打开 full,于是有 tracing),用的是 TokioExecutor:
== hyper-util 0.1.20 TokioExecutor (tracing feature on)
1ms event "checkout waiting for idle connection: (\"http\", 127.0.0.1:50743)" spans=["request"]
...
3ms response body read
3ms event "put; add idle connection for (\"http\", 127.0.0.1:50743)" spans=["request"]
3ms event "pooling idle connection for (\"http\", 127.0.0.1:50743)" spans=["request"]
1005ms event "idle interval checking for expired" spans=["request"]
1005ms event "idle interval evicting expired for (\"http\", 127.0.0.1:50743)" spans=["request"]
1005ms server: connection closed
2007ms event "idle interval checking for expired" spans=["request"]
3005ms drop client
3005ms event "pool closed, canceling idle interval" spans=["request"]
3005ms close span `request`
- 0.1.21 +
TokioExecutor:body 读完,请求 span 立刻关闭。后台任务的事件不在任何 span 里。 CurrentSpanExecutor:请求 span 一直开到 1 秒后连接被清理掉。不是在 body 读完时,也不是在连接离开池子时,而是连接任务和IdleTask都结束时;清理任务打出的三条事件都挂在这个早已结束的请求下面。- 0.1.20:行为和
CurrentSpanExecutor一样,但 0.1.20 没有 0.1.21 的 #292,池子空了IdleTask也不退出,每个周期醒一次(2007ms 那条),一直到Client被 drop。请求 span 跟着活到了Client被 drop 的那一刻。对一个进程级共享的Client来说,第一个请求的 span 永远不会关闭。
这里请求只有一个。真实的服务里,第一个触发建连接的请求的 span 被连接任务带走;同一条连接上后来的请求,它们的事件由连接任务产生时,挂的还是第一个请求的 span。日志里看到某个请求 ID 下面出现别的请求的连接错误,原因多半在这里。
小结
- hyper-util 0.1.11–0.1.20:开了
tracingfeature,TokioExecutor就把当前 span 传给 spawn 的任务。0.1.21(#322)去掉了,rt-tracing-exec-force可以临时恢复。tracing常常是被依赖的full打开的。 - 三个包装器:
CurrentSpanExecutor(每次取当前 span,等于旧行为)、WithSpanExecutor(固定一个 span)、MkSpanExecutor(每个任务新造一个,可配follows_from)。都不要求Send,不绑定 tokio。 - 经过
Executor的任务:hyper 的 HTTP/2 各种任务;legacyClient的连接任务、on_idle、后台建连接、池的清理任务。HTTP/1 服务端连接不经过。 - 实测:传播 span 时,请求的 span 要等连接任务和清理任务都结束才关闭;0.1.20 下清理任务不退出,span 活到
Client被 drop。要导出 span 的 subscriber(如 OpenTelemetry)用MkSpanExecutor或者不传播。