tracing 解决什么问题

A scoped, structured logging and diagnostics system.

In asynchronous systems like Tokio, interpreting traditional log messages can
often be quite challenging. Since individual tasks are multiplexed on the same
thread, associated events and log lines are intermixed making it difficult to
trace the logic flow. `tracing` expands upon logging-style diagnostics by
allowing libraries and applications to record structured events with additional
information about *temporality* and *causality* — unlike a log message, a span
in `tracing` has a beginning and end time, may be entered and exited by the
flow of execution, and may exist within a nested tree of similar spans. In
addition, `tracing` spans are *structured*, with the ability to record typed
data as well as textual messages.

log = "0.4"
tokio = { version = "=1.54.1", features = ["macros", "rt"] }

use log::{Level, LevelFilter, Log, Metadata, Record, info};

// 一个最小的 log 实现：把每条记录打印成一行
struct Stdout;

impl Log for Stdout {
  fn enabled(&self, metadata: &Metadata) -> bool {
    metadata.level() <= Level::Info
  }

  fn log(&self, record: &Record) {
    if self.enabled(record.metadata()) {
      println!("{:>5} {}: {}", record.level(), record.target(), record.args());
    }
  }

  fn flush(&self) {}
}

static LOGGER: Stdout = Stdout;

// 深处的函数：不知道自己在为哪个请求干活
async fn load_user(user: u32) {
  info!("cache miss");
  tokio::task::yield_now().await;
  info!("query ok, user={user}");
}

async fn handle(user: u32) {
  info!("start");
  load_user(user).await;
  info!("done");
}

#[tokio::main(flavor = "current_thread")]
async fn main() {
  log::set_logger(&LOGGER).unwrap();
  log::set_max_level(LevelFilter::Info);

  let a = tokio::spawn(handle(7));
  let b = tokio::spawn(handle(7));
  a.await.unwrap();
  b.await.unwrap();
}

 INFO plain_log: start
 INFO plain_log: cache miss
 INFO plain_log: start
 INFO plain_log: cache miss
 INFO plain_log: query ok, user=7
 INFO plain_log: done
 INFO plain_log: query ok, user=7
 INFO plain_log: done

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

use tracing::{Instrument, info, info_span};

// 深处的函数照样不知道请求 id；user 改成了字段
async fn load_user(user: u32) {
  info!("cache miss");
  tokio::task::yield_now().await;
  info!(user, "query ok");
}

async fn handle(user: u32) {
  info!("start");
  load_user(user).await;
  info!("done");
}

#[tokio::main(flavor = "current_thread")]
async fn main() {
  tracing_subscriber::fmt()
    .with_env_filter("info")
    .with_ansi(false)
    .without_time()
    .init();

  // 唯一的改动：每个请求的 future 外面套一个 span
  let a = tokio::spawn(handle(7).instrument(info_span!("request", id = 1)));
  let b = tokio::spawn(handle(7).instrument(info_span!("request", id = 2)));
  a.await.unwrap();
  b.await.unwrap();
}

 INFO request{id=1}: with_span: start
 INFO request{id=1}: with_span: cache miss
 INFO request{id=2}: with_span: start
 INFO request{id=2}: with_span: cache miss
 INFO request{id=2}: with_span: query ok user=7
 INFO request{id=2}: with_span: done
 INFO request{id=1}: with_span: query ok user=7
 INFO request{id=1}: with_span: done

impl<T: Future> Future for Instrumented<T> {
    type Output = T::Output;

    fn poll(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Self::Output> {
        let (span, inner) = self.project().span_and_inner_pin_mut();
        let _enter = span.enter();
        inner.poll(cx)
    }
}

use std::time::Duration;
use tracing::{Instrument, info, info_span};

async fn load_user(user: u32) {
  info!("cache miss");
  tokio::time::sleep(Duration::from_millis(5)).await;
  info!(user, "query ok");
}

async fn handle(user: u32) {
  info!("start");
  load_user(user).await;
  info!("done");
}

#[tokio::main(flavor = "multi_thread", worker_threads = 4)]
async fn main() {
  tracing_subscriber::fmt()
    .with_env_filter("info")
    .with_ansi(false)
    .without_time()
    .with_thread_ids(true)
    .init();

  let tasks: Vec<_> = (1..=2)
    .map(|id| tokio::spawn(handle(7).instrument(info_span!("request", id))))
    .collect();
  for t in tasks {
    t.await.unwrap();
  }
}

 INFO ThreadId(03) request{id=2}: across_threads: start
 INFO ThreadId(04) request{id=1}: across_threads: start
 INFO ThreadId(03) request{id=2}: across_threads: cache miss
 INFO ThreadId(04) request{id=1}: across_threads: cache miss
 INFO ThreadId(02) request{id=1}: across_threads: query ok user=7
 INFO ThreadId(02) request{id=1}: across_threads: done
 INFO ThreadId(04) request{id=2}: across_threads: query ok user=7
 INFO ThreadId(04) request{id=2}: across_threads: done

Libraries should link only to the `tracing` crate, and use the provided
macros to record whatever information will be useful to downstream
consumers.

Libraries should link only to the `log` crate, and use the provided
macros to log whatever information will be useful to downstream consumers.