A service accepts a request, parses its input, queries a database several times, and renders a response. The entire path normally takes about twenty milliseconds, but one day a client waited almost a second.
The logs are there. Every operation has a started entry before it and a done entry after it. There are no errors, and the request completed successfully.
Yet the log still does not contain a ready answer.
To determine how long a database query took, we have to find two related lines and subtract one timestamp from the other. Before that, we must identify which request was slow and separate its messages from hundreds of neighboring requests.
The problem is not the number of log entries. A line describes a single moment, while a delay belongs to an operation that has a beginning, an end, and a place inside a larger piece of work.
In tracing, a span represents exactly that structure.
We will first try to find the delay in ordinary log lines. Then we will describe each operation as a span and finally write a custom Layer that collects a completed request into a tree. The complete demo source is included in the appendix.
Two Lines Do Not Yet Form an Operation
Let us make the delay reproducible.
The service processes two hundred requests sequentially. Each request parses its input, performs three database queries, and renders a response. In request 37, the third database query simulates a cold cache and takes 900 ms; the remaining operations finish within a few milliseconds.
With ordinary logging, the beginning and end of each piece of work are recorded separately:
pub fn handle_logged(id: u64) {
info!("request {id} accepted");
info!("request {id}: parse started");
work(id, "parse", 0);
info!("request {id}: parse done");
for n in 0..3 {
info!("request {id}: db query {n} started");
work(id, "db.query", n);
info!("request {id}: db query {n} done");
}
info!("request {id}: render started");
work(id, "render", 0);
info!("request {id}: render done");
info!("request {id} completed");
}Each request produces twelve lines: two for the request itself, two for parsing, six for the database queries, and two for rendering.
After two hundred requests, the log looks like this:
$ cargo run --release --quiet > lines.log
$ wc -l lines.log
2400 lines.log
$ grep -c "db query" lines.log
1200It contains every required point in time, but no individual line contains an operation's duration.
If the slow request's number is already known, we can find the relevant pair manually:
$ grep 'request 37: db query 2' lines.log
[363.617ms] INFO request 37: db query 2 started
[ 1.264s] INFO request 37: db query 2 doneRoughly nine hundred milliseconds passed between these two messages.
During a real incident, however, the id is not known in advance. Finding it requires a separate parser: extract the request number and operation name from each line, group the messages, match started with done, ensure that pairs were not mixed up, and only then calculate the time difference.
The service originally knew the boundaries of every operation. But it stored them as independent messages, so now we have to reconstruct the structure from text.
A Span Stores the Entire Operation
In tracing, a request can be represented as a named interval:
let request = info_span!("request", id);
let _request = request.enter();The info_span! macro creates a span named request with an id field. The enter method makes it current, and the returned guard is stored in _request.
When the guard is dropped, the program exits the span.
A span describes an operation with a beginning and an end. It can contain fields such as
id=37and a reference to a parent span. An event marks one moment, such as an error, an incoming message, or a state change.
The request's internal steps become child spans:
pub fn handle_traced(id: u64) {
let request = info_span!("request", id);
let _request = request.enter();
info_span!("parse").in_scope(|| work(id, "parse", 0));
for n in 0..3 {
info_span!("db.query", n).in_scope(|| work(id, "db.query", n));
}
info_span!("render").in_scope(|| work(id, "render", 0));
}The in_scope method enters a span before running the closure and exits immediately afterward.
At that point, request is already the current span, so parse, db.query, and render automatically become its child operations. The database query number is stored in a separate n field rather than embedded in a text message.
Calling info_span! does not print anything by itself. It only tells the tracing system that a span was created, entered, or exited.
A subscriber receives those notifications:
tracing_subscriber::fmt()
.with_span_events(FmtSpan::CLOSE)
.with_target(false)
.with_ansi(false)
.init();A subscriber receives events and notifications about the lifetime of spans. It decides whether to print, store, aggregate, or send them to an external system. Here, the ready-made
fmtsubscriber writes closed spans to a text log.
The FmtSpan::CLOSE option adds an entry when each span closes.
Now one line corresponds to one completed operation:
$ cargo run --release --quiet > spans.log
$ wc -l spans.log
1200 spans.logEach request closes six spans: request itself, parse, three db.query spans, and render. Two hundred requests therefore produce 1,200 lines.
Let us sort the root spans by duration:
$ grep -E 'request.id=[0-9]+.: close' spans.log \
| sort -t= -k3 -rn | head -3
2026-08-04T13:42:38.005490Z INFO request{id=37}: close time.busy=907ms time.idle=793ns
2026-08-04T13:42:39.463954Z INFO request{id=178}: close time.busy=19.8ms time.idle=834ns
2026-08-04T13:42:39.045022Z INFO request{id=136}: close time.busy=19.2ms time.idle=833nsThe slow request appears immediately: request{id=37} took 907 ms, while the neighboring requests finished in roughly twenty.
time.busyis the total time for which the span was current afterenteror insidein_scope.time.idleis the time when the span already existed but was not current.
There are fewer lines now, but that is not the main change.
The duration now belongs to the operation itself. The id field is stored separately from the text, and tracing already knows the relationships between parent and child spans.
The formatter still turns this structure back into lines. To obtain a ready-made tree, we will intercept the spans before formatting.
Attaching a Custom Layer
We will write a small handler named TreeLayer. It will receive span notifications and put completed operations into a shared journal:
struct TreeLayer {
journal: Arc<Mutex<Journal>>,
}Then we attach it to the registry:
tracing_subscriber::registry()
.with(TreeLayer {
journal: journal.clone(),
})
.init();The registry stores created spans and the relationships between them. A
Layeris attached on top and receives callbacks at different points in a span's lifetime: creation, entry, exit, and closure.
To make TreeLayer such a handler, it implements the Layer trait.
We need two methods:
impl<S> Layer<S> for TreeLayer
where
S: Subscriber + for<'a> LookupSpan<'a>,
{
fn on_new_span(
&self,
attrs: &Attributes<'_>,
id: &Id,
ctx: Context<'_, S>,
) {
// Remember the span's start and its place in the tree.
}
fn on_close(
&self,
id: Id,
ctx: Context<'_, S>,
) {
// Calculate the duration and store the result.
}
}on_new_span is called immediately after a span is created. on_close is called when that same span closes.
The id argument identifies the record, while ctx provides access to the registry: through it, the layer can obtain the operation's name, fields, and parent.
Remembering the Start and Path
For every open span, we store its creation time, depth in the tree, and complete path:
struct Meta {
born: Instant,
depth: usize,
path: String,
}For the root span, the path looks like this:
request{id=37}For a child database query:
request{id=37} > db.query{n=2}At the beginning of on_new_span, we find the span that was just created:
let span = ctx.span(id).expect("span exists on creation");Then we collect its fields:
let mut fields = Fields::default();
attrs.record(&mut fields);
let label = if fields.0.is_empty() {
span.name().to_string()
} else {
format!("{}{{{}}}", span.name(), fields.0)
};tracing does not turn a span's fields into one ready-made string. The record method passes them to an object that implements the Visit trait.
In our case, Fields collects values such as id=37 or n=2, after which they are appended to the operation name.
Now we determine the span's position in the tree:
let (depth, path) = match span.parent() {
Some(parent) => {
let parent_meta = parent.extensions();
let meta = parent_meta
.get::<Meta>()
.expect("parent has meta");
(
meta.depth + 1,
format!("{} > {}", meta.path, label),
)
}
None => (0, label),
};The request span has no parent, so its depth is zero.
parse, db.query, and render find their parent request, increase its depth by one, and append their own label to the path already built.
The resulting Meta is attached to the span's record:
span.extensions_mut().insert(Meta {
born: Instant::now(),
depth,
path,
});Extensions are storage for arbitrary Rust values inside a span's record. A layer can put its own
Metathere and retrieve it later using the sameid, without creating a separate lookup table.
After on_new_span, the registry stores not only the standard tracing information but also the data needed for our tree.
Closing a Span Produces a Complete Record
When the last owner of a span disappears, the subscriber calls on_close.
First, we find the span by its identifier again and read the stored Meta:
let span = ctx.span(&id).expect("span exists on close");
let extensions = span.extensions();
let meta = extensions
.get::<Meta>()
.expect("span has meta");Then we calculate the duration and add the completed operation to the journal:
journal.closed.push(Closed {
depth: meta.depth,
path: meta.path.clone(),
micros: meta.born.elapsed().as_micros(),
});The journal now contains separate structured values instead of lines that would have to be parsed:
struct Closed {
depth: usize,
path: String,
micros: u128,
}They can be sorted by duration, grouped by root request, and printed with the required indentation.
After the same two hundred requests, the result looks like this:
$ cargo run --release --quiet
spans recorded: 1200
slowest spans:
906.665 ms request{id=37}
900.076 ms request{id=37} > db.query{n=2}
18.767 ms request{id=146}
18.029 ms request{id=110}
tree of the slowest request:
request{id=37} 906.665 ms
parse 1.588 ms
db.query{n=0} 1.627 ms
db.query{n=1} 1.730 ms
db.query{n=2} 900.076 ms
render 1.606 msThe first two entries immediately identify both the slow request and its cause.
Of the total 906.665 ms, the third database query took 900.076 ms. The remaining steps of the same request finished within the usual few milliseconds.
Regular expressions, matching started with done, and manual timestamp subtraction are no longer required.
A trace combines a root span and all its child operations into one tree. Distributed tracing systems usually draw this tree on a timeline; here, the same structure is printed as ordinary text.
Logs Do Not Disappear
Moving to spans does not mean that events are no longer needed.
Spans are a convenient way to describe operations, while events describe individual facts inside them.
For example, a database query can be a span:
let query = info_span!("db.query", n);and a retry inside it can be an event:
warn!(attempt, "query retry");The event automatically appears in the context of the current request and the current database operation.
The division is natural. A span answers which work was being performed and how long it took. An event reports what happened at a particular moment during that work.
It is possible to describe long-running operations using events alone, but then their structure must again be reconstructed from conventions in the text.
The Delay Becomes Part of the Model
The original log already contained all the information. Every operation had a start line and a completion line.
But the relationship between them existed only in the message format: the matching id, step name, and the words started and done.
A span stores this relationship directly. It has a name, fields, a parent, and lifetime boundaries. A subscriber receives structured notifications, and a Layer can turn them into text, metrics, a tree, or data for a graphical tracing system.
That is why tracing is not merely another way to print logs.
A line answers: what happened at this moment?
A span answers a different question: which operation was running, inside which request, and how long did it take?
That is what was missing when we searched for the lost second. Once the request became a tree of operations, the delay no longer had to be calculated from two lines.
It became the duration of db.query{n=2} inside request{id=37}.
Appendix: Full Source Files
log-lines/src/service.rs — 45 lines
//! The simulated service, shared verbatim by every scene: a request is
//! parsed, makes three database queries, renders a response. Request 37
//! hits a cold cache on its third query and pays ~900 ms — the incident
//! the whole article is about. Delays are deterministic.
use log::info;
use std::thread::sleep;
use std::time::Duration;
pub const REQUESTS: u64 = 200;
pub const SLOW_REQUEST: u64 = 37;
pub const SLOW_QUERY: u64 = 2;
/// Deterministic per-step delay in microseconds: small, id-dependent,
/// and one enormous outlier.
pub fn delay_us(id: u64, step: &str, n: u64) -> u64 {
if id == SLOW_REQUEST && step == "db.query" && n == SLOW_QUERY {
return 900_000;
}
let mix = id
.wrapping_mul(0x9E37_79B9)
.wrapping_add(n * 101)
.wrapping_add(step.len() as u64 * 13);
500 + mix % 2_500
}
fn work(id: u64, step: &str, n: u64) {
sleep(Duration::from_micros(delay_us(id, step, n)));
}
pub fn handle_logged(id: u64) {
info!("request {id} accepted");
info!("request {id}: parse started");
work(id, "parse", 0);
info!("request {id}: parse done");
for n in 0..3 {
info!("request {id}: db query {n} started");
work(id, "db.query", n);
info!("request {id}: db query {n} done");
}
info!("request {id}: render started");
work(id, "render", 0);
info!("request {id}: render done");
info!("request {id} completed");
}log-lines/src/main.rs — 45 lines
//! Scene 01: the same service, instrumented the classic way — log LINES.
//!
//! A simulated request pipeline (parse -> three db queries -> render)
//! logs the start and end of every stage with timestamps, exactly the
//! way most services do. One request in the batch is pathologically
//! slow. The exercise for the reader: find it in the output — armed
//! with nothing but grep.
mod service;
use anyhow::Result;
use log::{Level, LevelFilter, Metadata, Record};
use std::time::Instant;
/// A deliberately ordinary logger: timestamp, level, message. No
/// structure, no correlation — just lines, like everyone's first setup.
struct Plain {
started: Instant,
}
impl log::Log for Plain {
fn enabled(&self, metadata: &Metadata) -> bool {
metadata.level() <= Level::Info
}
fn log(&self, record: &Record) {
let t = self.started.elapsed();
println!("[{:>9.3?}] {} {}", t, record.level(), record.args());
}
fn flush(&self) {}
}
fn main() -> Result<()> {
let logger = Box::leak(Box::new(Plain {
started: Instant::now(),
}));
log::set_logger(logger).expect("logger is set once");
log::set_max_level(LevelFilter::Info);
for id in 0..service::REQUESTS {
service::handle_logged(id);
}
Ok(())
}spans/src/service.rs — 36 lines
//! The same simulated service as scene 01 — identical delays, identical
//! incident — instrumented with spans instead of lines.
use std::thread::sleep;
use std::time::Duration;
use tracing::info_span;
pub const REQUESTS: u64 = 200;
pub const SLOW_REQUEST: u64 = 37;
pub const SLOW_QUERY: u64 = 2;
pub fn delay_us(id: u64, step: &str, n: u64) -> u64 {
if id == SLOW_REQUEST && step == "db.query" && n == SLOW_QUERY {
return 900_000;
}
let mix = id
.wrapping_mul(0x9E37_79B9)
.wrapping_add(n * 101)
.wrapping_add(step.len() as u64 * 13);
500 + mix % 2_500
}
fn work(id: u64, step: &str, n: u64) {
sleep(Duration::from_micros(delay_us(id, step, n)));
}
pub fn handle_traced(id: u64) {
let request = info_span!("request", id);
let _request = request.enter();
info_span!("parse").in_scope(|| work(id, "parse", 0));
for n in 0..3 {
info_span!("db.query", n).in_scope(|| work(id, "db.query", n));
}
info_span!("render").in_scope(|| work(id, "render", 0));
}spans/src/main.rs — 23 lines
//! Scene 02: the same service, but the unit of instrumentation is a
//! SPAN — a named interval with fields that knows when it opened, when
//! it closed, and inside what. The stock fmt subscriber is asked to
//! print span closes: every line now carries a duration and a full
//! path, and the incident becomes one `sort` away.
mod service;
use anyhow::Result;
use tracing_subscriber::fmt::format::FmtSpan;
fn main() -> Result<()> {
tracing_subscriber::fmt()
.with_span_events(FmtSpan::CLOSE)
.with_target(false)
.with_ansi(false)
.init();
for id in 0..service::REQUESTS {
service::handle_traced(id);
}
Ok(())
}span-tree/src/main.rs — 143 lines
//! Scene 03: a custom subscriber turns spans into an analyzable tree.
//!
//! The Layer below records every span close as (depth, path, fields,
//! elapsed) into a shared journal. After the run, plain code — not
//! grep — renders the slowest request as an indented tree and answers
//! "where did the second go" with one sorted list. This is the seed of
//! the traceview TUI: the data is already the right shape.
mod service;
use anyhow::Result;
use std::fmt::Write as _;
use std::sync::{Arc, Mutex, PoisonError};
use std::time::Instant;
use tracing::span::{Attributes, Id};
use tracing::{Subscriber, field::Field, field::Visit};
use tracing_subscriber::layer::{Context, Layer, SubscriberExt};
use tracing_subscriber::registry::LookupSpan;
use tracing_subscriber::util::SubscriberInitExt;
/// One closed span: where it sat in the tree and how long it lived.
#[derive(Clone)]
struct Closed {
depth: usize,
path: String,
micros: u128,
}
#[derive(Default)]
struct Journal {
closed: Vec<Closed>,
}
/// Span extension data: birth time and the path assembled from parents.
struct Meta {
born: Instant,
depth: usize,
path: String,
}
/// Collects field values into "name{k=v}" form for the path.
#[derive(Default)]
struct Fields(String);
impl Visit for Fields {
fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) {
let _ = write!(self.0, "{}={value:?}", field.name());
}
}
struct TreeLayer {
journal: Arc<Mutex<Journal>>,
}
impl<S> Layer<S> for TreeLayer
where
S: Subscriber + for<'a> LookupSpan<'a>,
{
fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) {
let span = ctx.span(id).expect("span exists on creation");
let mut fields = Fields::default();
attrs.record(&mut fields);
let label = if fields.0.is_empty() {
span.name().to_string()
} else {
format!("{}{{{}}}", span.name(), fields.0)
};
let (depth, path) = match span.parent() {
Some(parent) => {
let parent_meta = parent.extensions();
let meta = parent_meta.get::<Meta>().expect("parent has meta");
(meta.depth + 1, format!("{} > {}", meta.path, label))
}
None => (0, label),
};
span.extensions_mut().insert(Meta {
born: Instant::now(),
depth,
path,
});
}
fn on_close(&self, id: Id, ctx: Context<'_, S>) {
let span = ctx.span(&id).expect("span exists on close");
let extensions = span.extensions();
let meta = extensions.get::<Meta>().expect("span has meta");
let mut journal = self.journal.lock().unwrap_or_else(PoisonError::into_inner);
journal.closed.push(Closed {
depth: meta.depth,
path: meta.path.clone(),
micros: meta.born.elapsed().as_micros(),
});
}
}
fn main() -> Result<()> {
let journal = Arc::new(Mutex::new(Journal::default()));
tracing_subscriber::registry()
.with(TreeLayer {
journal: journal.clone(),
})
.init();
for id in 0..service::REQUESTS {
service::handle_traced(id);
}
let journal = journal.lock().unwrap_or_else(PoisonError::into_inner);
let closed = &journal.closed;
println!("spans recorded: {}", closed.len());
// The verdict: the slowest spans, sorted — no grep involved.
let mut slowest: Vec<&Closed> = closed.iter().collect();
slowest.sort_by(|a, b| b.micros.cmp(&a.micros));
println!("\nslowest spans:");
for span in slowest.iter().take(4) {
println!(" {:>9.3} ms {}", span.micros as f64 / 1000.0, span.path);
}
// The tree of the worst request, exactly as a TUI would draw it.
let worst = slowest
.iter()
.find(|span| span.depth == 0)
.expect("a root span exists");
println!("\ntree of the slowest request:");
println!(
" {:<26} {:>9.3} ms",
worst.path,
worst.micros as f64 / 1000.0
);
for span in closed
.iter()
.filter(|span| span.path.starts_with(&format!("{} > ", worst.path)))
{
println!(
" {}{:<24} {:>9.3} ms",
" ".repeat(span.depth),
span.path.rsplit(" > ").next().unwrap_or(&span.path),
span.micros as f64 / 1000.0
);
}
Ok(())
}