🔭 tracing/tracing-subscriberでログが出力される仕組みを理解する

本記事ではRustのtracing/tracing-subscriberでログが出力される仕組みをソースコードを読みながら理解することを目指します。 具体的には以下のコードにおいてtracingがどのようにしてログを出力するかを見ていきます。

use tracing::{info, info_span};

fn main() {
    tracing_subscriber::fmt()
        .init();

    let span = info_span!("span_1", key="hello");
    let _guard = span.enter();

    info!("hello");
}

Cargo.toml

[dependencies]
thread_local = "1.1.4"
tracing = "=0.1.35"
tracing-core = "=0.1.30"
tracing-subscriber = { version = "=0.3.16", default-features = false, features = ["smallvec", "fmt", "ansi", "std"] }

上記のコードを実行すると以下の出力を得ます。

2022-11-11T08:39:02.198973Z  INFO span_1{key="hello"}: tracing_handson: hello

versionはtracing-subscriber-0.3.16を対象にしました。
(なお、tracing::info!()はtracing的にはEventといわれているので以下ではログではなくEventと呼んでいきます)

本記事のゴール

本記事では以下の点を目指します。

• tracing_subscriber::fmt()::init()でなにが初期化されているか
  • tracing_subscriber::Subscriberの内部構造
    • Subscriberの実態はLayer * n + Registry
  • tracing_subscriber::Registryの役割
• tracing::Spanの仕組み
  • info_span!()の内容がどのようにして後続のeventに出力されるか
• tracing::info!()が出力される仕組み

本記事で扱わないこと

• tracing-future
  • async/awaitでのtracingの利用の仕方(ただし、asyncなコードでそのまま使うとどうしてうまく動作しないかは理解できます)
• tracing-log
  • log crateとの互換処理も提供されています
• per-filter-layer
  • tracing-opentelemetryにPRを送った記事でper-filter-layerの利用方法について書きました

前提の確認

Spanとは

最初にtracingを触った時にinfo!()やerror!()はログの出力として理解できたのですが、spanの役割や使い方がわかりませんでした。公式のdocには以下のようにあります。

Unlike a log line that represents a moment in time, a span represents a period of time with a beginning and an end.

自分の言葉で説明するなら、spanは後続のstack trace上で作られるevent(info!())に付与されるkey,valueで、eventに実行時のcontextを付与するものです。といってもわかりづらいと思うので具体的なコードでみていきます。

use tracing::{info, info_span};

fn start() {
    // Generate unique request id
    let request_id = "req-123";

    let _guard = info_span!("req", request_id).entered();

    handle_request();
}

fn handle_request() {
    // Authenticate
    let user_id = "user_aaa";
    let _guard = info_span!("user", user_id).entered();

    do_process();
}

fn do_process() {
    info!("successfully processed");
}

fn main() {
    tracing_subscriber::fmt()
        .init();

    start();
}

処理の内容はなんでもよいのですが、まずリクエストの識別子を生成して次に認証して、...と処理を進めていく中で処理内容のcontextができていくと思います。それをspanとして表現します。上記のコードを実行すると以下のようなログが出力されます。

2022-11-11T09:19:18.317693Z  INFO req{request_id="req-123"}:user{user_id="user_aaa"}: span: successfully processed

info!()で生成したeventにspanに与えたkey,valueが付与されました。このように処理の階層構造のcontextをログに構造的に表現できます。一度このログが作れるとわかるともうspanなしには戻れないです。

thread_local!, thread_local::ThreadLocal

tracingの実装ではしばしばthread_local!やthread_local::ThreadLocalがでてきます。
自分自身、thread localという機構への理解があやしいのですが本記事を読む範囲では以下のようにRustのAPI的観点から捉えておけばよいと考えております。

thread_local!はglobalなstatic変数にRefCellを保持できる。
具体的には以下のコードはglobalなstatic変数を複数threadから変更しようとしておりcompileに失敗します。

static STATE: RefCell<String> = RefCell::new(String::new());

fn main() {
    let threads = 5;
    let mut handles = Vec::with_capacity(threads);
    for i in 0..threads {
        let handle = thread::spawn(move || {
            STATE.borrow_mut().push_str(i.to_string().as_str());
        });
        handles.push(handle);
    }

    for handle in handles {
        handle.join().unwrap();
    }
}

--> examples/thread_local.rs:8:15
  |
8 | static STATE: RefCell<String> = RefCell::new(String::new());
  |               ^^^^^^^^^^^^^^^ `RefCell<String>` cannot be shared between threads safely
  |
  = help: the trait `Sync` is not implemented for `RefCell<String>`
  = note: shared static variables must have a type that implements `Sync`

そこで、global変数STATEをthread_local!にするとcompileが通ります。

use std::cell::RefCell;
use std::thread;

thread_local! {
    static STATE: RefCell<String> = RefCell::new(String::new());
}

fn main() {
    let threads = 5;
    let mut handles = Vec::with_capacity(threads);
    for i in 0..threads {
        let handle = thread::spawn(move || {
            STATE.with(|state: &RefCell<String>| {
                state.borrow_mut().push_str(i.to_string().as_str());
            })
        });
        handles.push(handle);
    }

    for handle in handles {
        handle.join().unwrap();
    }
}

RefCellはSyncではないのでmulti threadではArc<Mutext<T>>等を使うところですが、thread localにするとthreadごとにglobal変数を保持でき、single threadで利用できたRefCellが使えます。

ThreadLocalは上記の機能をstructのfieldでも使えるようにするものです。 具体的には以下のコードはcompileが通りません。

use std::cell::RefCell;

struct A {
    _a: RefCell<String>,
}

fn should_sync<T: Sync>(_t: T) {}

fn main() {
    let a = A { _a: RefCell::new(String::new()) };
    should_sync(a);
}

  --> examples/thread_local.rs:14:17
   |
14 |     should_sync(a);
   |     ----------- ^ `RefCell<String>` cannot be shared between threads safely
   |     |
   |     required by a bound introduced by this call
   |
   = help: within `A`, the trait `Sync` is not implemented for `RefCell<String>`

RefCellがSyncでないと言われます。そこで、ThreadLocalでwrapするとcompileが通ります。

use std::cell::RefCell;
use thread_local::ThreadLocal;

struct A {
    _a: ThreadLocal<RefCell<String>>,
}

fn should_sync<T: Sync>(_t: T) {}

fn main() {
    let a = A { _a: ThreadLocal::new() };
    should_sync(a);
}

shareded_slab::Pool

shareded_slab::Poolはslabというデータ構造をmulti thread間で共有できるようにし(Sync)かつ、object pool likeなAPIを提供するものです。あまり深入りすると本記事のゴールからそれてしまうので、ここではdataをcreate/insertするとindex(usize)を返してくれるSyncで効率的なVecという程度に理解します。

Macroをexpand

tracing以外のcrateで押さえておきたい型は前提の確認で概要を押さえたのであとはtracingとstdだけで完結します。
まずはmacroをexpandして、実行されているtracingのapiを確認していきましょう。

use tracing::{info, info_span};

fn main() {
    tracing_subscriber::fmt()
        .init();

    let span = info_span!("span_1", key="hello");
    let _guard = span.enter();

    info!("hello");
}

このcodeをcargo expandすると以下のようになります。(compileできるようにprelude等を削りました。)

#![feature(fmt_internals)]
use std::prelude::rust_2021::*;
fn main() {
    tracing_subscriber::fmt().init();

    let span = {
        use ::tracing::__macro_support::Callsite as _;
        static CALLSITE: ::tracing::callsite::DefaultCallsite = {
            static META: ::tracing::Metadata<'static> = {
                ::tracing_core::metadata::Metadata::new(
                    "span_1",
                    "tracing_handson",
                    ::tracing::Level::INFO,
                    Some("src/main.rs"),
                    Some(8u32),
                    Some("tracing_handson"),
                    ::tracing_core::field::FieldSet::new(
                        &["key"],
                        ::tracing_core::callsite::Identifier(&CALLSITE),
                    ),
                    ::tracing::metadata::Kind::SPAN,
                )
            };
            ::tracing::callsite::DefaultCallsite::new(&META)
        };
        let mut interest = ::tracing::subscriber::Interest::never();
        if ::tracing::Level::INFO <= ::tracing::level_filters::STATIC_MAX_LEVEL
            && ::tracing::Level::INFO <= ::tracing::level_filters::LevelFilter::current()
            && {
                interest = CALLSITE.interest();
                !interest.is_never()
            }
            && ::tracing::__macro_support::__is_enabled(CALLSITE.metadata(), interest)
        {
            let meta = CALLSITE.metadata();
            ::tracing::Span::new(meta, &{
                #[allow(unused_imports)]
                use ::tracing::field::{debug, display, Value};
                let mut iter = meta.fields().iter();
                meta.fields().value_set(&[(
                    &iter.next().expect("FieldSet corrupted (this is a bug)"),
                    Some(&"hello" as  &dyn Value),
                )])
            })
        } else {
            let span = ::tracing::__macro_support::__disabled_span(CALLSITE.metadata());
            {};
            span
        }
    };
    let _guard = span.enter();
 {
        use ::tracing::__macro_support::Callsite as _;
        static CALLSITE: ::tracing::callsite::DefaultCallsite = {
            static META: ::tracing::Metadata<'static> = {
                ::tracing_core::metadata::Metadata::new(
                    "event src/main.rs:11",
                    "tracing_handson",
                    ::tracing::Level::INFO,
                    Some("src/main.rs"),
                    Some(11u32),
                    Some("tracing_handson"),
                    ::tracing_core::field::FieldSet::new(
                        &["message"],
                        ::tracing_core::callsite::Identifier(&CALLSITE),
                    ),
                    ::tracing::metadata::Kind::EVENT,
                )
            };
            ::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);
            })({
                #[allow(unused_imports)]
                use ::tracing::field::{debug, display, Value};
                let mut iter = CALLSITE.metadata().fields().iter();
                CALLSITE.metadata().fields().value_set(&[(
                    &iter.next().expect("FieldSet corrupted (this is a bug)"),
                    Some(&::core::fmt::Arguments::new_v1(&["hello"], &[]) as  &dyn Value),
                )])
            });
        } else {
        }
    };
}

長いですが、概要はシンプルです。 info_span!(),info!()共通で、macroを呼び出すと当該呼び出し箇所の情報が以下のようにtracing::callsite::DefaultCallsiteとして表現されます。

        static CALLSITE: ::tracing::callsite::DefaultCallsite = {
            static META: ::tracing::Metadata<'static> = {
                ::tracing_core::metadata::Metadata::new(
                    // ...
                )
            };
            ::tracing::callsite::DefaultCallsite::new(&META)
        };

まず見ていただきたいのが、static CALLSITEのようにstaticになっている点です。
tracingのコードを読むまで知らなかったのですが、rustでは関数の中でもstatic変数が定義できるそうです。

A static item defined in a generic scope (for example in a blanket or default implementation) will result in exactly one static item being defined, as if the static definition was pulled out of the current scope into the module.

https://doc.rust-lang.org/reference/items/static-items.html#statics--generics

関数内でstaticを定義しても実際にはmoduleのtop levelで定義したのと同様になり、当該変数には定義した関数からしかアクセスできないという挙動になります。
CALLSITEについては全体の構造を押さえてからのほうがわかりやすいのでここではmacroの呼び出しの情報(source code上の位置、key,value, span or event)を保持しているというくらいでOKです。

CALLSITEはstaticなのでcompile時に決まります。次の箇所からがruntime時の挙動です。

let mut interest = ::tracing::subscriber::Interest::never();
if ::tracing::Level::INFO <= ::tracing::level_filters::STATIC_MAX_LEVEL
    && ::tracing::Level::INFO <= ::tracing::level_filters::LevelFilter::current()
    && {
        interest = CALLSITE.interest();
        !interest.is_never()
    }
    && ::tracing::__macro_support::__is_enabled(CALLSITE.metadata(), interest)
{ // ... }

subscriberのInterestなるものや、levelの判定を行っています。こちらもsubscriberの構造がかかわってくるので後述します。ざっくりですがinfo_span!()やdebug_span!()のようなlevelに応じた判定処理を実施している程度に理解しておきます。次がspanの実質的な処理です。

let meta = CALLSITE.metadata();
::tracing::Span::new(meta, &{
    #[allow(unused_imports)]
    use ::tracing::field::{debug, display, Value};
    let mut iter = meta.fields().iter();
    meta.fields().value_set(&[(
        &iter.next().expect("FieldSet corrupted (this is a bug)"),
        Some(&"hello" as  &dyn Value),
    )])
})

ここで大事なのはtracing::Span::new()が呼び出されている点です。引数にはmacro呼び出し時の情報を渡しています。
spanの処理についてまとめると概要としては以下のようになります。

fn main() {
    tracing_subscriber::fmt().init();
    
    let span = {
        static CALLSITE = { /* ... */ };
        tracing::Span::new(CALLSITE)
    };
    let _guard = span.enter();
}

要は、tracing::Span::new()にmacroの情報渡して、spanを生成し、span.enter()して、guardをdropしないように変数で保持しているだけです。

info!()のevent生成でも流れはspanと同じで、staticなCALLSITE生成、levelの判定処理、api callという流れです。eventの場合はtracing::Event::dispatch(CALLSITE)が呼ばれます。

話を整理すると、メンタルモデルとしてはspanとeventのmacroは概ね以下のように展開されるといえます。

fn main() {
    tracing_subscriber::fmt().init();

    let span = info_span!("span_1", key="hello");
    let _guard = span.enter();

    info!("hello");
}

⬇

fn main() {
    tracing_subscriber::fmt().init();

    let span = {
        static CALLSITE = { /* ... */ };
        tracing::Span::new(CALLSITE)
    };
    let _guard = span.enter();

    {
        static CALLSITE = { /* ... */ }
        tracing::Event::dispatch(CALLSITE)
    }
}

ということで、以下のtracingのapiの処理を追っていきます。

1. tracing::Span::new()
2. tracing::Span::enter()
3. tracing::Event::dispatch()

さっそく、tracing::Span::new()のdefinitionにjumpしていきたいところですが、ここからはtracing_subscriber側の処理になるので、tracing_subscriber crateについて説明させてください。

tracing_subscriber crate

tracingは生成したspanやeventを処理するために必要な機能をtracing_core::Subscriberとして定義しています。tracingはtracing_core::Subscriberの実装がspanやeventの生成前にtracingのapiを通じて初期化されていることを期待しています。tracing_subscriberはtracing_core::Subscriberの実装を提供するためのcrateです。
tracingではtraitとそれを実装する型に同じ名前を使う場合があり最初は紛らわしいのですが、tracing_core::Subscriberはtraitでtracing_subscriber::fmt::Subscriberはこのtraitの実装を提供するstructです。
以後は紛らわしいのでtracing_subscriberのre-exportにならって、tracing_subscriber::fmt::SubscriberをFmtSubscriberと呼びます。

上記のコードの最初にでてきたtracing_subscriber::fmt().init();はFmtSubscriberを生成して、tracingに見える位置にセットする処理と理解することができます。

FmtSubscriber

さっそくFmtSubscriberの定義を確認してみましょう。

pub struct Subscriber<
    N = format::DefaultFields,
    E = format::Format<format::Full>,
    F = LevelFilter,
    W = fn() -> io::Stdout,
> {
    inner: layer::Layered<F, Formatter<N, E, W>>,
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/fmt/mod.rs#L225

Genericsが4つもでてきて、うっとなります。ただし、よくみてみると以下の構造をしているinnerのwrapperであることがわかります。

inner: layer::Layered<F,Formatter<_>>

Formatter<_>はすぐ下に以下のように定義されています。

pub type Formatter<
    N = format::DefaultFields,
    E = format::Format<format::Full>,
    W = fn() -> io::Stdout,
> = layer::Layered<fmt_layer::Layer<Registry, N, E, W>, Registry>;

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/fmt/mod.rs#L237

ということで、Formatterも実体はlayer::Layeredでした。
N = format::DefaultFieldsとE = format::Fromat<format::Full>はログの出力方法をカスタマイズするためのgenerics、W = fn() -> io::Stdoutはログの出力先を切り替えるためのgenericです。そこでこれらのgenericsをいったん無視するとFmtSubscriberは概ね以下の構造をしているといえます。

Layered<
    LevelFilter,
    Layered<
        fmt_layer::Layer,
        Registry,
    >
>

FmtSubscriberは、LevelFilter,fmt_layer::Layer, RegistryをLayeredというstructでnestさせてできていえるように見えないでしょうか。
ということで、tracing_subscriberのLayer,Layeredをまずは理解していきましょう。

Layer

まずはdocを見てみます。Layerについてはtracing_subscriber::layer moduleに説明があります。

The Layer trait, a composable abstraction for building Subscribers.

LayerはSubscriberを作るためのcomposable abstractionなtraitとあります。Layerを知ったあとに読むとなるほどと思えますが最初に読むとピンとこなかったです。

The Subscriber trait in tracing-core represents the complete set of functionality required to consume tracing instrumentation. This means that a single Subscriber instance is a self-contained implementation of a complete strategy for collecting traces; but it also means that the Subscriber trait cannot easily be composed with other Subscribers.

tracing_core::Subscriberはtracing instrumentationをconsumeするために必要な機能をすべて集約したものなので、Subscriber instanceはいろいろな責務をもちます。そのためSubscriberを他のSubscriberと組み合わせづらいという問題点があります。

In particular, Subscribers are responsible for generating span IDs and assigning them to spans. Since these IDs must uniquely identify a span within the context of the current trace, this means that there may only be a single Subscriber for a given thread at any point in time — otherwise, there would be no authoritative source of span IDs.

Subscriberを他のSubscriberとcomposableにできない理由が書いてあります。このspan IDを生成する箇所については後述します。ここではどうやらSubscriberの責務のひとつにspanにIDを振ることがあるくらいを押さえておきます。

On the other hand, the majority of the Subscriber trait’s functionality is composable: any number of subscribers may observe events, span entry and exit, and so on, provided that there is a single authoritative source of span IDs. The Layer trait represents this composable subset of the Subscriber behavior; it can observe events and spans, but does not assign IDs.

一方で、Subscriber traitのmethodはcomposable。
eventの出力やspanのentryやexitといった処理は複数のsubscriberで実装できます。(stdoutにjsonでloggingしつつ、特定のspanのパフォーマンス計測しつつ、特定のeventをmetricsで収集したり)
Layer traitはSubscriber traitの一部のmethodの実装を担い、Subscriberをcomposableにするためにあります。

まとめ

• tracing_core::Subscriberにはtracingを利用するうえで必要な処理がまとめて定義されている
• Subscriberの実装はspanにIDを付与する責務をもつ観点から特定のcontext内で1つである必要がある
• そこでSubscriberをcomposableに作っていくためにLayerがある

Layered

次にtracing_subscriber::layer::Layeredをみていきます。Layeredは以下のように定義されています。

pub struct Layered<L, I, S = I> {
    /// The layer.
    layer: L,

    /// The inner value that `self.layer` was layered onto.
    ///
    /// If this is also a `Layer`, then this `Layered` will implement `Layer`.
    /// If this is a `Subscriber`, then this `Layered` will implement
    /// `Subscriber` instead.
    inner: I,
    // ...
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/layer/layered.rs#L22

省略していますが、基本的には1つのLayerでinnerをwrapするstructです。コメントにある通り、inner: IにはSubscriberやLayerをいれます。

重要なのはLayeredはSubscriberをwrapしているときはSubscriberとして振る舞う点です。

impl<L, S> Subscriber for Layered<L, S>
where
    L: Layer<S>,
    S: Subscriber,
{
    // ...
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/layer/layered.rs#L89

またSubscriberの実装方法は

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

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/layer/layered.rs#L151-L154

のように、wrapしているinnerを呼び出した後自身のlayerを呼び出します。

まとめるとLayeredはSubscriberをcomposableに構築するためのLayerをまとめていくためのstructでそれ自身もSubscriberの実装であることがわかりました。

Filter

あらためてFmtSubscriberの概要を確認します。

Layered<
    LevelFilter,
    Layered<
        fmt_layer::Layer,
        Registry,
    >
>    

LayeredはinnerにSubscriber(orLayer)をもちLayerと組み合わせるということをみてきました。
とすると、LevelFilterもFilterといいながらLayerなのでしょうか。ここではFilterについて見ていきます。

Filterについてはlayer moduleのdocで以下のように説明されています。

As well as strategies for handling trace events, the Layer trait may also be used to represent composable filters. This allows the determination of what spans and events should be recorded to be decoupled from how they are recorded: a filtering layer can be applied to other layers or subscribers.

ということでLayerのうち,spanやeventを処理対象とするかの判定のみを行うLayerをFilterとしているようです。

pub use tracing_core::metadata::{LevelFilter, ParseLevelFilterError as ParseError};

impl<S: Subscriber> crate::Layer<S> for LevelFilter {
    fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest {
        if self >= metadata.level() {
            Interest::always()
        } else {
            Interest::never()
        }
    }

    fn enabled(&self, metadata: &Metadata<'_>, _: crate::layer::Context<'_, S>) -> bool {
        self >= metadata.level()
    }

    fn max_level_hint(&self) -> Option<LevelFilter> {
        Some(*self)
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/filter/level.rs#L11

として、LevelFilterにLayerを実装しています。
ということでLevelFilterの実体はtracingの有効判断を実装したLayerということがわかりました。

Registry

FmtSubscriberのcomponentで次にみていくのがRegistryです。

Layered<
    LevelFilter,
    Layered<
        fmt_layer::Layer,
        Registry,
    >
>    

Registryはもっとも深くnestされており、他のLayerはRegistry上にcomposeされています。また、Layeredの実装では基本的にinnerを最初に呼び出すので実質的に最初に呼び出されるのはRegistryの処理になります。まずはtracing_subscriber::registry::Registryのdocを見てみます。

A shared, reusable store for spans. A Registry is a Subscriber around which multiple Layers implementing various behaviors may be added. Unlike other types implementing Subscriber, Registry does not actually record traces itself: instead, it collects and stores span data that is exposed to any Layers wrapping it through implementations of the LookupSpan trait. The Registry is responsible for storing span metadata, recording relationships between spans, and tracking which spans are active and which are closed. In addition, it provides a mechanism for Layers to store user-defined per-span data, called extensions, in the registry. This allows Layer-specific data to benefit from the Registry’s high-performance concurrent storage.

まとめると

• Subscriberの実装で、layerが追加される
• traceを記録しない
• spanのdataをcollectして他のlayerに提供する
• metadataやrelationships,activeやcloseといったspanの情報を管理する
• extensionを通じてuser側でspanを拡張できる仕組みを提供する

ということで、Subscriberの機能のうちspan関連の責務をになっていそうです。詳細についてはこのあとSpan::new()やSpan::enter()をおっていく中でみていきます。
ここでは以下の点をおさえます

• Layeredの実装から最初によばれるのはRegistryの処理
• spanの情報を管理して他のLayerに提供するのがRegistryの責務

fmt_layer::Layer

Layered<
    LevelFilter,
    Layered<
        fmt_layer::Layer,
        Registry,
    >
>    

FmtSubscriberの最後のcomponentはfmt_layer::Layerです。docに

A Layer that logs formatted representations of tracing events.

とある通り、tracing_subscriber::Layerを実装するstructです。このLayerが実際にinfo!()した際にeventを出力する処理を実装します。

以下のように定義されています。

pub struct Layer<
    S,
    N = format::DefaultFields,
    E = format::Format<format::Full>,
    W = fn() -> io::Stdout,
> {
    make_writer: W,
    fmt_fields: N,
    fmt_event: E,
    fmt_span: format::FmtSpanConfig,
    is_ansi: bool,
    log_internal_errors: bool,
    _inner: PhantomData<fn(S)>,
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/fmt/fmt_layer.rs#L62

4つもgenericsをもっています。FmtSubscriberのgenericsが多かったのはこのfmt_layer::Layerのためです。
まずSですが、これはfmt_layer::LayerがwrapしているSubscriberを抽象化しています。最初わかりづらかったのはfmt_layer::Layer自体はSubscriberを保持しておらず、実際に保持しているのはLayeredになります。そのため、PhantomData<fn(S)>となっています。
NとEですが、tracing_subscriberではeventを出力する際に必要な機能が細かくtraitになっています。
Nはeventとspan共通のkey,valueを出力し、Eは実際にeventを出力します。Wは出力先の切り替えを担います。

impl<S, N, E, W> layer::Layer<S> for Layer<S, N, E, W>
where
    S: Subscriber + for<'a> LookupSpan<'a>,
    N: for<'writer> FormatFields<'writer> + 'static,
    E: FormatEvent<S, N> + 'static,
    W: for<'writer> MakeWriter<'writer> + 'static,
{
    // ...
    fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { /* .. */ }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/fmt/fmt_layer.rs#L764

のちほど処理の内容をおっていきますが、fmt_layer::LayerがLayerを実装しており、Layeredから呼ばれるon_event()が実際のeventのロギング処理です。

Subscriberの登録

FmtSubscriberの各componentをみてきたので最後にconstructしたFmtSubscriberをtracingから見える位置にセットする処理をみます。

tracing_subscriber::fmt().init();

この処理が呼ばれるとSubscriberBuilderがFmtSubscriberをconstructしたのち以下の処理が呼ばれます

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

        Ok(())
    }

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/util.rs#L59

dispatcher::set_global_defaultはtracing_coreに定義されており、以下のような処理です。

static GLOBAL_INIT: AtomicUsize = AtomicUsize::new(UNINITIALIZED);

const UNINITIALIZED: usize = 0;
const INITIALIZING: usize = 1;
const INITIALIZED: usize = 2;

static mut GLOBAL_DISPATCH: Option<Dispatch> = None;
// ...
pub fn set_global_default(dispatcher: Dispatch) -> Result<(), SetGlobalDefaultError> {
    if GLOBAL_INIT
        .compare_exchange(
            UNINITIALIZED,
            INITIALIZING,
            Ordering::SeqCst,
            Ordering::SeqCst,
        )
        .is_ok()
    {
        unsafe {
            GLOBAL_DISPATCH = Some(dispatcher);
        }
        GLOBAL_INIT.store(INITIALIZED, Ordering::SeqCst);
        EXISTS.store(true, Ordering::Release);
        Ok(())
    } else {
        Err(SetGlobalDefaultError { _no_construct: () })
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/dispatcher.rs#L296

名前にglobalとある通りglobal変数のGLOBAL_DISPATCHにセットする処理です。
AtomicUsize::compare_exchange()は現在の値が第一引数のときのみ第二引数の値をセットする関数です。
そのためこの処理は一度しか呼べないことがわかります。
set_global_default()の引数の型はDispatchとなっているので、FmtSubscriberからDispatchへの変換が必要です。

ここでDispatchの定義ですが以下にある通り、SubscriberをArcでtrait objectとして保持しているwrapperです。

#[derive(Clone)]
pub struct Dispatch {
    subscriber: Arc<dyn Subscriber + Send + Sync>,
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/dispatcher.rs#L154

シンプルなwrapperなのでtracing_core::Subscriberを実装した型からDispatchへの変換が提供されています。

impl<S> From<S> for Dispatch
where
    S: Subscriber + Send + Sync + 'static,
{
    #[inline]
    fn from(subscriber: S) -> Self {
        Dispatch::new(subscriber)
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/dispatcher.rs#L720

impl Dispatch {
    // ...
    pub fn new<S>(subscriber: S) -> Self
        where
            S: Subscriber + Send + Sync + 'static,
    {
        let me = Dispatch {
            subscriber: Arc::new(subscriber),
        };
        callsite::register_dispatch(&me);
        me
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/dispatcher.rs#L451

Dispatch::new()の中でSubscriberをHeapに確保します。callsite::register_dispatch()はのちほど言及します。

ということで、FmtSubscriberの初期化処理(init())ではFmtSubscriberをArcにしてDispatchで薄くwrapしてglobal変数にセットしていることがわかりました。info!()やinfo_span!()ではこのglobalのDispatch(FmtSubscriber)が参照されます。
callsite::register_dispatch()はfiltering処理を見ていく際に確認します。

FmtSubscriber まとめ

Layered<
    LevelFilter,
    Layered<
        fmt_layer::Layer,
        Registry,
    >
>

FmtSubscriberの各componentの概要をみてきました。
LayeredはLayerとSubscriberをcomposeする型でそれ自身がSubscriberです。
LevelFilterはloggingのenable判断を行うLayerです。
fmt_layer::Layerはeventのloggingを担うLayerでinfo!()がloggingされるのはこのLayerの実装によります。
Registerはroot Layerともいうべき役割で、spanの管理をおこないます。

tracing::Span::new()

FmtSubscriberの概要を押さえたのでいよいよtracingのapiを追っていきます。 コードの概略をもう一度みてみます。

fn main() {
    tracing_subscriber::fmt().init();

    let span = {
        static CALLSITE = { /* ... */ };
        tracing::Span::new(CALLSITE)
    };
    let _guard = span.enter();

    {
        static CALLSITE = { /* ... */ }
        tracing::Event::dispatch(CALLSITE)
    }
}

tracing_subscriber::fmt().init()がFmtSubscriberのconstructとglobal変数へのセットということを見てきたので、tracing::Span::new()をみていきます。

impl Span {
    pub fn new(meta: &'static Metadata<'static>, values: &field::ValueSet<'_>) -> Span {
        dispatcher::get_default(|dispatch| Self::new_with(meta, values, dispatch))
    }
    
    pub fn new_with(
        meta: &'static Metadata<'static>,
        values: &field::ValueSet<'_>,
        dispatch: &Dispatch,
    ) -> Span {
        let new_span = Attributes::new(meta, values);
        Self::make_with(meta, new_span, dispatch)
    }

    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));

        let span = Self {
            inner,
            meta: Some(meta),
        };

        // ...
        
        span
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing/src/span.rs#L436

dispatcher::get_default()にSpan::new_with()で自身をconstructする処理をclosureで渡しています。

thread_local! {
    static CURRENT_STATE: State = State {
        default: RefCell::new(None),
        can_enter: Cell::new(true),
    };
}

struct State {
    default: RefCell<Option<Dispatch>>,
    can_enter: Cell<bool>,
}

pub fn get_default<T, F>(mut f: F) -> T
where
    F: FnMut(&Dispatch) -> T,
{
    CURRENT_STATE
        .try_with(|state| {
            if let Some(entered) = state.enter() {
                return f(&*entered.current());
            }

            f(&Dispatch::none())
        })
        .unwrap_or_else(|_| f(&Dispatch::none()))
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/dispatcher.rs#L364

dispatcher::get_default()の中ではthreadごとに保持しているDispatchを参照します。State.defaultに保持されているRefCell<Option<Dispatch>>は初期状態ではNoneです。

State自体はstaticでcompile時に初期化されているので、State::enter()の処理をみてみると

impl State {
    // ...
    fn enter(&self) -> Option<Entered<'_>> {
    if self.can_enter.replace(false) {
        Some(Entered(self))
    } else {
        None
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/dispatcher.rs#L799

EnteredというStateのguardを表す型を返し、Entered::current()の戻り値でSpan::new()で渡したclosureを呼び出します。

impl<'a> Entered<'a> {
    #[inline]
    fn current(&self) -> RefMut<'a, Dispatch> {
        let default: RefMut<Option<Dispatch>> = self.0.default.borrow_mut();
        // default is None
        RefMut::map(default, |default| {
            default.get_or_insert_with(|| get_global().cloned().unwrap_or_else(Dispatch::none))
        })
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/dispatcher.rs#L811

わかりづらいかもしれませんがここにきてようやく最初にセットしたGlobalのDispatchが参照されます。上記のdefault変数はNoneで、Option::get_or_insert_with()はNoneの場合closureの戻り値を自身にセットしたうでそのmut参照を返します。

fn get_global() -> Option<&'static Dispatch> {
    if GLOBAL_INIT.load(Ordering::SeqCst) != INITIALIZED {
        return None;
    }
    unsafe {
        // This is safe given the invariant that setting the global dispatcher
        // also sets `GLOBAL_INIT` to `INITIALIZED`.
        Some(GLOBAL_DISPATCH.as_ref().expect(
            "invariant violated: GLOBAL_DISPATCH must be initialized before GLOBAL_INIT is set",
        ))
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/dispatcher.rs#L423

これでようやく最初のtracing_subscriber::fmt().init()でセットしたDispatch(FmtSubscriber)が参照されていることがわかりました。

あらためて、Span::new()に戻るとnew() -> new_with() -> make_with()と呼ばれます。

impl Span {
    // ...
    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));

        let span = Self {
            inner,
            meta: Some(meta),
        };

        // ...

        span
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing/src/span.rs#L563

MetadataやAttributesはinfo_span!()の情報です。

let id = dispatch.new_span(attrs);

ここにきてようやくtracingとtracing_subscriberがつながりました。
引数のdispatchはglobalに確保したDispatchであることを見てきておりさらにDispatchはFmtSubscriberのwrapperであることもわかっています。ということでFmtSubscriber::new_span()をみていきます。

pub struct Subscriber<
    N = format::DefaultFields,
    E = format::Format<format::Full>,
    F = LevelFilter,
    W = fn() -> io::Stdout,
> {
    inner: layer::Layered<F, Formatter<N, E, W>>,
}

impl<N, E, F, W> tracing_core::Subscriber for Subscriber<N, E, F, W>
    where // ...
{
    fn new_span(&self, attrs: &span::Attributes<'_>) -> span::Id {
        self.inner.new_span(attrs)
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/fmt/mod.rs#L387

Subscriber(FmtSubscriber)はLayeredのwrapperなので基本的に処理をすべてinnerに委譲します。ということで次はLayered::new_span()です。

impl<L, S> Subscriber for Layered<L, S>
where
    L: Layer<S>,
    S: Subscriber,
{
    fn new_span(&self, span: &span::Attributes<'_>) -> span::Id {
        let id = self.inner.new_span(span);
        self.layer.on_new_span(span, &id, self.ctx());
        id
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/layer/layered.rs#L125

LayeredのgenericsSは自身がwrapしているSubscriber(orLayer)でそれがSubscriberを実装していることがわかっています。
ここで注目していただきたいのが、最初にself.inner.new_span()を呼び出した後自身のself.layer.on_new_span()を呼んでいる点です。
FmtSubscriberの構造の概略を再掲すると

Layered<
    LevelFilter,
    Layered<
        fmt_layer::Layer,
        Registry,
    >
>

のようになっているので、上記のself.innerはLayered<fmt_layer::Layer,Registry>を参照します。そして、このnestしたLayeredのnew_span()でもself.inner.new_span()が最初によばれるので結局、Registry::new_span()が呼ばれることになります。

impl Subscriber for Registry {
    // ...
    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
            .create_with(|data| {
                data.metadata = attrs.metadata();
                data.parent = parent;
                data.filter_map = crate::filter::FILTERING.with(|filtering| filtering.filter_map());
                #[cfg(debug_assertions)]
                {
                    if data.filter_map != FilterMap::default() {
                        debug_assert!(self.has_per_layer_filters());
                    }
                }

                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の実質的な処理にたどり着きました。
まず、

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))
};

このparentはNoneが入ります。info_span!() macroは明示的に親のspanを指定することもできるのでここで親のspan::Idの判定をしています。今回の例では今生成しているspanがrootなので親はいません。
重要なのは以下の箇所です。

let id = self
    .spans
    .create_with(|data: &mut DataInner| {
        data.metadata = attrs.metadata();
        data.parent = parent;
        // ...

Registryの定義を確認すると

use sharded_slab::{pool::Ref, Clear, Pool};

pub struct Registry {
    spans: Pool<DataInner>,
    current_spans: ThreadLocal<RefCell<SpanStack>>,
    next_filter_id: u8,
}

となっており、self.span.create_with()はshareded_slab::Pool::create_with()を呼んでいます。
ここで前提でふれたshareded_slab::Poolがでてきます。 docには

Creates a new object in the pool with the provided initializer, returning a key that may be used to access the new object.

とあるので、この処理でRegistry内にDataInnerが生成され、そのDataInnerを識別するためのidが返されます。DataInnerの定義をみてみると以下のようになっています。

struct DataInner {
    filter_map: FilterMap,
    metadata: &'static Metadata<'static>,
    parent: Option<Id>,
    ref_count: AtomicUsize,
    pub(crate) extensions: RwLock<ExtensionsInner>,
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/registry/sharded.rs#L123

ここで、metadataとして、info_span!()で生成した呼び出し元の情報を 保持していることがわかります。またextensionsを通じて任意の型を保持できる機能もあるのですがこれはSpan::enter()で利用します。

最後にidx_to_id()でsharded_slabのindexをSpan::Idにwrapします。

pub struct Id(NonZeroU64);

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

この生成されたsharded_slabのindexをspanのidとして呼び出し元に返します。

impl Span {
    // ...
    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));

        let span = Self {
            inner,
            meta: Some(meta),
        };

        // ...

        span
    }
}