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 an optional runtime stats subsystem that aggregates shim counters, vCPU exit reasons, and a syscall histogram into per-process reports, gated by ELFUSE_RUNTIME_STATS with summary, JSON, and JSONL modes plus optional USR1 snapshots. Also adds steady-state syscall recording, fork-child accounting, and a converter to viewer formats.

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; each fork child keeps its own counters and emits its own final record.
- vCPU exit accounting tracks totals, VTIMER masks, spurious cancels, and null-exit share.
- 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 output shapes and signal dumps.
Bug Fixes
- Removed recorder-guard race by splitting syscall_hist_enter() and syscall_hist_record(); 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 0437ca9. Summary will update on new commits.}

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: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.

ELFUSE_RUNTIME_STATS gathers the shim counters, new vCPU exit-reason counts and a syscall histogram that records the whole run into one report per process: summary prints tables, json writes one object at exit, jsonl adds one line per snapshot. ELFUSE_STARTUP_TRACE gains syscalls-steady for the same histogram without the rest. ELFUSE_STATS_SIGNAL=USR1 requests a snapshot. The signal joins the set the preemption sigwait thread consumes, so no handler runs on a vCPU thread and no guest call sees EINTR for it, and a dumper thread does the write, so a stalled stderr cannot hold up the doorbell or the watchdog on that thread. The signal is claimed only while stats are on. Fork children keep recording and write their own final record before the parent can reap them. Each JSON record goes out in a single write so records from processes sharing stderr do not interleave in a file. tests/test-runtime-stats.sh covers the three modes, snapshots, a fork child, the stats-off signal default, and the converter in scripts/runtime-stats-convert.py, which turns jsonl into folded, speedscope, perfetto and csv views.

xalestar · 2026-10-13T09:26:16Z

+            "workload": " ".join(argv[1:]) if len(argv) > 1 else " ".join(argv),
+            "wall_ms": ms(rec.get("wall_ns")),
+            "syscall_ms": ms(rec.get("syscalls", {}).get("total_ns")),
+            "clone_ms": ms((by_name.get("SYS_clone") or {}).get("total_ns")),


clone_ms reads only SYS_clone, and openat_ms only SYS_openat, while the phase object in the same record sums SYS_clone + SYS_clone3 and SYS_openat + SYS_openat2. A glibc guest creates threads through clone3, so its CSV shows clone_ms near 0 while phase.clone_ns is not. Read phase.clone_ns and path.open_ns from the record here, so the CSV and the JSON cannot disagree.

xalestar · 2026-10-13T09:26:18Z

+     * expect.
+     */
+    const char *sig = getenv("ELFUSE_STATS_SIGNAL");
+    if (rt_mode != RT_STATS_OFF && sig && strcmp(sig, "USR1") == 0)


Any value other than the exact string USR1 is dropped without a message. With ELFUSE_STATS_SIGNAL=SIGUSR1 the signal is never claimed, so the first kill -USR1 terminates the guest through the default action. Accept SIGUSR1 as well, or log_warn on an unrecognized value while stats are on.

xalestar · 2026-10-13T09:26:19Z

+        fflush(stderr);
+        for (size_t off = 0; off < len;) {
+            ssize_t n = write(STDERR_FILENO, buf + off, len - off);
+            if (n <= 0)


n <= 0 treats EINTR and EAGAIN the same as a hard error, so the record is cut off mid-object with no trailing newline. In jsonl mode the next record then lands on the same line and both fail to parse. EAGAIN is reachable when the guest has set O_NONBLOCK on a stderr it shares with elfuse. Retry on EINTR, and on EAGAIN either poll for writability or drop the whole record before the first byte goes out (errno.h is not included yet).

xalestar · 2026-10-13T09:26:21Z

+    if (rt_mode == RT_STATS_SUMMARY) {
+        shim_globals_counters_dump(g);
+        proc_dump_vcpu_exit_stats();
+        if (final)


A snapshot in summary mode prints the shim and vCPU tables but no syscall histogram, because syscall_hist_dump() consumes the table. docs/usage.md describes snapshots without saying so, and a user who sends SIGUSR1 to a long-running guest in summary mode gets no syscall data until exit. Either print a live histogram here from hist_snapshot_rows (the JSON path already reads it live), or state in the docs that snapshots carry the histogram only in jsonl mode.

xalestar · 2026-10-13T09:26:22Z

+ *
+ * Returns false when another dump already took it or recording never started.
+ */
+static bool hist_take(void)


The description lists changes that are not in this diff: syscall_hist_enter() with record(nr, start_ns, end_ns), syscall_hist_reset, proc_reset_vcpu_exit_stats, runtime_stats_reset_baseline, rt_final_done, and per-interval jsonl records. syscall_hist_record is unchanged here and still enters the guard itself. Either the commits are missing from the branch or the description is from an earlier revision; update whichever is stale so the merge commit message matches the code.

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 2 times, most recently 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

This comment was marked as outdated.

Sign in to view

jserv force-pushed the stats branch from a5b6a0f to ecc160c Compare October 12, 2026 18:30

sysprog21 deleted a comment from cubic-dev-ai Bot Oct 12, 2026

jserv force-pushed the stats branch from ecc160c to 60995e6 Compare October 12, 2026 18:39

This comment was marked as resolved.

Sign in to view

jserv force-pushed the stats branch from 60995e6 to 5518a9f Compare October 12, 2026 18:43

This comment was marked as resolved.

Sign in to view

jserv force-pushed the stats branch from 5518a9f to 0437ca9 Compare October 12, 2026 18:54

jserv requested review from Max042004, alanhc and xalestar October 12, 2026 19:02

xalestar reviewed Oct 13, 2026

View reviewed changes

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!

Uh oh!

Uh oh!

Max042004 Jul 6, 2026

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Max042004 Jul 6, 2026

Choose a reason for hiding this comment

Uh oh!

This comment was marked as outdated.

This comment was marked as resolved.

Uh oh!

This comment was marked as resolved.

Uh oh!

xalestar Oct 13, 2026

Choose a reason for hiding this comment

Uh oh!

xalestar Oct 13, 2026

Choose a reason for hiding this comment

Uh oh!

xalestar Oct 13, 2026

Choose a reason for hiding this comment

Uh oh!

xalestar Oct 13, 2026

Choose a reason for hiding this comment

Uh oh!

xalestar Oct 13, 2026

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

jserv commented Jul 4, 2026 •

edited by cubic-dev-ai Bot

Loading