展开成什么

tracing = "=0.1.44"
tracing-subscriber = { version = "=0.3.23", default-features = false, features = ["fmt", "registry", "std"] }
tokio = { version = "=1.54.1", features = ["full"] }
async-trait = "0.1" # 只有 async-trait 那一节用，解析到 0.1.92

pub fn instrument(
    args: proc_macro::TokenStream,
    item: proc_macro::TokenStream,
) -> proc_macro::TokenStream {
    let args = syn::parse_macro_input!(args as attr::InstrumentArgs);
    // Cloning a `TokenStream` is cheap since it's reference counted internally.
    instrument_precise(args.clone(), item.clone())
        .unwrap_or_else(|_err| instrument_speculative(args, item))
}

#[derive(Debug)]
struct Config {
  retries: u8,
}

#[instrument]
fn handle(id: u64, name: &str, cfg: &Config) -> usize {
  name.len() + cfg.retries as usize + id as usize
}

fn handle(id: u64, name: &str, cfg: &Config) -> usize {
    {}
    #[allow(clippy::suspicious_else_formatting)]
    {
        let __tracing_attr_span;
        let __tracing_attr_guard;
        if ::tracing::Level::INFO <= ::tracing::level_filters::STATIC_MAX_LEVEL
            && ::tracing::Level::INFO <= ::tracing::level_filters::LevelFilter::current()
            || { false }
        {
            __tracing_attr_span = {
                use ::tracing::__macro_support::Callsite as _;
                static __CALLSITE: ::tracing::callsite::DefaultCallsite = {
                    // ... META：名字 "handle"，target "sync_fn"，INFO，字段 id、name、cfg
                };
                // ... 四道门，通过时：
                    ::tracing::Span::new(
                        meta,
                        &{
                            // ...
                            meta.fields()
                                .value_set_all(
                                    &[
                                        (::tracing::__macro_support::Option::Some(
                                            &id as &dyn ::tracing::field::Value,
                                        )),
                                        (::tracing::__macro_support::Option::Some(
                                            &name as &dyn ::tracing::field::Value,
                                        )),
                                        (::tracing::__macro_support::Option::Some(
                                            &::tracing::field::debug(&cfg)
                                                as &dyn ::tracing::field::Value,
                                        )),
                                    ],
                                )
                        },
                    )
                // ... 否则 __disabled_span(__CALLSITE.metadata())
            };
            __tracing_attr_guard = __tracing_attr_span.enter();
        }
        #[warn(clippy::suspicious_else_formatting)]
        {
            #[allow(
                // ...
            )]
            if false {
                let __tracing_attr_fake_return: usize = loop {};
                return __tracing_attr_fake_return;
            }
            { name.len() + cfg.retries as usize + id as usize }
        }
    }
}

use std::fmt::Write;
use tracing::field::{Field, Visit};
use tracing::span::{Attributes, Id};
use tracing::{Event, Subscriber, info, instrument};
use tracing_subscriber::layer::{Context, Layer, SubscriberExt};
use tracing_subscriber::registry::{LookupSpan, Registry};

// 把字段拼成 "a=1 b=\"x\""
struct Fields(String);
impl Visit for Fields {
  fn record_debug(&mut self, f: &Field, v: &dyn std::fmt::Debug) {
    let _ = write!(self.0, " {}={:?}", f.name(), v);
  }
}

struct Print;
impl<S: Subscriber + for<'a> LookupSpan<'a>> Layer<S> for Print {
  fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, _: Context<'_, S>) {
    let mut f = Fields(String::new());
    attrs.record(&mut f);
    println!("new_span {} {:?}{}", attrs.metadata().name(), id, f.0);
  }
  fn on_enter(&self, id: &Id, _: Context<'_, S>) {
    println!("enter    {:?}", id);
  }
  fn on_exit(&self, id: &Id, _: Context<'_, S>) {
    println!("exit     {:?}", id);
  }
  fn on_close(&self, id: Id, _: Context<'_, S>) {
    println!("close    {:?}", id);
  }
  fn on_event(&self, ev: &Event<'_>, cx: Context<'_, S>) {
    let mut f = Fields(String::new());
    ev.record(&mut f);
    let cur = cx.lookup_current().map(|s| s.name()).unwrap_or("-");
    println!("event    in {}:{}", cur, f.0);
  }
}

#[derive(Debug)]
#[allow(dead_code)]
struct User {
  name: String,
}

#[instrument]
fn sync_work(id: u64, user: &User) {
  info!("working");
}

#[instrument]
async fn async_work(id: u64) {
  info!("before yield");
  tokio::task::yield_now().await;
  info!("after yield");
}

#[tokio::main(flavor = "current_thread")]
async fn main() {
  tracing::subscriber::set_global_default(Registry::default().with(Print)).unwrap();

  println!("-- sync");
  sync_work(7, &User { name: "ann".into() });

  println!("-- async, awaited");
  async_work(8).await;
}

-- sync
new_span sync_work Id(1) id=7 user=User { name: "ann" }
enter    Id(1)
event    in sync_work: message=working
exit     Id(1)
close    Id(1)
-- async, awaited
new_span async_work Id(2251799813685249) id=8
enter    Id(2251799813685249)
event    in async_work: message=before yield
exit     Id(2251799813685249)
enter    Id(2251799813685249)
event    in async_work: message=after yield
exit     Id(2251799813685249)
enter    Id(2251799813685249)
exit     Id(2251799813685249)
close    Id(2251799813685249)

enum RecordType {
    /// The field should be recorded using its `Value` implementation.
    Value,
    /// The field should be recorded using `tracing::field::debug()`.
    Debug,
}

    fn parse_from_ty(ty: &Type) -> Self {
        match ty {
            Type::Path(TypePath { path, .. })
                if path
                    .segments
                    .iter()
                    .next_back()
                    .map(|path_segment| {
                        let ident = path_segment.ident.to_string();
                        Self::TYPES_FOR_VALUE.iter().any(|&t| t == ident)
                    })
                    .unwrap_or(false) =>
            {
                RecordType::Value
            }
            Type::Reference(syn::TypeReference { elem, .. }) => RecordType::parse_from_ty(elem),
            _ => RecordType::Debug,
        }
    }

use tracing::field::{Field, Visit};
use tracing::span::{Attributes, Id};
use tracing::{Subscriber, instrument};
use tracing_subscriber::layer::{Context, Layer, SubscriberExt};
use tracing_subscriber::registry::{LookupSpan, Registry};

// 只打印每个字段走的是哪个 record_* 方法
struct Which(Vec<String>);
impl Visit for Which {
  fn record_u64(&mut self, f: &Field, v: u64) {
    self.0.push(format!("{}: record_u64({v})", f.name()));
  }
  fn record_str(&mut self, f: &Field, v: &str) {
    self.0.push(format!("{}: record_str({v:?})", f.name()));
  }
  fn record_debug(&mut self, f: &Field, v: &dyn std::fmt::Debug) {
    self.0.push(format!("{}: record_debug({v:?})", f.name()));
  }
}

struct Print;
impl<S: Subscriber + for<'a> LookupSpan<'a>> Layer<S> for Print {
  fn on_new_span(&self, attrs: &Attributes<'_>, _: &Id, _: Context<'_, S>) {
    let mut w = Which(Vec::new());
    attrs.record(&mut w);
    for line in w.0 {
      println!("{line}");
    }
  }
}

type UserId = u64;

#[instrument]
fn lookup(a: u64, b: &str, c: String, d: UserId, e: Option<u64>, f: &&u64) {}

fn main() {
  tracing::subscriber::set_global_default(Registry::default().with(Print)).unwrap();
  lookup(1, "two", "three".into(), 4, Some(5), &&6);
}

a: record_u64(1)
b: record_str("two")
c: record_str("three")
d: record_debug(4)
e: record_debug(Some(5))
f: record_u64(6)

#[instrument]
async fn fetch(id: u64) -> u64 {
  id + 1
}

async fn fetch(id: u64) -> u64 {
    {}
    let __tracing_attr_span = {
        // ... span!：名字 "fetch"，字段 id，过四道门；
        //     不通过时 __disabled_span(__CALLSITE.metadata())
    };
    let __tracing_instrument_future = async move {
        #[allow(
            // ...
        )]
        if false {
            let __tracing_attr_fake_return: u64 = loop {};
            return __tracing_attr_fake_return;
        }
        { id + 1 }
    };
    if !__tracing_attr_span.is_disabled() {
        ::tracing::Instrument::instrument(
                __tracing_instrument_future,
                __tracing_attr_span,
            )
            .await
    } else {
        __tracing_instrument_future.await
    }
}

/// The specific async code pattern that was detected
enum AsyncKind<'a> {
    /// Immediately-invoked async fn, as generated by `async-trait <= 0.1.43`:
    /// `async fn foo<...>(...) {...}; Box::pin(foo<...>(...))`
    Function(&'a ItemFn),
    /// A function returning an async (move) block, optionally `Box::pin`-ed,
    /// as generated by `async-trait >= 0.1.44`:
    /// `Box::pin(async move { ... })`
    Async {
        async_expr: &'a ExprAsync,
        pinned_box: bool,
    },
}

#[instrument]
fn fetch_later(id: u64) -> impl Future<Output = u64> {
  async move { id + 1 }
}

#[instrument]
fn fetch_boxed(id: u64) -> Pin<Box<dyn Future<Output = u64> + Send>> {
  Box::pin(async move { id + 1 })
}

fn fetch_later(id: u64) -> impl Future<Output = u64> {
    async move {
        let __tracing_attr_span = {
            // ... span!：名字 "fetch_later"，字段 id
        };
        let __tracing_instrument_future = async move { id + 1 };
        if !__tracing_attr_span.is_disabled() {
            ::tracing::Instrument::instrument(
                    __tracing_instrument_future,
                    __tracing_attr_span,
                )
                .await
        } else {
            __tracing_instrument_future.await
        }
    }
}
fn fetch_boxed(id: u64) -> Pin<Box<dyn Future<Output = u64> + Send>> {
    ::std::boxed::Box::pin(async move {
        let __tracing_attr_span = {
            // ... span!：名字 "fetch_boxed"，字段 id
        };
        let __tracing_instrument_future = async move { id + 1 };
        // ... 同上
    })
}

#[async_trait]
trait Store {
  async fn get(&self, key: u32) -> u32;
}

#[derive(Debug)]
struct Mem;

#[async_trait]
impl Store for Mem {
  #[instrument]
  async fn get(&self, key: u32) -> u32 {
    key * 2
  }
}

impl Store for Mem {
    // ...
    fn get<'life0, 'async_trait>(
        &'life0 self,
        key: u32,
    ) -> ::core::pin::Pin<
        Box<
            dyn ::core::future::Future<
                Output = u32,
            > + ::core::marker::Send + 'async_trait,
        >,
    >
    where
        'life0: 'async_trait,
        Self: 'async_trait,
    {
        ::std::boxed::Box::pin(async move {
            let __tracing_attr_span = {
                // ... span!：名字 "get"，字段 self、key；
                //     self 是 ::tracing::field::debug(&self)，key 直接按值
            };
            let __tracing_instrument_future = async move {
                if let ::core::option::Option::Some(__ret) = ::core::option::Option::None::<
                    u32,
                > {
                    #[allow(unreachable_code)] return __ret;
                }
                let __self = self;
                let key = key;
                let __ret: u32 = { key * 2 };
                #[allow(unreachable_code)] __ret
            };
            if !__tracing_attr_span.is_disabled() {
                ::tracing::Instrument::instrument(
                        __tracing_instrument_future,
                        __tracing_attr_span,
                    )
                    .await
            } else {
                __tracing_instrument_future.await
            }
        })
    }
}

use std::future::Future;

// 最后一个表达式是 async 块：认得出
#[instrument]
fn direct(x: u64) -> impl Future<Output = u64> {
  async move {
    info!("inside direct");
    x
  }
}

// async 块先绑到变量上再返回：认不出，按同步函数处理
#[instrument]
fn via_let(x: u64) -> impl Future<Output = u64> {
  let fut = async move {
    info!("inside via_let");
    x
  };
  fut
}

#[tokio::main(flavor = "current_thread")]
async fn main() {
  tracing::subscriber::set_global_default(Registry::default().with(Print)).unwrap();
  println!("-- direct");
  let f = direct(1);
  println!("created");
  f.await;
  println!("-- via_let");
  let f = via_let(2);
  println!("created");
  f.await;
}

-- direct
created
new_span direct Id(1) x=1
enter    Id(1)
event    in direct: message=inside direct
exit     Id(1)
enter    Id(1)
exit     Id(1)
close    Id(1)
-- via_let
new_span via_let Id(2251799813685249) x=2
enter    Id(2251799813685249)
exit     Id(2251799813685249)
close    Id(2251799813685249)
created
event    in -: message=inside via_let

use criterion::{Criterion, black_box};
use std::future::Future;
use std::pin::pin;
use std::task::{Context, Poll, Waker};
use tracing::instrument;
use tracing::level_filters::LevelFilter;
use tracing_subscriber::layer::SubscriberExt;
use tracing_subscriber::registry::Registry;

#[inline(never)]
fn plain(x: u64) -> u64 {
  x * 2
}

#[instrument]
#[inline(never)]
fn traced(x: u64) -> u64 {
  x * 2
}

async fn plain_async(x: u64) -> u64 {
  x * 2
}

#[instrument]
async fn traced_async(x: u64) -> u64 {
  x * 2
}

// 在栈上 pin 住 future，用 noop waker poll 一次
fn poll_once<F: Future>(f: F) -> F::Output {
  let mut f = pin!(f);
  match f.as_mut().poll(&mut Context::from_waker(Waker::noop())) {
    Poll::Ready(v) => v,
    Poll::Pending => unreachable!(),
  }
}

fn main() {
  let mode = std::env::var("MODE").unwrap_or_default();
  match mode.as_str() {
    "none" => {}
    // 有 subscriber，但它说「最多 WARN」：INFO 的 span 被第二道门挡掉
    "warn" => tracing::subscriber::set_global_default(Registry::default().with(LevelFilter::WARN)).unwrap(),
    // 有 subscriber，INFO 的 span 真的被创建
    "on" => tracing::subscriber::set_global_default(Registry::default()).unwrap(),
    _ => panic!("MODE=none|warn|on"),
  }
  println!("mode={mode}");
  println!(
    "size_of future: plain_async={} traced_async={}",
    std::mem::size_of_val(&plain_async(1)),
    std::mem::size_of_val(&traced_async(1)),
  );
  let mut c = Criterion::default()
    .without_plots()
    .warm_up_time(std::time::Duration::from_millis(500))
    .measurement_time(std::time::Duration::from_secs(2));
  c.bench_function(&format!("{mode}/sync plain"), |b| b.iter(|| plain(black_box(3))));
  c.bench_function(&format!("{mode}/sync traced"), |b| b.iter(|| traced(black_box(3))));
  c.bench_function(&format!("{mode}/async plain"), |b| b.iter(|| poll_once(plain_async(black_box(3)))));
  c.bench_function(&format!("{mode}/async traced"), |b| b.iter(|| poll_once(traced_async(black_box(3)))));
}

mode=none
size_of future: plain_async=16 traced_async=120
none/sync plain         time:   [906.25 ps 910.83 ps 917.27 ps]
none/sync traced        time:   [1.2846 ns 1.3111 ns 1.3382 ns]
none/async plain        time:   [344.19 ps 349.08 ps 355.97 ps]
none/async traced       time:   [6.0199 ns 6.0496 ns 6.0839 ns]
mode=warn
size_of future: plain_async=16 traced_async=120
warn/sync plain         time:   [917.63 ps 932.26 ps 952.60 ps]
warn/sync traced        time:   [1.2508 ns 1.2703 ns 1.2917 ns]
warn/async plain        time:   [339.97 ps 340.40 ps 340.84 ps]
warn/async traced       time:   [6.0900 ns 6.2274 ns 6.4101 ns]
mode=on
size_of future: plain_async=16 traced_async=120
on/sync plain           time:   [922.06 ps 955.63 ps 997.34 ps]
on/sync traced          time:   [45.421 ns 59.634 ns 85.364 ns]
on/async plain          time:   [340.51 ps 341.06 ps 341.67 ps]
on/async traced         time:   [54.781 ns 65.898 ns 92.191 ns]

new_span work Id(1) id=2
enter    Id(1)
event    in work: message=running
exit     Id(1)
enter    Id(1)
exit     Id(1)
close    Id(1)