Rust in Everything
基于 tracing 0.1.44

一条日志穿过 tracing

主线位置：两条主线都在。本页用一个最小程序装上 subscriber，在循环里创建一个 span、进入它、在里面记一条事件，循环跑两遍；外面包一层把每个 Subscriber 回调都打印出来的 subscriber，看清哪些事只在第一次经过调用点时发生，哪些每次都发生。每一步只点出落在哪个函数上，机制留给 02、03、05 三部分。

sequenceDiagram
  participant App as main
  participant CS as 调用点 static
  participant G as 全局 Dispatch
  participant Sub as fmt Subscriber
  participant Reg as Registry
  participant FL as fmt Layer
  Note over App,FL: init，只一次
  App->>G: Dispatch::new
  G->>Sub: max_level_hint
  G->>G: MAX_LEVEL 设为 INFO
  App->>G: set_global_default
  Note over App,FL: 每遍 info_span
  App->>App: 两道级别门
  App->>CS: interest()
  CS->>Sub: register_callsite 仅首遍
  App->>Sub: new_span
  Sub->>Reg: 分配槽，返回 Id
  App->>Sub: enter
  Sub->>Reg: Id 压进线程栈
  Note over App,FL: 每遍 info!
  App->>CS: interest()
  CS->>Sub: register_callsite 仅首遍
  App->>Sub: event_enabled 与 event
  Sub->>FL: on_event
  FL->>Reg: 查当前 span
  FL-->>App: 一行写到 stdout
  Note over App,FL: 离开循环体
  App->>Sub: exit，守卫 drop
  App->>Sub: try_close，Span drop
  Sub->>FL: on_close

程序

正常的写法是 tracing_subscriber::fmt().with_env_filter("info").init()。SubscriberBuilder::try_init 就是 self.finish().try_init()，所以把 finish() 得到的 fmt::Subscriber 包进一层 Spy 再 init()，装上的是同一套东西，只是外面多了一层。Spy 实现 Subscriber，每个方法打印一行，再原样转给里面的 fmt::Subscriber。

tracing = "=0.1.44"
tracing-subscriber = { version = "=0.3.23", features = ["env-filter"] }

use std::any::TypeId;

use tracing::level_filters::LevelFilter;
use tracing::span::{Attributes, Id, Record};
use tracing::subscriber::Interest;
use tracing::{Event, Metadata, Subscriber, debug, info, info_span};
use tracing_subscriber::util::SubscriberInitExt;

// 包在 fmt::Subscriber 外面：每个方法先打印一行，再原样转给里面
struct Spy<S>(S);

impl<S: Subscriber> Subscriber for Spy<S> {
  fn register_callsite(&self, meta: &'static Metadata<'static>) -> Interest {
    let interest = self.0.register_callsite(meta);
    println!("  [register_callsite] {} -> {:?}", meta.name(), interest);
    interest
  }

  fn max_level_hint(&self) -> Option<LevelFilter> {
    let hint = self.0.max_level_hint();
    println!("  [max_level_hint] -> {:?}", hint);
    hint
  }

  fn enabled(&self, meta: &Metadata<'_>) -> bool {
    let on = self.0.enabled(meta);
    println!("  [enabled] {} -> {on}", meta.name());
    on
  }

  fn new_span(&self, attrs: &Attributes<'_>) -> Id {
    let id = self.0.new_span(attrs);
    println!("  [new_span] {} -> {:?}", attrs.metadata().name(), id);
    id
  }

  fn record(&self, span: &Id, values: &Record<'_>) {
    println!("  [record] {:?}", span);
    self.0.record(span, values)
  }

  fn record_follows_from(&self, span: &Id, follows: &Id) {
    self.0.record_follows_from(span, follows)
  }

  fn event_enabled(&self, event: &Event<'_>) -> bool {
    let on = self.0.event_enabled(event);
    println!("  [event_enabled] -> {on}");
    on
  }

  fn event(&self, event: &Event<'_>) {
    println!("  [event] {}", event.metadata().name());
    self.0.event(event)
  }

  fn enter(&self, span: &Id) {
    println!("  [enter] {:?}", span);
    self.0.enter(span)
  }

  fn exit(&self, span: &Id) {
    println!("  [exit] {:?}", span);
    self.0.exit(span)
  }

  fn clone_span(&self, id: &Id) -> Id {
    println!("  [clone_span] {:?}", id);
    self.0.clone_span(id)
  }

  fn try_close(&self, id: Id) -> bool {
    let closed = self.0.try_close(id.clone());
    println!("  [try_close] {:?} -> {closed}", id);
    closed
  }

  unsafe fn downcast_raw(&self, id: TypeId) -> Option<*const ()> {
    if id == TypeId::of::<Self>() {
      Some(self as *const Self as *const ())
    } else {
      unsafe { self.0.downcast_raw(id) }
    }
  }
}

fn main() {
  // 过滤指令从命令行取，默认 "info"
  let directives = std::env::args().nth(1).unwrap_or_else(|| "info".to_owned());
  let fmt_subscriber = tracing_subscriber::fmt()
    .with_env_filter(directives.as_str())
    .with_ansi(false)
    .without_time()
    .finish();
  println!("init");
  Spy(fmt_subscriber).init();

  for i in 0..2 {
    println!("pass {i}");
    let span = info_span!("request", id = i);
    let _guard = span.enter();
    info!(n = i, "hello");
    debug!("detail");
  }
  println!("end");
}

几点说明：

  • register_callsite、max_level_hint、enabled、new_span、event_enabled、try_close 先转发、拿到返回值再打印；event、enter、exit 先打印再转发，所以 fmt 输出的那一行出现在 [event] 之后。
  • downcast_raw 必须转发：tracing-subscriber 的 Layered 关闭 span 时要从里面找出 Registry（见下文 try_close）。
  • current_span 没有转发，用的是默认实现。这个程序里没有代码调用 Span::current()，fmt 找当前 span 走的是它自己内部的 Registry，不经过这个方法。
  • with_ansi(false)、without_time() 去掉颜色和时间戳，让输出可以逐字节比较。

输出

M2 Max、rustc 1.99.0、--release，不带参数（过滤指令是 info），跑 3 次逐字节相同：

init
  [max_level_hint] -> Some(LevelFilter::INFO)
pass 0
  [register_callsite] request -> Interest(Always)
  [new_span] request -> Id(1)
  [enter] Id(1)
  [register_callsite] event src/bin/walk.rs:102 -> Interest(Always)
  [event_enabled] -> true
  [event] event src/bin/walk.rs:102
 INFO request{id=0}: walk: hello n=0
  [exit] Id(1)
  [try_close] Id(1) -> true
pass 1
  [new_span] request -> Id(2251799813685249)
  [enter] Id(2251799813685249)
  [event_enabled] -> true
  [event] event src/bin/walk.rs:102
 INFO request{id=1}: walk: hello n=1
  [exit] Id(2251799813685249)
  [try_close] Id(2251799813685249) -> true
end

按时机归一下类：

回调init第 0 遍第 1 遍
max_level_hint100
register_callsite02（span 和 info! 各一次）0
enabled000
new_span、enter、exit、try_close0各 1各 1
event_enabled、event0各 1各 1
来自 debug! 的任何回调000

max_level_hint 和 register_callsite 是一次性的，结果缓存在全局和调用点里；span 的生命周期和事件的分发每遍都要做；enabled 一次没调；debug! 连调用点都没注册。下面按时间顺序逐段对照源码。

init：装上 subscriber

fmt() 返回 SubscriberBuilder，with_env_filter 把过滤器换成 EnvFilter，finish 搭出这样一个类型：

fmt::Subscriber
  └ Layered<EnvFilter, Layered<fmt::Layer<Registry>, Registry>>

最里面是 Registry，它管 span 的存储和每个线程的 span 栈，但自己不输出任何东西；外面一层是 fmt::Layer，负责把事件格式化成一行；最外面是 EnvFilter，负责过滤。这种「一个 subscriber 套几层 layer」的组合方式见 Layer 与 Layered。

Spy(...).init() 走的是 SubscriberInitExt::try_init：

    fn try_init(self) -> Result<(), TryInitError> {
        dispatcher::set_global_default(self.into()).map_err(TryInitError::new)?;

        // Since we are setting the global default subscriber, we can
        // opportunistically go ahead and set its global max level hint as
        // the max level for the `log` crate as well. This should make
        // skipping `log` diagnostics much faster.
        #[cfg(feature = "tracing-log")]
        tracing_log::LogTracer::builder()
            // Note that we must call this *after* setting the global default
            // subscriber, so that we get its max level hint.
            .with_max_level(tracing_core::LevelFilter::current().as_log())
            .init()
            .map_err(TryInitError::new)?;

        Ok(())
    }

self.into() 把 Spy 变成 Dispatch，调的是 Dispatch::new。它在返回之前调用 callsite::register_dispatch，后者走到 Callsites::rebuild_interest：

    fn rebuild_interest(&self, dispatchers: dispatchers::Rebuilder<'_>) {
        let mut max_level = LevelFilter::OFF;
        dispatchers.for_each(|dispatch| {
            // If the subscriber did not provide a max level hint, assume
            // that it may enable every level.
            let level_hint = dispatch.max_level_hint().unwrap_or(LevelFilter::TRACE);
            if level_hint > max_level {
                max_level = level_hint;
            }
        });

        self.for_each(|callsite| {
            rebuild_callsite_interest(callsite, &dispatchers);
        });
        LevelFilter::set_max(max_level);
    }

输出里唯一的 [max_level_hint] -> Some(LevelFilter::INFO) 就是这里问的。EnvFilter 根据指令 info 报出 INFO，LevelFilter::set_max 把它写进全局原子变量 MAX_LEVEL。这时还没有任何调用点注册过，self.for_each 什么也不做，所以 init 阶段没有 register_callsite。

注意顺序：重算发生在 Dispatch::new 里，比 set_global_default 还早。set_global_default 本身只做一次性初始化（GLOBAL_INIT 的 compare-exchange），第二次调用返回错误。最后 tracing-subscriber 默认开着的 tracing-log feature 顺手装上 LogTracer，把 log 记录转成 tracing 事件，见 与 log 互通。全局和线程局部两种 dispatcher 见 Dispatch。

第一、二道门：级别

info!(n = i, "hello") 展开后（cargo expand 1.0.104 的输出，删掉了元数据和字段部分）：

        {
            use ::tracing::__macro_support::Callsite as _;
            static __CALLSITE: ::tracing::callsite::DefaultCallsite = {
                // ... static META: Metadata<'static> = ...
                ::tracing::callsite::DefaultCallsite::new(&META)
            };
            let enabled = ::tracing::Level::INFO
                <= ::tracing::level_filters::STATIC_MAX_LEVEL
                && ::tracing::Level::INFO
                    <= ::tracing::level_filters::LevelFilter::current()
                && {
                    let interest = __CALLSITE.interest();
                    !interest.is_never()
                        && ::tracing::__macro_support::__is_enabled(
                            __CALLSITE.metadata(),
                            interest,
                        )
                };
            if enabled {
                (|value_set: ::tracing::field::ValueSet| {
                    let meta = __CALLSITE.metadata();
                    ::tracing::Event::dispatch(meta, &value_set);
                })({
                    // ... 用 i 和 format_args!("hello") 构造 ValueSet
                });
            } else {
            }
        };

这段代码来自 event! 的一个分支，&& 串起四道门，前一道不过后面的都不执行：

  1. STATIC_MAX_LEVEL：编译期常量，由 max_level_* / release_max_level_* feature 决定，这里没开，是 TRACE。
  2. LevelFilter::current()：读刚才 init 写进去的 MAX_LEVEL，是 INFO。
  3. __CALLSITE.interest()：调用点缓存的 Interest，下一节。
  4. __is_enabled：问当前 dispatcher 的 enabled，再下一节。

前两道在宏 level_enabled! 里。debug!("detail") 停在第二道：DEBUG <= INFO 不成立（Level 越详细越「大」），表达式短路，interest() 根本没被调用，所以输出里找不到 walk.rs:103 的任何痕迹，这个调用点自始至终没有注册。关掉的日志只花一次原子读和一次比较，靠的就是这两道门，细节在 级别的几道门 和 Metadata、Level 与 LevelFilter。

info_span!("request", id = i) 展开成 span! 的同一类判断，门是一样的，通过后调用 Span::new。宏怎么从 info! 一路分派到这个分支见 宏展开。

第三道门：调用点的 Interest 缓存

每个宏调用点都有一个自己的 static __CALLSITE，类型是 tracing-core 的 DefaultCallsite。它的 interest：

    pub fn interest(&'static self) -> Interest {
        match self.interest.load(Ordering::Relaxed) {
            Self::INTEREST_NEVER => Interest::never(),
            Self::INTEREST_SOMETIMES => Interest::sometimes(),
            Self::INTEREST_ALWAYS => Interest::always(),
            _ => self.register(),
        }
    }

interest 字段的初值是 0xFF（DefaultCallsite::new 里写的），三个已知值都对不上，于是第一次经过时落到 register：把注册状态从 UNREGISTERED 推到 REGISTERING，把自己挂进全局调用点链表，再由 rebuild_callsite_interest 问每个 dispatcher 的 register_callsite，合并结果写回 interest。输出里第 0 遍的两行 [register_callsite] 就是这里来的，span 调用点名字是 request，事件调用点的名字是宏拼出来的 "event " + file!() + ":" + line!()。

第 1 遍再经过，interest 已经是 INTEREST_ALWAYS，一次 Relaxed 读就返回，不再碰 subscriber。注册的并发处理、全局链表、新 subscriber 装上后怎么重算，见 Callsite 与 Interest 缓存。

结果为什么是 Always：最外层的 EnvFilter 有一条静态指令 info，它的 register_callsite 在静态指令放行时返回 Interest::always()，里层的 fmt::Layer 和 Registry 也都是 always，Layered 把三者合并起来仍是 always。合并规则见 Layer 与 Layered，指令怎么匹配见 EnvFilter。

第四道门：enabled，只在 sometimes 时问

第四道门是 tracing 的 __is_enabled：

    pub fn __is_enabled(meta: &Metadata<'static>, interest: Interest) -> bool {
        interest.is_always() || crate::dispatcher::get_default(|default| default.enabled(meta))
    }

Interest 是 always 时 || 直接短路，所以输出里一次 [enabled] 也没有。只有调用点的 Interest 是 sometimes（「这次放不放行要看当时的情况」），才在每次经过时问一遍 enabled。

❗IMPORTANT
动脑筋：第 1 遍里 debug!("detail") 会打印哪几行？

同一个程序，过滤指令换成 info,[request]=debug，意思是「默认 info；在名为 request 的 span 里放开到 debug」：

cargo run --release --bin walk -- 'info,[request]=debug'

平台 M2 Max、rustc 1.99.0。debug! 在 request span 里，这回会被输出。pass 1 之后、[exit] 之前，debug!("detail") 这一行会让 Spy 打印哪几个 [...]？

事件：从 Event::dispatch 到一行输出

四道门都过了，宏构造 ValueSet，调用 tracing-core 的 Event::dispatch：

    pub fn dispatch(metadata: &'static Metadata<'static>, fields: &'a field::ValueSet<'_>) {
        let event = Event::new(metadata, fields);
        crate::dispatcher::get_default(|current| {
            current.event(&event);
        });
    }

get_default 先看 SCOPED_COUNT：没有任何线程设过局部 dispatcher 时它是 0，直接用全局的那个，不碰线程局部变量。本程序走的就是这条快路径。

Dispatch::event 先问 event_enabled，通过了才调 event：

    pub fn event(&self, event: &Event<'_>) {
        let subscriber = self.subscriber();
        if subscriber.event_enabled(event) {
            subscriber.event(event);
        }
    }

这就是每遍都有的 [event_enabled] -> true 和 [event] 两行。和 enabled 不同，event_enabled 拿到的是整个 Event，可以看字段的值，所以它没法缓存，每次都要问。

📝NOTE
冷知识：event_enabled 是 0.1.28 才加的

tracing-core 0.1.27 及以前，Dispatch::event 拿到事件就直接调 subscriber.event(event)。过滤只能看 Metadata（级别、target、名字），看不到字段的值。

#2008 加上了这一步。提交说明的动机只有一句：「Allow filter layers to filter on the contents of events (see #2007).」做法是：「This branch adds a new Subscriber::event_enabled method, taking an Event and returning bool. This is called before the Subscriber::event method, and if it returns false, Subscriber::event is not called.」同时给 tracing-subscriber 的 Layer 加了同名方法，Layered 按层询问，任何一层说 false 就不再往下分发。这个 PR 合进的是 master（0.2 分支），0.1 线上第一个带它的版本是 tracing-core 0.1.28，CHANGELOG 写的是「Subscriber::event_enabled method to enable filtering based on Event field values」。上面输出里每遍都有的 [event_enabled] -> true，就是这次改动留下的。

fmt::Subscriber 把调用转给它里面的 Layered。Layered::event 先交给里层，再交给本层的 layer：

    fn event(&self, event: &Event<'_>) {
        self.inner.event(event);
        self.layer.on_event(event, self.ctx());
    }

三层依次是：Registry::event 什么也不做（「recording events is the responsibility of layers atop of this registry」），fmt::Layer::on_event 输出一行，EnvFilter 不处理事件。fmt::Layer::on_event 把事件格式化进一个线程局部的 String 缓冲区，再通过 make_writer 拿到 writer（默认是 stdout）一次 write_all 写出去。行首的 request{id=0}: 是格式化时通过 ctx 从 Registry 取出当前线程的 span 栈、逐个打印 span 名字和字段得到的。格式的拼法见 fmt。

span：new_span、enter、exit、try_close

info_span! 过了门以后调用 Span::new，它通过 get_default 拿到当前 dispatcher，最后到 Span::make_with：

    fn make_with(
        meta: &'static Metadata<'static>,
        new_span: Attributes<'_>,
        dispatch: &Dispatch,
    ) -> Span {
        let attrs = &new_span;
        let id = dispatch.new_span(attrs);
        let inner = Some(Inner::new(id, dispatch));
        // ...
    }

Inner 存了 id 和一份 Dispatch 的克隆。之后的 enter、exit、try_close 都直接用这份 Dispatch，不再查 get_default：一个 span 永远回到创建它的那个 subscriber。

new_span 一路到 Layered::new_span：先让里层分配 id，再通知本层 on_new_span。最里层的 Registry::new_span 从 sharded-slab 0.1.7 的池里取一个槽，记下元数据、父 span，引用计数置 1，idx_to_id 把槽的键加一当作 Id。第 0 遍拿到 Id(1)。fmt::Layer 在自己的 on_new_span 里把字段 id=0 格式化好，存进这个槽的扩展数据，事件输出时直接取用。

span.enter() 调 do_enter，也就是 inner.subscriber.enter(&inner.id)，返回守卫 Entered。Registry::enter 把 id 压进当前线程的 span 栈，事件就是从这个栈找到「当前 span」的。

循环体结束时，局部变量按声明的逆序 drop：先 _guard，Entered 的 Drop 调 do_exit，Registry 把 id 出栈，输出 [exit]；再 span，Span 的 Drop 调 subscriber.try_close(id)。Registry 把引用计数减一，减之前是 1，说明这是最后一个句柄，返回 true；Layered::try_close 看到 true 才调各层的 on_close，并且用 Registry 的 CloseGuard 保证所有层的 on_close 都跑完才真正释放槽。输出里的 [try_close] Id(1) -> true 就是这一步。

Span 被 clone 时会调 clone_span 把计数加一，那时 try_close 会返回 false；本程序没有 clone，所以 [clone_span] 没出现。Span、Entered 和引用计数见 Span 与 Entered，槽的分配和 CloseGuard 见 Registry。

📝NOTE
没有蠢问题

问： 第 1 遍的 span 拿到的 Id 是 2251799813685249，不是 2。第 0 遍的 span 已经关掉了，为什么不是 1 或者 2？

答： 第 0 遍的 span 关闭后，它的槽被释放，第 1 遍的 span 复用了同一个槽，但 sharded-slab 给槽的键加了一个「代数」，复用一次加一，它的文档管这叫「generational indices」。sharded-slab 0.1.7 的默认配置在 64 位平台上，键的低 38 位是槽地址，接着 13 位是线程分片号，再往上全是代数（Generation 的 SHIFT 是 38 + 13 = 51）。第 1 遍的键是「地址 0、分片 0、代数 1」，也就是 2⁵¹ = 2251799813685248，加一就是输出里的数。文档说这是为了防 ABA 问题：「the key returned by the first call to insert will not map to the new value」。拿旧的 Id(1) 去查，代数对不上，查不到，过期的 Id 不会被错认成复用了同一个槽的新 span。

动脑筋答案

M2 Max、rustc 1.99.0、--release，带参数 'info,[request]=debug' 跑 3 次逐字节相同：

init
  [max_level_hint] -> Some(LevelFilter::DEBUG)
pass 0
  [register_callsite] request -> Interest(Always)
  [new_span] request -> Id(1)
  [enter] Id(1)
  [register_callsite] event src/bin/walk.rs:102 -> Interest(Always)
  [event_enabled] -> true
  [event] event src/bin/walk.rs:102
 INFO request{id=0}: walk: hello n=0
  [register_callsite] event src/bin/walk.rs:103 -> Interest(Sometimes)
  [enabled] event src/bin/walk.rs:103 -> true
  [event_enabled] -> true
  [event] event src/bin/walk.rs:103
DEBUG request{id=0}: walk: detail
  [exit] Id(1)
  [try_close] Id(1) -> true
pass 1
  [new_span] request -> Id(2251799813685249)
  [enter] Id(2251799813685249)
  [event_enabled] -> true
  [event] event src/bin/walk.rs:102
 INFO request{id=1}: walk: hello n=1
  [enabled] event src/bin/walk.rs:103 -> true
  [event_enabled] -> true
  [event] event src/bin/walk.rs:103
DEBUG request{id=1}: walk: detail
  [exit] Id(2251799813685249)
  [try_close] Id(2251799813685249) -> true
end

答案是三行：[enabled]、[event_enabled]、[event]，后面跟着 fmt 输出的 DEBUG 那一行。逐项看：

  • init：max_level_hint 变成了 DEBUG。指令里最详细的级别是 debug，MAX_LEVEL 随之变成 DEBUG，debug! 这回过得了第二道门。
  • 第 0 遍：debug! 的调用点第一次注册，EnvFilter 的静态指令只放行到 info，不放行它；但指令里有按 span 生效的部分（[request]），EnvFilter 不能一口回绝，返回 Interest(Sometimes)。于是第四道门生效，问 enabled：当前在 request span 里，返回 true。
  • 第 1 遍：register_callsite 不再出现，Sometimes 已经缓存在调用点里；但 enabled 照样要问，因为答案取决于事件发生时在哪个 span 里，没法缓存。
  • info! 和 span 的调用点仍是 Always，两遍里都没有 [enabled]。

Sometimes 的代价就在这里：每次经过都要多一次 get_default 和一次 enabled 调用。EnvFilter 怎么判断当前 span 是否匹配，见 EnvFilter。

小结

  • 装 subscriber 时，Dispatch::new 就把所有 subscriber 的 max_level_hint 合并进全局 MAX_LEVEL，比 set_global_default 还早；这是 init 阶段唯一的回调。
  • 宏展开成一个 static DefaultCallsite 加四道用 && 串起的门：STATIC_MAX_LEVEL、LevelFilter::current()、调用点缓存的 Interest、Interest 为 sometimes 时才问的 enabled。
  • 被级别挡住的 debug! 连调用点都不注册，没有任何回调。
  • register_callsite 只在第一次经过调用点时发生，结果存进调用点的原子变量；之后一次 Relaxed 读就够。
  • 事件每次都走 Event::dispatch → get_default（没有局部 dispatcher 时直接用全局）→ event_enabled → event → Layered 逐层 on_event → fmt::Layer 写一行。
  • span 每次都走 new_span（Registry 分配槽）、enter（压栈）、exit（出栈）、try_close（计数归零才 on_close）；Span 自带创建它的 Dispatch，不再查 get_default。
  • 复用的槽带着新的代数，所以第二个 span 的 Id 是 2⁵¹ + 1，不是 2。

💬 关联讨论

发起讨论
加载中...