From a5b6a0ff63ca9ade33ff3597dcbe3ce6592b5be9 Mon Sep 17 00:00:00 2001 From: Jim Huang Date: Sun, 5 Jul 2026 03:00:39 +0800 Subject: [PATCH] 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. --- Makefile | 1 + docs/usage.md | 90 ++++++++++++ mk/tests.mk | 11 ++ scripts/runtime-stats-convert.py | 227 +++++++++++++++++++++++++++++ src/core/shim-globals.c | 25 +++- src/core/shim-globals.h | 3 + src/debug/runtime-stats.c | 204 ++++++++++++++++++++++++++ src/debug/runtime-stats.h | 18 +++ src/debug/syscall-hist.c | 243 ++++++++++++++++++++++++------- src/debug/syscall-hist.h | 40 +++-- src/main.c | 20 +-- src/runtime/forkipc.c | 39 +++-- src/syscall/proc.c | 101 ++++++++++++- src/syscall/proc.h | 11 ++ src/syscall/syscall.c | 18 +-- tests/test-runtime-stats.sh | 139 ++++++++++++++++++ 16 files changed, 1078 insertions(+), 112 deletions(-) create mode 100755 scripts/runtime-stats-convert.py create mode 100644 src/debug/runtime-stats.c create mode 100644 src/debug/runtime-stats.h create mode 100755 tests/test-runtime-stats.sh diff --git a/Makefile b/Makefile index 6eb88f9f..e5907ee4 100644 --- a/Makefile +++ b/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)) diff --git a/docs/usage.md b/docs/usage.md index bef8aca2..24267b13 100644 --- a/docs/usage.md +++ b/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 diff --git a/mk/tests.mk b/mk/tests.mk index c9499070..05fbf6ed 100644 --- a/mk/tests.mk +++ b/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 \ diff --git a/scripts/runtime-stats-convert.py b/scripts/runtime-stats-convert.py new file mode 100755 index 00000000..b0a7a85e --- /dev/null +++ b/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:]) diff --git a/src/core/shim-globals.c b/src/core/shim-globals.c index d5fd53d7..321fa796 100644 --- a/src/core/shim-globals.c +++ b/src/core/shim-globals.c @@ -465,13 +465,36 @@ void shim_globals_counters_dump(const guest_t *g) } } +void shim_globals_counters_dump_json(FILE *out, const guest_t *g) +{ + fputc('{', out); + bool first = true; + for (unsigned i = 0; i < SHIM_COUNTERS_N; i++) { + const char *name = counter_names[i]; + uint64_t v = shim_globals_counter_get(g, i); + if (!name && v == 0) + continue; + char namebuf[32]; + if (!name) { + snprintf(namebuf, sizeof(namebuf), "reserved%u", i); + name = namebuf; + } + fprintf(out, "%s\"%s\":%llu", first ? "" : ",", name, + (unsigned long long) v); + first = false; + } + fputc('}', out); +} + static pthread_once_t stats_once = PTHREAD_ONCE_INIT; static bool stats_enabled_cache; static void stats_resolve(void) { const char *v = getenv("ELFUSE_SHIM_STATS"); - stats_enabled_cache = v && v[0] && strcmp(v, "0") != 0; + const char *rv = getenv("ELFUSE_RUNTIME_STATS"); + stats_enabled_cache = (v && v[0] && strcmp(v, "0") != 0) || + (rv && rv[0] && strcmp(rv, "0") != 0); } bool shim_globals_stats_enabled(void) diff --git a/src/core/shim-globals.h b/src/core/shim-globals.h index 14cb24f1..59b7ddb6 100644 --- a/src/core/shim-globals.h +++ b/src/core/shim-globals.h @@ -39,6 +39,8 @@ #pragma once +#include + #include #include @@ -391,6 +393,7 @@ void shim_globals_refill_urandom_ring(guest_t *g); */ uint64_t shim_globals_counter_get(const guest_t *g, unsigned slot); void shim_globals_counters_dump(const guest_t *g); +void shim_globals_counters_dump_json(FILE *out, const guest_t *g); /* ELFUSE_SHIM_STATS env-var gate (idempotent / cached). When enabled the exit * path dumps the counter table to stderr so a single bench run attributes every diff --git a/src/debug/runtime-stats.c b/src/debug/runtime-stats.c new file mode 100644 index 00000000..55950a12 --- /dev/null +++ b/src/debug/runtime-stats.c @@ -0,0 +1,204 @@ +/* + * Runtime stats coordinator. + * + * Copyright 2026 elfuse contributors + * SPDX-License-Identifier: Apache-2.0 + */ + +#include "debug/runtime-stats.h" + +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include "core/shim-globals.h" +#include "debug/syscall-hist.h" +#include "syscall/proc.h" + +typedef enum { + RT_STATS_OFF = 0, + RT_STATS_SUMMARY, + RT_STATS_JSON, + RT_STATS_JSONL, +} rt_stats_mode_t; + +static rt_stats_mode_t rt_mode; +static int rt_argc; +static char **rt_argv; +static uint64_t rt_start_ns; +static _Atomic int rt_dump_requested; +static pthread_mutex_t rt_dump_mutex = PTHREAD_MUTEX_INITIALIZER; +static _Atomic bool rt_final_done; + +static bool env_on(const char *v) +{ + return v && v[0] && strcmp(v, "0") != 0; +} + +static void json_string(FILE *out, const char *s) +{ + fputc('"', out); + for (const unsigned char *p = (const unsigned char *) (s ? s : ""); *p; + p++) { + switch (*p) { + case '"': + fputs("\\\"", out); + break; + case '\\': + fputs("\\\\", out); + break; + case '\n': + fputs("\\n", out); + break; + case '\r': + fputs("\\r", out); + break; + case '\t': + fputs("\\t", out); + break; + default: + if (*p < 0x20) + fprintf(out, "\\u%04x", *p); + else + fputc(*p, out); + break; + } + } + fputc('"', out); +} + +static uint64_t now_ns(void) +{ + struct timespec ts; + if (clock_gettime(CLOCK_MONOTONIC, &ts) < 0) + return 0; + return (uint64_t) ts.tv_sec * 1000000000ULL + (uint64_t) ts.tv_nsec; +} + +static void stats_signal_handler(int signo) +{ + (void) signo; + atomic_store_explicit(&rt_dump_requested, 1, memory_order_release); +} + +void runtime_stats_init(int argc, char **argv) +{ + rt_start_ns = now_ns(); + const char *v = getenv("ELFUSE_RUNTIME_STATS"); + if (env_on(v)) { + if (strcmp(v, "json") == 0) + rt_mode = RT_STATS_JSON; + else if (strcmp(v, "jsonl") == 0) + rt_mode = RT_STATS_JSONL; + else + rt_mode = RT_STATS_SUMMARY; + } else if (env_on(getenv("ELFUSE_SHIM_STATS"))) { + rt_mode = RT_STATS_SUMMARY; + } + rt_argc = argc; + rt_argv = argv; + + const char *sig = getenv("ELFUSE_STATS_SIGNAL"); + if (env_on(sig) && strcmp(sig, "USR1") == 0) { + struct sigaction sa; + memset(&sa, 0, sizeof(sa)); + sa.sa_handler = stats_signal_handler; + sigemptyset(&sa.sa_mask); + sigaction(SIGUSR1, &sa, NULL); + } +} + +bool runtime_stats_enabled(void) +{ + return rt_mode != RT_STATS_OFF; +} + +void runtime_stats_reset_baseline(void) +{ + if (!runtime_stats_enabled()) + return; + rt_start_ns = now_ns(); + atomic_store_explicit(&rt_dump_requested, 0, memory_order_release); + atomic_store_explicit(&rt_final_done, false, memory_order_release); + proc_reset_vcpu_exit_stats(); + syscall_hist_reset(); +} + +static void runtime_stats_dump_json(const guest_t *g, + const char *reason, + bool final) +{ + fprintf(stderr, "{\"schema\":\"elfuse-runtime-stats/1\",\"reason\":"); + json_string(stderr, reason ? reason : "dump"); + fprintf(stderr, ",\"final\":%s,\"pid\":%lld,\"time_ns\":%llu,\"argv\":[", + final ? "true" : "false", (long long) proc_get_pid(), + (unsigned long long) now_ns()); + for (int i = 0; i < rt_argc; i++) { + if (i) + fputc(',', stderr); + json_string(stderr, rt_argv[i]); + } + uint64_t t = now_ns(); + fprintf(stderr, "],\"wall_ns\":%llu,\"guest_run_ns\":0,\"shim\":", + (unsigned long long) (t > rt_start_ns ? t - rt_start_ns : 0)); + shim_globals_counters_dump_json(stderr, g); + fputs(",\"vmexit\":", stderr); + proc_dump_vcpu_exit_stats_json(stderr); + fputs(",\"syscalls\":", stderr); + syscall_hist_dump_json(stderr, final); + fputc(',', stderr); + syscall_hist_dump_cost_buckets_json(stderr); + fputs("}\n", stderr); +} + +void runtime_stats_dump(const guest_t *g, const char *reason, bool final) +{ + if (!runtime_stats_enabled()) + return; + /* Suppress any dump once the final dump has completed. */ + if (atomic_load_explicit(&rt_final_done, memory_order_acquire)) + return; + + pthread_mutex_lock(&rt_dump_mutex); + /* Recheck after acquiring: a concurrent final dump may have just finished. + */ + if (atomic_load_explicit(&rt_final_done, memory_order_acquire)) { + pthread_mutex_unlock(&rt_dump_mutex); + return; + } + + /* JSON mode is a single top-level object emitted on exit. Drop non-final + * (signal-triggered) dumps so two objects never land on stderr without an + * array wrapper. JSONL is line-delimited, so per-signal objects are fine. + */ + if (rt_mode == RT_STATS_JSON && !final) { + pthread_mutex_unlock(&rt_dump_mutex); + return; + } + + if (rt_mode == RT_STATS_SUMMARY) { + shim_globals_counters_dump(g); + proc_dump_vcpu_exit_stats(); + if (final) + syscall_hist_dump(); + } else { + runtime_stats_dump_json(g, reason, final); + } + + if (final) + atomic_store_explicit(&rt_final_done, true, memory_order_release); + pthread_mutex_unlock(&rt_dump_mutex); +} + +void runtime_stats_maybe_dump_signal(const guest_t *g) +{ + if (!atomic_exchange_explicit(&rt_dump_requested, 0, memory_order_acq_rel)) + return; + runtime_stats_dump(g, "signal", false); +} diff --git a/src/debug/runtime-stats.h b/src/debug/runtime-stats.h new file mode 100644 index 00000000..ed9f1d83 --- /dev/null +++ b/src/debug/runtime-stats.h @@ -0,0 +1,18 @@ +/* + * Runtime stats coordinator. + * + * Copyright 2026 elfuse contributors + * SPDX-License-Identifier: Apache-2.0 + */ + +#pragma once + +#include + +#include "core/guest.h" + +void runtime_stats_init(int argc, char **argv); +bool runtime_stats_enabled(void); +void runtime_stats_reset_baseline(void); +void runtime_stats_dump(const guest_t *g, const char *reason, bool final); +void runtime_stats_maybe_dump_signal(const guest_t *g); diff --git a/src/debug/syscall-hist.c b/src/debug/syscall-hist.c index 46401bfb..10d2952a 100644 --- a/src/debug/syscall-hist.c +++ b/src/debug/syscall-hist.c @@ -1,5 +1,5 @@ /* - * Dynamic-linker startup syscall histogram + * Dynamic-linker startup / steady-state syscall histogram * * Copyright 2026 elfuse contributors * SPDX-License-Identifier: Apache-2.0 @@ -40,6 +40,7 @@ enum { HIST_FROZEN = 2, }; static _Atomic int hist_mode = HIST_OFF; +static bool hist_steady; /* Resolved once via pthread_once. The resolver is idempotent so multiple * dispatch contexts converge on the same answer without locking. @@ -59,14 +60,13 @@ static const char *_Atomic hist_freeze_reason = NULL; */ static _Atomic uint64_t hist_first_ns = 0; -/* Count of recorders currently inside the update window. Bumped at entry to - * syscall_hist_record before the mode probe and decremented after the slot - * updates retire. syscall_hist_dump waits for this to drain to zero after - * flipping mode to OFF, so a sibling vCPU that already passed the mode probe - * cannot land its atomic_fetch_add on count / total_ns / max_ns after the dump - * has read those slots. Without this barrier the dump and a mid-flight recorder - * race and the dump's totals can silently lose updates or read torn - * intermediate values. +/* Count of recorders currently inside the update window. syscall_hist_enter() + * first does a cheap disabled-mode probe, then bumps this guard and rechecks + * mode. syscall_hist_dump waits for the guard to drain after flipping mode to + * OFF, so a sibling vCPU that already passed the guarded probe cannot land its + * atomic_fetch_add on count / total_ns / max_ns after the dump has read those + * slots. Without this barrier the dump and a mid-flight recorder race and the + * dump's totals can silently lose updates or read torn intermediate values. */ static _Atomic int hist_active_recorders = 0; @@ -98,9 +98,10 @@ static const char *const hist_names[HIST_TABLE_SIZE] = { }; /* Parse ELFUSE_STARTUP_TRACE. Accepts comma-separated tokens. "syscalls" or - * "all" turns the histogram on. The legacy "1" value (steps trace) and the - * "steps" token leave the histogram off so existing scripts keep working. Token - * matching is whole-word against a fixed allow-list to avoid matching + * "all" turns the startup histogram on. "syscalls-steady" records until guest + * exit instead of freezing at execve. The legacy "1" value (steps trace) and + * the "steps" token leave the histogram off so existing scripts keep working. + * Token matching is whole-word against a fixed allow-list to avoid matching * "syscalls_disabled" or similar. */ static bool env_contains_token(const char *env, const char *tok) @@ -124,8 +125,15 @@ static bool env_contains_token(const char *env, const char *tok) static void hist_init_resolve(void) { const char *env = getenv("ELFUSE_STARTUP_TRACE"); - if (env_contains_token(env, "syscalls") || env_contains_token(env, "all")) + const char *rt = getenv("ELFUSE_RUNTIME_STATS"); + if ((rt && rt[0] && strcmp(rt, "0") != 0) || + env_contains_token(env, "syscalls-steady")) { + hist_steady = true; atomic_store_explicit(&hist_mode, HIST_RECORD, memory_order_release); + } else if (env_contains_token(env, "syscalls") || + env_contains_token(env, "all")) { + atomic_store_explicit(&hist_mode, HIST_RECORD, memory_order_release); + } } void syscall_hist_init(void) @@ -142,37 +150,54 @@ bool syscall_hist_enabled(void) uint64_t syscall_hist_now_ns(void) { - if (!syscall_hist_enabled()) - return 0; struct timespec ts; if (clock_gettime(CLOCK_MONOTONIC, &ts) < 0) return 0; return (uint64_t) ts.tv_sec * 1000000000ULL + (uint64_t) ts.tv_nsec; } -void syscall_hist_record(int nr, uint64_t ns) +uint64_t syscall_hist_enter(void) { - /* Enter the recording window before the mode probe. The matching decrement - * runs on every exit path. syscall_hist_dump waits for the counter to drain - * to zero after flipping mode to OFF; that wait is what guarantees the - * dump's reads see no further updates. + syscall_hist_init(); + if (atomic_load_explicit(&hist_mode, memory_order_acquire) != HIST_RECORD) + return 0; + + /* Increment the recorder guard after the cheap disabled probe, then recheck + * the mode. The first probe keeps normal runs off the global RMW hot path; + * the second preserves the dump race protection if a dump flips RECORD to + * OFF between the first probe and the guard increment. */ atomic_fetch_add_explicit(&hist_active_recorders, 1, memory_order_acquire); - if (atomic_load_explicit(&hist_mode, memory_order_acquire) != HIST_RECORD) - goto leave; - if (nr < 0 || nr >= HIST_TABLE_SIZE) - goto leave; + if (atomic_load_explicit(&hist_mode, memory_order_acquire) != HIST_RECORD) { + atomic_fetch_sub_explicit(&hist_active_recorders, 1, + memory_order_release); + return 0; + } + uint64_t ns = syscall_hist_now_ns(); + if (!ns) { + atomic_fetch_sub_explicit(&hist_active_recorders, 1, + memory_order_release); + return 0; + } + return ns; +} - /* Cheap-load probe before the clock_gettime: hist_first_ns is set exactly - * once at the first record, so subsequent records skip the syscall - * entirely. Without this gate, every record paid for a CLOCK_MONOTONIC read - * whose result was thrown away by the failing CAS. +void syscall_hist_record(int nr, uint64_t start_ns, uint64_t end_ns) +{ + /* Guard was entered by syscall_hist_enter(); always release on exit. end_ns + * == 0 or end_ns < start_ns means the end clock failed: skip the slot + * update but still release the guard so the dump can proceed. */ + if (!end_ns || end_ns < start_ns || nr < 0 || nr >= HIST_TABLE_SIZE) + goto leave; + + uint64_t ns = end_ns - start_ns; + if (atomic_load_explicit(&hist_first_ns, memory_order_relaxed) == 0) { uint64_t expected = 0; - atomic_compare_exchange_strong_explicit( - &hist_first_ns, &expected, syscall_hist_now_ns(), - memory_order_relaxed, memory_order_relaxed); + atomic_compare_exchange_strong_explicit(&hist_first_ns, &expected, + start_ns, memory_order_relaxed, + memory_order_relaxed); } hist_slot_t *slot = &hist_table[nr]; @@ -180,8 +205,7 @@ void syscall_hist_record(int nr, uint64_t ns) atomic_fetch_add_explicit(&slot->total_ns, ns, memory_order_relaxed); /* CAS-loop max keeps the slot lock-free under contention from sibling vCPUs - * racing on the same syscall number. Reads use relaxed order because the - * dump only consumes them after the active-recorder count drains. + * racing on the same syscall number. */ uint64_t prev = atomic_load_explicit(&slot->max_ns, memory_order_relaxed); while (ns > prev) { @@ -196,6 +220,9 @@ void syscall_hist_record(int nr, uint64_t ns) void syscall_hist_freeze(const char *reason) { + if (hist_steady) + return; + /* Publish the reason BEFORE the state transition so a concurrent dump that * wins the FROZEN -> OFF exchange cannot observe HIST_FROZEN with a NULL * reason and print the wrong dump header. The store on hist_freeze_reason @@ -223,6 +250,28 @@ void syscall_hist_disable(void) atomic_store_explicit(&hist_mode, HIST_OFF, memory_order_release); } +void syscall_hist_reset(void) +{ + atomic_store_explicit(&hist_mode, HIST_OFF, memory_order_release); + while (atomic_load_explicit(&hist_active_recorders, memory_order_acquire) > + 0) { + } + for (int i = 0; i < HIST_TABLE_SIZE; i++) { + atomic_store_explicit(&hist_table[i].count, 0, memory_order_relaxed); + atomic_store_explicit(&hist_table[i].total_ns, 0, memory_order_relaxed); + atomic_store_explicit(&hist_table[i].max_ns, 0, memory_order_relaxed); + } + atomic_store_explicit(&hist_first_ns, 0, memory_order_relaxed); + atomic_store_explicit(&hist_freeze_reason, NULL, memory_order_release); + if (hist_steady) + atomic_store_explicit(&hist_mode, HIST_RECORD, memory_order_release); +} + +static uint64_t sat_add_u64(uint64_t a, uint64_t b) +{ + return (a > UINT64_MAX - b) ? UINT64_MAX : a + b; +} + /* Sort key for the dump. Keys carry the slot index so the qsort comparator can * resolve names without consulting hist_table again. */ @@ -248,6 +297,112 @@ static int hist_row_cmp(const void *a, const void *b) return ra->nr - rb->nr; } +static int hist_snapshot_rows(hist_row_t rows[HIST_TABLE_SIZE], + uint64_t *total_count, + uint64_t *total_ns) +{ + int nrows = 0; + *total_count = 0; + *total_ns = 0; + for (int i = 0; i < HIST_TABLE_SIZE; i++) { + uint64_t cnt = + atomic_load_explicit(&hist_table[i].count, memory_order_relaxed); + if (cnt == 0) + continue; + rows[nrows].nr = i; + rows[nrows].count = cnt; + rows[nrows].total_ns = + atomic_load_explicit(&hist_table[i].total_ns, memory_order_relaxed); + rows[nrows].max_ns = + atomic_load_explicit(&hist_table[i].max_ns, memory_order_relaxed); + *total_count = sat_add_u64(*total_count, cnt); + *total_ns = sat_add_u64(*total_ns, rows[nrows].total_ns); + nrows++; + } + qsort(rows, (size_t) nrows, sizeof(rows[0]), hist_row_cmp); + return nrows; +} + +void syscall_hist_dump_json(FILE *out, bool consume) +{ + int mode = atomic_load_explicit(&hist_mode, memory_order_acquire); + if (mode == HIST_OFF) { + fputs("{\"total_count\":0,\"total_ns\":0,\"rows\":[]}", out); + return; + } + + if (consume) { + if (mode == HIST_RECORD) { + int expected = HIST_RECORD; + atomic_compare_exchange_strong_explicit( + &hist_mode, &expected, HIST_FROZEN, memory_order_release, + memory_order_acquire); + } + int prev = atomic_exchange_explicit(&hist_mode, HIST_OFF, + memory_order_acq_rel); + if (prev == HIST_OFF) { + fputs("{\"total_count\":0,\"total_ns\":0,\"rows\":[]}", out); + return; + } + while (atomic_load_explicit(&hist_active_recorders, + memory_order_acquire) > 0) { + } + } + + hist_row_t rows[HIST_TABLE_SIZE]; + uint64_t total_count = 0; + uint64_t total_ns = 0; + int nrows = hist_snapshot_rows(rows, &total_count, &total_ns); + + fprintf(out, "{\"total_count\":%llu,\"total_ns\":%llu,\"rows\":[", + (unsigned long long) total_count, (unsigned long long) total_ns); + for (int i = 0; i < nrows; i++) { + const char *name = hist_names[rows[i].nr]; + fprintf(out, + "%s{\"nr\":%d,\"name\":\"%s\",\"count\":%llu," + "\"total_ns\":%llu,\"max_ns\":%llu}", + i ? "," : "", rows[i].nr, name ? name : "", + (unsigned long long) rows[i].count, + (unsigned long long) rows[i].total_ns, + (unsigned long long) rows[i].max_ns); + } + fputs("]}", out); +} + +static uint64_t hist_total_for(int nr) +{ + if (nr < 0 || nr >= HIST_TABLE_SIZE) + return 0; + return atomic_load_explicit(&hist_table[nr].total_ns, memory_order_relaxed); +} + +void syscall_hist_dump_cost_buckets_json(FILE *out) +{ + uint64_t clone_ns = + sat_add_u64(hist_total_for(SYS_clone), hist_total_for(SYS_clone3)); + uint64_t wait_ns = + sat_add_u64(hist_total_for(SYS_wait4), hist_total_for(SYS_waitid)); + uint64_t open_ns = + sat_add_u64(hist_total_for(SYS_openat), hist_total_for(SYS_openat2)); + uint64_t futex_ns = + sat_add_u64(hist_total_for(SYS_futex), hist_total_for(SYS_futex_waitv)); + uint64_t mem_ns = sat_add_u64( + sat_add_u64(hist_total_for(SYS_mmap), hist_total_for(SYS_mprotect)), + hist_total_for(SYS_madvise)); + + fprintf(out, + "\"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}," + "\"futex\":{\"total_ns\":%llu},\"mem\":{\"total_ns\":%llu}", + (unsigned long long) sat_add_u64(clone_ns, wait_ns), + (unsigned long long) clone_ns, (unsigned long long) wait_ns, + (unsigned long long) open_ns, (unsigned long long) futex_ns, + (unsigned long long) mem_ns, (unsigned long long) open_ns, + (unsigned long long) futex_ns, (unsigned long long) mem_ns); +} + void syscall_hist_dump(void) { int mode = atomic_load_explicit(&hist_mode, memory_order_acquire); @@ -284,31 +439,13 @@ void syscall_hist_dump(void) */ } - hist_row_t rows[HIST_TABLE_SIZE]; - int nrows = 0; uint64_t total_count = 0; uint64_t total_ns = 0; - for (int i = 0; i < HIST_TABLE_SIZE; i++) { - uint64_t cnt = - atomic_load_explicit(&hist_table[i].count, memory_order_relaxed); - if (cnt == 0) - continue; - rows[nrows].nr = i; - rows[nrows].count = cnt; - rows[nrows].total_ns = - atomic_load_explicit(&hist_table[i].total_ns, memory_order_relaxed); - rows[nrows].max_ns = - atomic_load_explicit(&hist_table[i].max_ns, memory_order_relaxed); - total_count += cnt; - total_ns += rows[nrows].total_ns; - nrows++; - } - + hist_row_t rows[HIST_TABLE_SIZE]; + int nrows = hist_snapshot_rows(rows, &total_count, &total_ns); if (nrows == 0) return; - qsort(rows, (size_t) nrows, sizeof(rows[0]), hist_row_cmp); - const char *reason = atomic_load_explicit(&hist_freeze_reason, memory_order_acquire); fprintf(stderr, "=== syscall histogram (%s) ===\n", diff --git a/src/debug/syscall-hist.h b/src/debug/syscall-hist.h index 43d469e8..7cb10b67 100644 --- a/src/debug/syscall-hist.h +++ b/src/debug/syscall-hist.h @@ -10,6 +10,11 @@ * bring-up tracer). Recording stops at the first successful execve so the dump * reflects pre-execve startup; without execve it dumps on guest exit. * + * ELFUSE_STARTUP_TRACE=syscalls-steady records until guest exit instead. This + * is the measurement gate for steady-state performance work: it includes + * startup plus the workload, so run a long enough workload for startup to be + * noise. + * * Disabled cost is one branch + one global load per syscall_dispatch entry * because syscall_hist_enabled() resolves the env once and caches the result. * Enabled cost is two CLOCK_MONOTONIC reads per syscall plus three relaxed @@ -21,6 +26,7 @@ #include #include +#include /* Parse ELFUSE_STARTUP_TRACE once; safe to call repeatedly. Must be called * before any syscall is dispatched so the enabled flag is stable for the @@ -28,26 +34,31 @@ */ void syscall_hist_init(void); -/* Fast probe used by syscall_dispatch to decide whether to grab a start - * timestamp. +/* Returns true while the histogram is in RECORD mode. * - * Returns false after syscall_hist_freeze() so the recording stops cleanly at - * the first execve. + * Returns false after syscall_hist_freeze() in startup mode so recording stops + * cleanly at the first execve. Steady mode keeps returning true until dump. + * Callers that need to time a syscall should use syscall_hist_enter() instead, + * which also enters the recorder guard. */ bool syscall_hist_enabled(void); -/* Monotonic timestamp source. - * - * Returns 0 when the histogram is disabled so the caller can short-circuit - * without a branch on the env-var cache. - */ +/* Monotonic timestamp source. Returns 0 on clock failure. */ uint64_t syscall_hist_now_ns(void); -/* Record one syscall observation. nr is the Linux syscall number; ns is the - * elapsed time inside the dispatcher. Called from every vCPU thread, so the - * counters update under __atomic_fetch_add. No-op if disabled or frozen. +/* Enter the recorder guard and return the current monotonic timestamp. + * Returns 0 (guard NOT held) when the histogram is disabled or mode is not + * RECORD. On a non-zero return the caller MUST call syscall_hist_record() to + * release the guard, even if the elapsed time is unavailable. + */ +uint64_t syscall_hist_enter(void); + +/* Record one syscall observation and release the recorder guard entered by + * syscall_hist_enter(). nr is the Linux syscall number. start_ns and end_ns are + * monotonic timestamps; end_ns == 0 or end_ns < start_ns skips the slot update + * but still releases the guard. Called from every vCPU thread. */ -void syscall_hist_record(int nr, uint64_t ns); +void syscall_hist_record(int nr, uint64_t start_ns, uint64_t end_ns); /* Stop recording but keep the captured data ready to dump. Called from the * successful-execve path so steady-state syscall traffic does not pollute the @@ -63,11 +74,14 @@ void syscall_hist_freeze(const char *reason); * the parent's dump if both share stderr. */ void syscall_hist_disable(void); +void syscall_hist_reset(void); /* Emit a human-readable summary to stderr, sorted by total ns descending. * Idempotent: subsequent calls are no-ops. Safe to call from cleanup paths that * may run more than once. */ void syscall_hist_dump(void); +void syscall_hist_dump_json(FILE *out, bool consume); +void syscall_hist_dump_cost_buckets_json(FILE *out); #endif /* ELFUSE_SYSCALL_HIST_H */ diff --git a/src/main.c b/src/main.c index 7df733f5..5390915e 100644 --- a/src/main.c +++ b/src/main.c @@ -43,6 +43,7 @@ #include "debug/gdbstub.h" #include "debug/log.h" +#include "debug/runtime-stats.h" #include "debug/syscall-hist.h" static int parse_int_arg(const char *s, int min, int max, int *out) @@ -188,6 +189,7 @@ static int host_dc_zva_assert(void) int main(int argc, char **argv) { log_init(); + runtime_stats_init(argc, argv); /* Resolve ELFUSE_STARTUP_TRACE before any guest syscall can fire so the * histogram captures the very first dynamic-linker openat. */ @@ -663,19 +665,11 @@ int main(int argc, char **argv) /* Tear down debugger state before freeing guest/vCPU resources. */ gdb_stub_shutdown(); - /* Diagnostic counter dump runs before guest_destroy so the shim_data - * mapping is still valid. ELFUSE_SHIM_STATS is the gate; an unset variable - * produces no output. - */ - if (shim_globals_stats_enabled()) - shim_globals_counters_dump(&g); - - /* Dump the startup histogram before guest_destroy so any cleanup-path - * syscalls (closing host fds, unmapping the slab) do not appear in the - * captured set. The dump is a no-op when ELFUSE_STARTUP_TRACE=syscalls was - * not requested. - */ - syscall_hist_dump(); + /* Diagnostic dumps run before guest_destroy so shim_data is still valid. */ + if (runtime_stats_enabled()) + runtime_stats_dump(&g, "exit", true); + else + syscall_hist_dump(); cleanup_main_resources(&g, guest_initialized, &sysroot_mount, have_host_cwd ? host_cwd : NULL, guest_argv, guest_argc, elf_path, sysroot_path); diff --git a/src/runtime/forkipc.c b/src/runtime/forkipc.c index 686b6520..0afa6571 100644 --- a/src/runtime/forkipc.c +++ b/src/runtime/forkipc.c @@ -48,6 +48,7 @@ #include "syscall/signal.h" #include "debug/log.h" +#include "debug/runtime-stats.h" #include "debug/syscall-hist.h" /* Linux clone flags. Shared by the fork-child TID-sync emulation below and @@ -66,6 +67,13 @@ static int fork_child_vfork_notify_fd = -1; +static void fork_child_destroy_guest(guest_t *g, const char *reason) +{ + if (runtime_stats_enabled()) + runtime_stats_dump(g, reason, true); + guest_destroy(g); +} + void fork_notify_vfork_exec(void) { if (fork_child_vfork_notify_fd < 0) @@ -91,11 +99,13 @@ int fork_child_main(int ipc_fd, log_set_level(LOG_DEBUG); /* The startup syscall histogram captures dynamic-linker bring-up of the - * top-level guest only; the child resumes from the parent's snapshot, so - * its first syscalls would be steady-state traffic that confuses the dump. - * Disable before any guest syscall is dispatched. + * top-level guest only; the child resumes from the parent's snapshot. Keep + * child syscall recording only for ELFUSE_RUNTIME_STATS, whose contract is + * whole-workload cost attribution. */ - syscall_hist_disable(); + const char *rt_stats = getenv("ELFUSE_RUNTIME_STATS"); + if (!rt_stats || !rt_stats[0] || strcmp(rt_stats, "0") == 0) + syscall_hist_disable(); /* Reset static process/thread/futex state before receiving the parent * snapshot so the incoming metadata survives child restore. @@ -205,7 +215,7 @@ int fork_child_main(int ipc_fd, ((hdr.pt_pool_next - g.pt_pool_base) % GUEST_PAGE_SIZE) != 0) { 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"); close(ipc_fd); return 1; } @@ -214,7 +224,7 @@ int fork_child_main(int ipc_fd, ((ttbr0_off - g.pt_pool_base) % GUEST_PAGE_SIZE) != 0) { log_error("fork-child: invalid ttbr0 0x%llx", (unsigned long long) hdr.ttbr0); - guest_destroy(&g); + fork_child_destroy_guest(&g, "fork-child-error"); close(ipc_fd); return 1; } @@ -250,19 +260,19 @@ int fork_child_main(int ipc_fd, ipc_registers_t regs; if (fork_ipc_read_all(ipc_fd, ®s, sizeof(regs)) < 0) { log_error("fork-child: failed to read registers"); - guest_destroy(&g); + fork_child_destroy_guest(&g, "fork-child-error"); return 1; } if (fork_ipc_recv_memory_regions(ipc_fd, &g) < 0) { log_error("fork-child: failed to receive memory regions"); - guest_destroy(&g); + fork_child_destroy_guest(&g, "fork-child-error"); return 1; } if (fork_ipc_recv_fd_table(ipc_fd, &g) < 0) { log_error("fork-child: failed to receive fd table"); - guest_destroy(&g); + fork_child_destroy_guest(&g, "fork-child-error"); return 1; } @@ -271,20 +281,20 @@ int fork_child_main(int ipc_fd, */ if (fork_ipc_recv_pty_keepalives(ipc_fd) < 0) { log_error("fork-child: failed to receive pty keepalives"); - guest_destroy(&g); + fork_child_destroy_guest(&g, "fork-child-error"); return 1; } signal_state_t sig; if (fork_ipc_recv_process_state(ipc_fd, &g, &sig) < 0) { log_error("fork-child: failed to receive process state"); - guest_destroy(&g); + fork_child_destroy_guest(&g, "fork-child-error"); return 1; } if (chown_overlay_recv(ipc_fd) < 0) { log_error("fork-child: failed to receive chown overlay"); - guest_destroy(&g); + fork_child_destroy_guest(&g, "fork-child-error"); return 1; } @@ -339,7 +349,7 @@ int fork_child_main(int ipc_fd, * the single-threaded child at this point). */ if (shim_globals_install_per_vcpu(vcpu, &g, hdr.child_pid) < 0) { - guest_destroy(&g); + fork_child_destroy_guest(&g, "fork-child-error"); return 1; } @@ -407,6 +417,7 @@ int fork_child_main(int ipc_fd, */ shim_globals_init(&g); shim_globals_publish_stats_gate(&g); + runtime_stats_reset_baseline(); shim_globals_set_trace_enabled(&g, verbose); shim_globals_publish_pid(&g, hdr.child_pid, hdr.parent_pid); shim_globals_publish_creds(&g, hdr.uid, hdr.euid, hdr.gid, hdr.egid); @@ -451,7 +462,7 @@ int fork_child_main(int ipc_fd, /* The child resumes from the captured fork frame and returns 0 to EL0. */ int exit_code = vcpu_run_loop(vcpu, vexit, &g, verbose, timeout_sec); - guest_destroy(&g); + fork_child_destroy_guest(&g, "fork-child-exit"); return exit_code; } diff --git a/src/syscall/proc.c b/src/syscall/proc.c index 89fa521f..04c3ab52 100644 --- a/src/syscall/proc.c +++ b/src/syscall/proc.c @@ -49,6 +49,7 @@ #include "debug/crashreport.h" #include "debug/gdbstub.h" +#include "debug/runtime-stats.h" /* Process state. */ @@ -57,6 +58,24 @@ static _Atomic uint64_t wxcount_to_rx = 0; /* RW->RX (exec fault) */ static _Atomic uint64_t wxcount_to_rw = 0; /* RX->RW (write fault) */ static _Atomic uint64_t sysreg_write_count = 0; /* EC=0x18 Dir=0 (DC CVAU, IC IVAU, etc.) */ + +/* vCPU exit-reason accounting, gated by ELFUSE_SHIM_STATS so unset runs pay + * nothing on the hot path. Attributes how many hv_vcpu_run returns did no + * dispatchable guest work: VTIMER_ACTIVATED masks and spurious CANCELED/UNKNOWN + * cancels that reach the tail with nothing pending. The null-exit share against + * total returns is the measurement the hv_vcpu_run_until swap is gated on: a + * plain hv_vcpu_run returns even on transparently-handled VMEXITs, whereas + * run_until(HV_DEADLINE_FOREVER) reabsorbs them. no_signal_cancel is a + * heuristic -- an rseq fixup on the same tail counts here too -- but rseq_gva + * is 0 on the compute loops this targets, so the over-count is negligible. A + * transparent VMEXIT that HVF surfaces as UNKNOWN with nothing pending hits the + * crash path, not this tail, so null_exit_share is a lower bound on what + * run_until could reabsorb, not a proof it reabsorbs nothing. Relaxed ordering: + * these counters never publish state, they are read only at process exit. + */ +static _Atomic uint64_t vcpu_exit_total = 0; +static _Atomic uint64_t vcpu_exit_vtimer = 0; +static _Atomic uint64_t vcpu_exit_no_signal_cancel = 0; /* x86_64-via-Rosetta is on by default: the architecture is auto-detected from * the ELF header (EM_X86_64), and rosetta is the only viable path for those * binaries on Apple Silicon. The --no-rosetta CLI flag (or ELFUSE_NO_ROSETTA=1) @@ -89,6 +108,60 @@ static _Atomic int exit_group_code = 0; /* Public API. */ +void proc_dump_vcpu_exit_stats(void) +{ + uint64_t vtimer = + atomic_load_explicit(&vcpu_exit_vtimer, memory_order_relaxed); + uint64_t nosig = + atomic_load_explicit(&vcpu_exit_no_signal_cancel, memory_order_relaxed); + /* Load total last and clamp the numerator: matches the JSON path so the + * ratio stays in [0, 100] even under concurrent vCPU increments. + */ + uint64_t total = + atomic_load_explicit(&vcpu_exit_total, memory_order_relaxed); + uint64_t nul = vtimer + nosig; + if (nul > total) + nul = total; + double share = total ? (100.0 * (double) nul / (double) total) : 0.0; + fprintf(stderr, + "vcpu-exit-stats (pid=%lld)\n" + " exits_total %llu\n" + " exits_vtimer %llu\n" + " exits_no_signal_cancel %llu\n" + " null_exit_share %.2f%%\n", + (long long) proc_get_pid(), (unsigned long long) total, + (unsigned long long) vtimer, (unsigned long long) nosig, share); +} + +void proc_dump_vcpu_exit_stats_json(FILE *out) +{ + uint64_t vtimer = + atomic_load_explicit(&vcpu_exit_vtimer, memory_order_relaxed); + uint64_t nosig = + atomic_load_explicit(&vcpu_exit_no_signal_cancel, memory_order_relaxed); + /* Load total last: makes it most likely to exceed vtimer+nosig even under + * concurrent increments. Clamp the numerator so the ratio stays <= 100. + */ + uint64_t total = + atomic_load_explicit(&vcpu_exit_total, memory_order_relaxed); + uint64_t nul = vtimer + nosig; + if (nul > total) + nul = total; + double share = total ? (100.0 * (double) nul / (double) total) : 0.0; + fprintf(out, + "{\"exits_total\":%llu,\"exits_vtimer\":%llu," + "\"exits_no_signal_cancel\":%llu,\"null_exit_share\":%.2f}", + (unsigned long long) total, (unsigned long long) vtimer, + (unsigned long long) nosig, share); +} + +void proc_reset_vcpu_exit_stats(void) +{ + atomic_store_explicit(&vcpu_exit_total, 0, memory_order_relaxed); + atomic_store_explicit(&vcpu_exit_vtimer, 0, memory_order_relaxed); + atomic_store_explicit(&vcpu_exit_no_signal_cancel, 0, memory_order_relaxed); +} + void proc_init(void) { proc_identity_init(); @@ -1067,6 +1140,10 @@ int vcpu_run_loop(hv_vcpu_t vcpu, int iter = 0; const int is_main = (timeout_sec > 0); const char *prefix = is_main ? "elfuse" : "elfuse: worker"; + /* Resolve the exit-stats gate once; when ELFUSE_SHIM_STATS is unset the + * increments below cost a single predictable branch and no atomic traffic. + */ + const bool stats = shim_globals_stats_enabled(); /* Pin vCPU thread to a performance core via QoS class. On Apple Silicon, * USER_INTERACTIVE maps to P-cores, avoiding E-core migration that causes @@ -1108,12 +1185,20 @@ int vcpu_run_loop(hv_vcpu_t vcpu, HV_CHECK_CTX(hv_vcpu_run(vcpu), vcpu, g); - drain_external_guest_signal(); - - /* Main: disarm timeout */ + /* Main: disarm timeout before post-run work. The alarm scopes only + * hv_vcpu_run latency; a stats signal dump below can take arbitrary + * time and must not trip the vCPU-hang detector. + */ if (is_main) alarm(0); + if (stats) + atomic_fetch_add_explicit(&vcpu_exit_total, 1, + memory_order_relaxed); + + drain_external_guest_signal(); + runtime_stats_maybe_dump_signal(g); + /* Re-check exit_group after waking from hv_vcpu_run */ if (proc_exit_group_requested()) { exit_code = proc_exit_group_code(); @@ -2183,7 +2268,12 @@ int vcpu_run_loop(hv_vcpu_t vcpu, if (thread_fork_barrier_check()) continue; - /* No signal pending; truly unexpected cancelation */ + /* No signal pending; truly unexpected cancelation. This tail is a + * null exit: the run returned but nothing dispatchable was found. + */ + if (stats) + atomic_fetch_add_explicit(&vcpu_exit_no_signal_cancel, 1, + memory_order_relaxed); if (verbose) log_debug("%s: vCPU canceled (no signal pending)", prefix); } else if (vexit->reason == HV_EXIT_REASON_VTIMER_ACTIVATED) { @@ -2191,6 +2281,9 @@ int vcpu_run_loop(hv_vcpu_t vcpu, * mask the vtimer and continue. Without this, a pending vtimer * would cause an "unexpected exit reason" crash. */ + if (stats) + atomic_fetch_add_explicit(&vcpu_exit_vtimer, 1, + memory_order_relaxed); hv_vcpu_set_vtimer_mask(vcpu, true); } else { log_error("%s: unexpected exit reason 0x%x", prefix, vexit->reason); diff --git a/src/syscall/proc.h b/src/syscall/proc.h index c2877a34..93896dfd 100644 --- a/src/syscall/proc.h +++ b/src/syscall/proc.h @@ -15,6 +15,8 @@ #pragma once +#include + #include #include #include @@ -369,6 +371,15 @@ void proc_request_exit_group(int code); void proc_clear_exit_group(void); int proc_exit_group_requested(void); +/* Dump the vCPU exit-reason accounting (total returns, VTIMER masks, spurious + * cancels, null-exit share) to stderr. Intended for the process-exit path when + * runtime-stats are enabled (ELFUSE_SHIM_STATS or ELFUSE_RUNTIME_STATS, via + * shim_globals_stats_enabled()); counters stay zero when the gate is unset. + */ +void proc_dump_vcpu_exit_stats(void); +void proc_dump_vcpu_exit_stats_json(FILE *out); +void proc_reset_vcpu_exit_stats(void); + /* vCPU run loop. */ /* Request that the current host thread's HVC #6 run loop returns after the diff --git a/src/syscall/syscall.c b/src/syscall/syscall.c index ce2b75ac..0bf87797 100644 --- a/src/syscall/syscall.c +++ b/src/syscall/syscall.c @@ -2054,7 +2054,7 @@ int syscall_dispatch(hv_vcpu_t vcpu, guest_t *g, int *exit_code, bool verbose) /* Per-syscall histogram for the dynamic-linker bring-up storm. Zero when * disabled so the bottom-of-dispatch record path is a single branch. */ - uint64_t hist_start_ns = syscall_hist_now_ns(); + uint64_t hist_start_ns = syscall_hist_enter(); if (!verbose) { if (nr == SYS_getpid || nr == SYS_getppid || nr == SYS_gettid || @@ -2200,14 +2200,7 @@ int syscall_dispatch(hv_vcpu_t vcpu, guest_t *g, int *exit_code, bool verbose) result = 0; /* Not written back, but keep clean */ } else if (result == SYSCALL_EXEC_HAPPENED) { if (hist_start_ns) { - /* Guard the subtraction: syscall_hist_now_ns returns 0 if - * clock_gettime fails. An unsigned 0 minus a non-zero start - * would underflow to a huge value and pollute the histogram - * with a bogus latency sample. - */ - uint64_t hist_end_ns = syscall_hist_now_ns(); - if (hist_end_ns >= hist_start_ns) - syscall_hist_record(nr, hist_end_ns - hist_start_ns); + syscall_hist_record(nr, hist_start_ns, syscall_hist_now_ns()); syscall_hist_freeze("frozen at first execve"); } return SYSCALL_EXEC_HAPPENED; @@ -2256,11 +2249,8 @@ int syscall_dispatch(hv_vcpu_t vcpu, guest_t *g, int *exit_code, bool verbose) tlbi_request_emit_to_vcpu(vcpu); } - if (hist_start_ns) { - uint64_t hist_end_ns = syscall_hist_now_ns(); - if (hist_end_ns >= hist_start_ns) - syscall_hist_record(nr, hist_end_ns - hist_start_ns); - } + if (hist_start_ns) + syscall_hist_record(nr, hist_start_ns, syscall_hist_now_ns()); return should_exit; } diff --git a/tests/test-runtime-stats.sh b/tests/test-runtime-stats.sh new file mode 100755 index 00000000..4ab78f5e --- /dev/null +++ b/tests/test-runtime-stats.sh @@ -0,0 +1,139 @@ +#!/usr/bin/env bash +# Runtime-stats subsystem smoke test (ELFUSE_RUNTIME_STATS) +# +# Guards the runtime-stats output paths that have no other coverage: +# - json mode emits exactly one valid top-level JSON object on exit, +# even when SIGUSR1 dumps are requested mid-run. This is the guard +# against the "two bare JSON objects on stderr is not valid JSON" +# regression: a conforming parser must accept the whole stderr. +# - jsonl mode emits one valid JSON object per line and honors the +# on-demand SIGUSR1 dump, so a mid-run signal adds a line. +# - summary mode prints the human vcpu-exit and histogram tables. +# +# Usage: tests/test-runtime-stats.sh +# +# The guest binary just needs to run briefly and exit cleanly; busybox +# (invoked as `sleep`/`true`) is the fixture the suite already ships. + +set -u + +ELFUSE="${1:?Usage: $0 }" +GUEST="${2:?Usage: $0 }" + +RED=$'\033[0;31m' +GREEN=$'\033[0;32m' +RESET=$'\033[0m' + +tmpdir="$(mktemp -d)" +trap 'rm -rf "$tmpdir"' EXIT + +fail=0 +pass() +{ + printf "%sPASS%s %s\n" "$GREEN" "$RESET" "$1" +} +die() +{ + printf "%sFAIL%s %s\n" "$RED" "$RESET" "$1" + fail=1 +} + +# Count valid top-level JSON objects on stderr, ignoring any incidental +# non-JSON diagnostics (log_warn etc). Every stats object is emitted as one +# "{...}\n" line, so a line beginning with "{" is a candidate; it must parse +# or the whole check fails. Prints the count of valid objects, optionally +# filtered by reason; exits non-zero if a "{"-line does not parse as JSON. +count_objs() +{ + python3 - "$@" << 'PY' +import json, sys +n = 0 +want_reason = sys.argv[2] if len(sys.argv) > 2 else None +for line in open(sys.argv[1]): + if not line.lstrip().startswith("{"): + continue + obj = json.loads(line) # raises -> non-zero exit -> caller treats as failure + if want_reason is not None and obj.get("reason") != want_reason: + continue + n += 1 +print(n) +PY +} + +# --- json mode: one valid object on a clean exit ------------------------- +err="$tmpdir/json-clean.err" +ELFUSE_RUNTIME_STATS=json "$ELFUSE" "$GUEST" true 2> "$err" > /dev/null +n="$(count_objs "$err")" || { + die "json mode: a JSON line failed to parse" + cat "$err" + n=x +} +if [ "$n" = "1" ]; then + pass "json mode emits one valid JSON object on exit" +elif [ "$n" != "x" ]; then + die "json mode: expected exactly 1 JSON object, got $n" +fi + +# --- json mode: still one object when SIGUSR1 dumps are requested --------- +# Non-final (signal) dumps must be suppressed in json mode; otherwise the +# exit dump would append a second bare object and break the single-object +# contract. Spray signals across the sleep so at least one lands mid-run. +err="$tmpdir/json-signal.err" +ELFUSE_RUNTIME_STATS=json ELFUSE_STATS_SIGNAL=USR1 \ + "$ELFUSE" "$GUEST" sleep 1 2> "$err" > /dev/null & +pid=$! +for _ in 1 2 3 4; do + sleep 0.15 + kill -USR1 "$pid" 2> /dev/null || true +done +wait "$pid" +n="$(count_objs "$err")" || { + die "json+SIGUSR1: a JSON line failed to parse" + cat "$err" + n=x +} +if [ "$n" = "1" ]; then + pass "json mode suppresses signal dumps (one object under SIGUSR1)" +elif [ "$n" != "x" ]; then + die "json mode + SIGUSR1: signal dumps leaked extra objects ($n)" +fi + +# --- jsonl mode: every object line is standalone-valid -------------------- +# The final dump guarantees one line; per-signal dumps must add at least one +# more when SIGUSR1 lands mid-run. +err="$tmpdir/jsonl.err" +ELFUSE_RUNTIME_STATS=jsonl ELFUSE_STATS_SIGNAL=USR1 \ + "$ELFUSE" "$GUEST" sleep 1 2> "$err" > /dev/null & +pid=$! +for _ in 1 2 3 4; do + sleep 0.15 + kill -USR1 "$pid" 2> /dev/null || true +done +wait "$pid" +n="$(count_objs "$err")" || { + die "jsonl mode: a line failed to parse as standalone JSON" + cat "$err" + n=0 +} +s="$(count_objs "$err" signal)" || { + die "jsonl mode: a line failed to parse as standalone JSON" + cat "$err" + s=0 +} +if [ "$n" -gt 1 ] 2> /dev/null && [ "$s" -ge 1 ] 2> /dev/null; then + pass "jsonl mode emits standalone-valid JSON objects ($n)" +else + die "jsonl mode: missing SIGUSR1-triggered JSON object" +fi + +# --- summary mode: human tables present ---------------------------------- +err="$tmpdir/summary.err" +ELFUSE_RUNTIME_STATS=summary "$ELFUSE" "$GUEST" true 2> "$err" > /dev/null +if grep -q "vcpu-exit-stats" "$err" && grep -q "syscall histogram" "$err"; then + pass "summary mode prints vcpu-exit and histogram tables" +else + die "summary mode: missing vcpu-exit or histogram table" + cat "$err" +fi + +exit "$fail"