From 8400b55dc02d3fa787df1280a9fb474901adfcf4 Mon Sep 17 00:00:00 2001 From: Yves Date: Fri, 23 Oct 2026 03:22:42 +0800 Subject: [PATCH 1/3] Add opt-in stereo and XR frame attribution Co-authored-by: Yves --- docs/FRAME_TRACE.md | 72 +++ docs/TCP_COMMANDS.md | 5 +- docs/internal/upstream/vr-frame-tracing.md | 21 + runtime/CMakeLists.txt | 12 + runtime/include/frame_trace.h | 243 ++++++++++ runtime/include/gpu_gl_renderer.h | 3 + runtime/include/mod_plugins.h | 19 + runtime/runtime.cmake | 1 + runtime/src/debug_server.c | 30 ++ runtime/src/frame_trace.c | 494 +++++++++++++++++++++ runtime/src/gpu_gl_renderer.c | 8 + runtime/src/psx_openxr.c | 83 +++- runtime/src/render_pass.c | 145 +++++- runtime/tests/test_frame_trace.c | 340 ++++++++++++++ runtime/tests/test_frame_trace_guard.py | 117 +++++ runtime/tests/test_render_pass_abort.c | 7 + runtime/tests/test_render_pass_sandbox.c | 145 ++++++ 17 files changed, 1738 insertions(+), 7 deletions(-) create mode 100644 docs/FRAME_TRACE.md create mode 100644 docs/internal/upstream/vr-frame-tracing.md create mode 100644 runtime/include/frame_trace.h create mode 100644 runtime/src/frame_trace.c create mode 100644 runtime/tests/test_frame_trace.c create mode 100644 runtime/tests/test_frame_trace_guard.py diff --git a/docs/FRAME_TRACE.md b/docs/FRAME_TRACE.md new file mode 100644 index 00000000..dedf1db2 --- /dev/null +++ b/docs/FRAME_TRACE.md @@ -0,0 +1,72 @@ +# Frame tracing (stereo / OpenXR) + +`runtime/src/frame_trace.c` records one row per traced stereo frame so a visible +VR hitch can be attributed to a stage instead of guessed at. It is the +measurement floor for the VR optimization work: nothing else should be tuned +before there are traces. + +## Enable + + PSX_FRAME_TRACE=1 # off by default; one branch when off + PSX_FRAME_TRACE_CAP=2048 # optional power-of-two ring size (default 2048) + +The ring is static, the record holds fixed-size fields, and the record path +allocates nothing and writes no files (`runtime/tests/test_frame_trace_guard.py` +fails the build if that changes). Instrumentation off vs on is an A/B control. + +## Read + +Over the debug TCP server: + + {"cmd":"frame_trace","format":"json","max":240} + {"cmd":"frame_trace","format":"chrome","max":240} # Perfetto trace-event JSON + +`max` bounds the newest records (0 = all retained). The game-side helper is +`vr/trace_frames.py`, which writes `frame_trace.json`, `frame_trace.csv`, +optional `frame_trace_perfetto.json`, and a `summary.json` with P50/P95/P99 of +`pair_total`, each eye's total, and `xr_wait_frame`, plus stale/shed/failed +counts and the worst frames. + +## Stages (microseconds) + + guest_sim host time between traced frames + pair_total both eyes, pair open -> publish + eye_{begin,guest,end,restore}_{l,r} + one eye's VRAM backup+checkpoint, guest draw, + flush/capture/VRAM restore, machine restore + xr_wait_frame / xr_begin_frame xrWaitFrame / xrBeginFrame + xr_acquire / xr_wait_image / xr_copy / xr_release / xr_end_frame + hud_capture / hud_draw / hud_readback + a HUD capture transaction, its guest draw and + its readback + game_env / game_world / game_text / game_traverse / game_icon / + game_submit / game_laser + the guest scene rebuild one eye replays, split + by the call the game hook makes: draw env and + ordering-table setup, world passes, text, + scene traversal, HUD icon, DrawOTag, and the + hook's own per-eye raycast. PAIR totals (both + eyes write the same slots), so compare them + against eye_guest_l + eye_guest_r. Written by + the hook through + psx_mod_frame_trace_stage_begin/end, which + only accepts them inside a traced stereo eye. + +Per frame: `seq`, `open_ms`, guest frame/cycle, stereo attempt id, published +pair id, `pair_age_ms` (age of the retained whole pair), `source` (1 pair / 2 +native), `eye_failed`, shed skipped/streak, `prims`/`tex_prims` (the last eye's +own count), `prims_l`/`prims_r`, `tex_prims_l`/`tex_prims_r`, +`cycles_l`/`cycles_r` (guest cycles each eye's replay executed, separating +emulated machine work from host submission time), `vram_leaks`, `tex_bytes`, and +flags (`published`, `stale`, `shed`, `failed`, `xr_empty`, `scene`, `io`, +`no_telemetry`). + +## Guarantees + +* `xr_*` stages are CPU wall-clock waits, never GPU execution time. +* Only a complete pair is published; a stale frame retains the previous whole + pair (`pair_age_ms` says how old it is). +* A frame is `stale` when it published nothing, `shed` when the pair was skipped + on purpose, `failed` when a pair was attempted and lost, and + `no_telemetry` when an expected-to-be-instrumented frame recorded no stage. +* Timestamps are monotonic even if the host clock steps backwards. diff --git a/docs/TCP_COMMANDS.md b/docs/TCP_COMMANDS.md index 0d11ca8c..bece7d73 100644 --- a/docs/TCP_COMMANDS.md +++ b/docs/TCP_COMMANDS.md @@ -493,9 +493,9 @@ between Play and TCP availability. ## Complete command index (generated) -**383 commands registered** — 370 on the native server (`runtime/src/debug_server.c`), 61 on the Beetle server (`runtime/src/beetle_debug_server.c`). +**384 commands registered** — 371 on the native server (`runtime/src/debug_server.c`), 61 on the Beetle server (`runtime/src/beetle_debug_server.c`). -85 of 383 have prose above; **298 are index-only**. An index-only command still works — it just has no description here yet. Send it `{"cmd":""}` and read the reply, or find its `handle_*` function in the server source. +85 of 384 have prose above; **299 are index-only**. An index-only command still works — it just has no description here yet. Send it `{"cmd":""}` and read the reply, or find its `handle_*` function in the server source. Regenerate with `python tools/gen_tcp_commands.py`; `--check` fails if this block has drifted from the code. @@ -627,6 +627,7 @@ Regenerate with `python tools/gen_tcp_commands.py`; `--check` fails if this bloc | `frame_perf` | ✓ | | | | `frame_range` | ✓ | ✓ | ✓ | | `frame_timeseries` | ✓ | ✓ | ✓ | +| `frame_trace` | ✓ | | | | `frame_wall_ring` | ✓ | | | | `freeze_check` | ✓ | | | | `game_options` | ✓ | | | diff --git a/docs/internal/upstream/vr-frame-tracing.md b/docs/internal/upstream/vr-frame-tracing.md new file mode 100644 index 00000000..db6e69c6 --- /dev/null +++ b/docs/internal/upstream/vr-frame-tracing.md @@ -0,0 +1,21 @@ +# VR frame tracing: source and validation + +Adapted from [FractalEngineer/psxrecomp](https://github.com/FractalEngineer/psxrecomp): +- [022eb1ed](https://github.com/FractalEngineer/psxrecomp/commit/022eb1edb2d6b2d9d505641e198bd9aeb5eb8ce1) +- [0e0d2de8](https://github.com/FractalEngineer/psxrecomp/commit/0e0d2de82777857248ae6c1bf7e9b7cba05e3d0a) +- [5c67dced](https://github.com/FractalEngineer/psxrecomp/commit/5c67dced708a67e905b77be455263009f566d4bb) +- [63271ce7](https://github.com/FractalEngineer/psxrecomp/commit/63271ce7b4e2fb5f616050e7d59a2e4642a33b55) +- [571a8f10](https://github.com/FractalEngineer/psxrecomp/commit/571a8f1082dbbc95af19e90ce0226a0cb40f302d) +- [87a3e822](https://github.com/FractalEngineer/psxrecomp/commit/87a3e8223cf7c05761326bfce06e80ffc527e132) + +Original author: Yves ; retained as commit author +and Co-authored-by on this reconstructed port. + +Adapted: opt-in trace ring, XR cadence, HUD timing, nested replay attribution, +exports and tests. Excluded: shedding policy, checkpoint reuse, game hooks and +chronological research. Rebuilt on upstream master `9caf4c22`. + +Validation: Windows/GCC 13.2 Release: trace, source guard, sandbox, abort and +XR-off input tests pass (5/5); command index is current. XR-on integration is +checked separately after assembling the feature branches. +Consumer: [Medal of Honor v0.1.6](https://github.com/FractalEngineer/Medal-Of-Honor-PSX-Recomp/tree/1957e28a5dc7f5daa79e2b9b6ed867eb06b41ace); pin bump and rebuild, no regeneration. diff --git a/runtime/CMakeLists.txt b/runtime/CMakeLists.txt index f1c45888..833731f5 100644 --- a/runtime/CMakeLists.txt +++ b/runtime/CMakeLists.txt @@ -1629,6 +1629,11 @@ if(BUILD_TESTING) add_test(NAME present_sync_test COMMAND present_sync_test) target_include_directories(frame_pacing_test PRIVATE include) add_test(NAME frame_pacing_test COMMAND frame_pacing_test) + # Opt-in stereo/OpenXR frame-trace ring (frame_trace.c): disabled-by-default, + # ring wrap, timestamp monotonicity, missing telemetry, export validity. + add_executable(frame_trace_test tests/test_frame_trace.c src/frame_trace.c) + target_include_directories(frame_trace_test PRIVATE include) + add_test(NAME frame_trace_test COMMAND frame_trace_test) # Render thread core ([video] render_thread, docs/RENDER_THREAD.md): # ordering across ring wraps, the frame bound, stale-frame detection and # the drain + context hand-off sync point, against a fake executor. @@ -1774,6 +1779,7 @@ if(BUILD_TESTING) add_executable(render_pass_abort_test tests/test_render_pass_abort.c src/render_pass.c + src/frame_trace.c src/psx_cycles.c) target_include_directories(render_pass_abort_test PRIVATE include) add_test(NAME render_pass_abort_test COMMAND render_pass_abort_test) @@ -1785,6 +1791,7 @@ if(BUILD_TESTING) add_executable(render_pass_sandbox_test tests/test_render_pass_sandbox.c src/render_pass.c + src/frame_trace.c src/render_pass_plan.c src/psx_cycles.c src/timers.c @@ -2042,6 +2049,11 @@ if(BUILD_TESTING) COMMAND ${Python3_EXECUTABLE} ${CMAKE_CURRENT_SOURCE_DIR}/tests/test_memory_debug_trace_guard.py --cc ${CMAKE_C_COMPILER}) + # The frame-trace record path must stay allocation- and IO-free, or + # it perturbs the frame it measures and no functional test notices. + add_test(NAME frame_trace_guard_test + COMMAND ${Python3_EXECUTABLE} + ${CMAKE_CURRENT_SOURCE_DIR}/tests/test_frame_trace_guard.py) endif() add_test(NAME fntrace_c_linkage_test COMMAND ${Python3_EXECUTABLE} ${CMAKE_CURRENT_SOURCE_DIR}/tests/test_fntrace_c_linkage.py) add_test(NAME depth24_present_hold_vblank_test diff --git a/runtime/include/frame_trace.h b/runtime/include/frame_trace.h new file mode 100644 index 00000000..7edd64c2 --- /dev/null +++ b/runtime/include/frame_trace.h @@ -0,0 +1,243 @@ +#ifndef PSX_FRAME_TRACE_H +#define PSX_FRAME_TRACE_H + +/* Opt-in, fixed-capacity frame-time tracing for the stereo/OpenXR path. + * + * WHY THIS EXISTS + * --------------- + * VR stutter reports ("it hitches when enemies spawn", "fast head turns judder", + * "one heavy frame causes a run of stutters") could not be attributed. The + * renderer already smoothed a few averages, but only for a handful of stages, + * they were never reset, and there was no per-frame history to correlate a + * visible hitch with. This module is the measurement floor the VR optimization + * program is built on: one record per stereo frame, monotonic, allocation-free + * on the hot path, exported only on demand. + * + * DESIGN CONTRACT + * --------------- + * * DISABLED BY DEFAULT (PSX_FRAME_TRACE=0). Every entry point returns + * immediately while disabled, so an instrumented build costs one branch. + * * NO per-frame heap allocation and NO file I/O on the record path. The ring + * is static; the record holds fixed-size fields only. Export writes into a + * caller buffer, outside the frame. + * * Stages are supplied by the caller in MICROSECONDS, measured with whatever + * host clock it already uses. The module never reads a clock for durations, + * only for the record's open timestamp, through one injectable function + * pointer. That keeps the module dependency-free and unit-testable. + * * CPU submission time is NOT GPU execution time. Stages named "xr_*" are + * wall-clock waits; nothing here claims GPU completion. + * * Emulation/main thread only, like the OpenXR lifecycle it observes. + */ + +#include + +#ifdef __cplusplus +extern "C" { +#endif + +/* Per-frame stages, in the order one stereo frame produces them. The header + * order IS the ABI; keep frame_trace.c's name table in sync. */ +enum { + PSX_TRACE_GUEST_SIM = 0, /* guest work outside the stereo pair */ + PSX_TRACE_PAIR_TOTAL, /* both eyes, pair open to publish */ + PSX_TRACE_EYE_BEGIN_L, /* VRAM backup + checkpoint */ + PSX_TRACE_EYE_GUEST_L, /* the plugin's guest draw */ + PSX_TRACE_EYE_END_L, /* GPU flush, capture, VRAM restore */ + PSX_TRACE_EYE_RESTORE_L, /* machine state restore */ + PSX_TRACE_EYE_BEGIN_R, + PSX_TRACE_EYE_GUEST_R, + PSX_TRACE_EYE_END_R, + PSX_TRACE_EYE_RESTORE_R, + PSX_TRACE_XR_WAIT_FRAME, /* xrWaitFrame */ + PSX_TRACE_XR_BEGIN_FRAME, /* xrBeginFrame */ + PSX_TRACE_XR_ACQUIRE, /* swapchain acquire (both eyes) */ + PSX_TRACE_XR_WAIT_IMAGE, /* xrWaitSwapchainImage (both eyes) */ + PSX_TRACE_XR_COPY, /* eye blit into the runtime image */ + PSX_TRACE_XR_RELEASE, /* swapchain release (both eyes) */ + PSX_TRACE_XR_END_FRAME, /* xrEndFrame */ + /* How old the submitted pose was: xrLocateViews return to xrEndFrame + * return. This is the pose the compositor reprojects from, so it bounds + * the correction a head turn can need. */ + PSX_TRACE_POSE_AGE, + /* Host time a HUD capture transaction costs (psx_mod_render_capture_rgba). + * The wrist HUD captures the same guest slice twice per frame, once per + * matte colour, and both are full render transactions on the frame's own + * thread, so this is frame time the pair stats never showed. */ + PSX_TRACE_HUD_CAPTURE, + /* The capture's two halves, so the cost can be aimed at: the transaction is + * the checkpoint plus the guest HUD draw plus its verify, the readback is + * the blit out of the pair target and the synchronous glReadPixels. */ + PSX_TRACE_HUD_DRAW, + PSX_TRACE_HUD_READBACK, + /* The guest scene rebuild one eye replays, split by the call the game hook + * makes, so a hitch can be aimed at the guest call that grew instead of at + * the whole eye. These are PAIR totals: both eyes write the same slots. + * Written by the hook through psx_mod_frame_trace_stage_begin/end, which + * only accepts them inside a traced stereo eye. + * game_env draw environment, GP0 clear, ordering-table setup + * game_world the world/level passes + * game_text the generic text renderer + * game_traverse scene traversal: level groups and entities + * game_icon the HUD icon + * game_submit DrawOTag: walks the ordering table and submits it + * game_laser the hook's own per-eye raycast and line (host work) + * game_select the hook's own level visibility override (the LVTX + * entry filter): the eye-view AABB test and the leaf + * queue it writes. It runs INSIDE the guest traversal, + * and game_traverse is that call's wall time, so the + * guest's own traversal work is game_traverse minus + * game_select. Per eye and summed over the pair like the + * rest, and the only one that nests. */ + PSX_TRACE_GAME_ENV, + PSX_TRACE_GAME_WORLD, + PSX_TRACE_GAME_TEXT, + PSX_TRACE_GAME_TRAVERSE, + PSX_TRACE_GAME_ICON, + PSX_TRACE_GAME_SUBMIT, + PSX_TRACE_GAME_LASER, + PSX_TRACE_GAME_SELECT, + PSX_TRACE_STAGE_COUNT +}; + +/* Record flags. A hitch is the interesting case, so absent conditions are + * explicit: a stale frame is one that published no new pair. */ +enum { + PSX_FRAME_TRACE_STEREO_PUBLISHED = 1u << 0, + PSX_FRAME_TRACE_STALE_PAIR = 1u << 1, + PSX_FRAME_TRACE_SHED = 1u << 2, + PSX_FRAME_TRACE_FAILED = 1u << 3, + PSX_FRAME_TRACE_XR_EMPTY = 1u << 4, + PSX_FRAME_TRACE_SCENE_TRANSITION = 1u << 5, + PSX_FRAME_TRACE_IO_EVENT = 1u << 6, + PSX_FRAME_TRACE_NO_TELEMETRY = 1u << 7, + /* A stereo eye rendered from the pair's shared baseline instead of taking + * its own machine snapshot (see PR3's pair-scoped checkpoint reuse). */ + PSX_FRAME_TRACE_BASELINE_REUSED = 1u << 8, + /* The XR frame carried no new pair, so the retained one was submitted (or + * nothing was, when resubmission is off). */ + PSX_FRAME_TRACE_XR_REPEAT = 1u << 9 +}; + +enum { + PSX_FRAME_TRACE_NOTE = 24, /* scene / IO tag */ + PSX_FRAME_TRACE_REASON = 24 /* failure reason text */ +}; + +typedef struct PSXFrameTraceRecord { + uint64_t seq; /* monotonic record id (starts at 1) */ + uint64_t open_ms; /* host monotonic ms at open */ + uint64_t guest_frame; /* guest frame counter, 0 if unknown */ + uint64_t guest_cycle; /* guest cycle at open */ + uint64_t stereo_attempt; /* stereo attempt id (0 if none) */ + uint64_t pair_id; /* published pair id (0 if none) */ + uint64_t pair_age_ms; /* ms since the last published pair (0 if none) */ + uint32_t stages_us[PSX_TRACE_STAGE_COUNT]; + uint32_t shed_skipped; /* pair attempts shed immediately before this frame */ + uint32_t shed_streak_ms; /* how long that shed streak had lasted */ + uint32_t prims; /* guest draw primitives (0 = not measured) */ + uint32_t textured_prims; /* of which textured */ + /* The same two counters per eye. `prims`/`textured_prims` above keep their + * meaning (the last eye of the pair wrote them); a change to what ONE eye + * selects needs these, because the pair's total hides which eye moved. */ + uint32_t prims_l, prims_r; + uint32_t tex_prims_l, tex_prims_r; + /* Guest cycles each eye's replay executed, the machine work the eye cost in + * the emulated CPU rather than in host submission. 0 = not measured. */ + uint32_t eye_cycles_l, eye_cycles_r; + uint32_t vram_leaks; /* GPU writes outside the pass rect this eye */ + uint64_t tex_upload_bytes; /* texture bytes uploaded (0 = not measured) */ + /* Microseconds between this submission's XrFrameState.predictedDisplayTime + * and the previous one, from the runtime's clock. Divided by the session's + * target_period_us this is how many granted display periods one presented + * pair consumed, which is the cadence the compositor actually saw. 0 on the + * first submission of a session or when there was no frame this record. */ + uint32_t xr_display_delta_us; + uint32_t flags; /* PSX_FRAME_TRACE_* */ + int32_t eye_failed; /* last eye that failed, -1 if none */ + uint8_t source; /* 1 = stereo pair, 2 = native render */ + uint8_t xr_submit_fresh; /* 1 = carried a new pair, 0 = repeat/none */ + uint8_t reserved[2]; + char note[PSX_FRAME_TRACE_NOTE]; + char failure[PSX_FRAME_TRACE_REASON]; +} PSXFrameTraceRecord; + +/* Injectable monotonic millisecond clock. NULL (the default) records 0; the + * runtime installs psx_host_mono_ms(). Tests install a fake. */ +typedef uint64_t (*PSXFrameTraceClock)(void); +void psx_frame_trace_set_clock(PSXFrameTraceClock fn); + +/* Enables/disables capture. Disabling keeps the ring (read it, then reset). + * Reads PSX_FRAME_TRACE / PSX_FRAME_TRACE_CAP once. */ +void psx_frame_trace_configure_from_env(void); +void psx_frame_trace_set_enabled(int on); +int psx_frame_trace_enabled(void); + +/* Clears the ring, counters and any open record. */ +void psx_frame_trace_reset(void); + +/* Opens a record for the frame that is starting. Returns 1 if this call opened + * it, 0 if capture is off or a record is already open (the caller must then NOT + * commit). Cost is a branch while disabled. */ +int psx_frame_trace_open(void); +/* Commits the open record, stamping pair age from the last published pair. + * No-op when nothing is open. */ +void psx_frame_trace_commit(void); + +/* Adds `us` microseconds to `stage` of the open record. Ignores unknown stages; + * saturates instead of wrapping. Cheap while closed. */ +void psx_frame_trace_add(uint32_t stage, uint64_t us); + +/* Per-frame annotations (open record). Each is a no-op when closed. */ +void psx_frame_trace_ids(uint64_t guest_frame, uint64_t guest_cycle); +void psx_frame_trace_attempt(uint64_t attempt_id, uint32_t shed_skipped, + uint32_t shed_streak_ms); +void psx_frame_trace_result(int published, uint64_t pair_id, int eye_failed, + const char *failure); +void psx_frame_trace_source(uint8_t source); +/* Draw counters for `eye` (PSX_MOD_EYE_LEFT/0 or RIGHT/1). Also fills `prims` + * and `textured_prims`, which therefore remain the last eye's values. */ +void psx_frame_trace_draw(int eye, uint32_t prims, uint32_t textured); +/* Guest cycles one eye's replay executed (the transaction's own delta). */ +void psx_frame_trace_eye_cycles(int eye, uint32_t cycles); +void psx_frame_trace_gpu(uint64_t tex_upload_bytes, uint32_t vram_leaks); +/* XR cadence annotation (open record): the runtime's predicted-display-time + * delta for this submission and whether it carried a newly rendered pair. A + * repeat also sets PSX_FRAME_TRACE_XR_REPEAT. No-op when closed. */ +void psx_frame_trace_xr_cadence(uint32_t display_delta_us, int submit_fresh); +void psx_frame_trace_flag(uint32_t flag); +void psx_frame_trace_note(const char *tag); +void psx_frame_trace_io(const char *tag); /* note + IO_EVENT flag */ + +/* Session-level metadata, emitted once in the export header rather than per + * record: the OpenXR runtime actually in use and the target display period in + * microseconds (0 = unknown, e.g. no headset). Without these a trace cannot be + * interpreted later, because the same pair time is over budget at 90 Hz and + * comfortably under it at 60 Hz. Change-checked internally, so calling it every + * frame is a strcmp; it is a no-op while capture is off. */ +void psx_frame_trace_session(const char *runtime, uint32_t target_period_us); + +/* Queries. `capacity` is the caller's array length; returns how many records + * were written (oldest first, at most the newest `capacity`). */ +uint32_t psx_frame_trace_read(PSXFrameTraceRecord *out, uint32_t capacity); +uint32_t psx_frame_trace_capacity(void); +uint64_t psx_frame_trace_committed(void); /* records committed since reset */ +uint64_t psx_frame_trace_dropped(void); /* records overwritten (ring wrap) */ +uint64_t psx_frame_trace_missing(void); /* commits with no stage at all */ + +/* Exports. Each returns the number of bytes the full text needs (like + * snprintf); the buffer is always NUL-terminated when cap > 0. `max_records` + * (0 = all retained) bounds the newest records emitted. */ +int psx_frame_trace_to_json(char *buf, int cap, uint32_t max_records); +int psx_frame_trace_to_csv(char *buf, int cap, uint32_t max_records); +/* Chrome trace-event JSON (Perfetto compatible): one span per stage. */ +int psx_frame_trace_to_chrome_json(char *buf, int cap, uint32_t max_records); + +const char *psx_frame_trace_stage_name(uint32_t stage); +/* Renders the set bits as "a|b|c" into buf; always NUL-terminated. */ +const char *psx_frame_trace_flag_names(uint32_t flags, char *buf, int cap); + +#ifdef __cplusplus +} +#endif + +#endif /* PSX_FRAME_TRACE_H */ diff --git a/runtime/include/gpu_gl_renderer.h b/runtime/include/gpu_gl_renderer.h index 4a27bdb2..cca2306b 100644 --- a/runtime/include/gpu_gl_renderer.h +++ b/runtime/include/gpu_gl_renderer.h @@ -164,6 +164,9 @@ void gl_renderer_interpolation_diag(int *enabled, int *suspended, /* Cumulative CPU-upload diagnostics: calls, rects, pixels, conversion ticks, * texture-upload ticks, FBO-draw ticks. Active only with PSX_RUNTIME_PERF_DIAG. */ void gl_renderer_runtime_diag(uint64_t out[6]); +/* Cumulative scene primitive counters (pre double-draw): all submitted, and of + * those textured. Callers take deltas; the counters are never reset here. */ +void gl_renderer_scene_prim_counts(uint64_t *prims, uint64_t *textured); /* Present an ARGB8888 image (BGRA byte order) as a letterboxed quad + swap. * Used for 24-bit (FMV) frames and the PSX_GL_FORCE_CPU_PRESENT diagnostic. diff --git a/runtime/include/mod_plugins.h b/runtime/include/mod_plugins.h index 1038cd8e..bf458abc 100644 --- a/runtime/include/mod_plugins.h +++ b/runtime/include/mod_plugins.h @@ -733,6 +733,25 @@ typedef int (*PSXModStereoFn)(struct CPUState*, void*, uint32_t eye); int psx_mod_render_stereo(struct CPUState *cpu, const PSXModStereoFrame *frame, PSXModStereoFn fn, void *user); uint32_t psx_mod_render_stereo_status(void); +/* Annotate the current frame's trace record with a short tag (scene transition, + * state change). Only meaningful while PSX_FRAME_TRACE is on and a traced frame + * is open (a headset frame, opened by psx_mod_openxr_begin); a no-op otherwise. */ +void psx_mod_frame_trace_note(const char *tag); +/* Bracket one guest call of a stereo eye's replay with a frame-trace sub-stage, + * so a hitch can be aimed at the call that grew instead of at the whole eye + * (the PSX_TRACE_GAME_* stages in frame_trace.h). The runtime does the timing, + * with the same clock and conversion as the eye's own stages, so the parts sum + * against eye_guest. A no-op unless PSX_FRAME_TRACE is on AND the call is made + * inside a traced stereo eye: a HUD capture's guest draws, the flat path and + * anything outside the eye's callback are ignored. A begin without a matching + * end (or an eye aborted mid-entry) contributes nothing; the unmeasured time + * stays visible as the difference between eye_guest and the sub-stages. + * Spans may nest: each stage keeps its own start tick, so a stage bracketed + * inside another is timed on its own and reports a subset of the outer span's + * wall time rather than a sibling of it. The hook's visibility override nests + * inside the guest traversal it is part of (game_select in game_traverse). */ +void psx_mod_frame_trace_stage_begin(uint32_t stage); +void psx_mod_frame_trace_stage_end(uint32_t stage); /* 0 disables stereo output; 1 shows a complete pair side by side. Capture * itself does not enable presentation. Default 0; applies to this session. */ int psx_mod_set_stereo_presentation(uint32_t mode); diff --git a/runtime/runtime.cmake b/runtime/runtime.cmake index 3879f5f4..1236eea2 100644 --- a/runtime/runtime.cmake +++ b/runtime/runtime.cmake @@ -486,6 +486,7 @@ set(PSXRECOMP_RUNTIME_SOURCES ${PSXRECOMP_ROOT}/runtime/src/starvation_ring.c ${PSXRECOMP_ROOT}/runtime/src/guest_cycle_profile.c ${PSXRECOMP_ROOT}/runtime/src/latency_ring.c + ${PSXRECOMP_ROOT}/runtime/src/frame_trace.c ${PSXRECOMP_ROOT}/runtime/src/present_image_ring.c ${PSXRECOMP_ROOT}/runtime/src/gpu_timeline.c ${PSXRECOMP_ROOT}/runtime/src/data_shards.c diff --git a/runtime/src/debug_server.c b/runtime/src/debug_server.c index af45cb55..341dee89 100644 --- a/runtime/src/debug_server.c +++ b/runtime/src/debug_server.c @@ -66,6 +66,7 @@ #include "crash_trace.h" #include "gpu_gl_renderer.h" #include "render_pass.h" +#include "frame_trace.h" #include "mod_plugins.h" /* psx_mod_render_pass_status */ #include "lockstep.h" #include "guest_tty.h" @@ -9332,6 +9333,34 @@ static void handle_render_pass_dump(int id, const char *json) send_fmt("{\"id\":%d,\"ok\":true,\"count\":%d}", id, count); } +/* frame_trace [format=json|chrome] [max=]: the opt-in stereo/OpenXR frame + * trace (frame_trace.c). Capturing requires PSX_FRAME_TRACE=1 at launch; this + * command only reads the ring and never runs in the frame path. `max` bounds the + * newest records returned (default 240). Both formats are JSON objects, so the + * reply embeds the export verbatim. */ +static void handle_frame_trace(int id, const char *json) { + char format[16] = "json"; + int max = json_get_int(json, "max", 240); + (void)json_get_str(json, "format", format, sizeof format); + if (max < 0) max = 0; + int chrome = strcmp(format, "chrome") == 0; + int need = chrome ? psx_frame_trace_to_chrome_json(NULL, 0, (uint32_t)max) + : psx_frame_trace_to_json(NULL, 0, (uint32_t)max); + if (need <= 0) { send_err(id, "frame trace export failed"); return; } + char *buf = (char *)malloc((size_t)need + 1); + if (!buf) { send_err(id, "out of memory"); return; } + if (chrome) (void)psx_frame_trace_to_chrome_json(buf, need + 1, (uint32_t)max); + else (void)psx_frame_trace_to_json(buf, need + 1, (uint32_t)max); + send_fmt("{\"id\":%d,\"ok\":true,\"enabled\":%d,\"capacity\":%u," + "\"count\":%llu,\"dropped\":%llu,\"missing\":%llu," + "\"format\":\"%s\",\"max\":%d,\"trace\":%s}", + id, psx_frame_trace_enabled(), psx_frame_trace_capacity(), + (unsigned long long)psx_frame_trace_committed(), + (unsigned long long)psx_frame_trace_dropped(), + (unsigned long long)psx_frame_trace_missing(), format, max, buf); + free(buf); +} + /* gl_wide_fast on=<0|1>: native-wide centre-blit fast path. 1 (default) = skip * the redundant centre mirror and copy the canonical 4:3 frame into the wide * surface centre at present (fast). 0 = re-rasterize the whole wide surface @@ -16255,6 +16284,7 @@ static const CmdEntry s_commands[] = { { "openxr_hands_override", handle_openxr_hands_override }, #endif { "stereo_stats", handle_stereo_stats }, + { "frame_trace", handle_frame_trace }, { "stereo_dump", handle_stereo_dump }, { "render_pass_dump", handle_render_pass_dump }, { "render_pass_refuse", handle_render_pass_refuse }, diff --git a/runtime/src/frame_trace.c b/runtime/src/frame_trace.c new file mode 100644 index 00000000..7dba7663 --- /dev/null +++ b/runtime/src/frame_trace.c @@ -0,0 +1,494 @@ +/* frame_trace.c — opt-in per-frame stereo/OpenXR timing ring. See frame_trace.h. + * + * Emulation/main thread only. The record path allocates nothing and writes no + * files; export functions fill a caller buffer and are called outside the frame. + */ + +#include "frame_trace.h" + +#include +#include +#include +#include + +/* Compile-time ring bound. The live capacity is a power of two <= this, chosen + * by PSX_FRAME_TRACE_CAP (default 2048, ~34 s of 60 Hz or ~68 s of 30 Hz pairs). + * Static, so enabling the trace never adds an allocation to the frame path. */ +#define PSX_FRAME_TRACE_MAX 4096 +#define PSX_FRAME_TRACE_DEFAULT 2048 + +static PSXFrameTraceRecord s_ring[PSX_FRAME_TRACE_MAX]; + +static int s_configured; +static int s_enabled; +static uint32_t s_cap = PSX_FRAME_TRACE_DEFAULT; + +static uint64_t s_opened; /* records opened since reset (== newest seq) */ +static uint64_t s_committed; /* records committed since reset */ +static uint64_t s_missing; /* commits that carried no stage at all */ +static uint64_t s_mono_high; /* last timestamp handed out (monotonic floor) */ + +static int s_have_open; +static int s_have_publish; +static uint64_t s_last_publish_ms; + +/* Session metadata (see psx_frame_trace_session). */ +static char s_runtime[128]; +static uint32_t s_target_period_us; + +static PSXFrameTraceClock s_clock; + +static const char *const s_stage_names[PSX_TRACE_STAGE_COUNT] = { + "guest_sim", "pair_total", + "eye_begin_l", "eye_guest_l", "eye_end_l", "eye_restore_l", + "eye_begin_r", "eye_guest_r", "eye_end_r", "eye_restore_r", + "xr_wait_frame", "xr_begin_frame", "xr_acquire", "xr_wait_image", + "xr_copy", "xr_release", "xr_end_frame", "pose_age", "hud_capture", + "hud_draw", "hud_readback", + "game_env", "game_world", "game_text", "game_traverse", "game_icon", + "game_submit", "game_laser", "game_select" +}; + +static const struct { uint32_t bit; const char *name; } s_flag_names[] = { + { PSX_FRAME_TRACE_STEREO_PUBLISHED, "published" }, + { PSX_FRAME_TRACE_STALE_PAIR, "stale" }, + { PSX_FRAME_TRACE_SHED, "shed" }, + { PSX_FRAME_TRACE_FAILED, "failed" }, + { PSX_FRAME_TRACE_XR_EMPTY, "xr_empty" }, + { PSX_FRAME_TRACE_SCENE_TRANSITION, "scene" }, + { PSX_FRAME_TRACE_IO_EVENT, "io" }, + { PSX_FRAME_TRACE_NO_TELEMETRY, "no_telemetry" }, + { PSX_FRAME_TRACE_BASELINE_REUSED, "baseline_reused" }, + { PSX_FRAME_TRACE_XR_REPEAT, "xr_repeat" } +}; + +const char *psx_frame_trace_stage_name(uint32_t stage) { + return stage < PSX_TRACE_STAGE_COUNT ? s_stage_names[stage] : "?"; +} + +const char *psx_frame_trace_flag_names(uint32_t flags, char *buf, int cap) { + int off = 0; + if (!buf || cap <= 0) return ""; + buf[0] = '\0'; + for (size_t i = 0; i < sizeof s_flag_names / sizeof s_flag_names[0]; ++i) { + if (!(flags & s_flag_names[i].bit)) continue; + off += snprintf(buf + off, (size_t)(cap - off), "%s%s", + off ? "|" : "", s_flag_names[i].name); + if (off >= cap) break; + } + return buf; +} + +static uint32_t next_pow2(uint32_t v) { + uint32_t p = 1; + while (p < v && p < PSX_FRAME_TRACE_MAX) p <<= 1; + return p; +} + +static void configure_from_env(void) { + const char *e = getenv("PSX_FRAME_TRACE"); + s_enabled = (e && e[0] && e[0] != '0') ? 1 : 0; + e = getenv("PSX_FRAME_TRACE_CAP"); + if (e && e[0]) { + long v = strtol(e, NULL, 0); + if (v >= 64) s_cap = next_pow2((uint32_t)v); + } +} + +static void ensure_configured(void) { + if (!s_configured) { + s_configured = 1; + configure_from_env(); + } +} + +void psx_frame_trace_configure_from_env(void) { + s_configured = 1; + configure_from_env(); +} + +void psx_frame_trace_set_clock(PSXFrameTraceClock fn) { s_clock = fn; } + +void psx_frame_trace_set_enabled(int on) { + ensure_configured(); + s_enabled = on ? 1 : 0; +} + +int psx_frame_trace_enabled(void) { + ensure_configured(); + return s_enabled; +} + +void psx_frame_trace_reset(void) { + memset(s_ring, 0, sizeof s_ring); + s_opened = s_committed = s_missing = s_mono_high = 0; + s_have_open = s_have_publish = 0; + s_last_publish_ms = 0; + s_runtime[0] = '\0'; + s_target_period_us = 0; +} + +static PSXFrameTraceRecord *open_record(void) { + return &s_ring[(s_opened - 1u) & (uint64_t)(s_cap - 1u)]; +} + +static uint64_t stamp_now(void) { + uint64_t now = s_clock ? s_clock() : 0; + /* Monotonic floor: a coarse or throttled clock must never make a later + * record look older than the one before it. */ + if (now < s_mono_high) now = s_mono_high; + s_mono_high = now; + return now; +} + +int psx_frame_trace_open(void) { + ensure_configured(); + if (!s_enabled || s_have_open) return 0; + uint64_t seq = s_opened + 1u; + PSXFrameTraceRecord *r = &s_ring[(seq - 1u) & (uint64_t)(s_cap - 1u)]; + memset(r, 0, sizeof *r); + r->seq = seq; + r->eye_failed = -1; + r->open_ms = stamp_now(); + s_opened = seq; + s_have_open = 1; + return 1; +} + +void psx_frame_trace_add(uint32_t stage, uint64_t us) { + if (!s_have_open || stage >= PSX_TRACE_STAGE_COUNT) return; + PSXFrameTraceRecord *r = open_record(); + uint64_t v = (uint64_t)r->stages_us[stage] + us; + r->stages_us[stage] = v > 0xFFFFFFFFu ? 0xFFFFFFFFu : (uint32_t)v; +} + +void psx_frame_trace_ids(uint64_t guest_frame, uint64_t guest_cycle) { + if (!s_have_open) return; + PSXFrameTraceRecord *r = open_record(); + r->guest_frame = guest_frame; + r->guest_cycle = guest_cycle; +} + +void psx_frame_trace_attempt(uint64_t attempt_id, uint32_t shed_skipped, + uint32_t shed_streak_ms) { + if (!s_have_open) return; + PSXFrameTraceRecord *r = open_record(); + r->stereo_attempt = attempt_id; + r->shed_skipped = shed_skipped; + r->shed_streak_ms = shed_streak_ms; + if (shed_skipped) r->flags |= PSX_FRAME_TRACE_SHED; +} + +void psx_frame_trace_result(int published, uint64_t pair_id, int eye_failed, + const char *failure) { + if (!s_have_open) return; + PSXFrameTraceRecord *r = open_record(); + r->pair_id = pair_id; + r->eye_failed = eye_failed < 0 ? -1 : eye_failed; + if (published) { + r->flags |= PSX_FRAME_TRACE_STEREO_PUBLISHED; + r->source = 1; + return; + } + r->flags |= PSX_FRAME_TRACE_STALE_PAIR; + if (failure && failure[0]) { + r->flags |= PSX_FRAME_TRACE_FAILED; + snprintf(r->failure, sizeof r->failure, "%s", failure); + } +} + +void psx_frame_trace_source(uint8_t source) { + if (!s_have_open) return; + PSXFrameTraceRecord *r = open_record(); + /* First writer wins: a published stereo pair must not be relabelled + * "native" by a later end-of-frame annotation. */ + if (!r->source) r->source = source; +} + +void psx_frame_trace_draw(int eye, uint32_t prims, uint32_t textured) { + if (!s_have_open || eye < 0 || eye > 1) return; + PSXFrameTraceRecord *r = open_record(); + /* Per-eye fields first: `prims`/`textured_prims` are the legacy pair-level + * view of the same counter and stay the last eye's values, as before. */ + if (eye == 0) { r->prims_l = prims; r->tex_prims_l = textured; } + else { r->prims_r = prims; r->tex_prims_r = textured; } + r->prims = prims; + r->textured_prims = textured; +} + +void psx_frame_trace_eye_cycles(int eye, uint32_t cycles) { + if (!s_have_open || eye < 0 || eye > 1) return; + PSXFrameTraceRecord *r = open_record(); + if (eye == 0) r->eye_cycles_l = cycles; + else r->eye_cycles_r = cycles; +} + +void psx_frame_trace_gpu(uint64_t tex_upload_bytes, uint32_t vram_leaks) { + if (!s_have_open) return; + PSXFrameTraceRecord *r = open_record(); + r->tex_upload_bytes += tex_upload_bytes; + uint64_t leaks = (uint64_t)r->vram_leaks + vram_leaks; + r->vram_leaks = leaks > 0xFFFFFFFFu ? 0xFFFFFFFFu : (uint32_t)leaks; +} + +void psx_frame_trace_xr_cadence(uint32_t display_delta_us, int submit_fresh) { + if (!s_have_open) return; + PSXFrameTraceRecord *r = open_record(); + r->xr_display_delta_us = display_delta_us; + r->xr_submit_fresh = submit_fresh ? 1u : 0u; + if (!submit_fresh) r->flags |= PSX_FRAME_TRACE_XR_REPEAT; +} + +void psx_frame_trace_flag(uint32_t flag) { + if (!s_have_open) return; + open_record()->flags |= flag; +} + +void psx_frame_trace_note(const char *tag) { + if (!s_have_open || !tag) return; + snprintf(open_record()->note, PSX_FRAME_TRACE_NOTE, "%s", tag); +} + +void psx_frame_trace_io(const char *tag) { + if (!s_have_open) return; + PSXFrameTraceRecord *r = open_record(); + r->flags |= PSX_FRAME_TRACE_IO_EVENT; + if (tag) snprintf(r->note, PSX_FRAME_TRACE_NOTE, "%s", tag); +} + +void psx_frame_trace_session(const char *runtime, uint32_t target_period_us) { + if (!s_enabled) return; + if (target_period_us != s_target_period_us) s_target_period_us = target_period_us; + if (runtime && runtime != s_runtime && strcmp(runtime, s_runtime) != 0) + snprintf(s_runtime, sizeof s_runtime, "%s", runtime); +} + +void psx_frame_trace_commit(void) { + if (!s_have_open) return; + PSXFrameTraceRecord *r = open_record(); + int any = 0; + for (uint32_t i = 0; i < PSX_TRACE_STAGE_COUNT; ++i) + if (r->stages_us[i]) { any = 1; break; } + /* A frame that only shed its pair genuinely has no stage: that is "stale", + * not "no telemetry". Only an expected-to-be-instrumented frame that + * recorded nothing at all is missing. */ + if (!any && !(r->flags & PSX_FRAME_TRACE_SHED)) { + s_missing++; + r->flags |= PSX_FRAME_TRACE_NO_TELEMETRY; + } + if (r->flags & PSX_FRAME_TRACE_STEREO_PUBLISHED) { + s_have_publish = 1; + s_last_publish_ms = r->open_ms; + r->pair_age_ms = 0; + } else if (s_have_publish) { + r->pair_age_ms = r->open_ms - s_last_publish_ms; + } + s_committed++; + s_have_open = 0; +} + +uint32_t psx_frame_trace_capacity(void) { return s_cap; } +uint64_t psx_frame_trace_committed(void) { return s_committed; } +uint64_t psx_frame_trace_dropped(void) { + return s_committed > s_cap ? s_committed - s_cap : 0; +} +uint64_t psx_frame_trace_missing(void) { return s_missing; } + +uint32_t psx_frame_trace_read(PSXFrameTraceRecord *out, uint32_t capacity) { + uint32_t n = 0; + if (!out || !capacity || !s_committed) return 0; + uint64_t retained = s_committed < s_cap ? s_committed : s_cap; + uint64_t take = capacity < retained ? capacity : retained; + uint64_t first = s_committed - take + 1u; /* oldest of the newest `take` */ + for (uint64_t seq = first; seq <= s_committed; ++seq) { + const PSXFrameTraceRecord *r = + &s_ring[(seq - 1u) & (uint64_t)(s_cap - 1u)]; + if (r->seq != seq) continue; /* overwritten / not ours */ + out[n++] = *r; + } + return n; +} + +/* ---- export ------------------------------------------------------------- */ + +static int app(char *buf, int cap, int off, const char *fmt, ...) { + va_list ap; + if (off < 0) off = 0; + if (buf && off < cap) { + va_start(ap, fmt); + int n = vsnprintf(buf + off, (size_t)(cap - off), fmt, ap); + va_end(ap); + return n < 0 ? off : off + n; + } + va_start(ap, fmt); + int n = vsnprintf(NULL, 0, fmt, ap); /* measure only */ + va_end(ap); + return n < 0 ? off : off + n; +} + +/* JSON string body with the few escapes a generated tool must not break on. */ +static const char *jstr(const char *s, char *tmp, int cap) { + int o = 0; + if (cap <= 0) return ""; + tmp[0] = '\0'; + for (const char *p = s; p && *p && o < cap - 2; ++p) { + unsigned char c = (unsigned char)*p; + if (c == '"' || c == '\\') { tmp[o++] = '\\'; tmp[o++] = (char)c; } + else if (c == '\n') { tmp[o++] = '\\'; if (o < cap - 1) tmp[o++] = 'n'; } + else if (c < 0x20) { o += snprintf(tmp + o, (size_t)(cap - o), "\\u%04x", c); } + else tmp[o++] = (char)c; + } + if (o > cap - 1) o = cap - 1; + tmp[o] = '\0'; + return tmp; +} + +static int rec_json(char *buf, int cap, int off, const PSXFrameTraceRecord *r) { + char t1[PSX_FRAME_TRACE_REASON * 2 + 8], t2[PSX_FRAME_TRACE_NOTE * 2 + 8]; + off = app(buf, cap, off, + "{\"seq\":%llu,\"open_ms\":%llu,\"guest_frame\":%llu," + "\"guest_cycle\":%llu,\"attempt\":%llu,\"pair_id\":%llu," + "\"pair_age_ms\":%llu,\"source\":%u,\"eye_failed\":%d," + "\"shed\":%u,\"shed_ms\":%u,\"prims\":%u,\"tex_prims\":%u," + "\"prims_l\":%u,\"prims_r\":%u,\"tex_prims_l\":%u," + "\"tex_prims_r\":%u,\"cycles_l\":%u,\"cycles_r\":%u," + "\"vram_leaks\":%u,\"tex_bytes\":%llu,\"flags\":%u," + "\"xr_display_delta_us\":%u,\"xr_submit_fresh\":%u," + "\"failure\":\"%s\",\"note\":\"%s\",\"stages_us\":{", + (unsigned long long)r->seq, (unsigned long long)r->open_ms, + (unsigned long long)r->guest_frame, + (unsigned long long)r->guest_cycle, + (unsigned long long)r->stereo_attempt, + (unsigned long long)r->pair_id, + (unsigned long long)r->pair_age_ms, r->source, r->eye_failed, + r->shed_skipped, r->shed_streak_ms, r->prims, r->textured_prims, + r->prims_l, r->prims_r, r->tex_prims_l, r->tex_prims_r, + r->eye_cycles_l, r->eye_cycles_r, + r->vram_leaks, (unsigned long long)r->tex_upload_bytes, r->flags, + r->xr_display_delta_us, (unsigned)r->xr_submit_fresh, + jstr(r->failure, t1, sizeof t1), jstr(r->note, t2, sizeof t2)); + for (uint32_t s = 0; s < PSX_TRACE_STAGE_COUNT; ++s) + off = app(buf, cap, off, "%s\"%s\":%u", s ? "," : "", + s_stage_names[s], r->stages_us[s]); + return app(buf, cap, off, "}}"); +} + +/* Newest `max_records` (0 = all retained), oldest first. Returns the count and + * the seq of the first record to read; iteration indexes the ring in place so + * no export call touches the stack with a whole-ring copy. */ +static uint32_t export_window(uint32_t max_records, uint64_t *first_seq) { + uint64_t retained = s_committed < s_cap ? s_committed : s_cap; + if (!retained) { *first_seq = 1; return 0; } + uint32_t n = (uint32_t)retained; + uint32_t take = (max_records && max_records < n) ? max_records : n; + *first_seq = s_committed - take + 1u; + return take; +} + +static const PSXFrameTraceRecord *at_seq(uint64_t seq) { + const PSXFrameTraceRecord *r = &s_ring[(seq - 1u) & (uint64_t)(s_cap - 1u)]; + return r->seq == seq ? r : NULL; +} + +int psx_frame_trace_to_json(char *buf, int cap, uint32_t max_records) { + char t1[256]; + uint64_t first; + if (cap < 0 || (buf && cap == 0)) return 0; + if (buf) buf[0] = '\0'; + uint32_t take = export_window(max_records, &first); + int off = app(buf, cap, 0, + "{\"enabled\":%d,\"capacity\":%u,\"count\":%llu," + "\"dropped\":%llu,\"missing\":%llu," + "\"runtime\":\"%s\",\"target_period_us\":%u,\"records\":[", + s_enabled, s_cap, (unsigned long long)s_committed, + (unsigned long long)psx_frame_trace_dropped(), + (unsigned long long)s_missing, + jstr(s_runtime, t1, sizeof t1), s_target_period_us); + int emitted = 0; + for (uint64_t seq = first; emitted < (int)take; ++seq) { + const PSXFrameTraceRecord *r = at_seq(seq); + if (!r) continue; + off = app(buf, cap, off, "%s", emitted ? "," : ""); + off = rec_json(buf, cap, off, r); + emitted++; + } + return app(buf, cap, off, "]}"); +} + +int psx_frame_trace_to_csv(char *buf, int cap, uint32_t max_records) { + char flags[96]; + uint64_t first; + if (cap < 0 || (buf && cap == 0)) return 0; + if (buf) buf[0] = '\0'; + uint32_t take = export_window(max_records, &first); + int off = app(buf, cap, 0, + "seq,open_ms,guest_frame,guest_cycle,attempt,pair_id," + "pair_age_ms,source,eye_failed,flags,shed,streak_ms,prims," + "tex_prims,prims_l,prims_r,tex_prims_l,tex_prims_r,cycles_l," + "cycles_r,vram_leaks,tex_bytes,xr_display_delta_us," + "xr_submit_fresh"); + for (uint32_t s = 0; s < PSX_TRACE_STAGE_COUNT; ++s) + off = app(buf, cap, off, ",%s", s_stage_names[s]); + off = app(buf, cap, off, ",failure,note\n"); + int emitted = 0; + for (uint64_t seq = first; emitted < (int)take; ++seq) { + const PSXFrameTraceRecord *r = at_seq(seq); + if (!r) continue; + emitted++; + off = app(buf, cap, off, + "%llu,%llu,%llu,%llu,%llu,%llu,%llu,%u,%d,\"%s\",%u,%u,%u," + "%u,%u,%u,%u,%u,%u,%u,%u,%llu,%u,%u", + (unsigned long long)r->seq, (unsigned long long)r->open_ms, + (unsigned long long)r->guest_frame, + (unsigned long long)r->guest_cycle, + (unsigned long long)r->stereo_attempt, + (unsigned long long)r->pair_id, + (unsigned long long)r->pair_age_ms, r->source, r->eye_failed, + psx_frame_trace_flag_names(r->flags, flags, sizeof flags), + r->shed_skipped, r->shed_streak_ms, r->prims, r->textured_prims, + r->prims_l, r->prims_r, r->tex_prims_l, r->tex_prims_r, + r->eye_cycles_l, r->eye_cycles_r, + r->vram_leaks, (unsigned long long)r->tex_upload_bytes, + r->xr_display_delta_us, (unsigned)r->xr_submit_fresh); + for (uint32_t s = 0; s < PSX_TRACE_STAGE_COUNT; ++s) + off = app(buf, cap, off, ",%u", r->stages_us[s]); + off = app(buf, cap, off, ",\"%s\",\"%s\"\n", r->failure, r->note); + } + return off; +} + +int psx_frame_trace_to_chrome_json(char *buf, int cap, uint32_t max_records) { + char flags[96]; + uint64_t first; + if (cap < 0 || (buf && cap == 0)) return 0; + if (buf) buf[0] = '\0'; + uint32_t take = export_window(max_records, &first); + int off = app(buf, cap, 0, "{\"traceEvents\":["); + int first_ev = 1, emitted = 0; + for (uint64_t seq = first; emitted < (int)take; ++seq) { + const PSXFrameTraceRecord *r = at_seq(seq); + if (!r) continue; + emitted++; + uint64_t base_us = r->open_ms * 1000u, at = 0; + for (uint32_t s = 0; s < PSX_TRACE_STAGE_COUNT; ++s) { + uint64_t dur = r->stages_us[s]; + if (dur) { + off = app(buf, cap, off, + "%s{\"name\":\"%s\",\"ph\":\"X\",\"ts\":%llu," + "\"dur\":%llu,\"pid\":1,\"tid\":1,\"args\":{" + "\"seq\":%llu,\"attempt\":%llu,\"pair_id\":%llu," + "\"flags\":\"%s\"}}", + first_ev ? "" : ",", s_stage_names[s], + (unsigned long long)(base_us + at), + (unsigned long long)dur, + (unsigned long long)r->seq, + (unsigned long long)r->stereo_attempt, + (unsigned long long)r->pair_id, + psx_frame_trace_flag_names(r->flags, flags, sizeof flags)); + first_ev = 0; + } + at += dur; + } + } + return app(buf, cap, off, "]}"); +} diff --git a/runtime/src/gpu_gl_renderer.c b/runtime/src/gpu_gl_renderer.c index 098646d3..ddecb0f6 100644 --- a/runtime/src/gpu_gl_renderer.c +++ b/runtime/src/gpu_gl_renderer.c @@ -7588,6 +7588,14 @@ uint64_t gl_renderer_perf_prim_split(double *out_tex_frac) { return s_scene_prims; } +/* Cumulative scene primitives for per-frame attribution (frame_trace). Callers + * take deltas; these counters are never reset here. */ +void gl_renderer_scene_prim_counts(uint64_t *prims, uint64_t *textured) { + GL_RT_SYNC("scene_prim_counts"); + if (prims) *prims = s_scene_prims; + if (textured) *textured = s_scene_prims_tex; +} + int gl_renderer_perf_aggregate(int wide_filter, double out[18]) { GL_RT_SYNC("perf_aggregate"); for (int i = 0; i < 18; i++) out[i] = 0.0; diff --git a/runtime/src/psx_openxr.c b/runtime/src/psx_openxr.c index e9244553..1cf463ba 100644 --- a/runtime/src/psx_openxr.c +++ b/runtime/src/psx_openxr.c @@ -9,6 +9,8 @@ #include "psx_openxr.h" #include "vr_pose_math.h" #include "openxr_color.h" +#include "frame_trace.h" +#include "gpu_gl_renderer.h" #include #include #include @@ -103,6 +105,17 @@ int psx_openxr_surface_valid(const PSXModOpenXRSurface *v) { #define XR_USE_GRAPHICS_API_OPENGL #include #include + +/* Frame-trace stage helper: perf ticks -> microseconds (CPU submission/wait + * wall time only, never GPU execution time). */ +static uint64_t xr_trace_us(uint64_t ticks) { + static double inv = 0.0; + if (inv == 0.0) { + double f = (double)gl_renderer_perf_frequency(); + inv = f > 0.0 ? 1000000.0 / f : 1.0; + } + return (uint64_t)((double)ticks * inv); +} static XrInstance s_instance; static XrSystemId s_system; static XrSession s_session; @@ -123,6 +136,13 @@ static XrView s_views[2]; static PSXModRenderView s_render[2]; static double s_oq[4],s_op[3]; static XrTime s_time; +/* Cadence telemetry for the frame trace: the runtime's own predicted display + * time delta between submissions (what the compositor actually saw), and when + * the pose for the current frame was sampled (xrLocateViews return). */ +static XrTime s_prev_display_time; +static int s_prev_display_valid; +static uint32_t s_display_delta_us; +static uint64_t s_pose_sample_ticks; /* Loss handling. A lost session/instance (or an unusable swapchain) is only * flagged where it is detected; service_loss() tears the stack down at the end * of the public call so no caller loses handles mid-sequence. */ @@ -354,6 +374,9 @@ static void hands_locate(int focused) { /* Destroy every XR object (children before parents). Safe on a partially * initialised stack and on a lost session: destroy calls need no live session. */ static void xr_destroy(void) { + /* A new session must not inherit the previous one's display times: the + * first delta after a re-init would be meaningless. */ + s_prev_display_valid=0;s_prev_display_time=0; for(int eye=0;eye<2;eye++) { for(int k=0;k<2;k++) { if(s_pose_space[eye][k])xrDestroySpace(s_pose_space[eye][k]); @@ -547,11 +570,38 @@ int psx_openxr_begin(int width,int height,double units) { s_recovering=0; } if(!events() || !s_stats.running){(void)service_loss();return 0;} + /* Open this frame's trace record before the blocking waits. The record is + * committed by psx_openxr_end(); the two failure returns below commit it + * themselves so a lost session cannot leave a record open forever. */ + psx_frame_trace_open(); + /* Cleared so a frame that never reaches xrLocateViews (no render request, + * lost tracking, bad view maths) cannot report a stale pose age. */ + s_pose_sample_ticks=0; + uint64_t trace_t = gl_renderer_perf_ticks(); XrFrameWaitInfo wait={XR_TYPE_FRAME_WAIT_INFO};XrFrameState fs={XR_TYPE_FRAME_STATE}; - if(!check(xrWaitFrame(s_session,&wait,&fs),"wait_frame")){(void)service_loss();return 0;} + if(!check(xrWaitFrame(s_session,&wait,&fs),"wait_frame")){ + psx_frame_trace_add(PSX_TRACE_XR_WAIT_FRAME, xr_trace_us(gl_renderer_perf_ticks()-trace_t)); + (void)service_loss();psx_frame_trace_commit();return 0;} + psx_frame_trace_add(PSX_TRACE_XR_WAIT_FRAME, xr_trace_us(gl_renderer_perf_ticks()-trace_t)); s_stats.waits++;s_time=fs.predictedDisplayTime;s_stats.predicted_time=(uint64_t)s_time; + /* The runtime's own clock between submissions. This is the cadence the + * compositor saw, independent of our frame timing: delta / display period + * is how many granted periods one presented frame consumed. */ + s_display_delta_us=0; + if(s_prev_display_valid && s_time>s_prev_display_time) { + uint64_t d=(uint64_t)(s_time-s_prev_display_time)/1000u; + s_display_delta_us=d>0xFFFFFFFFull?0xFFFFFFFFu:(uint32_t)d; + } + s_prev_display_time=s_time;s_prev_display_valid=1; + /* Record the runtime display period with its name for cadence analysis. */ + psx_frame_trace_session(s_stats.runtime, + fs.predictedDisplayPeriod>0?(uint32_t)(fs.predictedDisplayPeriod/1000):0u); + trace_t = gl_renderer_perf_ticks(); XrFrameBeginInfo begin={XR_TYPE_FRAME_BEGIN_INFO}; - if(!check(xrBeginFrame(s_session,&begin),"begin_frame")){(void)service_loss();return 0;} + if(!check(xrBeginFrame(s_session,&begin),"begin_frame")){ + psx_frame_trace_add(PSX_TRACE_XR_BEGIN_FRAME, xr_trace_us(gl_renderer_perf_ticks()-trace_t)); + (void)service_loss();psx_frame_trace_commit();return 0;} + psx_frame_trace_add(PSX_TRACE_XR_BEGIN_FRAME, xr_trace_us(gl_renderer_perf_ticks()-trace_t)); s_stats.frame_open=1;s_stats.tracking=0; if(!fs.shouldRender){psx_openxr_end(0,NULL);return 0;} XrViewLocateInfo loc={XR_TYPE_VIEW_LOCATE_INFO};loc.viewConfigurationType=XR_VIEW_CONFIGURATION_TYPE_PRIMARY_STEREO; @@ -559,6 +609,7 @@ int psx_openxr_begin(int width,int height,double units) { XrViewState vs={XR_TYPE_VIEW_STATE};uint32_t count=0; memset(s_views,0,sizeof s_views);s_views[0].type=s_views[1].type=XR_TYPE_VIEW; int located=check(xrLocateViews(s_session,&loc,&vs,2,&count,s_views),"locate_views"); + s_pose_sample_ticks=gl_renderer_perf_ticks(); s_stats.view_flags=(uint64_t)vs.viewStateFlags; if(!located || count!=2 || (vs.viewStateFlags&(XR_VIEW_STATE_ORIENTATION_VALID_BIT|XR_VIEW_STATE_POSITION_VALID_BIT))!= @@ -619,26 +670,37 @@ int psx_openxr_quad(double distance,double width,double height) { int psx_openxr_end(int keep,PSXOpenXRCopy copy) { #if defined(PSX_OPENXR) if(!s_stats.frame_open)return 0; + /* Defensive open: normally psx_openxr_begin() already opened the record. */ + psx_frame_trace_open(); + uint64_t trace_t; XrCompositionLayerProjectionView pv[2]={{XR_TYPE_COMPOSITION_LAYER_PROJECTION_VIEW},{XR_TYPE_COMPOSITION_LAYER_PROJECTION_VIEW}}; int complete=keep && copy && s_stats.tracking; int quad=s_quad_distance>0; for(int eye=0;eye<(quad?1:2) && complete;eye++) { uint32_t index=0; + trace_t = gl_renderer_perf_ticks(); XrSwapchainImageAcquireInfo ai={XR_TYPE_SWAPCHAIN_IMAGE_ACQUIRE_INFO}; if(!check(xrAcquireSwapchainImage(s_chain[eye],&ai,&index),"acquire")){complete=0;break;} + psx_frame_trace_add(PSX_TRACE_XR_ACQUIRE, xr_trace_us(gl_renderer_perf_ticks()-trace_t)); XrSwapchainImageWaitInfo wi={XR_TYPE_SWAPCHAIN_IMAGE_WAIT_INFO};wi.timeout=1000000000; + trace_t = gl_renderer_perf_ticks(); XrResult wr=xrWaitSwapchainImage(s_chain[eye],&wi); /* A timeout leaves ownership acquired: wait again (bounded) before * releasing. Only XR_SUCCESS means the image is writable; the timeout * code is a success code and must not be mistaken for it. */ if(wr==XR_TIMEOUT_EXPIRED){wi.timeout=2000000000;wr=xrWaitSwapchainImage(s_chain[eye],&wi);} + psx_frame_trace_add(PSX_TRACE_XR_WAIT_IMAGE, xr_trace_us(gl_renderer_perf_ticks()-trace_t)); int writable=check(wr,"wait_image") && wr==XR_SUCCESS; if(writable) { + trace_t = gl_renderer_perf_ticks(); if(index>=s_count[eye] || !copy(eye,s_images[eye][index].image,s_w[eye],s_h[eye])) { s_stats.stage="copy_image";s_stats.failures++;complete=0; } + psx_frame_trace_add(PSX_TRACE_XR_COPY, xr_trace_us(gl_renderer_perf_ticks()-trace_t)); + trace_t = gl_renderer_perf_ticks(); XrSwapchainImageReleaseInfo ri={XR_TYPE_SWAPCHAIN_IMAGE_RELEASE_INFO}; if(!check(xrReleaseSwapchainImage(s_chain[eye],&ri),"release"))complete=0; + psx_frame_trace_add(PSX_TRACE_XR_RELEASE, xr_trace_us(gl_renderer_perf_ticks()-trace_t)); } else { /* Acquired but never writable. Release it best-effort so the acquire * count cannot leak; a runtime that refuses (the wait never completed) @@ -665,7 +727,13 @@ int psx_openxr_end(int keep,PSXOpenXRCopy copy) { XrFrameEndInfo end={XR_TYPE_FRAME_END_INFO};end.displayTime=s_time; end.environmentBlendMode=XR_ENVIRONMENT_BLEND_MODE_OPAQUE; end.layerCount=complete?1:0;end.layers=complete?layers:NULL; + trace_t = gl_renderer_perf_ticks(); int ok=check(xrEndFrame(s_session,&end),"end_frame");s_stats.frame_open=0; + psx_frame_trace_add(PSX_TRACE_XR_END_FRAME, xr_trace_us(gl_renderer_perf_ticks()-trace_t)); + if(s_pose_sample_ticks) + psx_frame_trace_add(PSX_TRACE_POSE_AGE, + xr_trace_us(gl_renderer_perf_ticks()-s_pose_sample_ticks)); + psx_frame_trace_xr_cadence(s_display_delta_us, complete); if(ok && complete) { s_stats.submitted_surfaces=quad?0:((s_surface_mask&1)!=0)+((s_surface_mask&2)!=0); s_stats.submitted++;s_stats.submitted_pair_id=s_pair_id; @@ -675,9 +743,18 @@ int psx_openxr_end(int keep,PSXOpenXRCopy copy) { if(s_source==2)s_stats.native_submitted++; if(quad){s_stats.quad_submitted++;s_stats.quad_distance_m=s_quad_distance; s_stats.quad_width_m=s_quad_width;s_stats.quad_height_m=s_quad_height;} - } else {s_stats.empty++;s_stats.submitted_surfaces=0;} + /* A fresh stereo pair already labelled the record source 1; only + * annotate native presentation when nothing else claimed it. */ + psx_frame_trace_source(2); + } else { + s_stats.empty++;s_stats.submitted_surfaces=0; + psx_frame_trace_flag(PSX_FRAME_TRACE_XR_EMPTY); + psx_frame_trace_flag(PSX_FRAME_TRACE_STALE_PAIR); + psx_frame_trace_source(2); + } if(ok && complete)s_stats.stage="submitted"; s_quad_distance=s_quad_width=s_quad_height=0; + psx_frame_trace_commit(); (void)service_loss(); /* after the frame is closed: lost session / bad swapchain */ return ok && complete; #else diff --git a/runtime/src/render_pass.c b/runtime/src/render_pass.c index 705600c0..e25ab04c 100644 --- a/runtime/src/render_pass.c +++ b/runtime/src/render_pass.c @@ -26,8 +26,10 @@ #include "cpu_state.h" #include "dirty_ram_interp.h" #include "dma.h" +#include "frame_trace.h" #include "gpu.h" #include "gpu_gl_renderer.h" +#include "host_time.h" #include "mod_plugins.h" #include "mod_runtime.h" #include "interrupts.h" @@ -282,6 +284,9 @@ static const char *s_checkpoint_failure; static RenderStereoStats s_stereo; static int s_pair_busy; static uint32_t s_pair_retry; +/* A HUD-only capture transaction reuses eye 0's slot but is not an eye draw; + * frame tracing must not attribute its cost to the left eye. */ +static int s_capture_only; static int pass_refuse(const char *reason, uint32_t status) { /* A refusal always carries a reason: last_failure.reason == NULL means @@ -338,6 +343,11 @@ void render_pass_reset_session(void) { s_stereo.last_eye = -1; s_pair_busy = 0; s_pair_retry = 0; + /* Frame tracing is opt-in per session: re-read the env, install the host + * clock, and clear any previous session's records. */ + psx_frame_trace_configure_from_env(); + psx_frame_trace_set_clock(psx_host_mono_ms); + psx_frame_trace_reset(); gl_renderer_stereo_reset(); gl_renderer_pass_set_flip_shown(0); } @@ -393,6 +403,14 @@ void render_stereo_get_stats(RenderStereoStats *out) { if (out) *out = s_stereo; int psx_mod_set_stereo_presentation(uint32_t mode) { return mode <= 1u ? gl_renderer_stereo_set_presentation(mode) : 0; } + +/* Game-side annotation for the frame trace (mod_plugins.h): a title hook marks + * a scene/state transition on the record the runtime opened for this frame. A + * no-op when tracing is off or no record is open. */ +void psx_mod_frame_trace_note(const char *tag) { + psx_frame_trace_note(tag); + psx_frame_trace_flag(PSX_FRAME_TRACE_SCENE_TRANSITION); +} int psx_mod_render_view_offset(int32_t x, int32_t y, int32_t z) { int32_t xyz[3] = {x, y, z}; if (!g_psx_render_pass_active) return 0; @@ -605,6 +623,51 @@ static double ema_ms(double cur, uint64_t ticks) { return cur > 0.0 ? cur * 0.9 + ms * 0.1 : ms; } +/* Ticks -> microseconds for frame_trace. CPU submission time only: it is not + * GPU execution time. */ +static double s_us_per_tick = 0.0; +static uint64_t trace_ticks_to_us(uint64_t ticks) { + if (s_us_per_tick == 0.0) { + double f = (double)gl_renderer_perf_frequency(); + s_us_per_tick = f > 0.0 ? 1000000.0 / f : 1.0; + } + return (uint64_t)((double)ticks * s_us_per_tick); +} + +/* ---- guest sub-stage spans (mod_plugins.h) ------------------------------ + * The game hook brackets the guest calls it replays once per eye, and the + * runtime times them with its own tick clock, exactly as the eye stages are + * timed, so the parts sum against eye_guest. Accepted only inside a traced + * stereo eye (s_sub_eye): a HUD capture's guest draws and the flat path report + * their own stages and must not write these slots. */ +static int s_sub_eye = -1; /* traced eye accepting spans, -1 = none */ +/* One start tick per stage rather than one open span at a time, so a stage can + * be bracketed inside another: the hook's visibility override runs inside the + * guest traversal it is part of. The outer span keeps its own wall time, so a + * nested stage is a subset of it rather than a sibling. */ +static int s_sub_open[PSX_TRACE_STAGE_COUNT]; +static uint64_t s_sub_ticks[PSX_TRACE_STAGE_COUNT]; + +/* No span survives an eye boundary, so an eye aborted mid-entry cannot carry a + * start tick into the next one. */ +static void sub_spans_forget(void) { + memset(s_sub_open, 0, sizeof s_sub_open); +} + +void psx_mod_frame_trace_stage_begin(uint32_t stage) { + if (s_sub_eye < 0 || stage >= PSX_TRACE_STAGE_COUNT) return; + s_sub_open[stage] = 1; /* an unpaired begin restarts that span */ + s_sub_ticks[stage] = gl_renderer_perf_ticks(); +} + +void psx_mod_frame_trace_stage_end(uint32_t stage) { + if (s_sub_eye < 0 || stage >= PSX_TRACE_STAGE_COUNT) return; + if (!s_sub_open[stage]) return; /* an end with no begin records nothing */ + uint64_t now = gl_renderer_perf_ticks(); + psx_frame_trace_add(stage, trace_ticks_to_us(now - s_sub_ticks[stage])); + s_sub_open[stage] = 0; +} + static void watchdog_overrun(void) { s_stats.watchdog++; s_stats.watchdog_flag = 1; @@ -692,6 +755,10 @@ static int render_transaction(struct CPUState *cpu, const PSXModRenderPass *pass s_attempt.attempt = ++s_stats.pass_attempts; s_attempt.plan = s_plan_serial; s_attempt.guest_cycle = psx_cycle_count; + /* No guest sub-stage span may survive into this transaction: the eye that + * accepts them is decided below, once the trace decision is known. */ + s_sub_eye = -1; + sub_spans_forget(); if (pass) { s_attempt.struct_size = pass->struct_size; if (pass->struct_size >= sizeof *pass) { @@ -726,6 +793,16 @@ static int render_transaction(struct CPUState *cpu, const PSXModRenderPass *pass if (inv == 0.0) inv = 1000.0 / (double)gl_renderer_perf_frequency(); s_ms_per_tick = inv; } + /* Per-eye trace sampling (opt-in): primitive counts and upload pixels are + * cumulative, so the eye's cost is the delta across its transaction. */ + int trace_on = eye >= 0 && !s_capture_only && psx_frame_trace_enabled(); + uint64_t trace_prims0 = 0, trace_tex0 = 0, trace_diag0[6] = {0,0,0,0,0,0}; + if (trace_on) { + gl_renderer_scene_prim_counts(&trace_prims0, &trace_tex0); + gl_renderer_runtime_diag(trace_diag0); + } + /* This eye, and only this eye, accepts the hook's guest sub-stage spans. */ + s_sub_eye = trace_on ? (int)eye : -1; reuse = !open && eye != RP_EYE_LOCAL && s_restored_valid && s_restored_plan == s_plan_serial && s_restored_cycle == psx_cycle_count && @@ -794,7 +871,13 @@ static int render_transaction(struct CPUState *cpu, const PSXModRenderPass *pass "%s", s_abort_detail); ok = 0; } - s_stats.guest_cycles_last = psx_cycle_count - cycles_before; + /* Any span still open here was never ended by the hook, or the eye aborted + * mid-entry through the longjmp above. Drop them instead of closing them: + * the elapsed time is then not charged to an entry that never finished, and + * it shows up as the difference between eye_guest and the guest sub-stages. */ + sub_spans_forget(); + uint64_t guest_cycles = psx_cycle_count - cycles_before; + s_stats.guest_cycles_last = guest_cycles; if (eye >= 0) gte_render_view_get(s_stereo.eye_view[eye]); tg = gl_renderer_perf_ticks(); s_pass_cpu = NULL; @@ -827,6 +910,26 @@ static int render_transaction(struct CPUState *cpu, const PSXModRenderPass *pass s_stats.avg_end_ms = ema_ms(s_stats.avg_end_ms, te - tg); s_stats.avg_restore_ms = ema_ms(s_stats.avg_restore_ms, tr - te); + if (trace_on) { + uint32_t base = eye == PSX_MOD_EYE_LEFT ? PSX_TRACE_EYE_BEGIN_L + : PSX_TRACE_EYE_BEGIN_R; + psx_frame_trace_add(base + 0, trace_ticks_to_us(tb - t0)); + psx_frame_trace_add(base + 1, trace_ticks_to_us(tg - tb)); + psx_frame_trace_add(base + 2, trace_ticks_to_us(te - tg)); + psx_frame_trace_add(base + 3, trace_ticks_to_us(tr - te)); + uint64_t p1 = 0, t1x = 0, diag1[6] = {0,0,0,0,0,0}; + gl_renderer_scene_prim_counts(&p1, &t1x); + gl_renderer_runtime_diag(diag1); + psx_frame_trace_draw(eye, (uint32_t)(p1 - trace_prims0), + (uint32_t)(t1x - trace_tex0)); + psx_frame_trace_eye_cycles(eye, (uint32_t)guest_cycles); + /* Upload pixels -> bytes assumes the 16-bit VRAM format uploads use. */ + psx_frame_trace_gpu((diag1[2] - trace_diag0[2]) * 2u, + (uint32_t)leaks); + s_sub_eye = -1; + sub_spans_forget(); + } + if (verify_on()) { hash_after = state_hash(cpu); s_stats.verify_checks++; @@ -920,10 +1023,31 @@ int psx_mod_render_stereo(CPUState *cpu, const PSXModStereoFrame *frame, if (status != PSX_MOD_RENDER_PASS_READY) { s_stereo.refused++; s_stereo.last_failure = "status"; return 0; } + /* Frame trace (opt-in). The runtime already opened this frame's record in + * psx_openxr_begin() when a headset is active; opening here covers the + * desktop stereo path, and the guest-sim gap is the host time since the + * previous traced frame. */ + int trace_on = psx_frame_trace_enabled(); + int trace_opened = trace_on ? psx_frame_trace_open() : 0; + if (trace_on) { + static uint64_t prev_ms; + static int prev_valid; + uint64_t now_ms = psx_host_mono_ms(); + if (prev_valid) + psx_frame_trace_add(PSX_TRACE_GUEST_SIM, (now_ms - prev_ms) * 1000u); + prev_ms = now_ms; prev_valid = 1; + psx_frame_trace_attempt(s_stereo.attempts, 0, 0); + } budget_ms = frame->period_vblanks * (double)g_psx_vblank_cycles / 33868.8 * 0.8; if (s_stereo.avg_pair_ms > budget_ms && ++s_pair_retry < 30u) { - s_stereo.shed++; return 0; + s_stereo.shed++; + if (trace_on) { + psx_frame_trace_attempt(s_stereo.attempts, s_pair_retry, 0); + psx_frame_trace_flag(PSX_FRAME_TRACE_STALE_PAIR); + if (trace_opened) psx_frame_trace_commit(); + } + return 0; } s_pair_retry = 0; if (g_overlay_flush_pending_cycles) g_overlay_flush_pending_cycles(); @@ -978,6 +1102,13 @@ int psx_mod_render_stereo(CPUState *cpu, const PSXModStereoFrame *frame, s_stereo.retained_pair_id = s_stereo.last_pair_id; gl_renderer_stereo_stage_reset(); } + if (trace_on) { + psx_frame_trace_add(PSX_TRACE_PAIR_TOTAL, (uint64_t)(elapsed * 1000.0)); + psx_frame_trace_result(ok, ok ? s_stereo.last_pair_id : 0, + ok ? -1 : s_stereo.last_eye, + ok ? NULL : s_stereo.last_failure); + if (trace_opened) psx_frame_trace_commit(); + } s_pair_busy = 0; return ok; } @@ -989,11 +1120,21 @@ int psx_mod_render_capture_rgba(CPUState *cpu,const PSXModRenderPass *rect, !rect->w || !rect->h || rect->x+rect->w>1024 || rect->y+rect->h>512 || (uint64_t)rect->w*rect->h*4>bytes || transaction_status(1)!=PSX_MOD_RENDER_PASS_READY)return 0; if(g_overlay_flush_pending_cycles)g_overlay_flush_pending_cycles(); + uint64_t trace_t0=gl_renderer_perf_ticks(); s_pair_busy=1;s_plan_serial++; gl_renderer_stereo_stage_reset(); PSXModRenderPass capture=*rect;capture.alpha_q16=0; + s_capture_only=1; /* this eye-0 transaction is a HUD capture, not an eye draw */ int ok=render_transaction(cpu,&capture,fn,user,0); + s_capture_only=0; + uint64_t trace_t1=gl_renderer_perf_ticks(); + psx_frame_trace_add(PSX_TRACE_HUD_DRAW, + trace_ticks_to_us(trace_t1-trace_t0)); if(ok)ok=gl_renderer_stereo_stage_readback(0,rect->w,rect->h,rgba); + psx_frame_trace_add(PSX_TRACE_HUD_READBACK, + trace_ticks_to_us(gl_renderer_perf_ticks()-trace_t1)); gl_renderer_stereo_stage_reset();s_pair_busy=0; + psx_frame_trace_add(PSX_TRACE_HUD_CAPTURE, + trace_ticks_to_us(gl_renderer_perf_ticks()-trace_t0)); return ok; } diff --git a/runtime/tests/test_frame_trace.c b/runtime/tests/test_frame_trace.c new file mode 100644 index 00000000..3f887fe0 --- /dev/null +++ b/runtime/tests/test_frame_trace.c @@ -0,0 +1,340 @@ +/* Unit tests for the opt-in frame-trace ring (frame_trace.c). + * + * The trace is the floor the VR stutter investigation stands on, so its + * contracts must hold without a headset: a disabled trace costs nothing and + * records nothing, timestamps never go backwards even when the host clock does, + * the ring wraps without losing the newest records, a frame that measured + * nothing is marked as such, and every export is NUL-terminated and safe to + * truncate. ctest -R frame_trace_test + */ +#include "frame_trace.h" + +#include +#include + +/* Evaluate side effects and failures even when NDEBUG is defined. */ +#define CHECK(expr) do { \ + if (!(expr)) { \ + fprintf(stderr, "FAIL line %d: %s\n", __LINE__, #expr); \ + return 1; \ + } \ +} while (0) + +static uint64_t g_fake_ms; +static uint64_t fake_clock(void) { return g_fake_ms; } + +/* A drifting clock: monotonic except one deliberate backwards step. */ +static uint64_t g_step; +static uint64_t stepping_clock(void) { + static const uint64_t seq[] = { 100, 120, 90, 140, 200 }; + return seq[(g_step++) % (sizeof seq / sizeof seq[0])]; +} + +static int frame_with(uint64_t base_us, int publish, uint64_t pair_id, + int eye_failed, const char *failure) { + uint64_t us = base_us; + if (!psx_frame_trace_open()) return 0; + psx_frame_trace_ids(0x1000 + pair_id, 0x2000 + pair_id); + psx_frame_trace_add(PSX_TRACE_EYE_BEGIN_L, us); + psx_frame_trace_add(PSX_TRACE_EYE_GUEST_L, us * 2); + psx_frame_trace_add(PSX_TRACE_EYE_END_L, us + 3); + psx_frame_trace_add(PSX_TRACE_EYE_RESTORE_L, 5); + psx_frame_trace_add(PSX_TRACE_EYE_BEGIN_R, us + 1); + psx_frame_trace_add(PSX_TRACE_EYE_GUEST_R, us * 2 + 1); + psx_frame_trace_add(PSX_TRACE_XR_WAIT_FRAME, 700); + psx_frame_trace_add(PSX_TRACE_XR_END_FRAME, 40); + psx_frame_trace_result(publish, pair_id, eye_failed, failure); + psx_frame_trace_commit(); + return 1; +} + +int main(void) { + /* ---- disabled by default: nothing recorded, nothing to export ---- */ + psx_frame_trace_set_clock(fake_clock); + psx_frame_trace_reset(); + psx_frame_trace_set_enabled(0); + CHECK(psx_frame_trace_enabled() == 0); + CHECK(psx_frame_trace_open() == 0); + psx_frame_trace_add(PSX_TRACE_PAIR_TOTAL, 999); + psx_frame_trace_commit(); + CHECK(psx_frame_trace_committed() == 0); + { + char buf[256]; + int n = psx_frame_trace_to_json(buf, sizeof buf, 0); + CHECK(n > 0 && n < (int)sizeof buf); + CHECK(strstr(buf, "\"enabled\":0") != NULL); + CHECK(strstr(buf, "\"records\":[]") != NULL); + /* Session metadata is a no-op while capture is off. */ + psx_frame_trace_session("ShouldNotAppear", 12345); + CHECK(psx_frame_trace_to_json(buf, sizeof buf, 0) > 0); + CHECK(strstr(buf, "\"runtime\":\"\"") != NULL); + CHECK(strstr(buf, "\"target_period_us\":0") != NULL); + } + + /* ---- enabled: stages land, result/pair age, monotonic seq ---- */ + psx_frame_trace_set_enabled(1); + CHECK(psx_frame_trace_capacity() >= 64); + g_fake_ms = 1000; + CHECK(frame_with(10, 1, 7, -1, NULL)); + g_fake_ms = 1033; + CHECK(frame_with(100, 0, 7, 1, "eye_capture")); /* stale: publish failed */ + g_fake_ms = 1066; + CHECK(frame_with(12, 1, 8, -1, NULL)); + CHECK(psx_frame_trace_committed() == 3); + + { + PSXFrameTraceRecord recs[8]; + uint32_t n = psx_frame_trace_read(recs, 8); + CHECK(n == 3); + CHECK(recs[0].seq == 1 && recs[2].seq == 3); + CHECK(recs[0].open_ms <= recs[1].open_ms && + recs[1].open_ms <= recs[2].open_ms); + /* stage accumulation is exact */ + CHECK(recs[0].stages_us[PSX_TRACE_EYE_GUEST_L] == 20); + CHECK(recs[0].stages_us[PSX_TRACE_EYE_BEGIN_R] == 11); + CHECK(recs[0].stages_us[PSX_TRACE_XR_WAIT_FRAME] == 700); + /* published then stale */ + CHECK((recs[0].flags & PSX_FRAME_TRACE_STEREO_PUBLISHED) != 0); + CHECK(recs[0].pair_id == 7 && recs[0].pair_age_ms == 0); + CHECK((recs[1].flags & PSX_FRAME_TRACE_STALE_PAIR) != 0); + CHECK((recs[1].flags & PSX_FRAME_TRACE_FAILED) != 0); + CHECK(recs[1].eye_failed == 1); + CHECK(strcmp(recs[1].failure, "eye_capture") == 0); + CHECK(recs[1].pair_age_ms == 33); + CHECK((recs[2].flags & PSX_FRAME_TRACE_STEREO_PUBLISHED) != 0); + CHECK(recs[2].pair_id == 8 && recs[2].pair_age_ms == 0); + } + + /* ---- missing telemetry: an open + commit with no stage is marked ---- */ + g_fake_ms = 1100; + CHECK(psx_frame_trace_open() == 1); + CHECK(psx_frame_trace_open() == 0); /* no double open */ + psx_frame_trace_commit(); + CHECK(psx_frame_trace_missing() == 1); + { + PSXFrameTraceRecord recs[8]; + uint32_t n = psx_frame_trace_read(recs, 8); + CHECK(n == 4); + CHECK((recs[3].flags & PSX_FRAME_TRACE_NO_TELEMETRY) != 0); + } + + /* ---- shed annotation and flag rendering ---- */ + g_fake_ms = 1133; + CHECK(psx_frame_trace_open() == 1); + psx_frame_trace_attempt(42, 3, 250); + psx_frame_trace_flag(PSX_FRAME_TRACE_STALE_PAIR); + psx_frame_trace_commit(); + { + PSXFrameTraceRecord recs[8]; + char names[96]; + uint32_t n = psx_frame_trace_read(recs, 8); + CHECK(n == 5); + CHECK(recs[4].stereo_attempt == 42); + CHECK(recs[4].shed_skipped == 3 && recs[4].shed_streak_ms == 250); + CHECK((recs[4].flags & PSX_FRAME_TRACE_SHED) != 0); + /* A shed-only frame is stale, not "missing telemetry". */ + CHECK((recs[4].flags & PSX_FRAME_TRACE_NO_TELEMETRY) == 0); + CHECK(psx_frame_trace_missing() == 1); + psx_frame_trace_flag_names(recs[4].flags, names, sizeof names); + CHECK(strstr(names, "stale") && strstr(names, "shed")); + } + + /* ---- stage saturation rather than wrap ---- */ + g_fake_ms = 1200; + CHECK(psx_frame_trace_open() == 1); + psx_frame_trace_add(PSX_TRACE_PAIR_TOTAL, 0xF0000000u); + psx_frame_trace_add(PSX_TRACE_PAIR_TOTAL, 0xF0000000u); + psx_frame_trace_commit(); + { + PSXFrameTraceRecord recs[8]; + uint32_t n = psx_frame_trace_read(recs, 8); + CHECK(recs[n - 1].stages_us[PSX_TRACE_PAIR_TOTAL] == 0xFFFFFFFFu); + } + + /* ---- a backwards clock step must not produce a backwards timestamp ---- */ + psx_frame_trace_reset(); + { + PSXFrameTraceRecord recs[8]; + psx_frame_trace_set_clock(stepping_clock); + for (int i = 0; i < 5; ++i) { + CHECK(psx_frame_trace_open() == 1); + psx_frame_trace_add(PSX_TRACE_GUEST_SIM, (uint32_t)(1 + i)); + psx_frame_trace_commit(); + } + uint32_t n = psx_frame_trace_read(recs, 8); + CHECK(n == 5); + for (uint32_t i = 1; i < n; ++i) + CHECK(recs[i].open_ms >= recs[i - 1].open_ms); + CHECK(recs[0].open_ms == 100); + CHECK(recs[2].open_ms >= recs[1].open_ms); /* the 90 was clamped up */ + } + + /* ---- ring wrap keeps the newest records ---- */ + psx_frame_trace_reset(); + psx_frame_trace_set_clock(fake_clock); + { + uint32_t cap = psx_frame_trace_capacity(); + uint32_t extra = cap + 10u; + for (uint32_t i = 0; i < extra; ++i) { + g_fake_ms = 2000u + i; + CHECK(psx_frame_trace_open() == 1); + psx_frame_trace_add(PSX_TRACE_GUEST_SIM, i + 1u); + psx_frame_trace_commit(); + } + CHECK(psx_frame_trace_committed() == extra); + CHECK(psx_frame_trace_dropped() == extra - cap); + PSXFrameTraceRecord recs[8]; + CHECK(psx_frame_trace_read(recs, 8) == 8); + CHECK(recs[7].seq == extra); /* newest present */ + CHECK(recs[0].seq == extra - 7u); + CHECK(recs[7].stages_us[PSX_TRACE_GUEST_SIM] == extra); + /* capacity-limited read returns exactly `capacity` of the newest */ + PSXFrameTraceRecord one[1]; + CHECK(psx_frame_trace_read(one, 1) == 1); + CHECK(one[0].seq == extra); + } + + /* ---- exports: valid, NULL-terminated, truncation-safe ---- */ + { + static char big[1 << 20]; + int n = psx_frame_trace_to_json(big, sizeof big, 16); + CHECK(n > 0 && n < (int)sizeof big); + CHECK(big[0] == '{' && strstr(big, "\"records\":[") != NULL); + CHECK(big[n - 1] == '}' && big[n - 2] == ']'); + CHECK(strstr(big, "\"stages_us\"") != NULL); + /* The record limit caps the emitted count. */ + CHECK(strstr(big, "\"seq\":") != NULL); + + n = psx_frame_trace_to_csv(big, sizeof big, 4); + CHECK(n > 0 && n < (int)sizeof big); + CHECK(strncmp(big, "seq,open_ms,", 12) == 0); + CHECK(strstr(big, "guest_sim") && strstr(big, "xr_end_frame")); + + n = psx_frame_trace_to_chrome_json(big, sizeof big, 4); + CHECK(n > 0 && n < (int)sizeof big); + CHECK(strncmp(big, "{\"traceEvents\":[", 16) == 0 && big[n - 1] == '}'); + CHECK(strstr(big, "\"ph\":\"X\"") != NULL); + + /* A tiny buffer must still be terminated and report the full length. */ + char small[8]; + int need = psx_frame_trace_to_json(small, sizeof small, 0); + CHECK(need > (int)sizeof small); + CHECK(small[sizeof small - 1] == '\0'); + CHECK(small[0] == '{'); + } + + /* ---- session metadata: runtime + target refresh, JSON-escaped ---- */ + psx_frame_trace_session("TestRuntime/1.0", 11111); /* 90 Hz headset */ + { + static char meta[1 << 16]; + int m = psx_frame_trace_to_json(meta, sizeof meta, 1); + CHECK(m > 0 && m < (int)sizeof meta); + CHECK(strstr(meta, "\"runtime\":\"TestRuntime/1.0\"") != NULL); + CHECK(strstr(meta, "\"target_period_us\":11111") != NULL); + /* A runtime name with a quote must not break the document. */ + psx_frame_trace_session("Odd\"Runtime", 0); + m = psx_frame_trace_to_json(meta, sizeof meta, 1); + CHECK(m > 0 && m < (int)sizeof meta); + CHECK(strstr(meta, "\"runtime\":\"Odd\\\"Runtime\"") != NULL); + CHECK(strstr(meta, "\"target_period_us\":0") != NULL); + } + + /* ---- XR cadence: the runtime's display-time delta and repeat marking ---- + * One presented pair per granted display period is the pacing target, so a + * frame that carried no new pair must be distinguishable from one that did + * without reading the counterpart stats. */ + psx_frame_trace_reset(); + psx_frame_trace_set_enabled(1); + { + PSXFrameTraceRecord recs[8]; + static char cad[1 << 16]; + char names[96]; + + CHECK(psx_frame_trace_open()); /* carried a new pair */ + psx_frame_trace_add(PSX_TRACE_POSE_AGE, 4200); + psx_frame_trace_result(1, 11, -1, NULL); + psx_frame_trace_xr_cadence(22222, 1); + psx_frame_trace_commit(); + + CHECK(psx_frame_trace_open()); /* carried no new pair */ + psx_frame_trace_result(0, 11, -1, NULL); + psx_frame_trace_xr_cadence(22222, 0); + psx_frame_trace_commit(); + + CHECK(psx_frame_trace_read(recs, 8) == 2); + CHECK(recs[0].xr_display_delta_us == 22222); + CHECK(recs[0].xr_submit_fresh == 1); + CHECK((recs[0].flags & PSX_FRAME_TRACE_XR_REPEAT) == 0); + CHECK(recs[0].stages_us[PSX_TRACE_POSE_AGE] == 4200); + CHECK(recs[1].xr_submit_fresh == 0); + CHECK((recs[1].flags & PSX_FRAME_TRACE_XR_REPEAT) != 0); + /* The pose was never sampled for the repeat, so no age is claimed. */ + CHECK(recs[1].stages_us[PSX_TRACE_POSE_AGE] == 0); + + CHECK(psx_frame_trace_to_json(cad, sizeof cad, 0) > 0); + CHECK(strstr(cad, "\"xr_display_delta_us\":22222") != NULL); + CHECK(strstr(cad, "\"xr_submit_fresh\":1") != NULL); + CHECK(strstr(cad, "\"pose_age\":4200") != NULL); + CHECK(psx_frame_trace_to_csv(cad, sizeof cad, 0) > 0); + CHECK(strstr(cad, "xr_display_delta_us,xr_submit_fresh") != NULL); + CHECK(strstr(cad, ",22222,1,") != NULL); + CHECK(strstr(cad, ",22222,0,") != NULL); + CHECK(strstr(psx_frame_trace_flag_names(recs[1].flags, names, sizeof names), + "xr_repeat") != NULL); + } + + /* ---- per-eye draw counters and guest cycles --------------------------- + * The pair's own prim count is the last eye's, which is useless for asking + * which eye a change moved, and the guest sub-stages of the replay are pair + * totals written by the game hook. */ + psx_frame_trace_reset(); + psx_frame_trace_set_enabled(1); + { + PSXFrameTraceRecord recs[4]; + static char buf[1 << 16]; + + CHECK(psx_frame_trace_open()); + /* An unknown eye or a closed record must not write anything. */ + psx_frame_trace_draw(2, 999, 999); + psx_frame_trace_eye_cycles(-1, 999); + psx_frame_trace_add(PSX_TRACE_GAME_TRAVERSE, 0); + psx_frame_trace_draw(0, 669, 667); + psx_frame_trace_draw(1, 947, 944); + psx_frame_trace_eye_cycles(0, 145000); + psx_frame_trace_eye_cycles(1, 151000); + psx_frame_trace_add(PSX_TRACE_GAME_TRAVERSE, 1200); + psx_frame_trace_add(PSX_TRACE_GAME_TRAVERSE, 1400); + psx_frame_trace_add(PSX_TRACE_GAME_SUBMIT, 800); + psx_frame_trace_commit(); + + CHECK(psx_frame_trace_read(recs, 4) == 1); + CHECK(recs[0].prims_l == 669 && recs[0].prims_r == 947); + CHECK(recs[0].tex_prims_l == 667 && recs[0].tex_prims_r == 944); + /* `prims`/`tex_prims` keep their meaning: the last eye of the pair. */ + CHECK(recs[0].prims == 947 && recs[0].textured_prims == 944); + CHECK(recs[0].eye_cycles_l == 145000 && recs[0].eye_cycles_r == 151000); + /* A guest sub-stage accumulates both eyes' spans of that call. */ + CHECK(recs[0].stages_us[PSX_TRACE_GAME_TRAVERSE] == 2600); + CHECK(recs[0].stages_us[PSX_TRACE_GAME_SUBMIT] == 800); + + CHECK(psx_frame_trace_to_json(buf, sizeof buf, 0) > 0); + CHECK(strstr(buf, "\"prims_l\":669") && strstr(buf, "\"prims_r\":947")); + CHECK(strstr(buf, "\"cycles_l\":145000") && + strstr(buf, "\"cycles_r\":151000")); + CHECK(strstr(buf, "\"game_traverse\":2600") && + strstr(buf, "\"game_submit\":800") && + strstr(buf, "\"game_laser\":0")); + CHECK(psx_frame_trace_to_csv(buf, sizeof buf, 0) > 0); + CHECK(strstr(buf, "prims_l,prims_r,tex_prims_l,tex_prims_r,cycles_l," + "cycles_r") != NULL); + CHECK(strstr(buf, ",669,947,667,944,145000,151000,") != NULL); + /* The name table must stay in enum order (the header order is the ABI). */ + CHECK(strcmp(psx_frame_trace_stage_name(PSX_TRACE_GAME_ENV), "game_env") == 0 + && strcmp(psx_frame_trace_stage_name(PSX_TRACE_GAME_LASER), + "game_laser") == 0); + } + + psx_frame_trace_set_enabled(0); + printf("frame_trace_test: all checks passed\n"); + return 0; +} \ No newline at end of file diff --git a/runtime/tests/test_frame_trace_guard.py b/runtime/tests/test_frame_trace_guard.py new file mode 100644 index 00000000..a8b06f77 --- /dev/null +++ b/runtime/tests/test_frame_trace_guard.py @@ -0,0 +1,117 @@ +#!/usr/bin/env python3 +"""Guard: the frame-trace RECORD path must not allocate or touch files. + +frame_trace.c exists so a visible VR hitch can be correlated with a stage +without changing the thing being measured. A malloc(), a stdio file write, or a +formatted print added to the per-frame path would perturb the frame it is +supposed to observe, and no functional test would notice. This check reads the +source and fails if such a call appears in a record-path function. + +Export functions (to_json/to_csv/to_chrome_json) are explicitly allowed to use +vsnprintf, and are never called from the record path; they are listed as +exceptions by name so the intent is not mistaken for an oversight. + +ctest -R frame_trace_guard_test +""" +from __future__ import annotations + +import re +import sys +from pathlib import Path + +ROOT = Path(__file__).resolve().parents[2] +SRC = ROOT / "runtime" / "src" / "frame_trace.c" + +# Functions that run per frame. Their bodies must stay allocation- and IO-free. +RECORD_PATH = [ + "psx_frame_trace_open", + "psx_frame_trace_commit", + "psx_frame_trace_add", + "psx_frame_trace_ids", + "psx_frame_trace_attempt", + "psx_frame_trace_result", + "psx_frame_trace_source", + "psx_frame_trace_draw", + "psx_frame_trace_eye_cycles", + "psx_frame_trace_gpu", + "psx_frame_trace_flag", + "psx_frame_trace_note", + "psx_frame_trace_io", + "psx_frame_trace_reset", + "psx_frame_trace_enabled", + "stamp_now", + "open_record", +] + +# Forbidden call patterns in a record-path body. Word boundaries matter: +# "printf" must not match "snprintf"/"vsnprintf", which write into the record's +# own fixed buffers and touch neither heap nor files. +FORBIDDEN = [ + r"(? str | None: + """The definition of `name` (top-level, so the signature starts at column 0).""" + lines = text.splitlines() + for i, line in enumerate(lines): + if re.match(r"^[A-Za-z_][^\n]*\b" + re.escape(name) + r"\s*\(", line): + body = [line] + for j in range(i + 1, len(lines)): + body.append(lines[j]) + if lines[j].rstrip() == "}": + break + return "\n".join(body) + return None + + +def main() -> int: + if not SRC.exists(): + print(f"frame_trace_guard_test: SKIP: {SRC} not found", file=sys.stderr) + return 77 + text = SRC.read_text(encoding="utf-8", errors="replace") + + failures: list[str] = [] + + if not re.search(r"static\s+PSXFrameTraceRecord\s+s_ring\s*\[", text): + failures.append("frame_trace.c: the ring is not a static array " + "(the record path must not own heap)") + + for name in RECORD_PATH: + body = function_body(text, name) + if body is None: + failures.append(f"frame_trace.c: record-path function {name}() not found") + continue + for pattern in FORBIDDEN: + if re.search(pattern, body): + failures.append(f"frame_trace.c: {name}() matches {pattern} " + "(the per-frame path must not allocate or do IO)") + + if failures: + print("frame_trace_guard_test: FAIL", file=sys.stderr) + for f in failures: + print(" " + f, file=sys.stderr) + return 1 + + print(f"frame_trace_guard_test: {len(RECORD_PATH)} record-path functions are " + "allocation- and IO-free") + return 0 + + +if __name__ == "__main__": + raise SystemExit(main()) diff --git a/runtime/tests/test_render_pass_abort.c b/runtime/tests/test_render_pass_abort.c index 2adba0e5..d623e8c3 100644 --- a/runtime/tests/test_render_pass_abort.c +++ b/runtime/tests/test_render_pass_abort.c @@ -232,6 +232,13 @@ int gl_renderer_stereo_publish(uint64_t id, uint64_t cycle, const int32_t view[2 s_stereo_published = id; return 1; } +/* Referenced by render_pass.c's frame tracing and stereo shedding. */ +void gl_renderer_runtime_diag(uint64_t out[6]) { memset(out, 0, 6 * sizeof *out); } +void gl_renderer_scene_prim_counts(uint64_t *prims, uint64_t *textured) { + if (prims) *prims = 0; + if (textured) *textured = 0; +} +uint64_t psx_host_mono_ms(void) { return 1; } /* ---- an overlay shard's cycle shim (overlay_dispatch_preamble.c.inc) --- */ static uint32_t s_shard_pending; diff --git a/runtime/tests/test_render_pass_sandbox.c b/runtime/tests/test_render_pass_sandbox.c index 37732ce8..caedab1c 100644 --- a/runtime/tests/test_render_pass_sandbox.c +++ b/runtime/tests/test_render_pass_sandbox.c @@ -23,6 +23,7 @@ * The GPU, presenter and remaining devices are mocks. Build/run: * ctest -R render_pass_sandbox_test */ +#include "frame_trace.h" #include "render_pass.h" #include "render_pass_plan.h" @@ -222,6 +223,9 @@ void gpu_pass_checkpoint_restore(void) {} static uint64_t s_ticks; uint64_t gl_renderer_perf_ticks(void) { return s_ticks += 1000; } uint64_t gl_renderer_perf_frequency(void) { return 1000000000u; } +/* 1000 ticks per sample and a 1 GHz tick make one runtime sample exactly 1 us, + * so a bracketed guest span is the caller's own bump plus a known microsecond. */ +static void tick_bump(uint64_t ticks) { s_ticks += ticks; } static uint32_t s_gl_status = PSX_MOD_RENDER_PASS_READY; uint32_t gl_renderer_pass_unavailable(void) { return s_gl_status; } uint32_t gl_renderer_pass_plan(uint32_t p, uint32_t s, uint32_t *a, @@ -301,6 +305,18 @@ int gl_renderer_stereo_publish(uint64_t id, uint64_t cycle, const int32_t view[2 return 1; } +/* Frame-trace draw/diag inputs and the host clock the stereo shedding and + * tracing use. Not GL state this sandbox models, but render_pass.c references + * them, so they must exist to link. */ +void gl_renderer_runtime_diag(uint64_t out[6]) { memset(out, 0, 6 * sizeof *out); } +static uint64_t s_prims_stub; +void gl_renderer_scene_prim_counts(uint64_t *prims, uint64_t *textured) { + if (prims) *prims = s_prims_stub; + if (textured) *textured = s_prims_stub / 2u; +} +static uint64_t s_host_ms; +uint64_t psx_host_mono_ms(void) { return s_host_ms; } + /* ---- 1. store policy --------------------------------------------------- */ static void test_store_policy(void) { RenderPassStoreTarget t = target(); @@ -763,6 +779,134 @@ static void test_stereo(void) { "capture failure still restores live state"); f.period_vblanks = 0; CHECK(!psx_mod_render_stereo(&cpu, &f, pair_draw, NULL), "invalid cadence refused"); + + /* Tracing is observation only: the same pair must publish the same id and + * reach the same guest-state hashes with capture on as with it off. */ + { + uint64_t off_pub, off_hash[2], off_pair; + f.period_vblanks = 2; + psx_frame_trace_set_enabled(0); + render_pass_reset_session(); psx_frame_trace_set_enabled(0); + s_gl_status = 0; s_begin_ok = 1; s_eye_calls = 0; + cpu.gpr[8] = 123; s_ram[0x456] = 0x77; + CHECK(psx_mod_render_stereo(&cpu, &f, pair_draw, NULL) == 1, "pair with tracing off"); + render_stereo_get_stats(&stats); + off_pub = s_stereo_published; + off_hash[0] = stats.eye_hash[0]; off_hash[1] = stats.eye_hash[1]; + off_pair = stats.last_pair_id; + + render_pass_reset_session(); + psx_frame_trace_set_enabled(1); psx_frame_trace_reset(); + s_gl_status = 0; s_begin_ok = 1; s_eye_calls = 0; + cpu.gpr[8] = 123; s_ram[0x456] = 0x77; + CHECK(psx_mod_render_stereo(&cpu, &f, pair_draw, NULL) == 1, "pair with tracing on"); + render_stereo_get_stats(&stats); + CHECK(s_stereo_published == off_pub && stats.last_pair_id == off_pair && + stats.eye_hash[0] == off_hash[0] && stats.eye_hash[1] == off_hash[1], + "tracing changes neither the published pair nor the guest state"); + CHECK(psx_frame_trace_committed() > 0, "the traced pair was recorded"); + psx_frame_trace_set_enabled(0); psx_frame_trace_reset(); + } +} + +/* ---- 4. per-eye trace counters and guest sub-stage spans ---------------- */ +/* The shape of the game hook's per-eye replay: bracket the guest calls, and let + * the runtime time them. See vr/psx_vr_stereo.c vr_draw_scene. */ +static int s_traced_calls; +static int traced_draw(CPUState *cpu, void *user, uint32_t eye) { + (void)user; + s_traced_calls++; + s_prims_stub += 100u + 100u * eye; /* 100 prims, then 200 */ + psx_mod_frame_trace_stage_begin(PSX_TRACE_GAME_TRAVERSE); + tick_bump(3000); /* 3 us, plus 1 per sample */ + /* The visibility override runs inside the traversal it belongs to, so its + * span nests in that one: it must be timed on its own without truncating + * the span it is inside. */ + psx_mod_frame_trace_stage_begin(PSX_TRACE_GAME_SELECT); + tick_bump(2000); + psx_mod_frame_trace_stage_end(PSX_TRACE_GAME_SELECT); + tick_bump(1000); + psx_mod_frame_trace_stage_end(PSX_TRACE_GAME_TRAVERSE); + /* An end for a stage that was never opened, and a begin that is never + * ended: neither may reach the record. */ + psx_mod_frame_trace_stage_begin(PSX_TRACE_GAME_ENV); + tick_bump(1000); + psx_mod_frame_trace_stage_end(PSX_TRACE_GAME_SUBMIT); + psx_mod_frame_trace_stage_begin(PSX_TRACE_GAME_ICON); + tick_bump(1000); + psx_advance_cycles(4000u + 1000u * eye); + return 1; +} + +static void test_trace_substages(void) { + CPUState cpu = {0}; + PSXModStereoFrame f = {sizeof f, 2, 0, 240, 320, 240}; + PSXFrameTraceRecord rec; + PSXModRenderPass rect = {sizeof rect, 0, 0, 0, 2, 2}; + int first = 1, second = 2; + uint8_t pixels[32] = {0}; + + /* A session reset re-reads PSX_FRAME_TRACE from the env, so enabling the + * trace has to come after it (as it does in a real session). */ + render_pass_reset_session(); + s_gl_status = 0; s_begin_ok = 1; s_eye_decline = -1; s_eye_calls = 0; + s_prims_stub = 0; s_traced_calls = 0; + psx_frame_trace_set_enabled(1); + psx_frame_trace_reset(); + + CHECK(psx_mod_render_stereo(&cpu, &f, traced_draw, NULL) == 1, + "the traced pair rendered"); + CHECK(s_traced_calls == 2, "both eyes replayed the guest draw"); + CHECK(psx_frame_trace_read(&rec, 1) == 1, "the pair left one record"); + CHECK(rec.prims_l == 100 && rec.prims_r == 200, + "each eye's own primitive delta is recorded"); + CHECK(rec.prims == 200 && rec.textured_prims == 100, + "the pair-level count is still the last eye's"); + CHECK(rec.eye_cycles_l >= 4000u && rec.eye_cycles_r >= 5000u && + rec.eye_cycles_r > rec.eye_cycles_l, + "each eye's own guest cycles are recorded"); + CHECK(rec.stages_us[PSX_TRACE_GAME_TRAVERSE] == 18, + "both eyes' guest spans are recorded (9 us per eye, nesting included)"); + CHECK(rec.stages_us[PSX_TRACE_GAME_SELECT] == 6, + "a nested span is timed on its own (3 us per eye) and stays a subset"); + CHECK(rec.stages_us[PSX_TRACE_GAME_ENV] == 0 && + rec.stages_us[PSX_TRACE_GAME_SUBMIT] == 0, + "an end that does not match an open span records nothing"); + CHECK(rec.stages_us[PSX_TRACE_GAME_ICON] == 0, + "an unpaired begin records nothing rather than leak into the next span"); + + /* A HUD capture's guest draws run outside a traced eye: the hook's spans + * must not land in the frame they belong to. */ + psx_frame_trace_reset(); + s_prims_stub = 0; + s_traced_calls = 0; + render_pass_reset_session(); s_gl_status = 0; s_begin_ok = 1; + psx_frame_trace_set_enabled(1); + CHECK(psx_frame_trace_open(), "a frame record is open across the capture"); + CHECK(psx_mod_render_capture_rgba(&cpu, &rect, traced_draw, &first, + pixels, sizeof pixels) && + psx_mod_render_capture_rgba(&cpu, &rect, traced_draw, &second, + pixels, sizeof pixels), + "the captures rendered both mattes"); + CHECK(s_traced_calls == 2 && psx_frame_trace_read(&rec, 1) == 0, + "the capture replayed the draw and left no record of its own"); + psx_frame_trace_commit(); + CHECK(psx_frame_trace_read(&rec, 1) == 1 && + rec.stages_us[PSX_TRACE_GAME_TRAVERSE] == 0 && + rec.prims_l == 0 && rec.prims_r == 0, + "a capture's guest draws write no per-eye or sub-stage slots"); + + /* Same with the trace off: the hook may bracket freely. */ + psx_frame_trace_set_enabled(0); + psx_frame_trace_reset(); + s_prims_stub = 0; + s_traced_calls = 0; + render_pass_reset_session(); s_gl_status = 0; s_begin_ok = 1; + CHECK(psx_mod_render_stereo(&cpu, &f, traced_draw, NULL) == 1, + "the pair renders with tracing off"); + CHECK(s_traced_calls == 2 && psx_frame_trace_committed() == 0, + "nothing is recorded while tracing is off"); + render_pass_reset_session(); } static int local_draw(CPUState *cpu, void *user, uint32_t alpha) { @@ -879,6 +1023,7 @@ int main(void) { test_journal(); test_stereo(); test_isolated_capture(); + test_trace_substages(); test_local_view(); test_texture_stream_journal(); CHECK(s_prec_open == 0, "precision checkpoints balanced"); From 4f40f6f3c7b58c24a54f71a635e2a094b81b9c86 Mon Sep 17 00:00:00 2001 From: Matthew Stanley <1379tech@gmail.com> Date: Thu, 22 Oct 2026 14:03:16 -0700 Subject: [PATCH 2/3] Publish frame trace records only when committed --- runtime/src/frame_trace.c | 7 +++++-- runtime/tests/test_frame_trace.c | 15 +++++++++++++++ 2 files changed, 20 insertions(+), 2 deletions(-) diff --git a/runtime/src/frame_trace.c b/runtime/src/frame_trace.c index 7dba7663..620287cc 100644 --- a/runtime/src/frame_trace.c +++ b/runtime/src/frame_trace.c @@ -18,6 +18,8 @@ #define PSX_FRAME_TRACE_DEFAULT 2048 static PSXFrameTraceRecord s_ring[PSX_FRAME_TRACE_MAX]; +/* An in-progress frame never overwrites the retained committed window. */ +static PSXFrameTraceRecord s_pending; static int s_configured; static int s_enabled; @@ -129,7 +131,7 @@ void psx_frame_trace_reset(void) { } static PSXFrameTraceRecord *open_record(void) { - return &s_ring[(s_opened - 1u) & (uint64_t)(s_cap - 1u)]; + return &s_pending; } static uint64_t stamp_now(void) { @@ -145,7 +147,7 @@ int psx_frame_trace_open(void) { ensure_configured(); if (!s_enabled || s_have_open) return 0; uint64_t seq = s_opened + 1u; - PSXFrameTraceRecord *r = &s_ring[(seq - 1u) & (uint64_t)(s_cap - 1u)]; + PSXFrameTraceRecord *r = &s_pending; memset(r, 0, sizeof *r); r->seq = seq; r->eye_failed = -1; @@ -283,6 +285,7 @@ void psx_frame_trace_commit(void) { } else if (s_have_publish) { r->pair_age_ms = r->open_ms - s_last_publish_ms; } + s_ring[(r->seq - 1u) & (uint64_t)(s_cap - 1u)] = *r; s_committed++; s_have_open = 0; } diff --git a/runtime/tests/test_frame_trace.c b/runtime/tests/test_frame_trace.c index 3f887fe0..821b46be 100644 --- a/runtime/tests/test_frame_trace.c +++ b/runtime/tests/test_frame_trace.c @@ -194,6 +194,21 @@ int main(void) { CHECK(one[0].seq == extra); } + /* Opening the next frame must not retire a committed slot before commit. */ + { + static PSXFrameTraceRecord retained[4096]; + uint32_t capacity = psx_frame_trace_capacity(); + uint64_t committed = psx_frame_trace_committed(); + CHECK(psx_frame_trace_open() == 1); + psx_frame_trace_note("not committed"); + CHECK(psx_frame_trace_read(retained, capacity) == capacity); + CHECK(retained[0].seq == committed - capacity + 1); + CHECK(retained[capacity - 1].seq == committed); + psx_frame_trace_commit(); + CHECK(psx_frame_trace_read(retained, capacity) == capacity); + CHECK(retained[capacity - 1].seq == committed + 1); + } + /* ---- exports: valid, NULL-terminated, truncation-safe ---- */ { static char big[1 << 20]; From 89161e93f36d169e1a1c61d6d7dfdd329a283199 Mon Sep 17 00:00:00 2001 From: Matthew Stanley <1379tech@gmail.com> Date: Thu, 22 Oct 2026 14:08:27 -0700 Subject: [PATCH 3/3] Keep truncated trace JSON string escapes complete --- runtime/src/frame_trace.c | 11 ++++++----- runtime/tests/test_frame_trace.c | 13 +++++++++++++ 2 files changed, 19 insertions(+), 5 deletions(-) diff --git a/runtime/src/frame_trace.c b/runtime/src/frame_trace.c index 620287cc..4567fbff 100644 --- a/runtime/src/frame_trace.c +++ b/runtime/src/frame_trace.c @@ -334,14 +334,15 @@ static const char *jstr(const char *s, char *tmp, int cap) { int o = 0; if (cap <= 0) return ""; tmp[0] = '\0'; - for (const char *p = s; p && *p && o < cap - 2; ++p) { - unsigned char c = (unsigned char)*p; + for (const unsigned char *p = (const unsigned char *)s; p && *p; ++p) { + const unsigned char c = *p; + const int need = c == '"' || c == '\\' || c == '\n' ? 2 : c < 0x20 ? 6 : 1; + if (need > cap - 1 - o) break; if (c == '"' || c == '\\') { tmp[o++] = '\\'; tmp[o++] = (char)c; } - else if (c == '\n') { tmp[o++] = '\\'; if (o < cap - 1) tmp[o++] = 'n'; } - else if (c < 0x20) { o += snprintf(tmp + o, (size_t)(cap - o), "\\u%04x", c); } + else if (c == '\n') { tmp[o++] = '\\'; tmp[o++] = 'n'; } + else if (c < 0x20) o += snprintf(tmp + o, (size_t)(cap - o), "\\u%04x", c); else tmp[o++] = (char)c; } - if (o > cap - 1) o = cap - 1; tmp[o] = '\0'; return tmp; } diff --git a/runtime/tests/test_frame_trace.c b/runtime/tests/test_frame_trace.c index 821b46be..8650980c 100644 --- a/runtime/tests/test_frame_trace.c +++ b/runtime/tests/test_frame_trace.c @@ -254,6 +254,19 @@ int main(void) { CHECK(strstr(meta, "\"target_period_us\":0") != NULL); } + /* Fixed scratch buffers may shorten a string, never split a JSON escape. */ + { + char controls[128]; static char json[1 << 16]; + memset(controls, 1, sizeof controls - 1); controls[127] = 0; + psx_frame_trace_session(controls, 0); + CHECK(psx_frame_trace_to_json(json, sizeof json, 1) > 0); + const char *value = strstr(json, "\"runtime\":\""); + CHECK(value != NULL); value += strlen("\"runtime\":\""); + const char *end = strchr(value, '\"'); + CHECK(end && (end - value) % 6 == 0); + for (; value < end; value += 6) CHECK(!memcmp(value, "\\u0001", 6)); + } + /* ---- XR cadence: the runtime's display-time delta and repeat marking ---- * One presented pair per granted display period is the pacing target, so a * frame that carried no new pair must be distinguishable from one that did