Rust in Everything
基于 tracing-subscriber 0.3.23

Registry

主线位置:span 主线的仓库。info_span! 过了几道门以后,new_span 一路传到最里面的 Registry,它在 sharded-slab 的池里占一个槽、返回 Id;span.enter() 把这个 Id 压进当前线程的 span 栈,事件靠这个栈找到「当前 span」;守卫 drop 时出栈;最后一个 Span 句柄 drop 时引用计数归零,所有 layer 的 on_close 跑完之后槽才被清空、放回池里。事件主线上它几乎什么都不做:event 是空函数,只在 layer 查当前 span 和父 span 时被用到。

flowchart TB
  reg["Registry"] --> spans["spans:Pool DataInner"]
  reg --> cur["current_spans"]
  reg --> nfid["next_filter_id:u8"]
  spans --> slot["一个槽:DataInner"]
  slot --> meta["metadata、parent"]
  slot --> rc["ref_count"]
  slot --> ext["extensions:RwLock"]
  slot --> fm["filter_map"]
  cur --> tls["每线程一个 SpanStack"]

Registry 是 tracing-subscriber 里唯一真正「存 span」的 Subscriber。它自己不输出任何东西,文档的说法是「Registry does not actually record traces itself: instead, it collects and stores span data that is exposed to any Layers wrapping it」。tracing_subscriber::registry() 就是 Registry::default()。它外面的 layer 怎么排、怎么收到通知,见 Layer 与 Layered;Id、Attributes 这些类型本身见 span 与 Event 的数据。

三个字段

pub struct Registry {
    spans: Pool<DataInner>,
    current_spans: ThreadLocal<RefCell<SpanStack>>,
    next_filter_id: u8,
}
字段存什么来自
spans所有还没关闭的 span,一个 span 一个槽sharded-slab 0.1.7 的 Pool
current_spans每个线程进入了哪些 spanthread_local 1.1 的 ThreadLocal
next_filter_id已经分出去几个每层过滤的 FilterId见 过滤:全局与每层

Registry 实现的 Subscriber 方法分成三类:

方法Registry 做什么
register_callsite / enabled / event_enabled没有每层过滤时总是 always / true;有的话取出各个过滤器汇总的结果
record / record_follows_from / event空函数:字段和事件交给外面的 layer 处理
new_span / clone_span / try_close分配槽、增减引用计数
enter / exit / current_span维护线程局部的 span 栈

record 的注释写得直接:「This is intentionally not implemented, as recording fields on a span is the responsibility of layers atop of this registry.」Registry 只存所有 layer 都用得到的东西:元数据、父 span、引用计数;字段格式化成什么样,各个 layer 自己决定,存进下面讲的 Extensions。

DataInner:一个槽里存什么

DataInner:

struct DataInner {
    filter_map: FilterMap,
    metadata: &'static Metadata<'static>,
    parent: Option<Id>,
    ref_count: AtomicUsize,
    // The span's `Extensions` typemap. Allocations for the `HashMap` backing
    // this are pooled and reused in place.
    pub(crate) extensions: RwLock<ExtensionsInner>,
}
字段含义
metadataspan 的调用点元数据,'static,只存一个指针
parent父 span 的 Id;子 span 持有父 span 的一个引用计数
ref_count有多少个 Span 句柄(以及子 span)指着它
extensionslayer 自己的数据,按类型存
filter_map每层过滤:这个 span 被哪些过滤器关掉了

Pool 和普通的 slab 不同:槽被清空时里面的值不 drop,而是调用 Clear::clear 原地清理,下次分配时直接复用。所以 DataInner 要实现 Default(第一次分配时用)和 Clear,文档说这两个实现是「load-bearing」。Default 里 metadata 不能是空指针,于是造了一个名为 "" 的 NULL_METADATA,它指向的 NullCallsite 被调用时会 unreachable!,因为槽在被 new_span 填好之前不会被读到。

Clear 做三件事:

    fn clear(&mut self) {
        // A span is not considered closed until all of its children have closed.
        // ...
        if self.parent.is_some() {
            // ...
            let subscriber = dispatcher::get_default(Dispatch::clone);
            if let Some(parent) = self.parent.take() {
                let _ = subscriber.try_close(parent);
            }
        }

        // Clear (but do not deallocate!) the pooled `HashMap` for the span's extensions.
        self.extensions
            .get_mut()
            // ...
            .clear();

        self.filter_map = FilterMap::new();
    }
  1. 释放对父 span 的引用。这里调的是整个 dispatcher 的 try_close,不是 self.try_close,注释解释了原因:Layered::try_close 靠内层的返回值决定要不要调 on_close,如果 Registry 直接减自己的计数,外面的 layer 就收不到父 span 关闭的通知。
  2. 清空 Extensions 的 HashMap,但保留它分配的内存,下一个用这个槽的 span 不用重新分配。
  3. 重置每层过滤的位图。

ref_count 不在这里清零:new_span 分配时断言它是 0 再设成 1,见下一节。

new_span:从池里取一个槽

new_span:

    fn new_span(&self, attrs: &span::Attributes<'_>) -> span::Id {
        let parent = if attrs.is_root() {
            None
        } else if attrs.is_contextual() {
            self.current_span().id().map(|id| self.clone_span(id))
        } else {
            attrs.parent().map(|id| self.clone_span(id))
        };

        let id = self
            .spans
            // Check out a `DataInner` entry from the pool for the new span. If
            // there are free entries already allocated in the pool, this will
            // preferentially reuse one; otherwise, a new `DataInner` is
            // allocated and added to the pool.
            .create_with(|data| {
                data.metadata = attrs.metadata();
                data.parent = parent;
                data.filter_map = crate::filter::FILTERING.with(|filtering| filtering.filter_map());
                // ...
                let refs = data.ref_count.get_mut();
                debug_assert_eq!(*refs, 0);
                *refs = 1;
            })
            .expect("Unable to allocate another span");
        idx_to_id(id)
    }

父 span 的三种来源在 span 与 Event 的数据 讲过。这里要注意的是 self.clone_span(id):确定父 span 后立刻给它的计数加一,这个引用由子 span 的 DataInner::parent 持有,直到子 span 的槽被 Clear 时才释放。所以只要子 span 还活着,父 span 就不会关闭,即使用户早就 drop 了父 span 的所有句柄。

create_with 返回槽的键,idx_to_id 把它变成 Id:

#[inline]
fn idx_to_id(idx: usize) -> Id {
    Id::from_u64(idx as u64 + 1)
}

#[inline]
fn id_to_idx(id: &Id) -> usize {
    id.into_u64() as usize - 1
}

加一是因为 Id 是 NonZeroU64,而 sharded-slab 的键可以是 0。池满了(超出下面算出的容量)create_with 返回 None,new_span 就 panic:「Unable to allocate another span」。

Id 里装着什么

键不是简单的「第几个槽」。sharded-slab 0.1.7 把三个数打包进一个 usize:槽在本分片里的地址、分片号(每个线程一个分片)、槽的代数。位宽由 DefaultConfig 算出来,64 位平台上:

常量(DefaultConfig)值
INITIAL_PAGE_SIZE32
MAX_THREADS4096
MAX_PAGESWIDTH / 2 = 32
部分位宽的算法位宽位置
地址 AddrMAX_PAGES + ADDR_INDEX_SHIFT,后者是 32.trailing_zeros() + 1 = 638第 0–37 位
线程号 TidMAX_SHARDS.trailing_zeros() + 1,MAX_SHARDS = next_pow2(4095) = 409613第 38–50 位
代数 Generation剩下的所有位:64 − 5113第 51–63 位

即 键 = 代数 << 51 | 线程号 << 38 | 地址。一个线程的分片里,第一页 32 个槽,之后每页翻倍,最多 32 页。代数在槽被清空时加一,13 位,同一个槽用 8192 次之后回绕。

为什么要代数?sharded-slab 的文档说是为了防 ABA:同一个槽被释放、再分配给别的值以后,拿旧键去查必须查不到,而不是查到新值。对 Registry 来说,这意味着一个已经关闭的 span 的 Id,不会被错认成复用了同一个槽的新 span。

用一个程序把 Id 拆开:

tracing = "=0.1.44"
tracing-subscriber = "=0.3.23"
use tracing::Span;
use tracing_subscriber::layer::SubscriberExt;

// sharded-slab 0.1.7 DefaultConfig(64 位):低 38 位地址,13 位线程号,再往上是代数
fn show(label: &str, span: &Span) {
  let id = span.id().expect("span 没被过滤").into_u64();
  let key = id - 1;
  let addr = key & ((1 << 38) - 1);
  let tid = (key >> 38) & ((1 << 13) - 1);
  let generation = key >> 51;
  println!("{label:<16} Id({id:<16}) 地址 {addr:<2} 线程 {tid} 代数 {generation}");
}

fn main() {
  let sub = tracing_subscriber::registry().with(tracing_subscriber::layer::Identity::new());
  tracing::subscriber::set_global_default(sub).unwrap();

  let a = tracing::info_span!("a");
  show("a", &a);
  let b = tracing::info_span!(parent: &a, "b");
  show("b (a 的子)", &b);
  let c = tracing::info_span!("c");
  show("c", &c);

  drop(c);
  let d = tracing::info_span!("d");
  show("d (c 关闭后)", &d);
  drop(d);
  let e = tracing::info_span!("e");
  show("e (d 关闭后)", &e);

  let a2 = a.clone();
  drop(a);
  let f = tracing::info_span!("f");
  show("f (a 还有克隆)", &f);
  drop(a2);
  drop(b); // b 是最后一个引用 a 的地方,a 在这之后才真正关闭
  let g = tracing::info_span!("g");
  show("g (a、b 关闭后)", &g);

  std::thread::spawn(|| {
    let t = tracing::info_span!("t");
    show("t (另一个线程)", &t);
  })
  .join()
  .unwrap();
}

Identity 是一个什么都不做的 layer,套上它是为了让 try_close 经过 Layered,走和真实程序一样的关闭路径。M2 Max、rustc 1.99.0、--release,连跑 3 次相同:

a                Id(1               ) 地址 0  线程 0 代数 0
b (a 的子)         Id(2               ) 地址 1  线程 0 代数 0
c                Id(3               ) 地址 2  线程 0 代数 0
d (c 关闭后)        Id(2251799813685251) 地址 2  线程 0 代数 1
e (d 关闭后)        Id(4503599627370499) 地址 2  线程 0 代数 2
f (a 还有克隆)       Id(4               ) 地址 3  线程 0 代数 0
g (a、b 关闭后)      Id(2251799813685250) 地址 1  线程 0 代数 1
t (另一个线程)        Id(274877906945    ) 地址 0  线程 1 代数 0
  • a、b、c:新槽按地址 0、1、2 依次分配,代数 0,Id 是 1、2、3。
  • d、e:c 关闭后槽 2 被清空、代数加一,d 复用它,键是 2⁵¹ + 2,Id 再加一。d 关闭后 e 又复用,代数 2。一条日志穿过 tracing 里看到的 Id(2251799813685249) 就是地址 0、代数 1。
  • f:drop 了 a,但还有克隆 a2,计数没归零,槽 0 没释放,f 只能拿新槽 3。
  • g:drop a2 以后 a 的计数还是 1(b 持有),drop b 才让 a 关闭。g 拿到的是 b 的槽 1,不是 a 的槽 0:a 是在 b 的槽被清空的过程中(Clear::clear 里释放父引用)关闭的,sharded-slab 先跑完 clear 再把槽放回空闲链表,所以 a 的槽 0 先入链表、b 的槽 1 后入,空闲链表后进先出。
  • t:另一个线程第一次用 sharded-slab,拿到线程号 1,在自己的分片里从地址 0 开始,Id 是 2³⁸ + 1。不同线程分配 span 不竞争同一个空闲链表,这是「sharded」的意思。
📝NOTE
没有蠢问题

问: 既然 Id 带了代数,旧 Id 不会撞上新 span,那我能不能把 span.id() 当请求 id 写进日志,事后用来串起一个请求?

答: 不能。Registry 文档的「Span ID Generation」一节只保证「unique at a given point in time」:同一时刻两个活着的 span 不会同号,但关闭的 span 的号「will eventually」被复用。代数只有 13 位,一个槽被用 8192 次就回绕到同一个键;而且不同进程之间的 Id 毫无关系。文档建议:要在历史数据里唯一标识 span,自己发号,「A counter is generally sufficient for this」;分布式追踪要用追踪系统自己的 id,通过字段或 span 的扩展数据挂上去。

Extensions:layer 自己的数据

Registry 只存公共数据,layer 的私有数据放在每个 span 的 extensions 里。它是一个按类型索引的 map(AnyMap,代码注释说取自 http crate 的 Extensions):

type AnyMap = HashMap<TypeId, Box<dyn Any + Send + Sync>, BuildHasherDefault<IdHasher>>;

键是 TypeId,本身已经是一个哈希值,所以 IdHasher 不再计算,write_u64 直接把它存下来当结果。每种类型只能存一个值:一个 layer 用自己的私有类型当键,就不会和别的 layer 冲突。

SpanRef::extensions() 返回 Extensions,里面是 RwLock 的读守卫,只能 get;extensions_mut() 返回 ExtensionsMut,是写守卫,可以 insert、replace、get_mut、remove。注意 insert 断言这个类型之前没有值:

    pub fn insert<T: Send + Sync + 'static>(&mut self, val: T) {
        assert!(self.replace(val).is_none())
    }

同一个类型插两次会 panic,要覆盖就用 replace。fmt::Layer 在 on_new_span 里把格式化好的字段以 FormattedFields<N> 的类型存进这里,事件输出时直接取出来拼接,见 fmt。span 关闭时 Clear::clear 清空这个 map 但不释放内存,下一个 span 复用。

SpanStack:每个线程一个当前 span 栈

current_spans 的类型是 ThreadLocal<RefCell<SpanStack>>。ThreadLocal 来自 thread_local crate,和 std 的 thread_local! 不同,它是一个普通的值,每个 Registry 实例各有一份「每线程一个栈」,同一个线程上两个 Registry(比如测试里用 with_default 各装一个)互不干扰。这是 PR #901 改的,提交标题是「use the thread_local crate to allow multiple registries」。

SpanStack 是一个 Vec,每个元素多带一个 duplicate 标记:

#[derive(Debug)]
struct ContextId {
    id: Id,
    duplicate: bool,
}
// ...
pub(crate) struct SpanStack {
    stack: Vec<ContextId>,
}

impl SpanStack {
    #[inline]
    pub(super) fn push(&mut self, id: Id) {
        let duplicate = self.stack.iter().any(|i| i.id == id);
        self.stack.push(ContextId { id, duplicate });
    }

    #[inline]
    pub(super) fn pop(&mut self, expected_id: &Id) -> bool {
        if let Some((idx, _)) = self
            .stack
            .iter()
            .enumerate()
            .rev()
            .find(|(_, ctx_id)| ctx_id.id == *expected_id)
        {
            let ContextId { id: _, duplicate } = self.stack.remove(idx);
            return !duplicate;
        }
        false
    }

    #[inline]
    pub(crate) fn iter(&self) -> impl Iterator<Item = &Id> {
        self.stack
            .iter()
            .rev()
            .filter_map(|ContextId { id, duplicate }| if !*duplicate { Some(id) } else { None })
    }

    #[inline]
    pub(crate) fn current(&self) -> Option<&Id> {
        self.iter().next()
    }
}

三个细节:

  • push 用线性查找判断重复。栈通常只有几层,比哈希表快。
  • pop 从栈顶往下找要出栈的 Id,不要求它在栈顶。守卫的 drop 顺序和进入顺序不一致时(比如两个 EnteredSpan 按非嵌套的顺序 drop),栈也不会错乱。
  • iter 和 current 跳过 duplicate 的元素。一个 span 已经在栈里、又被进入一次,新压入的那一项不算数:当前 span 由栈里没有重复的最上面那一项决定。这条规则从 #420 引入 Registry 时就在。

Registry 的 enter、exit 只是压栈和出栈:

    fn enter(&self, id: &span::Id) {
        self.current_spans
            .get_or_default()
            .borrow_mut()
            .push(id.clone());
    }

    fn exit(&self, id: &span::Id) {
        if let Some(spans) = self.current_spans.get() {
            spans.borrow_mut().pop(id);
        }
    }

pop 的返回值被丢掉了,push 也不再返回任何东西,下面的冷知识讲为什么。current_span 读栈的 current(),再查池拿元数据,组成 span::Current;Span::current()、new_span 的上下文父 span、Context::lookup_current 最终都走到这里。

📝NOTE
冷知识:enter 曾经会给 span 加引用计数

0.3.21 之前,push 返回「是不是第一次进入」,enter 在第一次进入时调 clone_span 给计数加一,exit 在对应的出栈时再减一(2020 年的 #1059 把它优化成只对第一次进入计数)。这样即使所有 Span 句柄都被 drop 了,一个还在栈上的 span 也不会被关闭。

后来出了两个问题。#3331 修的是 #3223:exit 里减计数用的是 dispatcher::get_default(|dispatch| dispatch.try_close(..)),span 在另一个没有装这个 subscriber 的线程上进出时,减到了别的 dispatcher 上,引用泄漏、span 永远不关闭。PR 的判断是「a span being exited is not yet ready to close. All that is needed is to decrement the reference count within the current registry」,改成了 self.try_close。紧接着 #3289 干脆把计数整个去掉:生产环境的持续剖析显示「7.7% of samples were found within the stacktrace of a Span::enter. Of those samples, 22.8% were inside clone_span」,而这层保护「was originally included to protect against misuse of the tracing-core API」,用得少,「not worth the performance hit」。

两个改动都首次出现在 tracing-subscriber 0.3.21,CHANGELOG 分别记作「Change registry exit to decrement local span ref only」和「Remove clone_span on enter」;0.3.21 被 yank,实际可用的第一个版本是 0.3.22。duplicate 标记原本是为计数服务的,现在只剩 iter 跳过重复项这一个用途。

duplicate 规则会带来一个不太直观的结果,见本页的动脑筋。

try_close 与 CloseGuard

引用计数

clone_span 和 try_close 照着 std::sync::Arc 写:

        let refs = span.ref_count.fetch_add(1, Ordering::Relaxed);
        assert_ne!(
            refs, 0,
            "tried to clone a span ({:?}) that already closed",
            id
        );
    fn try_close(&self, id: span::Id) -> bool {
        let span = match self.get(&id) {
            Some(span) => span,
            None if std::thread::panicking() => return false,
            None => panic!("tried to drop a ref to {:?}, but no such span exists!", id),
        };

        let refs = span.ref_count.fetch_sub(1, Ordering::Release);
        if !std::thread::panicking() {
            assert!(refs < usize::MAX, "reference count overflow!");
        }
        if refs > 1 {
            return false;
        }

        // Synchronize if we are actually removing the span (stolen
        // from std::Arc); this ensures that all other `try_close` calls on
        // other threads happen-before we actually remove the span.
        fence(Ordering::Acquire);
        true
    }

加计数用 Relaxed:能调 clone_span 说明手里已经有一个引用,计数至少是 1。减计数用 Release,减到零的那个线程再做一次 Acquire 栅栏,保证其他线程之前对这个 span 的所有访问都发生在关闭之前,和 Arc::drop 的做法一样。查不到 Id 时 panic,除非线程已经在 panic 中(Drop 里的 try_close 不能二次 panic)。clone_span 查不到时的 panic 消息还提示了一种常见的误用:「This may be caused by consuming a parent span (parent: span) rather than borrowing it (parent: &span).」

try_close 返回 true 时槽并没有被清空。 它只是报告「计数归零了」,真正的清空交给 CloseGuard。

CloseGuard:等所有 on_close 跑完

layer 在 on_close 里经常要读这个 span 的数据:名字、父 span、自己存在 Extensions 里的计时。如果 Registry::try_close 归零时立刻清空槽,外面的 layer 收到 on_close 时就查不到了。可 Registry 是最里面的一层,它不知道外面有几层、哪一层是最后一个。

解决办法是线程局部计数 CLOSE_COUNT 加守卫 CloseGuard。在 Layer 与 Layered 里看到,每一层 Layered::try_close 进来时,只要内层能 downcast 到 Registry,就调 start_close 把 CLOSE_COUNT 加一、拿一个守卫;内层返回 true 时 set_closing(),然后调本层的 on_close;函数返回时守卫 drop:

impl Drop for CloseGuard<'_> {
    fn drop(&mut self) {
        // ...
        let _ = CLOSE_COUNT.try_with(|count| {
            let c = count.get();
            // Decrement the count to indicate that _this_ guard's
            // `on_close` callback has completed.
            //
            // Note that we *must* do this before we actually remove the span
            // from the registry, since dropping the `DataInner` may trigger a
            // new close, if this span is the last reference to a parent span.
            count.set(c - 1);

            // If the current close count is 1, this stack frame is the last
            // `on_close` call. If the span is closing, it's okay to remove the
            // span.
            if c == 1 && self.is_closing {
                self.registry.spans.clear(id_to_idx(&self.id));
            }
        });
    }
}

以 Layered<C, Layered<B, Layered<A, Registry>>> 为例,drop 最后一个句柄时:

步骤CLOSE_COUNT发生什么
进入 C 层的 try_close1拿守卫 gC,递归到内层
进入 B 层的 try_close2拿守卫 gB
进入 A 层的 try_close3拿守卫 gA,Registry::try_close 返回 true
A 层3set_closing,A.on_close,gA drop:3 → 2,不清
B 层2B.on_close,gB drop:2 → 1,不清
C 层1C.on_close,gC drop:1 → 0,c == 1,清空槽

只有最外层的守卫看到 c == 1,它 drop 时所有层的 on_close 都已经返回。清空槽会调 Clear::clear,它可能释放父 span 的最后一个引用,触发父 span 的一整轮新的关闭;注释特意强调先减计数再清空,就是为了让这轮嵌套的关闭从 0 重新开始数。计数是线程局部的,因为一次关闭从头到尾都在同一个线程的同一条调用链上。

实测:三个 layer 都在 on_close 里查 span,A 还在 Extensions 里记进入次数;父 span 的句柄先 drop,子 span 后 drop。

use tracing::span::{Attributes, Id};
use tracing::{Dispatch, Subscriber};
use tracing_subscriber::layer::{Context, Layer, SubscriberExt};
use tracing_subscriber::registry::{LookupSpan, Registry};

// 挂在 span 的 Extensions 里的数据:进入了几次
struct Enters(u32);

struct Check(&'static str);

impl<S: Subscriber + for<'a> LookupSpan<'a>> Layer<S> for Check {
  fn on_new_span(&self, _: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) {
    if self.0 == "A" {
      ctx.span(id).unwrap().extensions_mut().insert(Enters(0));
    }
  }
  fn on_enter(&self, id: &Id, ctx: Context<'_, S>) {
    if self.0 == "A" {
      ctx.span(id).unwrap().extensions_mut().get_mut::<Enters>().unwrap().0 += 1;
    }
  }
  fn on_close(&self, id: Id, ctx: Context<'_, S>) {
    match ctx.span(&id) {
      Some(span) => {
        let parent = span.parent().map(|p| p.name()).unwrap_or("-");
        let enters = span.extensions().get::<Enters>().map(|e| e.0);
        println!(
          "  {} on_close {:?}: 查得到 {},父 {},进入 {:?} 次",
          self.0,
          id,
          span.name(),
          parent,
          enters
        );
      }
      None => println!("  {} on_close {:?}: 查不到", self.0, id),
    }
  }
}

fn main() {
  let dispatch = Dispatch::new(
    tracing_subscriber::registry()
      .with(Check("A"))
      .with(Check("B"))
      .with(Check("C")),
  );
  tracing::dispatcher::with_default(&dispatch, || {
    let parent = tracing::info_span!("parent");
    let child = tracing::info_span!(parent: &parent, "child");
    for _ in 0..3 {
      let _g = child.enter();
    }
    let parent_id = parent.id().unwrap();
    let child_id = child.id().unwrap();

    println!("-- drop(parent)");
    drop(parent);
    println!("-- drop(child)");
    drop(child);

    let registry = dispatch.downcast_ref::<Registry>().unwrap();
    println!("-- 关闭之后再查");
    println!("  parent {:?}: {}", parent_id, registry.span(&parent_id).is_some());
    println!("  child  {:?}: {}", child_id, registry.span(&child_id).is_some());
  });
}

连跑 3 次相同:

-- drop(parent)
-- drop(child)
  A on_close Id(2): 查得到 child,父 parent,进入 Some(3) 次
  B on_close Id(2): 查得到 child,父 parent,进入 Some(3) 次
  C on_close Id(2): 查得到 child,父 parent,进入 Some(3) 次
  A on_close Id(1): 查得到 parent,父 -,进入 Some(0) 次
  B on_close Id(1): 查得到 parent,父 -,进入 Some(0) 次
  C on_close Id(1): 查得到 parent,父 -,进入 Some(0) 次
-- 关闭之后再查
  parent Id(1): false
  child  Id(2): false
  • drop(parent) 什么都没打印:child 持有 parent 的一个引用,计数从 2 减到 1。
  • drop(child) 时三层都查得到 child,最外层的 C 也查得到,Extensions 里的计数还在:槽在 C 的守卫 drop 时才清空。
  • 清空 child 的槽时 Clear::clear 释放了父引用,parent 的关闭紧跟着发生,同样是 A、B、C 都查得到。
  • 都关闭以后,用 Dispatch::downcast_ref::<Registry>() 拿到 Registry 直接查,两个 Id 都查不到了:槽的代数已经变了。

LookupSpan、SpanRef 与 scope()

layer 通过 Context 查 span,Context 再通过 LookupSpan 去问最里面的 subscriber:

pub trait LookupSpan<'a> {
    type Data: SpanData<'a>;

    fn span_data(&'a self, id: &Id) -> Option<Self::Data>;

    fn span(&'a self, id: &Id) -> Option<SpanRef<'a, Self>>
    where
        Self: Sized,
    { /* ... */ }
    // ...
}

Registry 的实现很短:span_data 用 id_to_idx 去池里 get,拿到一个 pool::Ref<DataInner>,包成 Data。代数对不上的旧 Id,get 返回 None。SpanData 是这份数据的只读接口:id、metadata、parent、extensions、extensions_mut、is_enabled_for。这层 trait 的意义是:别的 subscriber 只要实现 LookupSpan 和 Subscriber,就能替换 Registry,外面的 layer 不用改。

SpanRef 把数据、registry 的引用和一个 FilterId 放在一起,提供 name()、fields()、parent()、extensions() 这些方法。parent() 拿着 DataInner::parent 再查一次池;用了每层过滤时,它会跳过对本层不可见的父 span,继续往上找。

scope() 返回一个从当前 span 往根走的迭代器 Scope,它的 next:

    fn next(&mut self) -> Option<Self::Item> {
        loop {
            let curr = self.registry.span(self.next.as_ref()?)?;

            #[cfg(all(feature = "registry", feature = "std"))]
            let curr = curr.with_filter(self.filter);
            self.next = curr.data.parent().cloned();

            // If the `Scope` is filtered, check if the current span is enabled
            // by the selected filter ID.

            #[cfg(all(feature = "registry", feature = "std"))]
            {
                if !curr.is_enabled_for(self.filter) {
                    // The current span in the chain is disabled for this
                    // filter. Try its parent.
                    continue;
                }
            }

            return Some(curr);
        }
    }

每一步查一次池、读出父 Id,被本层过滤器关掉的 span 跳过。要从根往下(fmt 打印 outer:inner: 前缀就是这个顺序),用 from_root():它先把整条链收集起来再反转。开了默认的 smallvec feature 时收集进 SmallVec<[SpanRef; 16]>,16 层以内不分配堆内存。Context::event_scope(event) 就是「事件的父 span 的 scope()」,本页动脑筋里的程序用它打印事件所在的 span 链。

注意 scope 走的是 parent 链,不是 span 栈。父子关系在 new_span 时就定死了;之后在哪个线程、按什么顺序进入,不改变 scope 的结果。span 栈只决定「新 span 和事件的上下文父 span 是谁」。

❗IMPORTANT
动脑筋:在 b 里再进一次 a,事件落在哪个 span?a 和 b 都是根 span(创建时没有进入任何 span)。先进入 a,再进入 b,然后在 b 里面再进入一次 a,发一条事件:
use tracing::{Event, Span, Subscriber};
use tracing_subscriber::layer::{Context, Layer, SubscriberExt};
use tracing_subscriber::registry::LookupSpan;

// 打印每条事件落在哪个 span 里(从 Registry 的 span 栈查出来的)
struct Where;
impl<S: Subscriber + for<'a> LookupSpan<'a>> Layer<S> for Where {
  fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) {
    let mut msg = String::new();
    struct V<'a>(&'a mut String);
    impl tracing::field::Visit for V<'_> {
      fn record_debug(&mut self, _: &tracing::field::Field, v: &dyn std::fmt::Debug) {
        self.0.push_str(&format!("{v:?}"));
      }
    }
    event.record(&mut V(&mut msg));
    let scope: Vec<_> = ctx
      .event_scope(event)
      .map(|s| s.map(|span| span.name()).collect())
      .unwrap_or_default();
    println!("{msg:<10} 所在 span 链:{scope:?}");
  }
}

fn cur() -> &'static str {
  Span::current().metadata().map(|m| m.name()).unwrap_or("(无)")
}

fn main() {
  let sub = tracing_subscriber::registry().with(Where);
  tracing::subscriber::with_default(sub, || {
    let a = tracing::info_span!("a");
    let b = tracing::info_span!("b");

    let _ga = a.enter();
    let _gb = b.enter();
    tracing::info!("进 a、b 后");
    {
      let _ga2 = a.enter(); // 在 b 里再进一次 a
      tracing::info!("再进 a 后");
      println!("Span::current() = {}", cur());
    }
    tracing::info!("出第二个 a 后");
    println!("Span::current() = {}", cur());
  });
}

M2 Max、rustc 1.99.0、--release。「再进 a 后」那条事件的 span 链是 ["a"] 还是 ["b"]?

动脑筋答案

连跑 3 次输出相同:

进 a、b 后    所在 span 链:["b"]
再进 a 后     所在 span 链:["b"]
Span::current() = b
出第二个 a 后   所在 span 链:["b"]
Span::current() = b

是 ["b"]。逐步看 span 栈:

操作栈(底 → 顶)current()
a.enter()aa
b.enter()a、bb
再 a.enter()a、b、a(重复)b:栈顶的 a 是重复项,被跳过
第二个守卫 dropa、bb:pop 从顶往下找到的是重复的那个 a

再次进入一个已经在栈里的 span,不会让它重新成为当前 span。链里只有 b 一项,是因为 b 创建时没有进入任何 span,它是根,event_scope 沿 parent 链往上走,走到 b 就结束了,a 不在这条链上。

如果真想让事件落在 a 里,可以写 info!(parent: &a, ..) 显式指定父 span,它不经过 span 栈。

小结

  • Registry 只存公共数据(元数据、父 span、引用计数、Extensions、过滤位图),record 和 event 是空函数,字段和输出交给 layer。
  • span 存在 sharded-slab 0.1.7 的 Pool<DataInner> 里,槽清空时原地 Clear,Extensions 的内存被复用;Clear 释放对父 span 的引用,可能连带关闭父 span。
  • Id = 键 + 1,键在 64 位平台上是「代数 13 位 | 线程号 13 位 | 地址 38 位」;复用的槽代数加一,所以复用后的 Id 是 2⁵¹ 量级的大数,旧 Id 查不到新 span。Id 只在同一时刻唯一,不能当请求 id。
  • 子 span 持有父 span 的一个引用,父 span 在所有子 span 关闭之后才关闭。
  • 当前 span 栈是 ThreadLocal<RefCell<SpanStack>>,每个 Registry 一份;重复进入的项被标为 duplicate,current() 跳过它们,所以再次进入一个已在栈里的 span 不改变当前 span。从 0.3.21 起 enter / exit 不再碰引用计数。
  • try_close 只报告计数归零;CloseGuard 和线程局部 CLOSE_COUNT 让最外层的 on_close 返回后才清空槽,所以每一层的 on_close 都能查到 span。
  • layer 通过 Context → LookupSpan → SpanRef 读数据;scope() 沿 parent 链往根走,from_root() 反过来。

💬 关联讨论

发起讨论
加载中...