Rust in Everything
基于 hyper-util 0.1.21

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 行池的清理任务 IdleTask0.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:开了 tracing feature,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 各种任务;legacy Client 的连接任务、on_idle、后台建连接、池的清理任务。HTTP/1 服务端连接不经过。
  • 实测:传播 span 时,请求的 span 要等连接任务和清理任务都结束才关闭;0.1.20 下清理任务不退出,span 活到 Client 被 drop。要导出 span 的 subscriber(如 OpenTelemetry)用 MkSpanExecutor 或者不传播。

💬 关联讨论

发起讨论
加载中...