diff --git a/Makefile b/Makefile index 482b74e3..b27bbe47 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 651e0a1d..5621c032 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 069972eb..f27266e8 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 00000000..bc26c90a --- /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 41fb93a7..e3b3a587 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 91846235..00c85000 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 08e593a7..fc9daa44 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 00000000..35b91e24 --- /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 00000000..00efe7a9 --- /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 46401bfb..43fcb0eb 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 c2bcb505..f2900fad 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 085be995..46926efe 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 c9eb8ec8..410fbfa4 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 0de01ebd..6105f41b 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 c127a543..577e0a02 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 ad4303da..1f191a99 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 00000000..83c353b8 --- /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"