从零写一个最小日志门面

[dependencies]

[dev-dependencies]
criterion = "0.5"

#[derive(Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Debug)]
#[repr(u8)]
pub enum Level {
  Error = 1,
  Warn,
  Info,
  Debug,
  Trace,
}

pub struct Metadata {
  pub name: &'static str,
  pub target: &'static str,
  pub level: Level,
  pub fields: &'static [&'static str],
}

#[repr(u8)]
pub enum Interest {
  Never = 0,
  Sometimes = 1,
  Always = 2,
}

const UNKNOWN: u8 = 0xFF; // 初值：还没问过

pub struct Callsite {
  meta: &'static Metadata,
  interest: AtomicU8,
}

impl Callsite {
  pub const fn new(meta: &'static Metadata) -> Self {
    Callsite { meta, interest: AtomicU8::new(UNKNOWN) }
  }

  #[inline]
  pub fn is_enabled(&'static self) -> bool {
    match self.interest.load(Relaxed) {
      NEVER => false,
      ALWAYS => true,
      SOMETIMES => dispatcher().is_some_and(|d| d.enabled(self.meta)),
      _ => self.register(), // UNKNOWN
    }
  }

  // 只在第一次经过时走到这里：问 subscriber，把答案写进字节
  #[cold]
  #[inline(never)]
  fn register(&'static self) -> bool {
    let Some(d) = dispatcher() else { return false };
    let interest = d.register_callsite(self.meta);
    self.interest.store(interest as u8, Relaxed);
    match interest {
      Interest::Never => false,
      Interest::Always => true,
      Interest::Sometimes => d.enabled(self.meta),
    }
  }
}

#[macro_export]
macro_rules! event {
  ($lvl:expr, $msg:literal $(, $k:ident = $v:expr)* $(,)?) => {{
    static META: $crate::Metadata = $crate::Metadata {
      name: concat!("event ", file!(), ":", line!()),
      target: module_path!(),
      level: $lvl,
      fields: &["message" $(, stringify!($k))*],
    };
    static CALLSITE: $crate::Callsite = $crate::Callsite::new(&META);
    if ($lvl as u8) <= $crate::max_level() && CALLSITE.is_enabled() {
      let values: &[&dyn ::std::fmt::Debug] = &[&format_args!($msg) $(, &$v)*];
      $crate::__dispatch_event(&META, values);
    }
  }};
}

pub trait Subscriber: Send + Sync {
  fn register_callsite(&self, meta: &'static Metadata) -> Interest {
    if self.enabled(meta) { Interest::Always } else { Interest::Never }
  }
  fn enabled(&self, meta: &Metadata) -> bool;
  fn max_level(&self) -> Level;
  fn event(&self, meta: &Metadata, values: &[&dyn Debug]);
  fn new_span(&self, meta: &Metadata, values: &[&dyn Debug]) -> u64;
  fn enter(&self, id: u64);
  fn exit(&self, id: u64);
}

static GLOBAL: OnceLock<Box<dyn Subscriber>> = OnceLock::new();
// 0 表示 OFF：还没装 subscriber 时，所有宏都停在这里
static MAX_LEVEL: AtomicU8 = AtomicU8::new(0);

pub fn set_global_default(sub: impl Subscriber + 'static) -> Result<(), &'static str> {
  let level = sub.max_level();
  GLOBAL.set(Box::new(sub)).map_err(|_| "a global default dispatcher has already been set")?;
  MAX_LEVEL.store(level as u8, Relaxed);
  Ok(())
}

pub struct Span {
  id: Option<u64>,
}

pub struct Entered<'a> {
  span: &'a Span,
}

impl Span {
  pub fn enter(&self) -> Entered<'_> {
    if let (Some(id), Some(d)) = (self.id, dispatcher()) {
      d.enter(id);
    }
    Entered { span: self }
  }
}

impl Drop for Entered<'_> {
  fn drop(&mut self) {
    if let (Some(id), Some(d)) = (self.span.id, dispatcher()) {
      d.exit(id);
    }
  }
}

pub struct Stderr {
  pub default: Level,
  pub prefix: &'static str,
  pub prefix_level: Level,
  spans: Mutex<Vec<String>>, // 下标 + 1 就是 span 的 id；从不释放
}

thread_local! {
  // 当前线程进入了哪些 span：只有 subscriber 知道
  static STACK: RefCell<Vec<u64>> = const { RefCell::new(Vec::new()) };
}

impl Subscriber for Stderr {
  fn enabled(&self, meta: &Metadata) -> bool {
    meta.level <= self.default || (meta.level <= self.prefix_level && meta.target.starts_with(self.prefix))
  }

  fn max_level(&self) -> Level {
    self.default.max(self.prefix_level)
  }

  fn new_span(&self, meta: &Metadata, values: &[&dyn Debug]) -> u64 {
    // 把 name{k=v ...} 格式化好存起来，返回下标 + 1
    // ...
  }

  fn enter(&self, id: u64) {
    STACK.with(|s| s.borrow_mut().push(id));
  }

  fn exit(&self, id: u64) {
    STACK.with(|s| {
      let mut s = s.borrow_mut();
      if let Some(pos) = s.iter().rposition(|x| *x == id) {
        s.remove(pos);
      }
    });
  }

  // event：从栈底到栈顶，把每个 span 的文本拼在行首，再拼 target、message、其余字段，
  // 一次 write_all 写到 stderr
  // ...
}

use exp_tracing_handson::{Level, Stderr, event, set_global_default, span};

mod app {
  pub mod db {
    use exp_tracing_handson::{Level, event};
    pub fn query(id: u32) {
      event!(Level::Debug, "query", id = id);
    }
  }
}

mod noisy {
  use exp_tracing_handson::{Level, event};
  pub fn tick() {
    event!(Level::Debug, "tick");
  }
}

fn main() {
  event!(Level::Error, "before init");
  eprintln!("init");
  // 相当于 RUST_LOG="info,demo::app=debug"
  let first = set_global_default(Stderr::new(Level::Info, "demo::app", Level::Debug));
  let second = set_global_default(Stderr::new(Level::Trace, "", Level::Trace));
  eprintln!("first = {first:?}, second = {second:?}");

  for i in 0..2 {
    eprintln!("pass {i}");
    let req = span!(Level::Info, "request", id = i);
    let _g = req.enter();
    event!(Level::Info, "start", user = "ann");
    app::db::query(i);
    noisy::tick();
    event!(Level::Trace, "too verbose");
    std::thread::spawn(|| event!(Level::Info, "from another thread"))
      .join()
      .unwrap();
  }
  let passes = 2;
  event!(Level::Warn, "done after {passes} passes");
}

init
first = Ok(()), second = Err("a global default dispatcher has already been set")
pass 0
  [register_callsite] request (demo) -> Always
  [register_callsite] event src/bin/demo.rs:31 (demo) -> Always
 INFO request{id=0}: demo: start user="ann"
  [register_callsite] event src/bin/demo.rs:7 (demo::app::db) -> Always
DEBUG request{id=0}: demo::app::db: query id=0
  [register_callsite] event src/bin/demo.rs:15 (demo::noisy) -> Never
  [register_callsite] event src/bin/demo.rs:35 (demo) -> Always
 INFO demo: from another thread
pass 1
 INFO request{id=1}: demo: start user="ann"
DEBUG request{id=1}: demo::app::db: query id=1
 INFO demo: from another thread
  [register_callsite] event src/bin/demo.rs:40 (demo) -> Always
 WARN demo: done after 2 passes

/// 对照组：同样的门，但不缓存 Interest，每次都问 subscriber。
macro_rules! event_nocache {
  ($lvl:expr, $msg:literal $(, $k:ident = $v:expr)* $(,)?) => {{
    static META: exp_tracing_handson::Metadata = exp_tracing_handson::Metadata {
      // ... 和 event! 相同
    };
    if ($lvl as u8) <= exp_tracing_handson::max_level() && exp_tracing_handson::dispatcher().is_some_and(|d| d.enabled(&META)) {
      let values: &[&dyn ::std::fmt::Debug] = &[&format_args!($msg) $(, &$v)*];
      exp_tracing_handson::__dispatch_event(&META, values);
    }
  }};
}

// 相当于 RUST_LOG="info,app=debug"：这个 bench 的 target 是 "disabled"，
// 所以 debug! 过得了全局级别门，却被 subscriber 拒绝
fn disabled(c: &mut Criterion) {
  set_global_default(Stderr::new(Level::Info, "app", Level::Debug)).unwrap();
  c.bench_function("baseline", |b| b.iter(|| black_box(1u64)));
  c.bench_function("trace_level_gate", |b| {
    b.iter(|| event!(Level::Trace, "msg", v = black_box(1u64)))
  });
  c.bench_function("debug_cached_never", |b| {
    b.iter(|| event!(Level::Debug, "msg", v = black_box(1u64)))
  });
  c.bench_function("debug_nocache_enabled", |b| {
    b.iter(|| event_nocache!(Level::Debug, "msg", v = black_box(1u64)))
  });
}

baseline                time:   [440.30 ps 472.03 ps 506.01 ps]
trace_level_gate        time:   [317.19 ps 320.06 ps 323.45 ps]
  [register_callsite] event benches/disabled.rs:31 (disabled) -> Never
debug_cached_never      time:   [440.87 ps 441.70 ps 442.55 ps]
debug_nocache_enabled   time:   [4.4371 ns 4.4532 ns 4.4723 ns]

baseline                time:   [358.52 ps 373.44 ps 389.81 ps]
trace_level_gate        time:   [320.41 ps 321.72 ps 323.05 ps]
debug_cached_never      time:   [321.44 ps 322.82 ps 324.13 ps]
debug_nocache_enabled   time:   [320.93 ps 322.43 ps 323.71 ps]