From 0437ca9feecda32818ac25c51b1426f761ae4db0 Mon Sep 17 00:00:00 2001 From: Jim Huang Date: Tue, 13 Oct 2026 02:30:02 +0800 Subject: [PATCH] Add runtime stats 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. --- Makefile | 1 + docs/usage.md | 116 ++++++++++- mk/tests.mk | 11 +- scripts/runtime-stats-convert.py | 241 +++++++++++++++++++++++ src/core/launch.c | 25 ++- src/core/shim-globals.c | 25 ++- src/core/shim-globals.h | 3 + src/debug/runtime-stats.c | 321 +++++++++++++++++++++++++++++++ src/debug/runtime-stats.h | 44 +++++ src/debug/syscall-hist.c | 159 ++++++++++++--- src/debug/syscall-hist.h | 15 +- src/main.c | 2 + src/runtime/forkipc.c | 21 +- src/syscall/internal.h | 4 +- src/syscall/proc.c | 103 +++++++++- src/syscall/proc.h | 10 + tests/test-runtime-stats.sh | 202 +++++++++++++++++++ 17 files changed, 1250 insertions(+), 53 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 482b74e31..b27bbe472 100644 --- a/Makefile +++ b/Makefile @@ -78,6 +78,7 @@ SRCS := \ debug/gdbstub-reg.c \ debug/gdbstub-rsp.c \ debug/log.c \ + debug/runtime-stats.c \ debug/syscall-hist.c # The USB fixture seam (src/syscall/usbdev-fixture.h). usbdev.c calls it with no diff --git a/docs/usage.md b/docs/usage.md index 651e0a1d1..5621c032a 100644 --- a/docs/usage.md +++ b/docs/usage.md @@ -309,6 +309,109 @@ 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 nonempty value other than `json`, `jsonl`, or `0`) | Human-readable tables on exit | +| `json` | One JSON object per process 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 claim SIGUSR1 +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 and `"fork-child-exit"` for fork children, so filter on `"final"` +rather than the reason string. In `json` (not `jsonl`) mode, snapshots are +suppressed so each process writes a single JSON object. Each record goes out +in one `write`, which keeps records from a parent and its fork children whole +in a file; a pipe only guarantees that for writes up to 512 bytes, so send +stderr to a file when a forking guest is measured. + +Snapshot requests are handled on elfuse's own signal thread and the record is +written by a separate stats thread, so it arrives even while the guest is +blocked in a long syscall, and no guest call sees an `EINTR` for it. The `sleep 0.1` matters only for a script that sends the signal +immediately: elfuse claims `SIGUSR1` early in startup, and one delivered before +then terminates the process by default. Without `ELFUSE_RUNTIME_STATS` or +`ELFUSE_SHIM_STATS`, `ELFUSE_STATS_SIGNAL` is ignored and `SIGUSR1` keeps its +default action. + +### 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, also +reported as `path.open_ns`), `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. + +Each fork child keeps its own counters from its first instruction and emits its +own final record, so per-process records add up rather than overlap. Within a +process the shim counters restart at each `execve`, because they live in the +shim's data page and a new image gets a fresh one; the syscall histogram and +vCPU exit counts cover the whole process. The same +holds for `syscalls-steady` without `ELFUSE_RUNTIME_STATS`: each child dumps its +own histogram at exit. 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 @@ -345,11 +448,16 @@ Off by default, and useful when a guest misbehaves rather than in normal use: - `ELFUSE_STARTUP_TRACE`: `steps` prints per-step VM bring-up timings, `syscalls` prints a per-syscall histogram of startup traffic (frozen at the - first `execve`, so steady-state calls do not swamp it), `all` does both. + first `execve`, so steady-state calls do not swamp it), `syscalls-steady` + records the whole run instead, `all` does `steps` and `syscalls`. Comma-separated tokens are accepted, and `1` is a legacy alias for `steps`. -- `ELFUSE_SHIM_STATS=1`: dump the EL1 shim counter table to stderr at exit, so - a syscall that should be served inside the shim but takes the HVC #5 exit is - attributed without a rebuild. +- `ELFUSE_SHIM_STATS=1`: dump the EL1 shim counter table and the vCPU exit + counts to stderr at exit, one table per process, so a syscall that should be + served inside the shim but takes the HVC #5 exit is attributed without a + rebuild. It is the `summary` mode of `ELFUSE_RUNTIME_STATS` without the + steady-state histogram. +- `ELFUSE_RUNTIME_STATS`, `ELFUSE_STATS_SIGNAL`: see + [Performance Analysis](#performance-analysis). - `ELFUSE_DISABLE_TLBI_RANGE=1`: refuse `FEAT_TLBIRANGE` and fall back to per-page and broadcast invalidation, which separates a stale-TLB bug from the range-encoding path. diff --git a/mk/tests.mk b/mk/tests.mk index 069972ebe..f27266e82 100644 --- a/mk/tests.mk +++ b/mk/tests.mk @@ -7,7 +7,7 @@ # src/elfuse-limits.h. ELFUSE_HOST_NOFILE_MIN ?= $(shell bash "$(CURDIR)/tests/test-config.sh" --host-nofile) -.PHONY: test-hello test-all check check-syscall-coverage check-eintr-contract check-lock-order check-atomics check-ascii check-usbdev-departed check-svc-tails check-skill-refs check-proof-targets test-gdbstub test-coreutils test-busybox test-shim-futex-stats test-vcpu-watchdog \ +.PHONY: test-hello test-all check check-syscall-coverage check-eintr-contract check-lock-order check-atomics check-ascii check-usbdev-departed check-svc-tails check-skill-refs check-proof-targets test-gdbstub test-coreutils test-busybox test-shim-futex-stats test-vcpu-watchdog test-runtime-stats \ test-static-bins \ test-dynamic test-dynamic-coreutils test-glibc-dynamic \ test-glibc-coreutils test-perf \ @@ -353,6 +353,7 @@ check: $(ELFUSE_BIN) $(TEST_DEPS) check-syscall-coverage check-eintr-contract ch $(call run-lane,test-rosetta-cli,rosetta CLI gating) $(call run-lane,test-bench-guardrail,hot-syscall guardrail) $(call run-lane,test-sharun,sharun launcher and probe) + $(call run-lane,test-runtime-stats,runtime-stats output validation) ## Hot-syscall performance guardrail: ensure getpid, libc clock_gettime, ## and 1-byte /dev/urandom reads stay under their TODO ns/op ceilings. @@ -1448,6 +1449,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 000000000..bc26c90a7 --- /dev/null +++ b/scripts/runtime-stats-convert.py @@ -0,0 +1,241 @@ +#!/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", + "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")), + "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 = [] + track_end = {} + for rec, rows in syscall_delta_rows(records): + pid = rec.get("pid", 1) + # A record only says how much ran before it was taken, so the + # interval's slices are stacked to end at the snapshot, not after it. + # Syscall time sums across vCPU threads and can exceed the wall time + # between snapshots, so a slice never starts before the previous + # interval's last one ended on the same track. + ts = (rec.get("time_ns", 0) - sum(r.get("total_ns", 0) for r in rows)) / 1000.0 + ts = max(ts, track_end.get(pid, 0.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": pid, + } + ) + ts += row.get("total_ns", 0) / 1000.0 + # A final record closes the process, as in syscall_delta_rows, so a + # later process that reuses the pid starts a fresh track. + if rec.get("final"): + track_end.pop(pid, None) + else: + track_end[pid] = ts + 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": 2_000_000, + "final": False, + "argv": ["elfuse", "guest"], + "wall_ns": 10_000_000, + "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"] = 5_000_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) + rows = list(csv.DictReader(StringIO(out.getvalue()))) + assert len(rows) == 2 + assert rows[1]["clone_ms"] == "1.0" and rows[1]["wait_ms"] == "2.0" + 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 + assert max(e["ts"] + e["dur"] for e in trace) <= sample2["time_ns"] / 1000.0 + spans = sorted((e["ts"], e["ts"] + e["dur"]) for e in trace) + assert all(a[1] <= b[0] for a, b in zip(spans, spans[1:])) + + +if __name__ == "__main__": + main(sys.argv[1:]) diff --git a/src/core/launch.c b/src/core/launch.c index 41fb93a7a..e3b3a587b 100644 --- a/src/core/launch.c +++ b/src/core/launch.c @@ -26,7 +26,6 @@ #include "core/bootstrap.h" #include "core/guest.h" -#include "core/shim-globals.h" #include "core/sysroot.h" #include "runtime/futex.h" /* futex_interrupt_request */ @@ -38,6 +37,7 @@ #include "debug/gdbstub.h" #include "debug/log.h" +#include "debug/runtime-stats.h" #include "debug/syscall-hist.h" /* Embedded shim binary (generated by xxd -i from shim.bin). */ @@ -204,6 +204,8 @@ int elfuse_launch(const launch_args_t *args) gdb_stub_wait_for_attach(); } + runtime_stats_attach(&g, args->guest_argc, args->guest_argv); + /* vcpu_run_loop owns guest execution until exit, fatal signal, or timeout. */ int exit_code = @@ -235,19 +237,16 @@ int elfuse_launch(const launch_args_t *args) thread_wake_all_blocked(); thread_join_workers(); - /* 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. + /* Diagnostic dumps run before guest_destroy so the shim_data mapping is + * still valid, and so cleanup-path syscalls (closing host fds, unmapping + * the slab) do not appear in the captured set. Each is a no-op when its + * gate (ELFUSE_RUNTIME_STATS or ELFUSE_SHIM_STATS, ELFUSE_STARTUP_TRACE) is + * unset. */ - syscall_hist_dump(); + if (runtime_stats_enabled()) + runtime_stats_dump_final("exit"); + else + syscall_hist_dump(); /* Give back any pty slaves this process still holds before the guest * teardown below. The guest's stdio slaves are closed by the kernel, not by diff --git a/src/core/shim-globals.c b/src/core/shim-globals.c index 91846235a..00c85000c 100644 --- a/src/core/shim-globals.c +++ b/src/core/shim-globals.c @@ -516,13 +516,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 08e593a75..fc9daa44f 100644 --- a/src/core/shim-globals.h +++ b/src/core/shim-globals.h @@ -27,6 +27,8 @@ #pragma once +#include + #include #include @@ -375,6 +377,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 000000000..35b91e243 --- /dev/null +++ b/src/debug/runtime-stats.c @@ -0,0 +1,321 @@ +/* + * 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 "core/shim-globals.h" +#include "debug/log.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; + +/* Written once by runtime_stats_init before any other thread exists. */ +static rt_stats_mode_t rt_mode; +static int rt_signal; +static uint64_t rt_start_ns; + +/* The guest and its argv are set by attach and cleared by the final dump, all + * under the mutex, which also keeps a snapshot from interleaving with the exit + * dump. + */ +static pthread_mutex_t rt_dump_mutex = PTHREAD_MUTEX_INITIALIZER; +static const guest_t *rt_guest; +static int rt_argc; +static const char *const *rt_argv; + +/* Snapshot requests. The sigwait thread that receives the signal also carries + * the cross-process doorbell and the watchdog, so it only posts here; the + * dumper thread does the write, which can block on a stalled stderr. The + * request lock is never held across a dump. + */ +static pthread_mutex_t rt_req_lock = PTHREAD_MUTEX_INITIALIZER; +static pthread_cond_t rt_req_cond = PTHREAD_COND_INITIALIZER; +static bool rt_req_pending; +static bool rt_dumper_started; + +static bool env_on(const char *v) +{ + return v && v[0] && strcmp(v, "0") != 0; +} + +/* Length of the well-formed UTF-8 sequence at @p (RFC 3629: no overlongs, no + * surrogates, nothing past U+10FFFF), or 0 when the bytes there are not one. + */ +static int utf8_seq_len(const unsigned char *p) +{ + unsigned char lo = 0x80, hi = 0xbf; + int n; + if (p[0] >= 0xc2 && p[0] <= 0xdf) + n = 2; + else if (p[0] >= 0xe0 && p[0] <= 0xef) + n = 3; + else if (p[0] >= 0xf0 && p[0] <= 0xf4) + n = 4; + else + return 0; + if (p[0] == 0xe0) + lo = 0xa0; + else if (p[0] == 0xed) + hi = 0x9f; + else if (p[0] == 0xf0) + lo = 0x90; + else if (p[0] == 0xf4) + hi = 0x8f; + if (p[1] < lo || p[1] > hi) + return 0; + for (int i = 2; i < n; i++) + if (p[i] < 0x80 || p[i] > 0xbf) + return 0; + return n; +} + +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: + /* Well-formed UTF-8 goes out as is. Any other byte past ASCII is + * escaped on its own, so an argv that is not UTF-8 still leaves a + * line every JSON parser accepts. + */ + if (*p >= 0x80) { + int n = utf8_seq_len(p); + if (n) { + fwrite(p, 1, (size_t) n, out); + p += n - 1; + break; + } + } + if (*p < 0x20 || *p >= 0x7f) + 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; +} + +void runtime_stats_init(void) +{ + 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; + } + + /* Only claim the signal when there is something to dump: otherwise it keeps + * its default action, as a user who set the variable by mistake would + * expect. + */ + const char *sig = getenv("ELFUSE_STATS_SIGNAL"); + if (rt_mode != RT_STATS_OFF && sig && strcmp(sig, "USR1") == 0) + rt_signal = SIGUSR1; +} + +bool runtime_stats_enabled(void) +{ + return rt_mode != RT_STATS_OFF; +} + +int runtime_stats_signal(void) +{ + return rt_signal; +} + +static void dump_locked(const char *reason, bool final); + +static void *dumper_main(void *arg) +{ + (void) arg; + for (;;) { + pthread_mutex_lock(&rt_req_lock); + while (!rt_req_pending) + pthread_cond_wait(&rt_req_cond, &rt_req_lock); + rt_req_pending = false; + pthread_mutex_unlock(&rt_req_lock); + + pthread_mutex_lock(&rt_dump_mutex); + dump_locked("signal", false); + pthread_mutex_unlock(&rt_dump_mutex); + } + return NULL; +} + +void runtime_stats_attach(const guest_t *g, int argc, const char *const *argv) +{ + if (!runtime_stats_enabled()) + return; + pthread_mutex_lock(&rt_dump_mutex); + rt_guest = g; + rt_argc = argv ? argc : 0; + rt_argv = argv; + pthread_mutex_unlock(&rt_dump_mutex); + + /* Started here rather than at init so it inherits the signal mask + * proc_preempt_init installed, like every other elfuse thread. + */ + pthread_mutex_lock(&rt_req_lock); + if (rt_signal && !rt_dumper_started) { + pthread_t t; + int err = pthread_create(&t, NULL, dumper_main, NULL); + rt_dumper_started = err == 0; + if (err == 0) + pthread_detach(t); + else + log_warn( + "runtime stats: no snapshot thread (%s), so " + "ELFUSE_STATS_SIGNAL requests are dropped", + strerror(err)); + } + pthread_mutex_unlock(&rt_req_lock); +} + +static void dump_json_to(FILE *out, + const guest_t *g, + const char *reason, + bool final) +{ + uint64_t t = now_ns(); + fprintf(out, "{\"schema\":\"elfuse-runtime-stats/1\",\"reason\":"); + json_string(out, reason); + fprintf(out, ",\"final\":%s,\"pid\":%lld,\"time_ns\":%llu,\"argv\":[", + final ? "true" : "false", (long long) proc_get_pid(), + (unsigned long long) t); + for (int i = 0; i < rt_argc; i++) { + if (i) + fputc(',', out); + json_string(out, rt_argv[i]); + } + fprintf(out, "],\"wall_ns\":%llu,\"shim\":", + (unsigned long long) (t > rt_start_ns ? t - rt_start_ns : 0)); + shim_globals_counters_dump_json(out, g); + fputs(",\"vmexit\":", out); + proc_dump_vcpu_exit_stats_json(out); + fputs(",\"syscalls\":", out); + syscall_hist_dump_json(out, final); + fputc(',', out); + syscall_hist_dump_cost_buckets_json(out); + fputs("}\n", out); +} + +/* Fork children share the parent's stderr, so a record built through stdio + * buffers would interleave with theirs mid-object. Build it in memory and hand + * it to the kernel in one write. + */ +static void dump_json(const guest_t *g, const char *reason, bool final) +{ + char *buf = NULL; + size_t len = 0; + FILE *mem = open_memstream(&buf, &len); + if (!mem) + return; + dump_json_to(mem, g, reason, final); + if (fclose(mem) == 0) { + fflush(stderr); + for (size_t off = 0; off < len;) { + ssize_t n = write(STDERR_FILENO, buf + off, len - off); + if (n <= 0) + break; + off += (size_t) n; + } + } + free(buf); +} + +static void dump_locked(const char *reason, bool final) +{ + const guest_t *g = rt_guest; + if (!g) + return; + + /* JSON is a single object per process, so a snapshot has nowhere to go + * without breaking the stream; JSONL takes one per line. + */ + if (rt_mode == RT_STATS_JSON && !final) + return; + + if (rt_mode == RT_STATS_SUMMARY) { + shim_globals_counters_dump(g); + proc_dump_vcpu_exit_stats(); + if (final) + syscall_hist_dump(); + } else { + dump_json(g, reason, final); + } + fflush(stderr); +} + +void runtime_stats_dump_final(const char *reason) +{ + pthread_mutex_lock(&rt_dump_mutex); + dump_locked(reason, true); + rt_guest = NULL; + rt_argv = NULL; + rt_argc = 0; + pthread_mutex_unlock(&rt_dump_mutex); +} + +void runtime_stats_request_snapshot(void) +{ + /* Dropped until attach has started the dumper, so a signal sent during + * bring-up does not surface later as a snapshot nobody asked for then. + */ + pthread_mutex_lock(&rt_req_lock); + if (rt_dumper_started) { + rt_req_pending = true; + pthread_cond_signal(&rt_req_cond); + } + pthread_mutex_unlock(&rt_req_lock); +} diff --git a/src/debug/runtime-stats.h b/src/debug/runtime-stats.h new file mode 100644 index 000000000..00efe7a9e --- /dev/null +++ b/src/debug/runtime-stats.h @@ -0,0 +1,44 @@ +/* + * Runtime stats coordinator + * + * Copyright 2026 elfuse contributors + * SPDX-License-Identifier: Apache-2.0 + * + * One gate, ELFUSE_RUNTIME_STATS, over the shim counters, the vCPU exit + * accounting, and the steady-state syscall histogram. Modes: summary (stderr + * tables), json (one object per process at exit), jsonl (one object per line, + * at exit and on each snapshot request). ELFUSE_STATS_SIGNAL=USR1 requests a + * snapshot from outside; the preemption sigwait thread receives it and a dumper + * thread writes it, so no handler ever runs on a vCPU thread. + */ + +#pragma once + +#include + +#include "core/guest.h" + +/* Resolve the env gates. Call before proc_preempt_init so the snapshot signal + * joins the blocked set every later thread inherits. + */ +void runtime_stats_init(void); +bool runtime_stats_enabled(void); + +/* The host signal that requests a snapshot, or 0 when none is configured or + * stats are off. + */ +int runtime_stats_signal(void); + +/* Name the guest whose shim counters the dumps read, and the guest argv the + * JSON records carry (none for a fork child). Snapshot requests that arrive + * before this are ignored. Call after proc_preempt_init. + */ +void runtime_stats_attach(const guest_t *g, int argc, const char *const *argv); + +/* Emit the final dump and detach the guest; later requests are no-ops. */ +void runtime_stats_dump_final(const char *reason); + +/* Queue one snapshot. Called from the preemption sigwait thread; never blocks + * on the dump itself. + */ +void runtime_stats_request_snapshot(void); diff --git a/src/debug/syscall-hist.c b/src/debug/syscall-hist.c index 46401bfbb..43fcb0eb3 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. @@ -98,9 +99,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 +126,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) @@ -196,6 +205,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 +235,17 @@ void syscall_hist_disable(void) atomic_store_explicit(&hist_mode, HIST_OFF, memory_order_release); } +bool syscall_hist_steady(void) +{ + syscall_hist_init(); + return hist_steady; +} + +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,11 +271,42 @@ static int hist_row_cmp(const void *a, const void *b) return ra->nr - rb->nr; } -void syscall_hist_dump(void) +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; +} + +/* Take the table for a one-shot dump: stop recording and wait out recorders + * already inside the update window. + * + * Returns false when another dump already took it or recording never started. + */ +static bool hist_take(void) { int mode = atomic_load_explicit(&hist_mode, memory_order_acquire); if (mode == HIST_OFF) - return; + return false; /* One-shot: flip to OFF so a second call (cleanup from forked child after * the parent already dumped, etc) is a clean no-op. @@ -266,7 +320,7 @@ void syscall_hist_dump(void) int prev = atomic_exchange_explicit(&hist_mode, HIST_OFF, memory_order_acq_rel); if (prev == HIST_OFF) - return; + return false; /* Wait for any in-flight recorders to retire. A sibling vCPU that already * incremented hist_active_recorders and observed the prior RECORD mode must @@ -283,31 +337,86 @@ void syscall_hist_dump(void) * the spin terminates as soon as the in-flight recorders retire. */ } + return true; +} + +void syscall_hist_dump_json(FILE *out, bool consume) +{ + /* A snapshot reads the counters live, which can be a few updates behind but + * never torn; only the final dump stops recording first. + */ + bool live = !consume && atomic_load_explicit( + &hist_mode, memory_order_acquire) != HIST_OFF; + if (!live && !(consume && hist_take())) { + fputs("{\"total_count\":0,\"total_ns\":0,\"rows\":[]}", out); + return; + } 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++; + 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); +} - if (nrows == 0) +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}," + "\"path\":{\"open_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) +{ + if (!hist_take()) return; - qsort(rows, (size_t) nrows, sizeof(rows[0]), hist_row_cmp); + uint64_t total_count = 0; + uint64_t total_ns = 0; + hist_row_t rows[HIST_TABLE_SIZE]; + int nrows = hist_snapshot_rows(rows, &total_count, &total_ns); + if (nrows == 0) + return; const char *reason = atomic_load_explicit(&hist_freeze_reason, memory_order_acquire); diff --git a/src/debug/syscall-hist.h b/src/debug/syscall-hist.h index c2bcb5055..f2900fada 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 @@ -20,6 +25,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 @@ -31,7 +37,7 @@ void syscall_hist_init(void); * timestamp. * * Returns false after syscall_hist_freeze() so the recording stops cleanly at - * the first execve. + * the first execve. Steady mode never freezes and stays true until the dump. */ bool syscall_hist_enabled(void); @@ -63,8 +69,15 @@ void syscall_hist_freeze(const char *reason); */ void syscall_hist_disable(void); +/* Whether recording runs until guest exit (syscalls-steady, or + * ELFUSE_RUNTIME_STATS) rather than freezing at the first execve. + */ +bool syscall_hist_steady(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); diff --git a/src/main.c b/src/main.c index 085be995d..46926efef 100644 --- a/src/main.c +++ b/src/main.c @@ -47,6 +47,7 @@ #include "syscall/wakeup-pipe.h" #include "debug/log.h" +#include "debug/runtime-stats.h" #include "debug/syscall-hist.h" extern char **environ; @@ -230,6 +231,7 @@ static int host_dc_zva_assert(void) int main(int argc, char **argv) { log_init(); + runtime_stats_init(); /* Resolve ELFUSE_STARTUP_TRACE before any guest syscall can fire so the * histogram captures the very first dynamic-linker openat. diff --git a/src/runtime/forkipc.c b/src/runtime/forkipc.c index c9eb8ec8c..410fbfa4e 100644 --- a/src/runtime/forkipc.c +++ b/src/runtime/forkipc.c @@ -77,6 +77,7 @@ #include "syscall/wakeup-pipe.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 @@ -127,11 +128,12 @@ 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. A + * steady-state histogram is whole-workload accounting, so the child keeps + * recording its own share and dumps it at exit. */ - syscall_hist_disable(); + if (!syscall_hist_steady()) + syscall_hist_disable(); /* Reset static process/thread/futex state before receiving the parent * snapshot so the incoming metadata survives child restore. @@ -545,6 +547,7 @@ int fork_child_main(int ipc_fd, */ signal_set_state(&sig); + runtime_stats_attach(&g, 0, NULL); log_debug("fork-child: entering vCPU loop"); /* The child resumes from the captured fork frame and returns 0 to EL0. */ @@ -552,6 +555,15 @@ int fork_child_main(int ipc_fd, int exit_code = vcpu_run_loop(vcpu, vexit, &g, verbose, timeout_sec, &wait_status); + /* Before proc_process_exit: once the parent can reap this child, whoever + * reads the stats stream after the parent exits must already find this + * process's record there. + */ + if (runtime_stats_enabled()) + runtime_stats_dump_final("fork-child-exit"); + else + syscall_hist_dump(); + proc_process_exit(wait_status); /* Same reason as the main-process path: this child is where a forked shell @@ -560,7 +572,6 @@ int fork_child_main(int ipc_fd, * the master and is waiting for exactly this hangup. */ proc_pty_release_process_slaves(); - guest_destroy(&g); return exit_code; } diff --git a/src/syscall/internal.h b/src/syscall/internal.h index 0de01ebd9..6105f41be 100644 --- a/src/syscall/internal.h +++ b/src/syscall/internal.h @@ -152,8 +152,8 @@ * overlay_lock (chown-overlay.c) shm_dir_lock (procemu.c) * proc_scratch_lock (procemu.c) shm_lock (sysvipc.c) * removed_overlay_lock (fs.c) syscpu_dir_lock (procemu.c) - * sysinfo_lock (sys.c) - * sysroot_lock (proc-state.c) + * rt_dump_mutex (runtime-stats.c) sysinfo_lock (sys.c) + * rt_req_lock (runtime-stats.c) sysroot_lock (proc-state.c) * usb_lock (runtime/usb-sysfs.c) * usbdev_loop_lock (usbdev.c) * usbdev_fixture_lock (usbdev-fixture.c) diff --git a/src/syscall/proc.c b/src/syscall/proc.c index c127a5433..577e0a02c 100644 --- a/src/syscall/proc.c +++ b/src/syscall/proc.c @@ -57,6 +57,7 @@ #include "debug/crashreport.h" #include "debug/gdbstub.h" +#include "debug/runtime-stats.h" /* Process state. */ @@ -65,6 +66,27 @@ 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 shim_globals_stats_enabled + * (ELFUSE_SHIM_STATS or ELFUSE_RUNTIME_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; a snapshot may read them a few updates + * behind, and the exit dump reads them after the run loop has stopped. + */ +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) @@ -164,6 +186,55 @@ static void proc_notify_reparent(pid_t host_pid, int64_t new_ppid); static int64_t proc_wait_autoreap_children(int pid, int options); +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_init(void) { proc_identity_init(); @@ -3102,11 +3173,21 @@ static void *preempt_thread_main(void *arg) sigemptyset(&wait_set); sigaddset(&wait_set, SIGUSR2); sigaddset(&wait_set, SIGALRM); + int stats_sig = runtime_stats_signal(); + if (stats_sig) + sigaddset(&wait_set, stats_sig); for (;;) { int sig = 0; if (sigwait(&wait_set, &sig) != 0) continue; + if (stats_sig && sig == stats_sig) { + /* A snapshot request touches no guest thread, so nothing is kicked + * out of hv_vcpu_run; the dump itself runs on the stats thread. + */ + runtime_stats_request_snapshot(); + continue; + } if (sig == SIGUSR2) { atomic_store_explicit(&g_external_guest_signal, 1, memory_order_release); @@ -3240,6 +3321,8 @@ int proc_preempt_init(void) sigemptyset(&block); sigaddset(&block, SIGUSR2); sigaddset(&block, SIGALRM); + if (runtime_stats_signal()) + sigaddset(&block, runtime_stats_signal()); /* pthread_sigmask returns the error code directly. If the block fails, vCPU * threads would inherit an unblocked mask and a signal landing mid-run @@ -4664,7 +4747,12 @@ static vcpu_action_t vcpu_handle_canceled_exit(guest_t *g, if (thread_fork_barrier_check()) return VCPU_RESUME; - /* 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 (shim_globals_stats_enabled()) + atomic_fetch_add_explicit(&vcpu_exit_no_signal_cancel, 1, + memory_order_relaxed); if (verbose) log_debug("%s: vCPU canceled (no signal pending)", prefix); return VCPU_RESUME; @@ -4711,6 +4799,12 @@ int vcpu_run_loop_with_hooks(hv_vcpu_t vcpu, const int is_main = (timeout_sec > 0); const char *prefix = is_main ? "elfuse" : "elfuse: worker"; + /* Resolve the exit-stats gate once; with ELFUSE_SHIM_STATS and + * ELFUSE_RUNTIME_STATS both 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 * measurable jank in HVF workloads. @@ -4810,6 +4904,10 @@ int vcpu_run_loop_with_hooks(hv_vcpu_t vcpu, atomic_store_explicit(&g_vcpu_progress, iter * 2 + 2, memory_order_relaxed); + if (stats) + atomic_fetch_add_explicit(&vcpu_exit_total, 1, + memory_order_relaxed); + drain_external_guest_signal(); /* Re-check exit_group after waking from hv_vcpu_run */ @@ -4861,6 +4959,9 @@ int vcpu_run_loop_with_hooks(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 ad4303dae..1f191a999 100644 --- a/src/syscall/proc.h +++ b/src/syscall/proc.h @@ -15,6 +15,8 @@ #pragma once +#include + #include #include #include @@ -623,6 +625,14 @@ 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); + /* vCPU run loop. */ /* Request that the current host thread's HVC #6 run loop returns after the diff --git a/tests/test-runtime-stats.sh b/tests/test-runtime-stats.sh new file mode 100755 index 000000000..83c353b83 --- /dev/null +++ b/tests/test-runtime-stats.sh @@ -0,0 +1,202 @@ +#!/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. +# - a fork child closes its own window with a final record. +# - ELFUSE_STATS_SIGNAL leaves SIGUSR1 alone while stats are off. +# - scripts/runtime-stats-convert.py passes its self-checks. +# - 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 }" + +# The guest shell runs applets by exec, and a busybox built without standalone +# applets resolves "sleep" through PATH to the host's own binary. Name the +# fixture by absolute path so the shell can exec it as itself. +GUEST="$(cd "$(dirname "$GUEST")" && pwd)/$(basename "$GUEST")" + +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 +} + +# Send SIGUSR1 a few times once the guest has printed "ready". A guest that runs +# has been attached, so every request lands; one sent earlier would be dropped, +# or kill elfuse outright before it claims the signal. +signal_when_ready() +{ + local pid="$1" out="$2" + for _ in $(seq 1 100); do + grep -q ready "$out" 2> /dev/null && break + sleep 0.05 + done + for _ in 1 2 3; do + kill -USR1 "$pid" 2> /dev/null || true + sleep 0.1 + done +} + +# 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 +rc=$? +[ "$rc" -eq 0 ] || die "json mode: guest exited $rc" +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" sh -c 'echo ready; exec "$0" sleep 1' "$GUEST" 2> "$err" \ + > "$tmpdir/json-signal.out" & +pid=$! +signal_when_ready "$pid" "$tmpdir/json-signal.out" +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" sh -c 'echo ready; exec "$0" sleep 1' "$GUEST" 2> "$err" \ + > "$tmpdir/jsonl.out" & +pid=$! +signal_when_ready "$pid" "$tmpdir/jsonl.out" +wait "$pid" +rc=$? +e="$(count_objs "$err" exit)" || e=x +s="$(count_objs "$err" signal)" || s=x +if [ "$rc" -eq 0 ] && [ "$e" = "1" ] && [ "$s" -ge 1 ] 2> /dev/null; then + pass "jsonl mode emits one exit record and $s snapshot(s)" +else + die "jsonl mode: rc=$rc exit records=$e snapshots=$s" + cat "$err" +fi + +# Fork children: each process emits its own final record. A backgrounded +# subshell is a fork child; it must close its own window with a final record +# instead of vanishing from the accounting. +err="$tmpdir/jsonl-fork.err" +ELFUSE_RUNTIME_STATS=jsonl "$ELFUSE" "$GUEST" sh -c 'true & wait' \ + 2> "$err" > /dev/null +n="$(count_objs "$err" fork-child-exit)" || n=x +if [ "$n" -ge 1 ] 2> /dev/null; then + pass "fork child emits its own final record" +else + die "fork child: no fork-child-exit record ($n)" + cat "$err" +fi + +# the snapshot signal is claimed only while stats are on With +# ELFUSE_STATS_SIGNAL set but stats off, SIGUSR1 keeps its default action and +# terminates elfuse, as it would any other process. The probe waits for the +# guest so the signal lands after bring-up, where a wrongly claimed SIGUSR1 +# would be swallowed rather than kill the process. +ELFUSE_RUNTIME_STATS=0 ELFUSE_SHIM_STATS=0 ELFUSE_STATS_SIGNAL=USR1 \ + "$ELFUSE" "$GUEST" sh -c 'echo ready; exec "$0" sleep 5' "$GUEST" \ + 2> /dev/null > "$tmpdir/off.out" & +pid=$! +for _ in $(seq 1 100); do + grep -q ready "$tmpdir/off.out" 2> /dev/null && break + sleep 0.05 +done +kill -USR1 "$pid" 2> /dev/null || true +wait "$pid" 2> /dev/null +rc=$? +want=$((128 + $(kill -l USR1))) +if [ "$rc" -eq "$want" ]; then + pass "SIGUSR1 keeps its default action with stats off" +else + die "SIGUSR1 with stats off: expected exit $want, got $rc" +fi + +# converter self-checks +convert="$(dirname "$0")/../scripts/runtime-stats-convert.py" +for fmt in csv folded speedscope perfetto; do + if python3 "$convert" --selftest "$fmt"; then + pass "runtime-stats-convert.py $fmt self-check" + else + die "runtime-stats-convert.py $fmt self-check" + fi +done + +# 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"