Add runtime stats by jserv · Pull Request #151 · sysprog21/elfuse

jserv · 2026-07-04T19:03:16Z

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.

Summary by cubic

Adds a runtime stats subsystem gated by ELFUSE_RUNTIME_STATS with summary, JSON, and JSONL outputs, plus optional USR1 snapshots. Integrates into main and fork paths, tracks vCPU exit reasons, and records startup or steady-state syscall histograms; includes a converter for flamegraphs/timelines.

New Features
- Runtime stats coordinator: aggregates shim counters, vCPU exit stats, and syscall histograms; modes: summary/json/jsonl; ELFUSE_STATS_SIGNAL=USR1 triggers snapshots; JSON includes "schema", pid, argv, wall_ns, shim, vmexit, syscalls, and phase/cost buckets.
- Steady-state syscall histogram via ELFUSE_STARTUP_TRACE=syscalls-steady or when ELFUSE_RUNTIME_STATS is on; per-process resets on fork (runtime_stats_reset_baseline, syscall_hist_reset, proc_reset_vcpu_exit_stats).
- vCPU exit accounting (human + JSON): totals, VTIMER masks, spurious cancels, and null-exit share; shim_globals_stats_enabled() now also honors ELFUSE_RUNTIME_STATS.
- scripts/runtime-stats-convert.py: turns jsonl output into folded, speedscope, perfetto, and csv; docs updated in docs/usage.md.
- Added test-runtime-stats to validate summary/json/jsonl and signal dumps.
Bug Fixes
- Removed recorder-guard race by splitting syscall_hist_enter() and syscall_hist_record(nr, start_ns, end_ns); guard always releases, even on clock failure.
- Serialized concurrent dumps with a mutex; final dump suppresses later signals; JSON mode drops non-final signal dumps.
- Corrected vCPU-exit JSON ratios by loading totals last and clamping; used saturating adds for histogram totals and cost buckets.
- Shim counters JSON now emits unique reservedN keys for unnamed slots.

^{Written for commit a5b6a0f. Summary will update on new commits.}

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.

Max042004 · 2026-07-06T18:23:27Z

+        json_string(stderr, rt_argv[i]);
+    }
+    uint64_t t = now_ns();
+    fprintf(stderr, "],\"wall_ns\":%llu,\"guest_run_ns\":0,\"shim\":",


guest_run_ns hardcoded to 0
Literal 0 in JSON output, never computed. Confirmed empirically (sleep 1 → wall_ns=1035216000, guest_run_ns=0).

Max042004 · 2026-07-06T18:32:05Z

+        struct sigaction sa;
+        memset(&sa, 0, sizeof(sa));
+        sa.sa_handler = stats_signal_handler;
+        sigemptyset(&sa.sa_mask);


Bare sigaction(SIGUSR1), no SA_RESTART, not routed through the sigwait architecture that SIGALRM/SIGUSR2 use on main to avoid guest-visible EINTR (PR #145 — note the branch is based on c15b647, which predates it; the conflict materializes on rebase). Can leak spurious EINTR into blocking guest I/O. Worse: rosetta.c:1096 documents SIGUSR1 as "the vCPU timer kick" — Hypervisor.framework uses SIGUSR1 internally to force vCPU exits (hv_vcpus_exit), so a process-wide sigaction() may replace HVF's own handler and break vCPU cancellation (timeout, exit_group, ptrace all depend on it). Needs an empirical check before merge.

Max042004 · 2026-07-06T18:32:55Z

+    rt_argc = argc;
+    rt_argv = argv;
+
+    const char *sig = getenv("ELFUSE_STATS_SIGNAL");


SIGUSR1 handler installed even when stats are disabled
If ELFUSE_STATS_SIGNAL=USR1 is set but stats aren't enabled, SIGUSR1's default terminate action is silently replaced by a no-op.

Max042004 · 2026-07-06T18:33:50Z

-        drain_external_guest_signal();
-
-        /* Main: disarm timeout */
+        /* Main: disarm timeout before post-run work. The alarm scopes only


Watchdog alarm(0) reordered too early
Timeout is disarmed before drain_external_guest_signal()/runtime_stats_maybe_dump_signal() run, so a hang in either is no longer caught by --timeout.

Max042004 · 2026-07-06T18:34:37Z

+     * whole-workload cost attribution.
     */
-    syscall_hist_disable();
+    const char *rt_stats = getenv("ELFUSE_RUNTIME_STATS");


ELFUSE_STARTUP_TRACE=syscalls-steady silently disabled across fork children
Gate only checks ELFUSE_RUNTIME_STATS, not ELFUSE_STARTUP_TRACE. Child syscall activity vanishes from the steady-state histogram with no warning. The comment above the gate claims this is intentional, but it contradicts syscall-hist.h:13's "records until guest exit" — either the gate or the doc should change.

Max042004 · 2026-07-06T18:35:21Z

        log_error("fork-child: invalid pt_pool_next 0x%llx",
                  (unsigned long long) hdr.pt_pool_next);
-        guest_destroy(&g);
+        fork_child_destroy_guest(&g, "fork-child-error");


Stale/parent counters dumped on fork-child error paths
For CoW-shm forks, shim_globals_init() hasn't zeroed the region yet when an early bootstrap failure dumps stats — the "fork-child-error" record actually reports the parent's live counters.

Max042004 · 2026-07-06T18:36:20Z

+            "\"phase\":{\"process_lifecycle_ns\":%llu,"
+            "\"clone_ns\":%llu,\"wait_ns\":%llu,"
+            "\"host_vfs_ns\":%llu,\"futex_ns\":%llu,\"mem_ns\":%llu},"
+            "\"fd\":{},\"path\":{\"openat_ns\":%llu},"


openat+openat2 combined total mislabeled openat_ns
Same combined value feeds both phase.host_vfs_ns and path.openat_ns; the latter implies openat-only cost.

Max042004 · 2026-07-06T18:38:22Z

+
+def main(argv):
+    ap = argparse.ArgumentParser()
+    ap.add_argument("--selftest", action="store_true")


--selftest never wired into CI/build
Not called from any Makefile target, test script, or CI workflow — looks like coverage, provides none.

jserv requested a review from Max042004 July 4, 2026 19:05

This comment was marked as resolved.

Sign in to view

jserv force-pushed the stats branch from aa4e3c6 to 02fe563 Compare July 5, 2026 14:22

jserv force-pushed the stats branch from 02fe563 to a5b6a0f Compare July 5, 2026 15:13

Max042004 suggested changes Jul 6, 2026

View reviewed changes

jserv requested a review from henrybear327 July 8, 2026 16:19

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Add runtime stats#151

Add runtime stats#151
jserv wants to merge 1 commit into
mainfrom
stats

jserv commented Jul 4, 2026 •

edited by cubic-dev-ai Bot

Loading

Uh oh!

This comment was marked as resolved.

Uh oh!

Max042004 Jul 6, 2026

Uh oh!

Max042004 Jul 6, 2026

Uh oh!

Max042004 Jul 6, 2026

Uh oh!

Max042004 Jul 6, 2026

Uh oh!

Max042004 Jul 6, 2026

Uh oh!

Max042004 Jul 6, 2026

Uh oh!

Max042004 Jul 6, 2026

Uh oh!

Max042004 Jul 6, 2026

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

Uh oh!

Conversation

jserv commented Jul 4, 2026 • edited by cubic-dev-ai Bot Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Summary by cubic

Uh oh!

This comment was marked as resolved.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

jserv commented Jul 4, 2026 •

edited by cubic-dev-ai Bot

Loading