# 203. What a request did

**For:** everyone. The trace behind a slow or wrong page and how to read one.

## Why traces

A log line records one fact. Ten log lines from one request have to be reassembled by hand, interleaved with every other request in flight. A trace records the whole request: every step it took, nested the way it ran and each with its own cost.

`tracing` does not give you a trace back. Spans go to a subscriber and nothing returns. That works when the destination is a file but not when you want to read a request back, so the host keeps the spans itself.

## Setting up tracing

You do not wire `tracing` yourself. `snapfire_fsr_host::trace` sets it up, because every application needs the same code:

```rust
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.

`observe` returns three values. `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` sets up both, which is usually what you want.

## Reading a trace

The host answers `GET /__fsr/traces` with the last fifty, newest last. It is for development only, since a production client should not read what each source cost.

```
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`. The indented shape above is built from it by the reader. 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, so the time went to waiting and not to rendering.

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.

## Overhead

With no collector installed a span costs a relaxed atomic load and a branch, with no allocation and no field formatting. 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. That is all the storage there is until you add more.

## Exporting traces

Nothing leaves the process on its own. A listener runs as each request finishes:

```rust
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.

## Try it

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, because the loaders run in parallel. 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` and 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.