What a request did
A request is one object
A log line is one fact. Ten of them from one request are ten facts you reassemble by hand, interleaved with every other request in flight. A trace is the request itself: every step it took, nested the way it nested, each with its own cost.
tracing does not give you one back. Spans go to a subscriber and nothing returns, which is right when the destination is a file and wrong here. So the host keeps them.
The host sets it up
You do not wire tracing yourself. snapfire_fsr_host::trace owns the whole arrangement, because every application wants the same lines:
let logging = Path::new(env!("CARGO_MANIFEST_DIR")).join("fibre_logging.yaml");
let (traces, _logging, why) = snapfire_fsr_host::trace::observe(&logging);
let host = Host::from(env!("CARGO_MANIFEST_DIR"))
.and_then(|builder| builder.traces(traces).build())?;observe composes two different jobs on one registry: fibre_logging taking the events out to its appenders and fibre_tracing keeping the spans. Neither replaces the other.
Three things come back. traces is the handle. It is an Option because something else may already own the global dispatcher, in which case no trace is kept and that is not an error. _logging is a guard you have to hold, since dropping it flushes the appenders. why is the reason the logging configuration could not be read, if it could not: the collector is installed alone and the application still traces.
If the host already logs through tracing's default there is install(). If a layer already owns the events there is install_with(layer). observe is the pair you want.
Reading one
The host answers GET /__fsr/traces with the last fifty, newest last. Development only: what a source cost is nothing a production client should read.
request 19.92ms ok {"method": "GET", "path": "/agents", "status": "200"}
source 16.25ms ok {"id": "layout", "memo": "miss", "node": "1"}
source 16.60ms ok {"id": "agents.layout", "node": "2"}
call 15.99ms ok {"service": "fleet", "method": "listAlerts", "cache": "none"}
call 15.54ms ok {"service": "fleet", "method": "listAgents", "cache": "miss"}
render 1.37ms {"module": "shell#document"}
render 1.16ms {"module": "routes/layout.tsx#default", "cache": "miss"}
render 0.10ms {"module": "routes/agents/page.tsx#default", "cache": "miss"}The endpoint answers a JSON array. Every span carries its own depth, so the shape above is the reader's work. Both loaders took about sixteen milliseconds inside a request that took twenty, so they ran together rather than one after the other. Each service call sits under the loader waiting on it, so you know which loader is blocked on which backend. Rendering the whole tree cost one and a half milliseconds against sixteen spent waiting, which tells you where to look and where not to.
Three caches report themselves on three spans. A source span carries memo: hit or memo: miss when that loader is memoizable. A call span carries cache: hit or cache: miss when the method has a cache policy and cache: none when it has none, so two otherwise identical requests differ in exactly the call the data cache answered. A render span carries cache: hit or cache: miss when the render cache was consulted for that node. Ask for the same page again and the render subtree gets shorter rather than faster: a cache: hit high in the tree means the nodes beneath it were never rendered, so they have no spans at all.
The four spans
| Span | One per | Says |
|---|---|---|
request | request, the root | method, path, status and the outcome |
source | plan node with a loader | the id, the node, the outcome and memo when it is memoizable |
call | service method, whatever the transport | service, method, cache when a policy was consulted and the failure kind when it failed |
render | plan node | the module, plus cache when the render cache was consulted |
A failure names its kind rather than a raw status, because the kind is what your code branches on. Only request, source and call set an outcome: a render span has none, so read its cache field instead of looking for ok on it. Anything you open with tracing yourself joins whichever request it is inside.
What it costs when nobody is watching
With no collector installed a span is a relaxed atomic load and a branch: no allocation, no formatting of fields. Leave the instrumentation in production builds and decide separately whether anything collects it. The ring holds the last few hundred traces in memory at roughly a kilobyte each, which is the whole storage story until you want more.
Getting them out
Nothing leaves the process on its own. A listener runs as each request finishes:
traces.on_finish(|trace| exporter.send(trace));That is also the only place tail sampling can happen, keeping what failed or ran long and dropping the rest, because the decision needs the finished trace. Anything that samples when a span opens has not seen it yet.
The lab
Load a page, fetch /__fsr/traces and find that request. Now make one service method sleep for half a second and load the page again: the request grows by roughly that, one source span grows with it and the call span underneath names the method that did it. The other loader is unchanged, which is the parallelism showing itself. Then load the same page twice without changing anything and compare the render spans: the second says cache: hit where the first said cache: miss; the spans beneath it are gone. The call spans say the same of the data cache: a method with a policy goes from cache: miss to cache: hit and its transport is never reached the second time.