Tracing and Observability

Observability is the ability to tell what a running program is doing from the data it emits: logs, traces, and metrics. Plain println! logging breaks down in async code because many tasks interleave on the same threads, so a line of output does not say which request produced it. The tracing crate solves this with spans, which record that a stretch of work belongs to one request, and events, which are log records that carry structured fields and the span they happened in.

Concept	API
Event	`info!`, `warn!`, `error!`, `debug!`, `trace!`
Span	`info_span!`, `#[instrument]`, `Span::current()`
Attaching a span to a future	`Instrument::instrument`, `in_current_span`
Output and filtering	`tracing-subscriber`: `fmt`, `EnvFilter`, `Layer`
Runtime numbers	`Handle::metrics` (stable methods)

The crates are tracing and tracing-subscriber (with its env-filter and json features). Add them with cargo add tracing tracing-subscriber --features tracing-subscriber/env-filter,tracing-subscriber/json.

Every example writes to standard output with the timestamp turned off (.without_time()) and colors turned off (.with_ansi(false)), so the output is reproducible. A real service keeps timestamps.

Example 1: An event

An event is one record at a point in time, with a level (TRACE, DEBUG, INFO, WARN, ERROR, from most to least verbose) and optional key-value fields. Events do nothing until a subscriber is installed. The subscriber decides what to do with them. tracing_subscriber::fmt() builds a subscriber that prints lines.

Rust

use tracing::{info, warn};

#[tokio::main]
async fn main() {
    tracing_subscriber::fmt()
        .with_writer(std::io::stdout)
        .with_ansi(false)
        .without_time()
        .init();

    info!("server starting");
    warn!(port = 8080, "port is a default value");
}

Output

 INFO master_tokio_runtime_production_tokio_tracing_and_observability_0: server starting
 WARN master_tokio_runtime_production_tokio_tracing_and_observability_0: port is a default value port=8080

The first argument style, port = 8080, records a field. The last argument is the message. .init() installs the subscriber as the process-wide default. Calling init twice panics, so a program calls it once, early in main.

Example 2: Field formatting

A field value is recorded by its own type when it is a number, a bool, or a string. The prefixes % and ? record the value through Display or Debug. with_target(false) removes the module path that the formatter prints by default.

Rust

use tracing::info;

#[derive(Debug)]
struct User {
    id: u32,
    name: &'static str,
}

#[tokio::main]
async fn main() {
    tracing_subscriber::fmt()
        .with_writer(std::io::stdout)
        .with_ansi(false)
        .without_time()
        .with_target(false)
        .init();

    let user = User { id: 7, name: "asha" };
    let path = std::path::Path::new("/tmp/report.txt");
    info!(id = user.id, name = user.name, "plain values");
    info!(user = ?user, "debug format");
    info!(path = %path.display(), "display format");
    let retries = 3;
    info!(retries, ok = true, "shorthand: the variable name becomes the field name");
}

Output

 INFO plain values id=7 name="asha"
 INFO debug format user=User { id: 7, name: "asha" }
 INFO display format path=/tmp/report.txt
 INFO shorthand: the variable name becomes the field name retries=3 ok=true

Fields stay separate from the message, so a log system can filter on id = 7 without parsing text.

Example 3: Levels and a maximum level

The subscriber drops events above a maximum verbosity. with_max_level sets it. A macro whose level is filtered out does not evaluate its field expressions.

Rust

use tracing::{Level, debug, error, info, trace, warn};

#[tokio::main]
async fn main() {
    tracing_subscriber::fmt()
        .with_writer(std::io::stdout)
        .with_ansi(false)
        .without_time()
        .with_target(false)
        .with_max_level(Level::INFO)
        .init();

    trace!("trace: hidden");
    debug!("debug: hidden");
    info!("info: shown");
    warn!("warn: shown");
    error!("error: shown");
}

Output

 INFO info: shown
 WARN warn: shown
ERROR error: shown

Runtime filtering by a string such as RUST_LOG=warn uses EnvFilter (Example 14).

Example 4: A span and the `enter` guard

A span is a period of time with a name and fields. Events created while a span is entered are reported inside it. span.enter() returns a guard; the span stays entered until the guard is dropped.

Rust

use tracing::{info, info_span};

fn handle(request_id: u32) {
    let span = info_span!("request", id = request_id);
    let _guard = span.enter();
    info!("started");
    info!("finished");
}

#[tokio::main]
async fn main() {
    tracing_subscriber::fmt()
        .with_writer(std::io::stdout)
        .with_ansi(false)
        .without_time()
        .with_target(false)
        .init();

    info!("before");
    handle(1);
    handle(2);
    info!("after");
}

Output

 INFO before
 INFO request{id=1}: started
 INFO request{id=1}: finished
 INFO request{id=2}: started
 INFO request{id=2}: finished
 INFO after

Both events inside handle print with the request{id=1}: prefix, so they can be tied to the request even when other requests log between them.

Example 5: Why `enter()` must not be held across `.await`

An entered span is a per-thread setting. If a future holds the guard while it is suspended at an .await, the span stays entered on that thread while the executor runs other futures. Events from those futures are then reported inside the wrong span. The example runs two futures in one task with tokio::join! (explained in join!, try_join!, and Running Work Concurrently) so the order is fixed.

Rust

use tracing::{info, info_span};

async fn slow_request() {
    let span = info_span!("request", id = 1);
    let _guard = span.enter(); // held across the await below: wrong
    info!("request waiting");
    tokio::task::yield_now().await;
    info!("request done");
}

async fn unrelated_work() {
    info!("unrelated work");
}

#[tokio::main(flavor = "current_thread")]
async fn main() {
    tracing_subscriber::fmt()
        .with_writer(std::io::stdout)
        .with_ansi(false)
        .without_time()
        .with_target(false)
        .init();

    tokio::join!(slow_request(), unrelated_work());
}

Output

 INFO request{id=1}: request waiting
 INFO request{id=1}: unrelated work
 INFO request{id=1}: request done

The line "unrelated work" is printed inside request{id=1} although it has nothing to do with that request. The fix is to attach the span to the future with instrument, which enters the span only while that future is being polled (Example 7).

Example 6: `#[instrument]`

The #[instrument] attribute wraps a function in a span named after the function, with the arguments recorded as fields. On an async fn it attaches the span to the returned future correctly, so no guard is held across an .await.

Rust

use std::time::Duration;
use tracing::{info, instrument};

#[instrument]
async fn fetch_user(id: u32, region: &str) -> String {
    info!("looking up user");
    tokio::time::sleep(Duration::from_millis(10)).await;
    info!("lookup finished");
    format!("user-{id}")
}

#[tokio::main(flavor = "current_thread", start_paused = true)]
async fn main() {
    tracing_subscriber::fmt()
        .with_writer(std::io::stdout)
        .with_ansi(false)
        .without_time()
        .with_target(false)
        .init();

    let name = fetch_user(42, "eu").await;
    info!(%name, "done");
}

Output

 INFO fetch_user{id=42 region="eu"}: looking up user
 INFO fetch_user{id=42 region="eu"}: lookup finished
 INFO done name=user-42

The arguments must implement Debug, because the attribute records them with ?. The span is created when the function is called, entered each time the future is polled, and closed when the future completes or is dropped.

Example 7: `#[instrument]` options

Attribute options control the span. skip(...) leaves an argument out (for large values or secrets), fields(...) adds fields, name = "..." renames the span, level = "..." sets its level, ret logs the return value, and err logs an Err return.

Rust

use tracing::instrument;

#[instrument(name = "login", skip(password), fields(attempt = 1), ret, err)]
async fn login(user: &str, password: &str) -> Result<u32, String> {
    if password == "secret" { Ok(1001) } else { Err(format!("bad password for {user}")) }
}

#[tokio::main]
async fn main() {
    tracing_subscriber::fmt()
        .with_writer(std::io::stdout)
        .with_ansi(false)
        .without_time()
        .with_target(false)
        .init();

    let _ = login("asha", "secret").await;
    let _ = login("ben", "guess").await;
}

Output

 INFO login{user="asha" attempt=1}: return=1001
ERROR login{user="ben" attempt=1}: error=bad password for ben

The password never appears in the output because of skip. ret emits an event at the span's level with the returned value, and err emits an ERROR event with the error. When ret and err are combined on a Result, the Ok value is reported by ret and the Err value by err.

Example 8: Instrumenting a future with `.instrument`

Instrument::instrument(span) attaches a span to any future. The span is entered on every poll of the future and exited when the poll returns. This is the correct form of Example 5.

Rust

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

async fn slow_request() {
    info!("request waiting");
    tokio::task::yield_now().await;
    info!("request done");
}

async fn unrelated_work() {
    info!("unrelated work");
}

#[tokio::main(flavor = "current_thread")]
async fn main() {
    tracing_subscriber::fmt()
        .with_writer(std::io::stdout)
        .with_ansi(false)
        .without_time()
        .with_target(false)
        .init();

    tokio::join!(
        slow_request().instrument(info_span!("request", id = 1)),
        unrelated_work(),
    );
}

Output

 INFO request{id=1}: request waiting
 INFO unrelated work
 INFO request{id=1}: request done

Now "unrelated work" has no span, and both request events are inside request{id=1} even though the request future was suspended between them.

Example 9: Seeing polls with span events

fmt can print an event when a span is created, entered, exited, or closed. FmtSpan::ENTER | FmtSpan::EXIT shows every poll of an instrumented future, which makes the suspension points visible. (FmtSpan::CLOSE also prints busy and idle durations, which change on every run, so it is not used in these examples.)

Rust

use tracing::{Instrument, info_span};
use tracing_subscriber::fmt::format::FmtSpan;

#[tokio::main(flavor = "current_thread")]
async fn main() {
    tracing_subscriber::fmt()
        .with_writer(std::io::stdout)
        .with_ansi(false)
        .without_time()
        .with_target(false)
        .with_span_events(FmtSpan::NEW | FmtSpan::ENTER | FmtSpan::EXIT)
        .init();

    async {
        tokio::task::yield_now().await;
        tokio::task::yield_now().await;
    }
    .instrument(info_span!("job"))
    .await;
}

Output

 INFO job: new
 INFO job: enter
 INFO job: exit
 INFO job: enter
 INFO job: exit
 INFO job: enter
 INFO job: exit
 INFO job: enter
 INFO job: exit

The future is polled three times: once until the first yield_now, once until the second, and once to finish. Each poll produces an enter and an exit line.

Example 10: Spans and `tokio::spawn`

A spawned task is a separate future. It does not inherit the span of the code that called spawn. To keep the relationship, instrument the spawned future with a span, either the current one with in_current_span() or a new child span.

Rust

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

#[tokio::main(flavor = "current_thread")]
async fn main() {
    tracing_subscriber::fmt()
        .with_writer(std::io::stdout)
        .with_ansi(false)
        .without_time()
        .with_target(false)
        .init();

    async {
        let lost = tokio::spawn(async {
            info!("spawned without a span");
        });
        lost.await.unwrap();

        let kept = tokio::spawn(
            async {
                info!("spawned with in_current_span");
            }
            .in_current_span(),
        );
        kept.await.unwrap();

        let child = tokio::spawn(
            async {
                info!("spawned with a child span");
            }
            .instrument(info_span!("worker", n = 1)),
        );
        child.await.unwrap();
    }
    .instrument(info_span!("request", id = 9))
    .await;
}

Output

 INFO spawned without a span
 INFO request{id=9}: spawned with in_current_span
 INFO request{id=9}:worker{n=1}: spawned with a child span

The child span's line shows both spans, request{id=9}:worker{n=1}:, because a span created inside a span records the outer one as its parent. in_current_span() captures Span::current() at the moment it is called, which is inside request.

Example 11: Recording a field after the span exists

Some values are unknown when the span starts, such as a status code. Declare the field as tracing::field::Empty and fill it in later with Span::record.

Rust

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

async fn handle(path: &str) -> u16 {
    let status = if path == "/" { 200 } else { 404 };
    Span::current().record("status", status);
    info!("responding");
    status
}

#[tokio::main]
async fn main() {
    tracing_subscriber::fmt()
        .with_writer(std::io::stdout)
        .with_ansi(false)
        .without_time()
        .with_target(false)
        .init();

    for path in ["/", "/missing"] {
        let span = info_span!("http", %path, status = field::Empty);
        handle(path).instrument(span).await;
    }
}

Output

 INFO http{path=/ status=200}: responding
 INFO http{path=/missing status=404}: responding

The value is recorded before the responding event, so the event line shows it. A field that is never recorded is omitted from the output.

Example 12: Capturing output in a buffer

fmt writes through a MakeWriter, and any Fn() -> impl io::Write closure works as one. A shared buffer collects the log text so a program, or a test, can inspect it. tracing::subscriber::with_default installs a subscriber for the duration of a closure on the current thread, which suits a current_thread runtime.

Rust

use std::io;
use std::sync::{Arc, Mutex};
use tracing::{Instrument, info, info_span};
use tracing_subscriber::fmt::MakeWriter;

#[derive(Clone, Default)]
struct Buffer(Arc<Mutex<Vec<u8>>>);

impl io::Write for Buffer {
    fn write(&mut self, bytes: &[u8]) -> io::Result<usize> {
        self.0.lock().unwrap().extend_from_slice(bytes);
        Ok(bytes.len())
    }
    fn flush(&mut self) -> io::Result<()> {
        Ok(())
    }
}

impl<'a> MakeWriter<'a> for Buffer {
    type Writer = Buffer;
    fn make_writer(&'a self) -> Buffer {
        self.clone()
    }
}

fn main() {
    let buffer = Buffer::default();
    let subscriber = tracing_subscriber::fmt()
        .with_writer(buffer.clone())
        .with_ansi(false)
        .without_time()
        .with_target(false)
        .finish();

    let runtime = tokio::runtime::Builder::new_current_thread().build().unwrap();
    tracing::subscriber::with_default(subscriber, || {
        runtime.block_on(async {
            info!("checking out");
        }
        .instrument(info_span!("order", id = 5)));
    });

    let text = String::from_utf8(buffer.0.lock().unwrap().clone()).unwrap();
    println!("captured {} line(s)", text.lines().count());
    println!("contains the span: {}", text.contains("order{id=5}"));
    print!("{text}");
}

Output

captured 1 line(s)
contains the span: true
 INFO order{id=5}: checking out

Lesson Testing Async Code uses this pattern to assert on log output. The captured text is thread-local to the with_default closure only when the runtime runs on the same thread, which is why the example builds a current_thread runtime.

Example 13: A custom `Layer`

A layer is a composable piece of a subscriber. tracing_subscriber::Layer has hooks such as on_event and on_new_span. A layer can count, forward to a metrics system, or export spans. The example counts events per level.

Rust

use std::sync::Arc;
use std::sync::atomic::{AtomicUsize, Ordering};
use tracing::{Event, Level, Subscriber, error, info, warn};
use tracing_subscriber::layer::{Context, SubscriberExt};
use tracing_subscriber::util::SubscriberInitExt;
use tracing_subscriber::Layer;

#[derive(Default)]
struct Counts {
    info: AtomicUsize,
    warn: AtomicUsize,
    error: AtomicUsize,
}

struct CountLayer(Arc<Counts>);

impl<S: Subscriber> Layer<S> for CountLayer {
    fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) {
        let counter = match *event.metadata().level() {
            Level::ERROR => &self.0.error,
            Level::WARN => &self.0.warn,
            _ => &self.0.info,
        };
        counter.fetch_add(1, Ordering::Relaxed);
    }
}

#[tokio::main]
async fn main() {
    let counts = Arc::new(Counts::default());
    tracing_subscriber::registry().with(CountLayer(counts.clone())).init();

    info!("a");
    info!("b");
    warn!("c");
    error!("d");

    println!("info={} warn={} error={}",
        counts.info.load(Ordering::Relaxed),
        counts.warn.load(Ordering::Relaxed),
        counts.error.load(Ordering::Relaxed));
}

Output

info=2 warn=1 error=1

registry() is a subscriber that stores span data and prints nothing. .with(layer) adds behavior to it. A real service stacks an output layer, a filter, and an exporter the same way.

Example 14: Filtering by target with `EnvFilter`

EnvFilter reads directives such as warn,billing=debug: a default level, plus per-target overrides. A target is a string on each event, the module path by default, and can be set with target: "...". EnvFilter::from_default_env() reads the RUST_LOG variable; the example builds the filter from a string so its behavior is fixed.

Rust

use tracing::{debug, info, warn};
use tracing_subscriber::EnvFilter;

#[tokio::main]
async fn main() {
    tracing_subscriber::fmt()
        .with_writer(std::io::stdout)
        .with_ansi(false)
        .without_time()
        .with_env_filter(EnvFilter::new("warn,billing=debug"))
        .init();

    debug!(target: "billing", "invoice computed");
    debug!(target: "search", "query parsed");
    info!(target: "search", "query finished");
    warn!(target: "search", "index is stale");
}

Output

DEBUG billing: invoice computed
 WARN search: index is stale

Only the billing target passes at debug. Everything else must be warn or above. In production the same string is supplied through RUST_LOG=warn,billing=debug, and changing verbosity needs no rebuild.

Example 15: JSON output

Log pipelines usually want one JSON object per line. .json() switches the formatter. Spans that were entered are included under span and spans.

Rust

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

#[tokio::main(flavor = "current_thread")]
async fn main() {
    tracing_subscriber::fmt()
        .json()
        .with_writer(std::io::stdout)
        .without_time()
        .with_target(false)
        .init();

    async {
        info!(items = 3, "batch accepted");
    }
    .instrument(info_span!("request", id = 12))
    .await;
}

Output

{"level":"INFO","fields":{"message":"batch accepted","items":3},"span":{"id":12,"name":"request"},"spans":[{"id":12,"name":"request"}]}

Each line is a complete JSON document, so tools can index fields.items and span.id without regular expressions.

Example 16: Runtime metrics

Handle::metrics() returns a RuntimeMetrics value with counters about the runtime. Three methods are stable and need no special build flag: num_workers (worker threads, always 1 on current_thread), num_alive_tasks (tasks spawned and not yet finished), and global_queue_depth (tasks waiting in the global queue). On 64-bit targets worker_total_busy_duration, worker_park_count, and worker_park_unpark_count are stable as well.

Rust

use tokio::runtime::Handle;
use tokio::sync::oneshot;

#[tokio::main(flavor = "current_thread")]
async fn main() {
    let metrics = Handle::current().metrics();
    println!("workers: {}", metrics.num_workers());
    println!("alive before spawn: {}", metrics.num_alive_tasks());

    let mut gates = Vec::new();
    let mut handles = Vec::new();
    for _ in 0..3 {
        let (open, wait) = oneshot::channel::<()>();
        gates.push(open);
        handles.push(tokio::spawn(async move {
            let _ = wait.await;
        }));
    }
    tokio::task::yield_now().await;
    println!("alive with 3 blocked tasks: {}", metrics.num_alive_tasks());

    for gate in gates {
        let _ = gate.send(());
    }
    for handle in handles {
        handle.await.unwrap();
    }
    println!("alive after all finished: {}", metrics.num_alive_tasks());
}

Output

workers: 1
alive before spawn: 0
alive with 3 blocked tasks: 3
alive after all finished: 0

A count of alive tasks that keeps rising while the load stays flat is a leak: tasks that never finish, often because they wait on a channel or lock that is never released. On the multi-thread runtime the count is not strongly consistent, so treat it as a trend and not as an exact value.

Many more metrics (poll counts, steal counts, queue depths per worker, poll-time histograms, blocking-pool sizes) exist behind the tokio_unstable compiler flag. That flag opts in to APIs that may change between minor versions, and it is set with RUSTFLAGS="--cfg tokio_unstable" or in .cargo/config.toml. These methods are named here without code because they are not part of the stable API.

Example 17: Finding stuck tasks

A task is stuck when it waits for something that never happens. Two things make it findable: a count of tasks in flight, and a record of what each task is waiting for. The example keeps a shared table of stages and a drop guard that removes an entry when its task ends. A watchdog task checks the table after a deadline and reports what is left. The clock is paused, so the deadline passes without real waiting.

Rust

use std::collections::BTreeMap;
use std::sync::{Arc, Mutex};
use std::time::Duration;
use tokio::sync::oneshot;
use tokio::time::sleep;

type Stages = Arc<Mutex<BTreeMap<u32, &'static str>>>;

struct InFlight {
    id: u32,
    stages: Stages,
}

impl InFlight {
    fn start(id: u32, stages: &Stages) -> InFlight {
        stages.lock().unwrap().insert(id, "started");
        InFlight { id, stages: stages.clone() }
    }
    fn stage(&self, name: &'static str) {
        self.stages.lock().unwrap().insert(self.id, name);
    }
}

impl Drop for InFlight {
    fn drop(&mut self) {
        self.stages.lock().unwrap().remove(&self.id);
    }
}

#[tokio::main(flavor = "current_thread", start_paused = true)]
async fn main() {
    let stages: Stages = Arc::default();
    let (never_sent, never_received) = oneshot::channel::<u32>();

    for id in 1..=3 {
        let stages = stages.clone();
        tokio::spawn(async move {
            let tracker = InFlight::start(id, &stages);
            tracker.stage("waiting for the database");
            sleep(Duration::from_millis(100)).await;
            tracker.stage("done");
        });
    }

    let stuck_stages = stages.clone();
    tokio::spawn(async move {
        let tracker = InFlight::start(99, &stuck_stages);
        tracker.stage("waiting for a reply that is never sent");
        let _ = never_received.await;
    });

    sleep(Duration::from_secs(5)).await; // the watchdog deadline
    let remaining = stages.lock().unwrap().clone();
    println!("tasks still in flight after 5s: {}", remaining.len());
    for (id, stage) in remaining {
        println!("  task {id}: {stage}");
    }
    drop(never_sent);
}

Output

tasks still in flight after 5s: 1
  task 99: waiting for a reply that is never sent

Tasks 1 to 3 finished and removed their entries. Task 99 is still there, with the stage it recorded before it blocked. In a real service the same information comes from an instrumented span per task and from num_alive_tasks. With tokio_unstable, a task dump (an unstable feature that prints the stack of every task) and tokio-console show it without hand-written bookkeeping.

Example 18: A latency histogram

A single average hides slow requests. A histogram counts how many samples fall into each range, and a percentile such as p99 is the value below which 99 percent of samples fall. Metrics systems store histograms because bucket counts from many processes can be added together, and averages cannot.

The example times operations with the paused clock, where sleeps take exactly their nominal length, and prints only bucket counts and derived percentiles.

Rust

use std::time::Duration;
use tokio::time::{Instant, sleep};

struct Histogram {
    bounds_ms: Vec<u64>, // upper bound of each bucket; the last bucket is unbounded
    counts: Vec<u64>,
}

impl Histogram {
    fn new(bounds_ms: &[u64]) -> Histogram {
        Histogram { bounds_ms: bounds_ms.to_vec(), counts: vec![0; bounds_ms.len() + 1] }
    }
    fn record(&mut self, elapsed: Duration) {
        let ms = elapsed.as_millis() as u64;
        let index = self.bounds_ms.iter().position(|&bound| ms <= bound).unwrap_or(self.bounds_ms.len());
        self.counts[index] += 1;
    }
    /// Upper bound of the bucket that contains the given percentile.
    fn percentile(&self, p: f64) -> String {
        let total: u64 = self.counts.iter().sum();
        let target = (total as f64 * p).ceil() as u64;
        let mut seen = 0;
        for (index, count) in self.counts.iter().enumerate() {
            seen += count;
            if seen >= target {
                return match self.bounds_ms.get(index) {
                    Some(bound) => format!("<= {bound}ms"),
                    None => "above the last bound".to_string(),
                };
            }
        }
        unreachable!()
    }
}

#[tokio::main(flavor = "current_thread", start_paused = true)]
async fn main() {
    let mut histogram = Histogram::new(&[10, 50, 100, 500]);
    let work_ms = [3, 4, 4, 5, 6, 8, 9, 12, 15, 20, 30, 45, 70, 90, 400, 900];

    for ms in work_ms {
        let start = Instant::now();
        sleep(Duration::from_millis(ms)).await;
        histogram.record(start.elapsed());
    }

    let labels = ["<=10ms", "<=50ms", "<=100ms", "<=500ms", ">500ms"];
    for (label, count) in labels.iter().zip(&histogram.counts) {
        println!("{label:<8} {count}");
    }
    println!("p50: {}", histogram.percentile(0.50));
    println!("p95: {}", histogram.percentile(0.95));
    println!("p99: {}", histogram.percentile(0.99));
}

Output

<=10ms   7
<=50ms   5
<=100ms  2
<=500ms  1
>500ms   1
p50: <= 50ms
p95: above the last bound
p99: above the last bound

Sixteen samples give a median in the first bucket and a p99 above 500 ms. The mean of these samples is about 100 ms, which describes none of the requests. Percentiles expose the slow tail, and that tail is what users of a service notice.

Example 19: What to measure in a Tokio service

Signals for a service fall into a few groups. Each row names the signal and what a change in it indicates.

Signal	Source	What a change means
Requests per second, errors per second	counters in handlers	load and failure rate
Latency p50, p95, p99	histograms around handlers	slow tail, overloaded dependency
`num_alive_tasks`	`Handle::metrics`	rising with flat load: leaked or stuck tasks
Queued messages in an `mpsc` channel (`max_capacity() - capacity()` on the sender)	gauge around a bounded channel	consumer slower than producer
Permits available in a `Semaphore`	`available_permits`	saturation of a limited resource
Worker busy time, poll time	unstable metrics, `tokio-console`	tasks that block or run long between awaits
Spans per request	`tracing`	where a single request spent its time

tokio-console is a terminal tool that connects to a running process through the console-subscriber crate. It lists tasks with their poll counts, busy and idle time, and wakers. It requires building with tokio_unstable and installing the console-subscriber layer, so it is normally used in development and staging.

Interview points

tracing separates instrumentation (macros in library code) from collection (a subscriber installed by the binary). Libraries call macros and never install a subscriber.
An event is a point in time; a span is a period with a name and fields. Events record which span was active.
A span guard from enter() must not be held across .await: the span would stay entered on the thread while other tasks run. Use #[instrument] or .instrument(span), which enter the span per poll.
Spawned tasks do not inherit the caller's span. Use .in_current_span() or .instrument(child_span) on the spawned future.
#[instrument] records arguments with Debug; skip removes large or secret arguments, ret and err log results.
EnvFilter sets verbosity per target at run time through RUST_LOG.
Stable runtime metrics are few (num_workers, num_alive_tasks, global_queue_depth, and busy and park counts on 64-bit). Detailed metrics need tokio_unstable.
Rising num_alive_tasks at flat load points to leaked or stuck tasks. tokio-console shows which tasks and why.
Report percentiles from histograms. Means hide the tail, and averages cannot be combined across instances, while bucket counts can.

Summary

Install a subscriber once in main; fmt() prints text or JSON, registry() plus layers composes behavior.
Use .without_time() and .with_ansi(false) for reproducible output in examples and tests.
Attach spans to futures with #[instrument] or .instrument(span), and to spawned tasks with .in_current_span() or a child span.
Capture output into a shared buffer through a MakeWriter to assert on logs.
Handle::metrics() gives stable counters for workers, alive tasks, and the global queue.
Find stuck tasks with a per-task record of the current stage and a watchdog, or with tokio-console.
Latency belongs in histograms with percentile reporting.

Example 1: An event

Example 2: Field formatting

Example 3: Levels and a maximum level

Example 4: A span and the enter guard

Example 5: Why enter() must not be held across .await

Example 6: #[instrument]

Example 7: #[instrument] options

Example 8: Instrumenting a future with .instrument

Example 9: Seeing polls with span events

Example 10: Spans and tokio::spawn

Example 11: Recording a field after the span exists

Example 12: Capturing output in a buffer

Example 13: A custom Layer

Example 14: Filtering by target with EnvFilter

Example 15: JSON output

Example 16: Runtime metrics

Example 17: Finding stuck tasks

Example 18: A latency histogram

Example 19: What to measure in a Tokio service

Interview points

Summary

Example 4: A span and the `enter` guard

Example 5: Why `enter()` must not be held across `.await`

Example 6: `#[instrument]`

Example 7: `#[instrument]` options

Example 8: Instrumenting a future with `.instrument`

Example 10: Spans and `tokio::spawn`

Example 13: A custom `Layer`

Example 14: Filtering by target with `EnvFilter`