Debug a page in production

You'll read a request back as one tree that shows which loader waited on which service, what ran at the same time and which cache answered. You'll do it first from the dev server and then from the binary you actually deploy, where the endpoint you just used doesn't exist.

cargo install snapfire_compiler
cargo install snapfire_fsr_cli
fsr --version

Start the collector#

fsr dev and fsr serve install the trace collector themselves for a development host and say so in the banner:

$ fsr dev shop/app
fsr server on http://127.0.0.1:3000/
fsr traces on http://127.0.0.1:3000/__fsr/traces

If the second line is missing, no collector is installed. That happens when the host isn't a development one. That's server.dev in your configuration, which defaults to whether RELEASE_ENV is development.

Read one request#

The endpoint answers a JSON array, one entry per trace, each with id, ms and a flat spans list. Every span carries its own depth, so whatever reads it lays it out as a tree:

$ curl -s localhost:3000/__fsr/traces | jq '.[-1].spans[] | {name, ms, outcome, fields}'
request 19.92ms ok {"method": "GET", "path": "/product/9", "status": "200"}
  source 16.25ms ok {"id": "layout", "memo": "miss", "node": "1"}
  source 16.60ms ok {"id": "product.$id", "node": "2"}
    call 15.99ms ok {"service": "catalog", "method": "getProduct"}
    call 15.54ms ok {"service": "pricing", "method": "quote"}
  render 1.37ms {"module": "shell#document"}
    render 1.16ms {"module": "routes/layout.tsx#default"}
      render 0.10ms {"module": "routes/product/[id]/page.tsx#default", "cache": "miss"}

The two service calls sit under the loader that made them, so you can see which loader waits on which backend.

Both loaders took about sixteen milliseconds inside a request that took twenty, so they ran together. Had they run one after the other the request would have been thirty-three.

Rendering the whole tree cost 1.37ms against sixteen spent waiting, so the backend is what makes this page slow.

Three caches report themselves. A source span carries memo: hit or memo: miss when that loader is memoizable. A call span carries cache: hit, stale or miss when the data cache answered or was asked. A render span carries cache: hit or cache: miss when the render cache was consulted for that node. A node you expected to be cached that says miss on every request is a bug. You can't see it from outside, because the page is correct and only costs more to produce.

Request the page a second time and the render subtree has fewer spans. A cache: hit high in the tree means the nodes beneath it were never rendered, so they have no spans at all. When a subtree disappears between two traces, the cache is working.

The spans#

Only request, source and call set an outcome. A render span has none, so read its cache field rather than looking for ok on it.

Anything you open yourself with tracing joins whichever request it's inside, so a span around your own slow function appears nested in the tree.

Trace in production#

In production the endpoint isn't registered on a production host, because a client shouldn't be able to read what a source cost. An app with no crate runs fsr-server (410), which keeps traces only for the paths [trace] names under expose or inline. The rest of this section is for an app with its own binary, which installs nothing on its own.

Here is that binary in full, with the collector wired:

[package]
name = "shop"
version = "0.1.0"
edition = "2024"

[dependencies]
snapfire_fsr_host = "0"
tokio = { version = "1", features = ["macros", "rt-multi-thread"] }

use std::path::Path;
use std::sync::Arc;

use snapfire_fsr_host::Host;

#[tokio::main]
async fn main() -> std::io::Result<()> {
  let (traces, _logging, why) = snapfire_fsr_host::trace::observe(Path::new("fibre_logging.yaml"));
  if let Some(why) = why {
    eprintln!("logging: {why}");
  }

  let host = Host::from_cwd()
    .and_then(|builder| builder.traces(traces.clone()).build())
    .map_err(std::io::Error::other)?;

  print!("{}", host.report());
  let listen = host.listen().to_owned();
  Arc::new(host).serve(&listen).await
}

observe composes two layers on one registry: fibre_logging taking events out to its appenders and the collector keeping each request's spans. Logging and tracing are separate. You need fibre_logging for logs even with the collector installed. Hold _logging, because its Drop flushes the appenders and binding it to _ loses the tail of your log on every exit. A missing or unreadable fibre_logging.yaml isn't fatal: the collector is installed alone and the reason comes back as the third value.

With no endpoint to read, traces leave through a listener. Add this to main after the observe call. The listener hands each trace to a channel and a thread at the other end prints it:

  let (sender, receiver) = std::sync::mpsc::channel::<snapfire_fsr_host::trace::Trace>();
  std::thread::spawn(move || {
    for trace in receiver {
      println!("trace {} took {}ms", trace.id, trace.duration.as_millis());
    }
  });
  if let Some(traces) = &traces {
    traces.on_finish(move |trace| {
      let _ = sender.send(trace.clone());
    });
  }

Every finished trace is handed to each listener as its root closes, before the ring. That's also the only place tail sampling can happen, because deciding to keep the slow ones and the failed ones needs the finished trace; anything sampling when a span opens hasn't seen it yet. To keep only those, replace the on_finish call with this one:

    traces.on_finish(move |trace| {
      let slow = trace.duration.as_millis() > 500;
      let failed = trace.root().and_then(|s| s.outcome()) != Some("ok");
      if slow || failed {
        let _ = sender.send(trace.clone());
      }
    });

A listener runs on the thread that closed the root, so a slow one delays that request's close. That is why the listener above only sends to a channel and the printing happens on another thread. Don't do a blocking HTTP post in there.

trace::server_timing(&trace) formats one trace as a Server-Timing header value, which puts per-step cost in browser devtools. Nothing in the host sends it, so that one is for an application that wants to attach it to its own responses.

What it costs with no collector#

With no collector installed a span is a relaxed atomic load and a branch. It doesn't allocate or format fields. That is why the instrumentation stays in release builds. Whether anything collects is decided in main instead of at compile time.

The ring holds the last 256 traces in memory, about a kilobyte each; /__fsr/traces returns the last fifty of them, newest last. Nothing is written to disk and nothing leaves the process until you wire an exporter.

Next up: 430. Make a page fast.