Lab 2: Tracing and Metrics

Background

A debugger is a scalpel: precise, but slow to wield and useless if you don't already know roughly where to cut. Most Firecracker debugging starts somewhere cheaper. Firecracker is, by design, a jailed process you cannot easily introspect — so it exports its own observability: a logger that emits human-readable lines at a configurable level, a metrics system that serializes a fixed tree of atomic counters to JSON, an in-tree log_instrument tracing facility that can record function entry/exit at Trace level, and a BootTimer pseudo-device that times boot to userspace with near-zero overhead. Before you attach gdb, you flush metrics and read logs; nine times out of ten, which counter moved and which log line confirmed it already tells you what broke and where.

This lab makes you build an observability workflow around a concrete, common failure: a microVM that boots slowly, or doesn't reach userspace at all. You will configure all four instruments, read the emitted JSON counter tree, turn on tracing for one path, time the boot with the BootTimer, and assemble it into a repeatable diagnosis loop — without a debugger.

Note: This lab is the hands-on counterpart to the Logging and metrics deep dive and the Signals, shutdown, and reset deep dive. Read both; they explain what the counters mean. This lab is about using them under time pressure.

Why This Lab Matters for Contributors

• In production, the VMM is seccomp-jailed and there is no debugger on the host. The metrics file and the log FIFO are the only window an operator has — so a contributor who adds a feature must also make it observable. Knowing the observability surface is part of knowing the codebase.
• "Add a counter / add a log_instrument span to a path that was a black box" is a real, valued, mergeable PR class — see the logging and metrics deep dive for where new metrics get wired in.
• The BootTimer is the mechanism behind the project's most-defended number (boot time). Understanding it here is the prerequisite for the boot-time masterclass lab.
• A metrics-first triage habit is what keeps you from burning an afternoon in gdb on a problem a single counter would have localized.

Prerequisites

• Lab 1.3: Boot your first microVM — you can boot a microVM from the API or a config file.
• Lab 2 of this intensive's sibling reading — you know the counter tree exists.
• A built firecracker, a vmlinux, and a rootfs.ext4.

cd ~/src/firecracker
FC=$(find build/cargo_target -type f -name firecracker | head -1); echo "$FC"
# Confirm the metrics tree and the BootTimer exist on your branch (paths move).
rg -n "struct FirecrackerMetrics|SharedIncMetric|SharedStoreMetric" src/vmm/src/logger/
rg -n "BootTimer|MAGIC_VALUE_SIGNAL_GUEST_BOOT_COMPLETE|Guest-boot-time" \
  src/vmm/src/devices/pseudo/boot_timer.rs

Step 1: Configure the logger and the metrics sink

Both are configured pre-boot, by pointing them at a path (a file or a FIFO). Use a config file so the whole machine, plus logging and metrics, is one artifact you can re-run:

mkfifo /tmp/fc-metrics.fifo 2>/dev/null || true   # a FIFO you can drain; a plain file works too
: > /tmp/fc.log

cat > vm.json <<'EOF'
{
  "boot-source": {
    "kernel_image_path": "./vmlinux",
    "boot_args": "console=ttyS0 reboot=k panic=1 pci=off nomodule i8042.noaux i8042.nomux 8250.nr_uarts=0"
  },
  "drives": [
    {"drive_id": "rootfs", "path_on_host": "./rootfs.ext4",
     "is_root_device": true, "is_read_only": false}
  ],
  "machine-config": {"vcpu_count": 1, "mem_size_mib": 256},
  "logger":  {"log_path": "/tmp/fc.log", "level": "Debug",
              "show_level": true, "show_log_origin": true},
  "metrics": {"metrics_path": "/tmp/fc-metrics.fifo"}
}
EOF

Note: Set the logger first and at Debug while diagnosing. The whole point of configuring it pre-boot is that configuration errors and early boot failures show up in the log — if you only turn logging on after the failure, you have nothing.

Step 2: Boot, flush metrics, and read the counter tree

Drain the metrics FIFO in one terminal, boot in another, then flush on demand.

# Terminal A: drain the metrics FIFO (each flush is ONE JSON line).
cat /tmp/fc-metrics.fifo

# Terminal B: boot with the API so you can send FlushMetrics on demand.
API=/tmp/fc.sock
sudo "$FC" --api-sock "$API" --config-file vm.json &   # config-file boot also starts the VM
# (or PUT the sections then InstanceStart as in Lab 1.3)

# Force one immediate metrics snapshot:
curl -X PUT --unix-socket "$API" --data '{"action_type":"FlushMetrics"}' http://localhost/actions

Terminal A prints one line. Pretty-print and read it:

# Capture one flush to a file and format it.
head -1 /tmp/fc-metrics.fifo > /tmp/metrics.json 2>/dev/null
python3 -m json.tool < /tmp/metrics.json | head -60

The tree mirrors the architecture — it is a map of where to look:

The two counter kinds, from the deep dive:

rg -n "SharedIncMetric|SharedStoreMetric|IncMetric|StoreMetric|fn inc|fn add|fn store" \
  src/vmm/src/logger/

• SharedIncMetric (IncMetric) — a monotonic counter; inc()/add(n). Cumulative, so you diff two flushes to get a rate.
• SharedStoreMetric (StoreMetric) — stores a latest value (a gauge).

Tip: Each flush is a full cumulative snapshot. The monitoring pattern is: ship every line, diff consecutive lines for rates, and alert on counters that must stay zero — seccomp.num_faults, signals.sigbus/sigsegv, and every *.failures. If one of those moved, you have your subsystem before you read a single log line.

Step 3: Read the log to learn why

Metrics tell you that and where; logs tell you why. With the logger at Debug, the boot path is narrated:

# The boot story, with level and origin prefixes.
sed -n '1,80p' /tmp/fc.log
# The lines that matter most when something is wrong:
rg -n "ERROR|WARN|seccomp|SIGSYS|bad syscall|SIGSEGV|SIGBUS|panic|failed|Guest-boot-time" /tmp/fc.log

The pairing is the method:

metrics: seccomp.num_faults = 1   → a syscall was denied
log:     "Shutting down because of SIGSYS ... syscall=NNN ..."  → which syscall, which thread
         → now you know the exact denied syscall to add a rule for, or the bug that called it

metrics: signals.sigbus = 1       → a bad memory access (often a short/truncated mem file)
log:     the SIGBUS handler logged the faulting address
         → see signals-shutdown-and-reset.md; suspect the guest-memory mmap / a snapshot mem file

Step 4: Time the boot with the BootTimer

A slow boot is not a crash — no counter is alarming, no error logs. You need a number. The BootTimer pseudo-device gives you boot-to-userspace with negligible overhead: the guest writes a single magic byte to a known MMIO address the instant init finishes; Firecracker catches that write, diffs the timestamp against the microVM's start time, and logs Guest-boot-time.

# The mechanism: a single-byte MMIO write of the magic value at offset 0.
rg -n "MAGIC_VALUE_SIGNAL_GUEST_BOOT_COMPLETE|Guest-boot-time|start_ts|fn write" \
  src/vmm/src/devices/pseudo/boot_timer.rs

The magic value is 123 (verify on your branch via the rg above). The device is attached via a developer flag; the integration test enables it exactly this way:

# How the project's own boot-time test turns the device on and parses the result.
rg -n "boot-timer|Guest-boot-time|extra_args|DEFAULT_BOOT_ARGS" \
  tests/integration_tests/performance/test_boottime.py

The test enables the device with vm.jailer.extra_args.update({"boot-timer": None}) and parses the log line with the regex r"Guest-boot-time =\s+(\d+) us\s+(\d+) ms,\s+(\d+) CPU us\s+(\d+) CPU ms". To do it by hand, add the developer flag to your firecracker invocation and grep the log after boot:

# Boot with the boot-timer pseudo-device enabled, then read the timing line.
sudo "$FC" --no-api --config-file vm.json --boot-timer 2>/dev/null &   # flag name verifies on your branch
sleep 3
rg -n "Guest-boot-time" /tmp/fc.log
# Guest-boot-time =   84231 us   84 ms,   71204 CPU us   71 CPU ms

That single line is the foundation of the boot-time lab: wall-clock boot time and CPU boot time, from InstanceStart to guest-ready. Always record the exact kernel, rootfs, boot args, and host alongside it — a boot number without that context is unfalsifiable.

Step 5: Turn on log_instrument tracing for one path

When the counters and the boot number say "boot is slow somewhere in the VMM setup or early device init" but not where, the in-tree log_instrument facility records function entry/exit so that, at Trace level, you get a call trace through the code.

# The tracing crates and the annotations.
find src/log-instrument src/log-instrument-macros -name "*.rs" 2>/dev/null
rg -n "log_instrument|#\[instrument|clippy-tracing|trace!" src/ | head

It is normally compiled out / disabled to keep the fast path lean; enable it deliberately when tracing a path. Drop the logger to Trace, reproduce, and read the entry/exit trace — then turn it off (it is a firehose that can itself slow the path enough to change behaviour, a Heisenbug):

# In vm.json, set "level":"Trace" for the logger, re-boot, reproduce, then read:
rg -n "load_kernel|configure_system|attach.*device|build_microvm_for_boot|->.*\bret\b" /tmp/fc.log | head -40
# Restore "level":"Debug" the moment you have the trace you need.

clippy-tracing is the CI tool that keeps the #[instrument] annotations consistent across the tree (a lint concern, not a runtime one) — rg -n "clippy-tracing" tools/ src/ shows how CI enforces it.

Step 6: Assemble the workflow

Put the four instruments in order. This is the deliverable — a loop you can run on any slow-or-failing-boot report:

flowchart TD
    Sym["microVM boots slowly or not at all"] --> M["1. FlushMetrics, read the tree"]
    M -->|"seccomp.num_faults / signals.* / *.failures moved"| Log1["2. read log at Debug → which syscall/fault/error"]
    M -->|"all clean, but no userspace"| BT["3. BootTimer: is there a Guest-boot-time line at all?"]
    BT -->|"no line"| Log2["boot never finished → log + Lab 1 gdb the guest"]
    BT -->|"line present but large"| Trace["4. log_instrument Trace → which phase is slow"]
    Log1 --> Fix["root cause: rule / mem file / config"]
    Trace --> Fix2["root cause: the slow phase → optimize or fix"]

In words: metrics first (which subsystem moved, and is a must-be-zero counter nonzero?) → logs (why) → BootTimer (did boot finish, and how slow?) → log_instrument Trace (which phase) → only then a debugger (Lab 1) if you still cannot localize it. You climb down the cost ladder one rung at a time.

Implementation Requirements / Deliverables

• A microVM booted with the logger at Debug and a metrics sink configured.
• A captured, pretty-printed metrics JSON snapshot, with three groups annotated (what each tells you) and the must-be-zero counters identified.
• Two consecutive flushes diffed to show a counter is cumulative (a rate, not an absolute).
• A Guest-boot-time line captured with the BootTimer, recorded with its kernel/rootfs/boot-args/host context.
• A Trace-level log_instrument excerpt for one boot phase, turned back off afterwards.
• The assembled workflow (the mermaid above, in your own words) applied to one real slow-or-failing boot, with the localized subsystem named.

Troubleshooting

The metrics file/FIFO is empty

Nothing flushed. Either send FlushMetrics (PUT /actions), or wait for the periodic flush timer (rg -n "FlushMetrics|metrics.*timer|TimerFd|periodic" src/vmm/src/). If you used a FIFO, a reader (cat) must be draining it or the writer blocks.

No log output at all

log_path was never set, or was set after the failure. Configure the logger in the config file (pre-boot), at Debug. Confirm the path is writable by the (possibly jailed) process.

Guest-boot-time line never appears

The boot-timer device was not enabled (re-check the --boot-timer developer flag / extra_args), or the guest never reached the point where it writes the magic byte — i.e. boot genuinely did not finish. That absence is itself the signal: go to Lab 1 and gdb the guest to see where it stalled.

I "computed a rate" but the numbers are nonsense

You read absolute cumulative counters as deltas. Counters are cumulative; diff two flushes and divide by the time between them.

Trace logging changed the timing

Expected — tracing has overhead and can mask or move the very latency you are chasing. Use it to find which phase, not to quote a real latency, and turn it off immediately.

Expected Output

A metrics line whose shape (abbreviated) is:

{"utc_timestamp_ms": ..., "api_server": {"process_startup_time_us": ...},
 "block": {"read_count": ..., "write_count": ...},
 "vcpu": {"exit_io_in": ..., "exit_mmio_read": ..., "failures": 0},
 "seccomp": {"num_faults": 0}, "signals": {"sigbus": 0, "sigsegv": 0}}

and a log containing Guest-boot-time = NNNNN us NN ms, ....

Stretch Goals

1. Build a tiny monitor. Write a 20-line script that reads the metrics FIFO, diffs consecutive lines, and prints a non-zero alert if seccomp.num_faults, signals.sigbus/sigsegv, or any *.failures ever moves. That is the production monitoring pattern in miniature.
2. Add a counter (read-only first). Find where block.read_count is incremented (rg -n "\.inc\(\)|\.add\(" src/vmm/src/devices/virtio/block/), then read the metrics struct and its Serialize to see exactly what wiring a new counter would require. Sketch the diff.
3. Correlate the BootTimer with metrics. Capture latencies_us alongside the Guest-boot-time line and reconcile the host-measured phase timings with the guest-measured total.

Validation / Self-check

1. In what order do you reach for metrics, logs, the BootTimer, and log_instrument tracing, and why is metrics first?
2. Which counters must always stay zero, and what does a nonzero value of each tell you?
3. Why must the logger and metrics sink be configured before boot?
4. Explain the difference between an IncMetric and a StoreMetric, and why both metric types are "shared."
5. How does the BootTimer measure boot to userspace, what is the magic byte, and what does the absence of a Guest-boot-time line mean?
6. Why is log_instrument tracing normally compiled out, and why must you turn it off the moment you have your trace?
7. Given "the VMM vanished and the last metrics flush shows signals.sigsegv = 1," what happened and where do you look next?

Next: Lab 3: Reproduce and bisect — once observability has localized the subsystem, this is how you find the exact commit that broke it.