Add runtime stats

This introduces a runtime-stats subsystem that coordinates per-process
vCPU exit accounting, shim counter snapshots, and syscall histograms
under a single env-var gate (ELFUSE_RUNTIME_STATS). Modes: summary
(stderr table), json (one JSON object on exit), jsonl (one JSON object
per interval or signal). ELFUSE_STATS_SIGNAL=USR1 delivers a snapshot on
demand; final dumps suppress subsequent signal dumps via rt_final_done.

Fix a recorder-guard race in syscall_hist_record: the old code entered
the hist_active_recorders guard inside record() itself, leaving a window
between syscall_hist_now_ns() and record() where the dump could flip
mode to OFF, observe guard==0, and read the table before the in-flight
recorder landed its updates. Replace the enter/record split with
syscall_hist_enter() which does a cheap disabled-mode probe then
increments the guard and rechecks mode before returning the start
timestamp. record() takes (nr, start_ns, end_ns) and owns the guard
release on every exit path including clock-failure.

Fix unserialized concurrent dumps: runtime_stats_dump() now holds
rt_dump_mutex for the duration of each dump so JSON/human output from
a SIGUSR1 handler cannot interleave with the process-exit dump.

Fix impossible JSON ratios in proc_dump_vcpu_exit_stats_json: load
vcpu_exit_total last to maximize the denominator under concurrent
increments, then clamp the null-exit numerator to total so
null_exit_share stays in [0, 100].

Fix duplicate "reserved" JSON keys in shim_globals_counters_dump_json:
unnamed counter slots now emit "reserved12", "reserved13", etc.

Fix silent counter wrap in hist_snapshot_rows and cost-bucket sums:
use saturating add (sat_add_u64) for total_count, total_ns, and all
inter-bucket sums including process_lifecycle_ns.

Add proc_reset_vcpu_exit_stats, syscall_hist_reset, and
runtime_stats_reset_baseline so fork children start with clean counters
rather than inheriting the parent's recording window.

Cover the ELFUSE_RUNTIME_STATS output paths that lacked tests.
tests/test-runtime-stats.sh checks json single-object output under a
SIGUSR1 spray, jsonl per-line objects with a signal-triggered snapshot,
and the summary tables. The make check wiring already references it.

Add scripts/runtime-stats-convert.py to turn jsonl output into folded,
speedscope, perfetto, and csv views for flamegraphs and timelines.

Author: jserv

Makefile

@@ -68,6 +68,7 @@ SRCS := \
     debug/gdbstub-reg.c \
     debug/gdbstub-rsp.c \
     debug/log.c \
+    debug/runtime-stats.c \
     debug/syscall-hist.c
 
 SRCS := $(addprefix src/,$(SRCS))

docs/usage.md

@@ -195,6 +195,96 @@ and memory access, and per-thread inspection. Implementation details, including
 the snapshot protocol used to keep Hypervisor.framework register access on the
 owning thread, are documented in [internals.md](internals.md).
 
+## Performance Analysis
+
+`elfuse` can account for where a guest spends its time without an external
+profiler. Set `ELFUSE_RUNTIME_STATS` to turn on a stats coordinator that
+aggregates three sources at exit: shim fast-path counters, vCPU exit reasons,
+and a per-syscall histogram (count, total, average, and max latency). All
+output goes to stderr, so guest stdout stays clean for pipelines.
+
+| `ELFUSE_RUNTIME_STATS` | Output |
+|------------------------|--------|
+| `summary` (the default for any value other than `json`, `jsonl`, or `0`) | Human-readable tables on exit |
+| `json` | Exactly one JSON object on exit |
+| `jsonl` | One JSON object per line: a final object plus one per on-demand snapshot |
+
+Quick eyeball of a run:
+
+```sh
+ELFUSE_RUNTIME_STATS=summary build/elfuse ./guest-program 2>stats.txt
+```
+
+The summary prints a `vcpu-exit-stats` block (`exits_total`, `exits_vtimer`,
+`exits_no_signal_cancel`, and `null_exit_share`) and a `syscall histogram`
+sorted by total time, with a trailing line reporting what fraction of wall time
+was spent inside syscalls. A high null-exit share or a syscall dominating total
+time is the first thing to chase.
+
+### On-Demand Snapshots
+
+For a long-running guest, request a snapshot without stopping it by setting
+`ELFUSE_STATS_SIGNAL=USR1` and sending `SIGUSR1` to the `elfuse` process:
+
+```sh
+ELFUSE_RUNTIME_STATS=jsonl ELFUSE_STATS_SIGNAL=USR1 \
+    build/elfuse ./guest-program 2>stats.jsonl &
+sleep 0.1        # let the process install the SIGUSR1 handler
+kill -USR1 $!    # emit a snapshot; repeat as the workload progresses
+```
+
+Each snapshot is one JSON line tagged `"reason":"signal","final":false`. The
+final dump has `"final":true`; its `reason` is `"exit"` for the top-level
+process, `"fork-child-exit"` (or `"fork-child-error"`) for fork children, so
+filter on `"final"` rather than the reason string. In `json` (not `jsonl`)
+mode, snapshots are suppressed so the output stays a single valid JSON document.
+
+The `sleep 0.1` matters only for a script that sends the signal immediately: the
+handler is installed early in startup, but `SIGUSR1` delivered before then
+terminates the process by default.
+
+### Timeline And Flamegraphs
+
+`jsonl` mode plus `scripts/runtime-stats-convert.py` turns a run into viewer
+formats. The `folded`, `speedscope`, and `perfetto` exports diff consecutive
+snapshots per pid, so each interval shows the syscalls that ran during it; `csv`
+emits the raw cumulative rows, one row per snapshot record:
+
+```sh
+# Flamegraph input (Brendan Gregg's flamegraph.pl):
+scripts/runtime-stats-convert.py folded stats.jsonl | flamegraph.pl >stats.svg
+
+# Load in https://www.speedscope.app:
+scripts/runtime-stats-convert.py speedscope stats.jsonl >stats.speedscope.json
+
+# Perfetto UI (https://ui.perfetto.dev):
+scripts/runtime-stats-convert.py perfetto stats.jsonl >stats.perfetto.json
+
+# Cumulative per-snapshot rows for a spreadsheet:
+scripts/runtime-stats-convert.py csv stats.jsonl >stats.csv
+```
+
+The JSON schema (`elfuse-runtime-stats/1`) also carries a `phase` object of
+coarse buckets summed from syscall-family totals: `clone_ns` (clone + clone3),
+`wait_ns` (wait4 + waitid), `host_vfs_ns` (openat + openat2 only), `futex_ns`,
+`mem_ns` (mmap + mprotect + madvise), and `process_lifecycle_ns` (clone + wait).
+They are a quick read on where fork-heavy or lock-heavy guests spend time, not
+independent phase timers; the raw histogram is authoritative.
+
+### Startup Histogram
+
+To profile just the dynamic-linker bring-up storm, use
+`ELFUSE_STARTUP_TRACE=syscalls`, which freezes the histogram at the first
+`execve` instead of recording the whole run. `ELFUSE_STARTUP_TRACE=syscalls-steady`
+keeps recording past `execve` for steady-state workloads. Turning on
+`ELFUSE_RUNTIME_STATS` implies steady-state recording.
+
+Counters reset per process, so fork children start from a clean window rather
+than inheriting the parent's totals. Enabling stats adds a `clock_gettime` pair
+plus atomic counter updates around each syscall; the disabled path is a
+`pthread_once` guard and one atomic load, so leaving stats off costs
+effectively nothing.
+
 ## Guest Compatibility Model
 
 `elfuse` is designed for Linux user-space workloads, not for booting a Linux

mk/tests.mk

@@ -1,6 +1,7 @@
 # Test targets
 
 .PHONY: test-hello test-all check check-syscall-coverage test-gdbstub test-coreutils test-busybox \
+        test-runtime-stats \
         test-static-bins \
         test-dynamic test-dynamic-coreutils test-glibc-dynamic \
         test-glibc-coreutils test-perf \
@@ -73,6 +74,8 @@ check: $(ELFUSE_BIN) $(TEST_DEPS) check-syscall-coverage \
 	@$(MAKE) --no-print-directory test-rosetta-cli
 	@printf "\n$(BLUE)━━━ hot-syscall guardrail ━━━$(RESET)\n"
 	@$(MAKE) --no-print-directory test-bench-guardrail
+	@printf "\n$(BLUE)━━━ runtime-stats output validation ━━━$(RESET)\n"
+	@$(MAKE) --no-print-directory test-runtime-stats
 
 ## Hot-syscall performance guardrail: ensure getpid, libc clock_gettime,
 ## and 1-byte /dev/urandom reads stay under their TODO ns/op ceilings.
@@ -430,6 +433,14 @@ test-busybox: $(ELFUSE_BIN) $(BUSYBOX_DEPS)
 	fi
 	@bash tests/test-busybox.sh $(ELFUSE_BIN) $(BUSYBOX_BIN)
 
+## Validate ELFUSE_RUNTIME_STATS output shapes (json/jsonl/summary + signal)
+test-runtime-stats: $(ELFUSE_BIN) $(BUSYBOX_DEPS)
+	@if [ ! -x "$(BUSYBOX_BIN)" ]; then \
+		printf "$(RED)✗ Busybox not found.$(RESET) Set BUSYBOX_BIN=/path/to/busybox.\n"; \
+		exit 1; \
+	fi
+	@bash tests/test-runtime-stats.sh $(ELFUSE_BIN) $(BUSYBOX_BIN)
+
 ## Run the low-stack argv rewrite regression on busybox startup
 test-proctitle-low-stack: $(ELFUSE_BIN) $(BUSYBOX_DEPS)
 	@if [ ! -x "$(BUSYBOX_BIN)" ]; then \

scripts/runtime-stats-convert.py

@@ -0,0 +1,227 @@
+#!/usr/bin/env python3
+"""Convert ELFUSE_RUNTIME_STATS=jsonl output to simple viewer formats."""
+
+import argparse
+import csv
+import json
+import sys
+import tempfile
+from contextlib import redirect_stdout
+from io import StringIO
+
+
+def load_records(path):
+    records = []
+    with open(path, "r", encoding="utf-8") as f:
+        for line in f:
+            line = line.strip()
+            if not line or not line.startswith("{"):
+                continue
+            rec = json.loads(line)
+            if rec.get("schema") == "elfuse-runtime-stats/1":
+                records.append(rec)
+    return records
+
+
+def ms(ns):
+    return float(ns or 0) / 1_000_000.0
+
+
+def syscall_rows(rec):
+    return rec.get("syscalls", {}).get("rows", [])
+
+
+def syscall_delta_rows(records):
+    prev_by_pid = {}
+    for rec in records:
+        pid = rec.get("pid", 1)
+        prev = prev_by_pid.setdefault(pid, {})
+        rows = []
+        for row in syscall_rows(rec):
+            key = row.get("nr", row.get("name"))
+            total = row.get("total_ns", 0)
+            last = prev.get(key, 0)
+            out = dict(row)
+            out["total_ns"] = total - last if total >= last else total
+            rows.append(out)
+            prev[key] = total
+        yield rec, rows
+        if rec.get("final"):
+            prev_by_pid.pop(pid, None)
+
+
+def write_csv(records):
+    fields = [
+        "workload",
+        "wall_ms",
+        "guest_run_ms",
+        "syscall_ms",
+        "clone_ms",
+        "wait_ms",
+        "openat_ms",
+        "null_exit_share",
+    ]
+    w = csv.DictWriter(sys.stdout, fieldnames=fields)
+    w.writeheader()
+    for rec in records:
+        by_name = {r.get("name"): r for r in syscall_rows(rec)}
+        argv = rec.get("argv") or []
+        row = {
+            "workload": " ".join(argv[1:]) if len(argv) > 1 else " ".join(argv),
+            "wall_ms": ms(rec.get("wall_ns")),
+            "guest_run_ms": ms(rec.get("guest_run_ns")),
+            "syscall_ms": ms(rec.get("syscalls", {}).get("total_ns")),
+            "clone_ms": ms((by_name.get("SYS_clone") or {}).get("total_ns")),
+            "wait_ms": ms(
+                sum(
+                    (by_name.get(n) or {}).get("total_ns", 0)
+                    for n in ("SYS_wait4", "SYS_waitid")
+                )
+            ),
+            "openat_ms": ms((by_name.get("SYS_openat") or {}).get("total_ns")),
+            "null_exit_share": rec.get("vmexit", {}).get("null_exit_share", 0),
+        }
+        w.writerow(row)
+
+
+def write_folded(records):
+    totals = {}
+    for _, rows in syscall_delta_rows(records):
+        for row in rows:
+            name = row.get("name") or f"SYS_{row.get('nr')}"
+            totals[f"elfuse;syscall;{name}"] = totals.get(
+                f"elfuse;syscall;{name}", 0
+            ) + row.get("total_ns", 0)
+    for stack, total in sorted(totals.items()):
+        print(stack, total)
+
+
+def write_speedscope(records):
+    frames = []
+    frame_index = {}
+    events = []
+    at = 0
+    for _, rows in syscall_delta_rows(records):
+        for row in rows:
+            name = row.get("name") or f"SYS_{row.get('nr')}"
+            if name not in frame_index:
+                frame_index[name] = len(frames)
+                frames.append({"name": name})
+            dur = row.get("total_ns", 0) / 1000.0
+            events.append({"type": "O", "at": at, "frame": frame_index[name]})
+            events.append({"type": "C", "at": at + dur, "frame": frame_index[name]})
+            at += dur
+    json.dump(
+        {
+            "$schema": "https://www.speedscope.app/file-format-schema.json",
+            "shared": {"frames": frames},
+            "profiles": [
+                {
+                    "type": "evented",
+                    "name": "elfuse runtime stats",
+                    "unit": "microseconds",
+                    "startValue": 0,
+                    "endValue": at,
+                    "events": events,
+                }
+            ],
+        },
+        sys.stdout,
+    )
+    print()
+
+
+def write_perfetto(records):
+    trace = []
+    pid = 1
+    for rec, rows in syscall_delta_rows(records):
+        tid = rec.get("pid", 1)
+        ts = rec.get("time_ns", 0) / 1000.0
+        for row in rows:
+            trace.append(
+                {
+                    "name": row.get("name") or f"SYS_{row.get('nr')}",
+                    "ph": "X",
+                    "ts": ts,
+                    "dur": row.get("total_ns", 0) / 1000.0,
+                    "pid": pid,
+                    "tid": tid,
+                }
+            )
+            ts += row.get("total_ns", 0) / 1000.0
+    json.dump({"traceEvents": trace}, sys.stdout)
+    print()
+
+
+def main(argv):
+    ap = argparse.ArgumentParser()
+    ap.add_argument("--selftest", action="store_true")
+    ap.add_argument("format", choices=["csv", "folded", "speedscope", "perfetto"])
+    ap.add_argument("input", nargs="?")
+    args = ap.parse_args(argv)
+    if args.selftest:
+        selftest(args.format)
+        return
+    if not args.input:
+        ap.error("input is required")
+    records = load_records(args.input)
+    if args.format == "csv":
+        write_csv(records)
+    elif args.format == "folded":
+        write_folded(records)
+    elif args.format == "speedscope":
+        write_speedscope(records)
+    else:
+        write_perfetto(records)
+
+
+def selftest(fmt):
+    sample1 = {
+        "schema": "elfuse-runtime-stats/1",
+        "pid": 1,
+        "time_ns": 1_000,
+        "final": False,
+        "argv": ["elfuse", "guest"],
+        "wall_ns": 10_000_000,
+        "guest_run_ns": 0,
+        "vmexit": {"null_exit_share": 0.0},
+        "syscalls": {
+            "total_ns": 1_000_000,
+            "rows": [
+                {"nr": 220, "name": "SYS_clone", "total_ns": 1_000_000},
+            ],
+        },
+    }
+    sample2 = json.loads(json.dumps(sample1))
+    sample2["time_ns"] = 2_000
+    sample2["final"] = True
+    sample2["wall_ns"] = 20_000_000
+    sample2["syscalls"]["total_ns"] = 3_000_000
+    sample2["syscalls"]["rows"].append(
+        {"nr": 260, "name": "SYS_wait4", "total_ns": 2_000_000}
+    )
+    with tempfile.NamedTemporaryFile("w+", encoding="utf-8") as f:
+        f.write(json.dumps(sample1) + "\n")
+        f.write(json.dumps(sample2) + "\n")
+        f.flush()
+        records = load_records(f.name)
+    out = StringIO()
+    with redirect_stdout(out):
+        if fmt == "csv":
+            write_csv(records)
+            assert "clone_ms" in out.getvalue()
+        elif fmt == "folded":
+            write_folded(records)
+            assert "elfuse;syscall;SYS_clone 1000000" in out.getvalue()
+        elif fmt == "speedscope":
+            write_speedscope(records)
+            profile = json.loads(out.getvalue())["profiles"][0]
+            assert profile["endValue"] == 3000.0
+        else:
+            write_perfetto(records)
+            trace = json.loads(out.getvalue())["traceEvents"]
+            assert sum(e["dur"] for e in trace) == 3000.0
+
+
+if __name__ == "__main__":
+    main(sys.argv[1:])