From d46495def85f12b60e14215935c82a742822ce4e Mon Sep 17 00:00:00 2001 From: Mihawk Date: Sat, 19 Sep 2026 11:30:05 -0400 Subject: [PATCH] Keep development logs while buffering GPU timing off the frame loop Retain frontend INFO/WARN/ERROR, driver errors, startup trace and klog. Restore frontend log setup after rebuilt arguments, mark its build identity, and retrieve it with each run. Remove periodic frame and button chatter; log menu texture handover once. Profiling is opt-in, bounded and written only after capture; validate per-frame partitions and presentation-return cadence. Verified: bash tools/verify.sh (all gates, 28 tests); fresh vendor patch replay/idempotence (86 edits). Two 60-second captures completed: first at 59.940238 FPS with maximum interval 16.905813 ms; fresh frontend logging exposed three late texture-probe stalls, then those probes were limited. Final refined build launched with zero refusals, logged handover once and returned 0 before profiling completed; no final timing claim is made. User requested ending performance investigation and proceeding to XMB. Evidence: evidence/vulkan-buffered-logging/{capture,expectation}.json Replay: python3 tools/evidence.py compare evidence/ Console: bash tools/run-title.sh --no-build --gpu-profile 60 --watch 80 Analysis: python3 tools/analyze-gpu-profile.py klog/gpu-profile-.tsv --- docs/ACTIVE.md | 112 +++-- docs/DEPLOYMENT.md | 9 + docs/GPU_TIMING.md | 124 +++-- docs/PHASE_LOG.md | 36 ++ evidence/vulkan-buffered-logging/capture.json | 423 ++++++++++++++++++ .../vulkan-buffered-logging/expectation.json | 13 + patches/series | 9 + src/input_ps5.cpp | 22 +- src/main.cpp | 7 + src/vulkan_trace.cpp | 201 +++++++-- tests/test_frontend.py | 2 +- tests/test_gpu_profile.py | 41 ++ tests/test_vulkan_trace.py | 22 + tools/analyze-gpu-profile.py | 80 ++++ tools/apply-port-patches.py | 77 ++++ tools/run-title.sh | 65 ++- 16 files changed, 1075 insertions(+), 168 deletions(-) create mode 100644 evidence/vulkan-buffered-logging/capture.json create mode 100644 evidence/vulkan-buffered-logging/expectation.json create mode 100644 tests/test_gpu_profile.py create mode 100644 tools/analyze-gpu-profile.py diff --git a/docs/ACTIVE.md b/docs/ACTIVE.md index 6babbf3..c61d23f 100644 --- a/docs/ACTIVE.md +++ b/docs/ACTIVE.md @@ -4,74 +4,66 @@ _Updated: 2026-09-19_ ## Now -**Quiet GPU profiling is verified.** The new performance request supersedes the -previous note that performance was outside the completed menu-rendering task. -The final 45-second run produced eight timing windows: **53.76–57.94 FPS**, or -**55.92 FPS** over 2,239 measured frames / 40.039 seconds. There was no progressive -collapse. This is not yet steady 60 FPS: isolated frame spikes remain. +**The user ended further performance investigation and requested committing the +logging work, then enabling XMB as the default menu and testing it on PS5.** +That is the next task; do not continue optimizing RGUI frame timing. -The owner reports "Noticeable improvement" and an estimated refresh-rate display -that starts near 40 Hz and rises. That display averages observed frame intervals -(`video_monitor_fps_statistics`), not the fixed 60 Hz output mode. Slower early -frames can depress it while later faster frames raise it. +## Logging step -## What the measurements distinguish +Routine periodic frame/render/API-success messages and successful input-button +traces are removed; bounded startup diagnostics and all errors remain. Menu +handover/staging-ask probes now log once. `retroarch.log` is explicitly enabled +after argument/config processing and records this build's identity; the old file +had been stale because this port rebuilds arguments. INFO/WARN/ERROR output, +Vulkan refusals/assertions in `trace.txt`, and host kernel capture remain enabled. -Final weighted averages, milliseconds per frame: +Profiling is off by default. `tools/run-title.sh --gpu-profile 60 --watch 80` +opts into 120 warmup frames followed by up to 60 seconds of in-memory timing. +The report is written only after measurement and the one-shot control is consumed. +The runner checks idle state before upload/launch, retrieves `retroarch.log` and +optional timing, and rejects a frontend log without the expected build identity. +Definitions/replay: `docs/GPU_TIMING.md`, `tools/analyze-gpu-profile.py`. -| Work | Time | -| --- | ---: | -| Video callback preparation/other recording work | 5.344 | -| Command-buffer finalization | 0.020 | -| `vkQueueSubmit` | 3.525 | -| `vkQueuePresentKHR` | 8.075 | -| Fence/image acquisition waits | 0.041 | -| Menu texture update outside the callback | 0.153 | -| Other time between video callbacks | 0.724 | -| Total frame interval | 17.882 | +## Verified results and limits -The preliminary run quieted three logs but left texture-creation/staging-ask -logging active. Its rate fell from 35.91 to 1.63–1.98 FPS; the growing delay was -outside the video callback (up to 958 ms), while submit stayed near 3.5 ms. -Limiting the other two logs removed that collapse in the final run. This strongly -implicates this port's unbuffered diagnostic I/O, rather than long submission or -presentation stalls, in the severe slowdown. No driver code changed. +- First buffered run: 3,597 frames / 60.0098 seconds, **59.940238 FPS**; + maximum frame interval **16.905813 ms**, no presentation-return gap above 20 ms. + Owner: "Very smooth", stable estimated refresh **59.941 Hz** after startup. +- Restoring fresh frontend logging exposed three ~100 ms texture-update stalls + from remaining first-four-call diagnostics. They were reduced to one initial + message. The logger now contains this build's identity and Vulkan startup. +- Final refined build launched with zero driver refusals, logged each menu + handover probe once, and returned from `rarch_main` with status 0 before the + profile completed. The runner rejected the missing report. **No final timing + result is claimed.** The user requested proceeding to XMB instead of more tests. +- `evidence/vulkan-buffered-logging/` contains both completed timing analyses and + the final startup/logging evidence, including that incomplete final capture. +- All five `tools/verify.sh` gates PASS; 28 tests. Fresh vendor patch replay and + second-pass idempotence PASS: 86 edits. +- Installed identity: + `a6063c61145fb42ac409a1d78026f29865673e4575e9a6afc3500e4abccc4f66`. +- Fresh frontend logs retain the existing audio-driver initialization errors and + missing configuration-save directory error. These are outside this logging/menu + step, not Vulkan failures; audio/config persistence are not claimed complete. -These are CPU-observed elapsed times, not GPU timestamps or CPU utilization. -The final trace still has occasional spikes (maximum interval 282 ms, including -early work; later windows reach 167–184 ms). Sparse progress logs and the timing -summary itself remain possible contributors, not measured root causes of every -spike. Definitions and reproduction: `docs/GPU_TIMING.md`. - -## Evidence and validation - -- `evidence/vulkan-quiet-timing/`: both run windows, identities, sanitized API - counters, owner observations and timing audit. Final trace has zero refusals, - no recorded API errors and no CPU fallback initialization. -- Final tested and installed identity: - `38ada4be3b74b8230ec13aae97b7d3618c4635760c30e90b29a54f0008e14450`. -- All five `tools/verify.sh` gates PASS, 26 tests. Fake-clock regression verifies - phase partitions, warmup exclusion, window reset and unchanged API results. -- Fresh vendor patch application and second-pass idempotence PASS: 77 edits. -- Both 45-second runs completed and were closed by their scripts. All five - formerly unbounded texture diagnostics emit only their first four calls. -- PS5_Vulkan remains at **6f0ce0d**, unmodified in this profiling step. +Presentation measurements are CPU timestamps at this driver's synchronous +present return, not hardware vblank counters. RGUI's refresh estimate averages +frame intervals; startup frames depress it. No guarantee for other workloads. ## Preserved GPU acceptance and operating notes -The owner-confirmed correct GPU menu remains recorded in -`evidence/vulkan-fragment-inputs/`: RGBA conversion **947134d**, fragment compiler -fix **6f0ce0d**, no flicker/triangles. `video_vulkan` uses statically linked libps5vk; -`video_ps5` stays registered and selectable. No partial rendering-route switch. -Temporary image/resource captures remain retired under `parked/gpu-readback/`; -the failed blend experiment remains under `parked/explicit-stock-blend/`. +Correct GPU RGUI is recorded in `evidence/vulkan-fragment-inputs/`: RGBA conversion +**947134d**, driver compiler fix **6f0ce0d**, owner-confirmed correct colours and no +flicker/triangles. PS5_Vulkan was not modified in this logging step. `video_vulkan` +uses statically linked libps5vk; `video_ps5` stays registered/selectable. -The user authorized necessary driver changes with documentation and a commit in -PS5_Vulkan, and console uploads/runs without further confirmation. Check the shared -console is idle **before uploading**; never interrupt an existing title to test. -`tools/run-title.sh` owns deployment, identity readback, launch, watch and closure. -Raw console data stays in ignored `klog/`. Extract the last `bss check=` substring -from appended traces and check the build identity before interpreting results. +The user authorized necessary driver fixes with documentation and a commit in +PS5_Vulkan, and console uploads/runs without further permission. Never interrupt +an existing title to test. Raw captures remain in ignored `klog/`. Extract the +last `bss check=` substring and verify identity before reading appended traces. +No partial switch to the CPU route if the GPU refusal gate cannot be satisfied. -Further performance work should isolate remaining spikes and summary/progress -I/O before changing driver synchronization. Core/audio work is a separate scope. +XMB preparation: the current build disables HAVE_XMB, only RGUI fonts are staged. +Official assets were fetched into ignored `vendor/retroarch-assets` at +`73106363e14e34c08a5854b4cfbc29f184e3b783`; monochrome icons/font are available. +No XMB implementation change has landed yet. diff --git a/docs/DEPLOYMENT.md b/docs/DEPLOYMENT.md index b79b3cf..315f6d3 100644 --- a/docs/DEPLOYMENT.md +++ b/docs/DEPLOYMENT.md @@ -127,3 +127,12 @@ Two habits follow from that: - Treat a run as a claim about the revision it was launched from. The launch records the revision in `evidence//capture.json`, so a run that belongs to a different revision is visible rather than implied. + +## Buffered GPU timing with development logs + +`tools/run-title.sh --gpu-profile 60 --watch 80` opts into a bounded in-memory +capture, then retrieves the profile and the current `retroarch.log` alongside +its kernel/trace capture. A normal run omits `--gpu-profile`. The runner checks +console availability before upload and again before launch, and validates the +frontend log's build identity to reject stale logs. See `docs/GPU_TIMING.md` for +measurement definitions and `tools/analyze-gpu-profile.py` for replay. diff --git a/docs/GPU_TIMING.md b/docs/GPU_TIMING.md index 7014aa8..8018b07 100644 --- a/docs/GPU_TIMING.md +++ b/docs/GPU_TIMING.md @@ -1,51 +1,93 @@ -# Quiet Vulkan frame timing +# Buffered Vulkan frame timing and development logs -Build with `bash tools/verify.sh`, confirm the shared console is idle, then run -`bash tools/run-title.sh --no-build --watch 45`. The runner clears stale capture -arguments and closes the title at the end. No image readback hook is active. -Extract only the last launch from the appended trace, starting at the last -`bss check=` substring, and verify its input-derived build identity. +Normal launches keep logging enabled but do not run the profiler. Keep +`/app0/retroarch.log` for frontend/core/menu lifecycle, INFO/WARN/ERROR messages; +`/app0/trace.txt` for build identity, startup milestones, assertions and driver +refusals/API errors; and host `klog/` captures for kernel failures. Errors are +not buffered away. Successful button transitions and periodic frame/render +markers are routine chatter and no longer write files. Startup probes remain +bounded to their initial calls. -Patch 0056 limits the formerly unbounded RGUI texture-handover, Vulkan -texture-update, texture-creation and staging-copy diagnostics to their first four calls. Existing -startup, sparse progress and error/refusal reporting stays enabled. Timing adds -no per-frame file writes or allocation: one summary appears after each window -of at least five seconds. The first four completed video callbacks are warmup. +Patch 0058 reasserts the frontend file logger after config/argument processing: +this port's argument rebuilding previously lost the launcher's logging request. +Each frontend startup/core reload records the title's input-derived build identity +in `retroarch.log`. The run tool refuses to accept a log without the expected +identity. This is distinct from the identity check on the uploaded executable. -`src/vulkan_trace.cpp` uses `CLOCK_MONOTONIC` around the real Vulkan function -pointers and around `vulkan_frame`, from its initial diagnostic marker through -the return from the context's swap callback. Results and arguments are preserved. -The current title's video loop is single-threaded; this instrumentation is for -that configuration and the ordinary menu path, not threaded rendering or BFI. +## Capture and reproduce -Each `gpu timing:` line records completed frame count, measured seconds, -`fps = frames / seconds`, and **average/maximum milliseconds per frame**: +Build with `bash tools/verify.sh`, then: + +```sh +bash tools/run-title.sh --no-build --gpu-profile 60 --watch 80 +python3 tools/analyze-gpu-profile.py klog/gpu-profile-.tsv +``` + +The runner requires the shared console to be idle before uploading, checks again +before launching, clears stale capture controls, and closes its title afterward. +It saves `retroarch-.log`, `gpu-profile-.tsv` and the kernel capture +in ignored `klog/`. Trace output stays in the run transcript. Extract only the +last `bss check=` substring from appended traces and verify its build identity. + +`--gpu-profile` accepts 1..60 seconds. Allow at least 15 extra watch seconds for +startup and reporting. The runner writes `/app0/gpu-profile.txt`; title startup +consumes this one-shot opt-in. The runner also removes stale controls on later +runs, including runs without profiling. Neither control nor results are deployed +as part of the normal title. There is no image readback hook. + +The profiler skips 120 completed callbacks, then collects nanosecond records in +a bounded 8,192-frame array and aggregates five-second windows **without file +I/O**. When the requested interval finishes, it stops sampling and writes one +buffered `gpu-profile.tsv` report. That reporting pause is outside the sample +and occurs only in an opted-in diagnostic run. A killed/failed run may have no +report; a full buffer is explicitly flagged and rejected by the analyzer rather +than being presented as a complete measurement. + +## Meaning of the measurements + +`src/vulkan_trace.cpp` uses `CLOCK_MONOTONIC` around real Vulkan function pointers +and around `vulkan_frame`, from its initial diagnostic marker through the return +from the context's swap callback. Arguments and results remain unchanged. +Measurements assume the title's single-threaded video loop and ordinary menu +path, not threaded video or BFI/multiple presentations per callback. + +Each `gpu timing:` window in the result gives completed frames, measured seconds, +FPS, and average/maximum milliseconds per frame. TSV records preserve every +frame's phase times and presentation-completion interval in nanoseconds. | Field | Measurement | | --- | --- | -| `interval` | Previous completed callback through this completed callback; includes frontend work between them. | -| `outside` | Previous callback completion through this callback entry, excluding `texture`: frontend/menu/input/pacing work, previous callback tail, and summary I/O. | -| `texture` | Menu `vulkan_set_texture_frame` callback between video frames, including resource creation/reuse, CPU conversion and memory mapping/flushes. | -| `prepare` | Callback wall time minus the four explicitly timed API categories below; includes command recording, uploads and other frontend/driver calls. | -| `end` | Sum of real `vkEndCommandBuffer` calls inside the callback. | -| `submit` | Sum of real `vkQueueSubmit` calls inside the callback, including synchronous driver work/waits. | -| `present` | Sum of real `vkQueuePresentKHR` calls inside the callback, including display waits. | -| `wait` | Sum of real `vkWaitForFences` and `vkAcquireNextImageKHR` calls inside the callback. | +| `interval` | Previous completed callback through this completed callback. | +| `outside` | Time between callbacks excluding the menu texture-update callback: menu/input/pacing work and the previous callback's tail. | +| `texture` | Menu `vulkan_set_texture_frame` between video callbacks, including resource creation/reuse, conversion and memory operations. | +| `prepare` | Video callback wall time minus the four explicitly timed API categories below; includes command recording, uploads and other calls. | +| `end` | Real `vkEndCommandBuffer` calls inside the callback. | +| `submit` | Real `vkQueueSubmit` calls, including synchronous driver work/waits. | +| `present` | Real `vkQueuePresentKHR` calls, including display waits. | +| `wait` | Real `vkWaitForFences` and `vkAcquireNextImageKHR` calls. | +| `present_interval` | Time between successful synchronous `vkQueuePresentKHR` returns. | -Average `outside + texture + prepare + end + submit + present + wait` equals average -`interval` apart from printed rounding. Maxima can belong to different frames; -they must not be added. An early return without a completion hook invalidates -that interval rather than charging its gap to the next completed frame. +`outside + texture + prepare + end + submit + present + wait` equals `interval` +for each recorded frame. Maxima can belong to different frames and cannot be +added. An incomplete callback invalidates the next interval instead of charging +an unmeasured gap to it. -These are CPU-observed **elapsed times**, not CPU utilization or GPU execution -timestamps. A long submission locates the stall inside the driver call but does -not distinguish cache maintenance, CPU copies, kernel submission and waiting for -the GPU. A long `prepare` likewise requires further separation before assigning -blame to RetroArch rather than driver command-recording operations. Measurements -at the driver's current 3840x2160 swapchain are not a like-for-like comparison -with the CPU fallback's 1920x1080 output. +These are CPU-observed elapsed times, not CPU utilization or GPU timestamps. +This driver's present call returns after its flip marker reaches VideoOut, so +return intervals provide useful presentation-completion cadence. They are not +hardware scanout timestamps or exact missed-vblank counts. The analyzer reports +intervals above 20/25 ms and rounded estimates of extra 60 Hz intervals, explicitly +labelled as estimates. Small scheduling jitter around 16.67 ms is not proof of a +missed refresh. A cadence near 16.683 ms corresponds to about 59.94 Hz. -The fake-clock regression in `tests/test_vulkan_trace.py` checks partition sums, -warmup exclusion, five-second windows, reset behavior and dispatch/result -preservation, including timeout/suboptimal acquire results. Measured run records -live under `evidence/`; current findings belong in `docs/ACTIVE.md`. +The menu's "estimated screen refresh rate" averages observed frame intervals +(`video_monitor_fps_statistics`); startup delays can initially depress it. It +is separate from the driver's declared 60 Hz display mode. This measurement +cannot guarantee other cores/workloads, nor compare 4K Vulkan with the 1080p CPU +fallback as if they rendered the same number of pixels. + +Fake-clock tests cover phase partitions, presentation spacing, warmup, delayed +output, capacity limits, stop behavior and dispatch/result preservation. Analyzer +tests reject truncated/error captures and inconsistent timing partitions. Run +`bash tools/verify.sh` for the complete gates. Current results and remaining +limitations belong in `docs/ACTIVE.md` and the committed evidence. diff --git a/docs/PHASE_LOG.md b/docs/PHASE_LOG.md index 07233ab..72bcfe9 100644 --- a/docs/PHASE_LOG.md +++ b/docs/PHASE_LOG.md @@ -1694,3 +1694,39 @@ Evidence: `evidence/vulkan-quiet-timing/{capture,expectation}.json`, replay with `python3 tools/evidence.py compare evidence/`. Private raw captures: `klog/gpu-quiet-timing-run.log`, `klog/gpu-quiet-texture-timing-run.log` and their `*-latest-trace.txt` extracts. Timing definitions: `docs/GPU_TIMING.md`. + +## 2026-09-19 — Keep development logs, buffer profiling, then move to XMB + +User requested important logs remain available while removing frame-loop stalls. +Patches 0057–0059 and the local profiler remove periodic successful-frame writes, +stop button-transition chatter, and make the two menu-handover probes once-only. +Startup diagnostics, driver errors/refusals and assertions remain. The frontend +logger is explicitly re-enabled after argument/config processing and writes the +build identity: the old 1,200-byte file had been stale. The run tool now captures +and verifies this log, and checks idle state before uploading and launching. + +Profiling is opt-in (one-shot gpu-profile.txt), with 120 warmup frames and a bounded +8,192-frame buffer. No summary/file writes occur during the measurement. It writes +windows and per-frame TSV after capture; tools/analyze-gpu-profile.py validates +phase sums/completeness and reports percentiles and presentation-return intervals. +These intervals are not hardware scanout timestamps; missed-interval values are +explicitly estimates. No driver or SDK code changed. + +Commands: bash tools/verify.sh; bash tools/run-title.sh --no-build --gpu-profile 60 +--watch 80; python3 tools/analyze-gpu-profile.py klog/gpu-profile-.tsv. +First buffered run (111457): 3,597 frames, 60.009771315 s, 59.940238 FPS, maximum +interval 16.905813 ms, no presentation-completion gap above 20 ms. Owner: "Very +smooth", estimate stabilizes at 59.941 Hz. With fresh frontend logging (112036): +3,582 frames, 59.690273 FPS, three ~100 ms gaps localized to texture updates. +The remaining first-four-call texture probes could occur late and were limited +to one initial call. The final run (112603), identity +a6063c61145fb42ac409a1d78026f29865673e4575e9a6afc3500e4abccc4f66, launched with +zero refusals and a current frontend log, then rarch_main returned 0 before the +profile completed. Required profile retrieval failed correctly. No final timing +claim is made, and no further performance run was started: the user requested +committing and proceeding to XMB. Existing audio/config-save errors remain visible +and outside this step's acceptance. + +All five host gates PASS, 28 tests; fresh patch replay/idempotence PASS, 86 edits. +Evidence: evidence/vulkan-buffered-logging/{capture,expectation}.json. Replay: +python3 tools/evidence.py compare evidence/. Raw logs and TSV remain in klog/. diff --git a/evidence/vulkan-buffered-logging/capture.json b/evidence/vulkan-buffered-logging/capture.json new file mode 100644 index 0000000..2d5762b --- /dev/null +++ b/evidence/vulkan-buffered-logging/capture.json @@ -0,0 +1,423 @@ +{ + "step": "vulkan-buffered-logging", + "command": "bash tools/verify.sh; bash tools/run-title.sh --no-build --gpu-profile 60 --watch 80; python3 tools/analyze-gpu-profile.py klog/gpu-profile-.tsv", + "raw_capture": "klog/gpu-buffered-final-latest-trace.txt", + "raw_lines": 69, + "tested_build_identity": "a6063c61145fb42ac409a1d78026f29865673e4575e9a6afc3500e4abccc4f66", + "driver_modified": false, + "first_buffered_run": { + "frames": 3597, + "seconds": 60.009771315, + "fps": 59.94023841748746, + "phases": { + "interval": { + "mean_ms": 16.683283657214346, + "p99_ms": 16.72267, + "max_ms": 16.905813 + }, + "outside": { + "mean_ms": 0.12889975896580483, + "p99_ms": 0.188516, + "max_ms": 0.406701 + }, + "texture": { + "mean_ms": 0.035703493744787325, + "p99_ms": 0.049474, + "max_ms": 0.08219 + }, + "prepare": { + "mean_ms": 4.4030740150125105, + "p99_ms": 4.912078, + "max_ms": 6.101148 + }, + "end": { + "mean_ms": 0.018530612732832918, + "p99_ms": 0.023414, + "max_ms": 0.037767 + }, + "submit": { + "mean_ms": 3.592564045315541, + "p99_ms": 4.402821, + "max_ms": 4.690767 + }, + "present": { + "mean_ms": 8.46717335474006, + "p99_ms": 12.006885, + "max_ms": 13.024278 + }, + "wait": { + "mean_ms": 0.037338376702807895, + "p99_ms": 0.046908, + "max_ms": 0.062786 + }, + "present_interval": { + "mean_ms": 16.68331225827078, + "p99_ms": 16.719542, + "max_ms": 16.901242 + } + }, + "presentation": { + "completion_intervals_over_20ms": 0, + "completion_intervals_over_25ms": 0, + "estimated_extra_60hz_intervals": 0, + "limitation": "CPU times at successful synchronous vkQueuePresentKHR return; not hardware vblank counters or scanout timestamps. Extra 60 Hz intervals are rounded estimates, not exact missed-vblank counts." + }, + "slowest_frames": [ + { + "frame": 1945, + "interval_ns": 16905813, + "outside_ns": 137438, + "texture_ns": 41536, + "prepare_ns": 4832054, + "end_ns": 20528, + "submit_ns": 3537620, + "present_ns": 8292054, + "wait_ns": 44583, + "present_interval_ns": 16901242, + "present_calls": 1 + }, + { + "frame": 2750, + "interval_ns": 16869248, + "outside_ns": 138319, + "texture_ns": 41777, + "prepare_ns": 4836143, + "end_ns": 20447, + "submit_ns": 3521824, + "present_ns": 8270244, + "wait_ns": 40494, + "present_interval_ns": 16869408, + "present_calls": 1 + }, + { + "frame": 2025, + "interval_ns": 16832042, + "outside_ns": 142649, + "texture_ns": 42819, + "prepare_ns": 4788753, + "end_ns": 20207, + "submit_ns": 3542111, + "present_ns": 8254769, + "wait_ns": 40734, + "present_interval_ns": 16831883, + "present_calls": 1 + }, + { + "frame": 2630, + "interval_ns": 16825387, + "outside_ns": 140725, + "texture_ns": 42258, + "prepare_ns": 4798214, + "end_ns": 20127, + "submit_ns": 3529281, + "present_ns": 8250920, + "wait_ns": 43862, + "present_interval_ns": 16820897, + "present_calls": 1 + }, + { + "frame": 2321, + "interval_ns": 16813680, + "outside_ns": 141127, + "texture_ns": 43139, + "prepare_ns": 4827802, + "end_ns": 21810, + "submit_ns": 3451903, + "present_ns": 8287083, + "wait_ns": 40816, + "present_interval_ns": 16813199, + "present_calls": 1 + }, + { + "frame": 2324, + "interval_ns": 16810071, + "outside_ns": 138481, + "texture_ns": 43139, + "prepare_ns": 4851858, + "end_ns": 20207, + "submit_ns": 3547002, + "present_ns": 8168649, + "wait_ns": 40735, + "present_interval_ns": 16809831, + "present_calls": 1 + }, + { + "frame": 932, + "interval_ns": 16806623, + "outside_ns": 143852, + "texture_ns": 44904, + "prepare_ns": 4834540, + "end_ns": 20367, + "submit_ns": 3547964, + "present_ns": 8173861, + "wait_ns": 41135, + "present_interval_ns": 16806142, + "present_calls": 1 + }, + { + "frame": 35, + "interval_ns": 16794516, + "outside_ns": 406701, + "texture_ns": 0, + "prepare_ns": 4790597, + "end_ns": 20126, + "submit_ns": 3345817, + "present_ns": 8190300, + "wait_ns": 40975, + "present_interval_ns": 16797483, + "present_calls": 1 + }, + { + "frame": 975, + "interval_ns": 16759314, + "outside_ns": 88525, + "texture_ns": 0, + "prepare_ns": 4795649, + "end_ns": 20127, + "submit_ns": 3348383, + "present_ns": 8465977, + "wait_ns": 40653, + "present_interval_ns": 16757630, + "present_calls": 1 + }, + { + "frame": 2139, + "interval_ns": 16739989, + "outside_ns": 149145, + "texture_ns": 42979, + "prepare_ns": 4826280, + "end_ns": 20207, + "submit_ns": 3526955, + "present_ns": 8133769, + "wait_ns": 40654, + "present_interval_ns": 16741273, + "present_calls": 1 + } + ] + }, + "logger_restored_run": { + "frames": 3582, + "seconds": 60.009777249, + "fps": 59.6902732222638, + "phases": { + "interval": { + "mean_ms": 16.75314831072027, + "p99_ms": 16.721948, + "max_ms": 100.113583 + }, + "outside": { + "mean_ms": 0.13493418118369627, + "p99_ms": 0.19477, + "max_ms": 1.333243 + }, + "texture": { + "mean_ms": 0.10768433277498604, + "p99_ms": 0.050357, + "max_ms": 87.218083 + }, + "prepare": { + "mean_ms": 4.4205507816862095, + "p99_ms": 4.917371, + "max_ms": 5.951922 + }, + "end": { + "mean_ms": 0.01857901479620324, + "p99_ms": 0.023735, + "max_ms": 0.039772 + }, + "submit": { + "mean_ms": 3.591722783919598, + "p99_ms": 4.392236, + "max_ms": 4.691568 + }, + "present": { + "mean_ms": 8.442264174204356, + "p99_ms": 12.002956, + "max_ms": 12.123875 + }, + "wait": { + "mean_ms": 0.037413042155220545, + "p99_ms": 0.046507, + "max_ms": 0.058535 + }, + "present_interval": { + "mean_ms": 16.753175307928533, + "p99_ms": 16.719302, + "max_ms": 100.11246 + } + }, + "presentation": { + "completion_intervals_over_20ms": 3, + "completion_intervals_over_25ms": 3, + "estimated_extra_60hz_intervals": 15, + "limitation": "CPU times at successful synchronous vkQueuePresentKHR return; not hardware vblank counters or scanout timestamps. Extra 60 Hz intervals are rounded estimates, not exact missed-vblank counts." + }, + "slowest_frames": [ + { + "frame": 185, + "interval_ns": 100113583, + "outside_ns": 126852, + "texture_ns": 83809161, + "prepare_ns": 4854507, + "end_ns": 20287, + "submit_ns": 3531526, + "present_ns": 7730356, + "wait_ns": 40894, + "present_interval_ns": 100112460, + "present_calls": 1 + }, + { + "frame": 195, + "interval_ns": 100110776, + "outside_ns": 130862, + "texture_ns": 83570288, + "prepare_ns": 4828125, + "end_ns": 20126, + "submit_ns": 3523428, + "present_ns": 7997053, + "wait_ns": 40894, + "present_interval_ns": 100110456, + "present_calls": 1 + }, + { + "frame": 191, + "interval_ns": 100087763, + "outside_ns": 128057, + "texture_ns": 87218083, + "prepare_ns": 4892272, + "end_ns": 20207, + "submit_ns": 3535936, + "present_ns": 4252554, + "wait_ns": 40654, + "present_interval_ns": 100087362, + "present_calls": 1 + }, + { + "frame": 2664, + "interval_ns": 16949193, + "outside_ns": 147060, + "texture_ns": 41937, + "prepare_ns": 4801342, + "end_ns": 20046, + "submit_ns": 3499372, + "present_ns": 8398221, + "wait_ns": 41215, + "present_interval_ns": 16948151, + "present_calls": 1 + }, + { + "frame": 1509, + "interval_ns": 16915756, + "outside_ns": 149867, + "texture_ns": 42338, + "prepare_ns": 4815135, + "end_ns": 20126, + "submit_ns": 3529923, + "present_ns": 8317313, + "wait_ns": 41054, + "present_interval_ns": 16915355, + "present_calls": 1 + }, + { + "frame": 2661, + "interval_ns": 16820255, + "outside_ns": 140645, + "texture_ns": 43140, + "prepare_ns": 4797896, + "end_ns": 20126, + "submit_ns": 3534814, + "present_ns": 8242580, + "wait_ns": 41054, + "present_interval_ns": 16821298, + "present_calls": 1 + }, + { + "frame": 871, + "interval_ns": 16786578, + "outside_ns": 156121, + "texture_ns": 42178, + "prepare_ns": 4860279, + "end_ns": 20207, + "submit_ns": 3527276, + "present_ns": 8139782, + "wait_ns": 40735, + "present_interval_ns": 16786256, + "present_calls": 1 + }, + { + "frame": 150, + "interval_ns": 16750895, + "outside_ns": 93095, + "texture_ns": 0, + "prepare_ns": 4797414, + "end_ns": 20206, + "submit_ns": 3364901, + "present_ns": 8434464, + "wait_ns": 40815, + "present_interval_ns": 16750494, + "present_calls": 1 + }, + { + "frame": 1630, + "interval_ns": 16744721, + "outside_ns": 147301, + "texture_ns": 42739, + "prepare_ns": 4803749, + "end_ns": 20126, + "submit_ns": 3550209, + "present_ns": 8132405, + "wait_ns": 48192, + "present_interval_ns": 16727159, + "present_calls": 1 + }, + { + "frame": 1244, + "interval_ns": 16740150, + "outside_ns": 137920, + "texture_ns": 42257, + "prepare_ns": 4857150, + "end_ns": 20127, + "submit_ns": 3532087, + "present_ns": 8109633, + "wait_ns": 40976, + "present_interval_ns": 16739669, + "present_calls": 1 + } + ] + }, + "final_run": "Exited via rarch_main return 0 before the profile completed; retrieval correctly failed. No further performance run at user direction.", + "frontend_log": { + "sha256": "c64df8c97594642c48f0a1f2cdca3c483e19df966355e960f7af25c79d74911f", + "bytes": 2674, + "identity_matched": true + }, + "lines": [ + "build identity: a6063c61145fb42ac409a1d78026f29865673e4575e9a6afc3500e4abccc4f66", + "gpu profile: armed seconds=60 warmup=120 buffered=1", + "gpu result: vkEndCommandBuffer calls=1 failures=0 result=0", + "gpu result: vkQueueSubmit calls=1 failures=0 result=0", + "gpu result: vkEndCommandBuffer calls=2 failures=0 result=0", + "gpu result: vkQueueSubmit calls=2 failures=0 result=0", + "gpu result: vkEndCommandBuffer calls=3 failures=0 result=0", + "gpu result: vkQueueSubmit calls=3 failures=0 result=0", + "gpu result: vkEndCommandBuffer calls=4 failures=0 result=0", + "gpu result: vkQueueSubmit calls=4 failures=0 result=0", + "gpu result: vkQueuePresentKHR calls=1 failures=0 result=0", + "gpu result: swapchain image calls=1 failures=0 result=0", + "gpu result: vkQueuePresentKHR calls=2 failures=0 result=0", + "gpu result: swapchain image calls=2 failures=0 result=0", + "gpu result: vkQueuePresentKHR calls=3 failures=0 result=0", + "gpu result: swapchain image calls=3 failures=0 result=0", + "gpu result: vkQueuePresentKHR calls=4 failures=0 result=0", + "gpu result: swapchain image calls=4 failures=0 result=0", + "rarch_main returned = 0", + "audit: final startup trace refusals=0; menu handover and staging ask each logged once", + "frontend log: final build identity present; INFO/WARN/ERROR logging retained", + "owner (first buffered run): Very smooth; estimated refresh rate caps at 59.941 Hz stable", + "timing (first buffered run): 3597 frames; 59.940238 FPS; maximum interval 16.905813 ms; no completion gap over 20 ms", + "timing (logger restored): 3582 frames; three 100 ms texture-update stalls; remaining first-four-call probes identified", + "final run: frontend returned 0 before profile completion; no final timing result claimed", + "scope: user stopped further performance investigation and requested committing then enabling XMB", + "host: all five gates PASS; 28 tests; fresh patch application and idempotence PASS (86 edits)" + ] +} diff --git a/evidence/vulkan-buffered-logging/expectation.json b/evidence/vulkan-buffered-logging/expectation.json new file mode 100644 index 0000000..5b29c11 --- /dev/null +++ b/evidence/vulkan-buffered-logging/expectation.json @@ -0,0 +1,13 @@ +{ + "step": "vulkan-buffered-logging", + "note": "Logging and buffered capture verified; final once-only probe refinement has startup evidence but no completed performance sample.", + "must_contain": [ + "refusals=0", + "menu handover and staging ask each logged once", + "final build identity present", + "59.940238 FPS", + "no final timing result claimed", + "all five gates PASS" + ], + "must_not_contain": [] +} diff --git a/patches/series b/patches/series index 0175064..4308857 100644 --- a/patches/series +++ b/patches/series @@ -37,3 +37,12 @@ # 0056 quiet steady-frame diagnostics and time Vulkan video preparation/submission/presentation 0056-quiet-vulkan-frame-timing + +# 0057 retain startup/error logs without periodic successful-frame markers +0057-startup-only-frame-diagnostics + +# 0058 reassert the title frontend logger after config parsing/rebuilt arguments +0058-preserve-frontend-development-log + +# 0059 the first menu upload proves the handover; later updates must not write probes +0059-log-menu-handover-once diff --git a/src/input_ps5.cpp b/src/input_ps5.cpp index 723be46..df0296f 100644 --- a/src/input_ps5.cpp +++ b/src/input_ps5.cpp @@ -124,7 +124,6 @@ struct PadState std::int32_t sample_count = 0; std::uint32_t buttons = 0; bool owns_user_service = false; - bool released_reported = false; }; PadState *state_of(void *data) noexcept @@ -271,27 +270,10 @@ void ps5_input_poll(void *data) noexcept } state->sample_count = count; const PadSample *newest = newest_sample(*state); - const std::uint32_t previous = state->buttons; state->buttons = newest != nullptr ? newest->buttons : 0; - /* The first press is written to the trace, and the first release after it, so - * a run's own file answers "did a controller reach the frontend" - the - * question this step exists for - without anyone watching a screen at the - * right moment. */ - if (previous == 0 && state->buttons != 0) - { - char line[176]; - std::snprintf(line, sizeof(line), "input: press, pad=0x%08x retropad=0x%08x", - state->buttons, pad_buttons_to_retropad(state->buttons)); - ps5_input_trace(line); - } - else if (previous != 0 && state->buttons == 0 && !state->released_reported) - { - state->released_reported = true; - char line[176]; - std::snprintf(line, sizeof(line), "input: release, pad was 0x%08x", previous); - ps5_input_trace(line); - } + /* Successful button transitions are routine, not diagnostics. Keep pad-open + * failures and lifecycle logs, without a synchronous file write per press. */ } std::int16_t ps5_input_state(void *data, const input_device_driver_t *joypad_data, diff --git a/src/main.cpp b/src/main.cpp index 439f596..9877a6b 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -45,6 +45,12 @@ extern "C" int rarch_main(int argc, char *argv[], void *data); extern "C" int sceSystemServiceHideSplashScreen(); +extern "C" void ps5_vulkan_profile_init(); +extern "C" const char *ps5_frontend_build_identity() +{ + return PS5_RETROARCH_BUILD_ID; +} + namespace { /* The title's own folder, as the console mounts it: the application image is at @@ -134,6 +140,7 @@ int main() std::set_terminate(on_terminate); ps5::debug::mark(PS5_RETROARCH_BUILD_ID); + ps5_vulkan_profile_init(); /* The shell's splash covers the title until it explicitly dismisses it. * video_ps5 does this while opening its display, but video_vulkan never diff --git a/src/vulkan_trace.cpp b/src/vulkan_trace.cpp index e9780dd..b787366 100644 --- a/src/vulkan_trace.cpp +++ b/src/vulkan_trace.cpp @@ -50,69 +50,149 @@ struct Sample maximum = value; } }; +struct Frame +{ + uint64_t ns[MetricCount]{}; + uint64_t present_interval = 0; + unsigned present_calls = 0; +}; +struct Window +{ + unsigned frames = 0; + Sample samples[MetricCount]{}; +}; +unsigned gpu_failures = 0; struct Profile { - bool active = false; - unsigned warmup = 0, frames = 0; + static constexpr unsigned capacity = 8192; + bool enabled = false, active = false, finished = false; + unsigned warmup = 0, warmup_limit = 120, frames = 0; + unsigned record_count = 0, window_count = 0; + uint64_t duration = 0, elapsed = 0; uint64_t start = 0, previous_end = 0, texture_pending = 0; + uint64_t previous_present = 0, present_interval = 0; + unsigned present_calls = 0; uint64_t api[MetricCount]{}; Sample samples[MetricCount]{}; + Frame records[capacity]{}; + Window windows[13]{}; + void configure(unsigned seconds, unsigned skip = 120) + { + enabled = seconds >= 1 && seconds <= 60; + duration = uint64_t(seconds) * 1000000000ULL; + warmup_limit = skip; + } void begin(uint64_t now) { - // An early return has no matching end. Do not charge its gap to the next frame. + if (!enabled || finished) + return; if (active) + { previous_end = 0; + previous_present = 0; + } active = true; start = now; + present_calls = 0; + present_interval = 0; std::memset(api, 0, sizeof(api)); } + void presented(uint64_t now) + { + if (!active) + return; + ++present_calls; + if (previous_present) + present_interval = now - previous_present; + previous_present = now; + } + void save_window() + { + if (!frames) + return; + windows[window_count].frames = frames; + std::memcpy(windows[window_count++].samples, samples, sizeof(samples)); + frames = 0; + for (auto &sample : samples) + sample = {}; + } void finish(uint64_t now) { if (!active) return; active = false; - if (warmup < 4 || !previous_end) + if (warmup < warmup_limit || !previous_end) { ++warmup; previous_end = now; texture_pending = 0; return; } + Frame &frame = records[record_count++]; uint64_t measured = 0; for (unsigned i = End; i < MetricCount; ++i) { - samples[i].add(api[i]); + frame.ns[i] = api[i]; measured += api[i]; } - samples[Interval].add(now - previous_end); + frame.ns[Interval] = now - previous_end; const uint64_t outside = start - previous_end; - samples[Texture].add(texture_pending); - samples[Outside].add(outside >= texture_pending ? outside - texture_pending : 0); + frame.ns[Texture] = texture_pending; + frame.ns[Outside] = outside >= texture_pending ? outside - texture_pending : 0; texture_pending = 0; const uint64_t video = now - start; - samples[Prepare].add(video >= measured ? video - measured : 0); + frame.ns[Prepare] = video >= measured ? video - measured : 0; + frame.present_interval = present_interval; + frame.present_calls = present_calls; previous_end = now; + elapsed += frame.ns[Interval]; ++frames; - if (samples[Interval].sum < 5000000000ULL) - return; - // One write per window; its cost belongs to the next Outside sample. - std::fprintf(stderr, - "gpu timing: frames=%u seconds=%.3f fps=%.3f ms_avg/max " - "interval=%.3f/%.3f outside=%.3f/%.3f texture=%.3f/%.3f prepare=%.3f/%.3f " - "end=%.3f/%.3f submit=%.3f/%.3f present=%.3f/%.3f wait=%.3f/%.3f\n", - frames, samples[Interval].sum / 1e9, frames * 1e9 / samples[Interval].sum, - samples[Interval].sum / (1e6 * frames), samples[Interval].maximum / 1e6, - samples[Outside].sum / (1e6 * frames), samples[Outside].maximum / 1e6, - samples[Texture].sum / (1e6 * frames), samples[Texture].maximum / 1e6, - samples[Prepare].sum / (1e6 * frames), samples[Prepare].maximum / 1e6, - samples[End].sum / (1e6 * frames), samples[End].maximum / 1e6, - samples[Submit].sum / (1e6 * frames), samples[Submit].maximum / 1e6, - samples[Present].sum / (1e6 * frames), samples[Present].maximum / 1e6, - samples[Wait].sum / (1e6 * frames), samples[Wait].maximum / 1e6); - frames = 0; - for (auto &sample : samples) - sample = {}; + for (unsigned i = 0; i < MetricCount; ++i) + samples[i].add(frame.ns[i]); + if (samples[Interval].sum >= 5000000000ULL) + save_window(); + if (elapsed >= duration || record_count == capacity) + { + save_window(); + finished = true; + } + } + void dump(FILE *out) const + { + for (unsigned w = 0; w < window_count; ++w) + { + const auto &window = windows[w]; + const auto *s = window.samples; + const double n = window.frames; + std::fprintf(out, + "gpu timing: frames=%u seconds=%.3f fps=%.3f ms_avg/max " + "interval=%.3f/%.3f outside=%.3f/%.3f texture=%.3f/%.3f prepare=%.3f/%.3f " + "end=%.3f/%.3f submit=%.3f/%.3f present=%.3f/%.3f wait=%.3f/%.3f\n", + window.frames, s[Interval].sum / 1e9, n * 1e9 / s[Interval].sum, + s[Interval].sum / (1e6 * n), s[Interval].maximum / 1e6, + s[Outside].sum / (1e6 * n), s[Outside].maximum / 1e6, + s[Texture].sum / (1e6 * n), s[Texture].maximum / 1e6, + s[Prepare].sum / (1e6 * n), s[Prepare].maximum / 1e6, + s[End].sum / (1e6 * n), s[End].maximum / 1e6, s[Submit].sum / (1e6 * n), + s[Submit].maximum / 1e6, s[Present].sum / (1e6 * n), + s[Present].maximum / 1e6, s[Wait].sum / (1e6 * n), s[Wait].maximum / 1e6); + } + std::fprintf(out, "# frames=%u elapsed_ns=%llu capacity_reached=%u api_failures=%u\n", + record_count, static_cast(elapsed), + record_count == capacity ? 1u : 0u, gpu_failures); + std::fputs("frame\tinterval_ns\toutside_ns\ttexture_ns\tprepare_ns\tend_ns\tsubmit_ns" + "\tpresent_ns\twait_ns\tpresent_interval_ns\tpresent_calls\n", + out); + for (unsigned i = 0; i < record_count; ++i) + { + std::fprintf(out, "%u", i); + for (auto value : records[i].ns) + std::fprintf(out, "\t%llu", static_cast(value)); + std::fprintf(out, "\t%llu\t%u\n", + static_cast(records[i].present_interval), + records[i].present_calls); + } } }; Profile profile; @@ -126,10 +206,13 @@ struct ApiTimer : metric(kind), enabled(profile.active), start(enabled ? PS5_VULKAN_PROFILE_NOW() : 0) { } - void finish() + uint64_t finish() { - if (enabled) - profile.api[metric] += PS5_VULKAN_PROFILE_NOW() - start; + if (!enabled) + return 0; + const uint64_t now = PS5_VULKAN_PROFILE_NOW(); + profile.api[metric] += now - start; + return now; } }; @@ -142,8 +225,11 @@ struct Results { ++calls; if (result != VK_SUCCESS) + { ++failures; - if (calls <= 4 || calls % 600 == 0 || result != VK_SUCCESS) + ++gpu_failures; + } + if (calls <= 4 || result != VK_SUCCESS) std::fprintf(stderr, "gpu result: %s calls=%u failures=%u result=%d\n", name, calls, failures, static_cast(result)); } @@ -176,7 +262,9 @@ VKAPI_ATTR VkResult VKAPI_CALL traced_present(VkQueue queue, const VkPresentInfo static Results images; ApiTimer timer(Present); const VkResult result = queue_present(queue, present); - timer.finish(); + const uint64_t completed = timer.finish(); + if (result == VK_SUCCESS) + profile.presented(completed); results.record("vkQueuePresentKHR", result); if (present->pResults) for (uint32_t i = 0; i < present->swapchainCount; ++i) @@ -204,22 +292,63 @@ VKAPI_ATTR VkResult VKAPI_CALL traced_acquire(VkDevice device, VkSwapchainKHR sw } } // namespace +extern "C" void ps5_vulkan_profile_init() +{ + FILE *config = std::fopen("/app0/gpu-profile.txt", "r"); + if (!config) + return; + unsigned seconds = 0; + const int parsed = std::fscanf(config, "%u", &seconds); + std::fclose(config); + // Consume the opt-in so a later manual launch cannot inherit the experiment. + std::remove("/app0/gpu-profile.txt"); + if (parsed == 1 && seconds >= 1 && seconds <= 60) + { + profile.configure(seconds); + std::fprintf(stderr, "gpu profile: armed seconds=%u warmup=120 buffered=1\n", seconds); + } + else + std::fputs("gpu profile: invalid duration (expected 1..60 seconds)\n", stderr); +} + extern "C" uint64_t ps5_vulkan_profile_texture_begin() { - return PS5_VULKAN_PROFILE_NOW(); + return profile.enabled && !profile.finished ? PS5_VULKAN_PROFILE_NOW() : 0; } extern "C" void ps5_vulkan_profile_texture_end(uint64_t start) { - profile.texture_pending += PS5_VULKAN_PROFILE_NOW() - start; + if (start) + profile.texture_pending += PS5_VULKAN_PROFILE_NOW() - start; } extern "C" void ps5_vulkan_profile_begin() { - profile.begin(PS5_VULKAN_PROFILE_NOW()); + if (profile.enabled && !profile.finished) + profile.begin(PS5_VULKAN_PROFILE_NOW()); } extern "C" void ps5_vulkan_profile_end() { + if (!profile.active) + return; profile.finish(PS5_VULKAN_PROFILE_NOW()); + if (profile.finished) + { + FILE *out = std::fopen("/app0/gpu-profile.tsv", "w"); + if (!out) + { + std::fputs("gpu profile: could not open result file\n", stderr); + return; + } + // Reporting happens only after the measured interval, never inside it. + char buffer[65536]; + std::setvbuf(out, buffer, _IOFBF, sizeof(buffer)); + profile.dump(out); + const bool failed = std::ferror(out) != 0; + const int closed = std::fclose(out); + std::fprintf(stderr, "gpu profile: completed frames=%u seconds=%.3f errors=%u write=%s\n", + profile.record_count, profile.elapsed / 1e9, gpu_failures, + failed || closed != 0 ? "failed" : "ok"); + } } /* Called by both frontend symbol loaders. Keep the driver's real function, diff --git a/tests/test_frontend.py b/tests/test_frontend.py index 6d488e6..496dc70 100644 --- a/tests/test_frontend.py +++ b/tests/test_frontend.py @@ -300,7 +300,7 @@ class PortPatches(unittest.TestCase): change deliberately, in a commit that says why. """ self.assertEqual( - len(self.blocks()), 77, + len(self.blocks()), 86, "the patch count changed: if a block was added or removed on purpose, " "update this number in the same commit and say why in its message") diff --git a/tests/test_gpu_profile.py b/tests/test_gpu_profile.py new file mode 100644 index 0000000..b581caa --- /dev/null +++ b/tests/test_gpu_profile.py @@ -0,0 +1,41 @@ +"""Reject incomplete timing evidence and check deadline-proxy accounting.""" + +import importlib.util +from pathlib import Path +import unittest + +ROOT = Path(__file__).resolve().parent.parent +SPEC = importlib.util.spec_from_file_location('gpu_profile', ROOT / 'tools/analyze-gpu-profile.py') +MODULE = importlib.util.module_from_spec(SPEC) +SPEC.loader.exec_module(MODULE) + + +def fixture(): + values = [16666667, 50000, 100000, 4500000, 20000, 3500000, 8466667, 30000] + fields = ['interval'] + list(MODULE.PHASES) + header = 'frame\t' + '\t'.join(name + '_ns' for name in fields) + header += '\tpresent_interval_ns\tpresent_calls\n' + body = ''.join('\t'.join(map(str, [i] + [value * (i + 1) for value in values] + + [16666667 * (i + 1), 1])) + '\n' for i in range(2)) + return '# frames=2 elapsed_ns=50000001 capacity_reached=0 api_failures=0\n' + header + body + + +class GpuProfile(unittest.TestCase): + def test_partition_and_completion_cadence(self): + result = MODULE.analyze(fixture()) + self.assertAlmostEqual(result['fps'], 40, places=5) + self.assertAlmostEqual(result['phases']['interval']['p99_ms'], 33.333334) + self.assertEqual(result['presentation']['completion_intervals_over_20ms'], 1) + self.assertEqual(result['presentation']['estimated_extra_60hz_intervals'], 1) + self.assertEqual(result['slowest_frames'][0]['frame'], 1) + + def test_rejects_truncation_failed_calls_and_bad_partition(self): + for broken in [fixture().replace('frames=2', 'frames=3'), + fixture().replace('api_failures=0', 'api_failures=1'), + fixture().replace('capacity_reached=0', 'capacity_reached=1'), + fixture().replace('\t50000\t', '\t50001\t'), + fixture().replace('elapsed_ns=50000001', 'elapsed_ns=50000002'), + fixture().replace('\t1\n', '\t2\n')]: + with self.subTest(broken=broken): + with self.assertRaises(ValueError): + MODULE.analyze(broken) diff --git a/tests/test_vulkan_trace.py b/tests/test_vulkan_trace.py index b88ecee..ea55884 100644 --- a/tests/test_vulkan_trace.py +++ b/tests/test_vulkan_trace.py @@ -128,6 +128,7 @@ static VkResult VKAPI_CALL fake_acquire(VkDevice, VkSwapchainKHR, } int main() { + profile.configure(60, 4); end_command_buffer = fake_end; queue_submit = fake_submit; queue_present = fake_present; @@ -168,6 +169,26 @@ int main() tick += 1000000; ps5_vulkan_profile_end(); assert(profile.frames == 2); + std::fputs("dump begins\n", stderr); + profile.dump(stderr); + assert(profile.record_count == 12); + assert(profile.records[0].present_calls == 1); + assert(profile.records[0].present_interval == 1000000000); + static Profile bounded; + bounded.configure(1, 0); + bounded.begin(1); bounded.finish(2); + bounded.begin(3); bounded.finish(1000000002); + assert(bounded.finished && bounded.record_count == 1 && bounded.window_count == 1); + bounded.begin(2000000000); bounded.finish(3000000000); + assert(bounded.record_count == 1); + static Profile capped; + capped.configure(60, 0); + capped.begin(1); capped.finish(2); + for (unsigned i = 0; i < Profile::capacity + 3; ++i) + { + capped.begin(3 + i*2); capped.finish(4 + i*2); + } + assert(capped.finished && capped.record_count == Profile::capacity); } ''' with tempfile.TemporaryDirectory() as directory: @@ -180,6 +201,7 @@ int main() run = subprocess.run([str(binary)], check=True, capture_output=True, text=True) lines = [line for line in run.stderr.splitlines() if line.startswith("gpu timing:")] self.assertEqual(len(lines), 2) + self.assertNotIn("gpu timing:", run.stderr.split("dump begins")[0]) for line in lines: self.assertIn("frames=5 seconds=5.000 fps=1.000", line) self.assertIn("interval=1000.000/1000.000 outside=40.000/40.000 texture=50.000/50.000", line) diff --git a/tools/analyze-gpu-profile.py b/tools/analyze-gpu-profile.py new file mode 100644 index 0000000..e64a123 --- /dev/null +++ b/tools/analyze-gpu-profile.py @@ -0,0 +1,80 @@ +#!/usr/bin/env python3 +"""Validate and summarize a buffered PS5 GPU profile (CPU wall time, nanoseconds).""" + +import argparse +import csv +import io +import json +import math +import re +from pathlib import Path + +PHASES = ('outside', 'texture', 'prepare', 'end', 'submit', 'present', 'wait') + + +def describe(values): + ordered = sorted(values) + return { + 'mean_ms': sum(ordered) / len(ordered) / 1e6, + 'p99_ms': ordered[math.ceil(len(ordered) * .99) - 1] / 1e6, + 'max_ms': ordered[-1] / 1e6, + } + + +def analyze(text): + lines = text.splitlines() + meta = next((line for line in lines if line.startswith('# frames=')), '') + header = next((i for i, line in enumerate(lines) if line.startswith('frame\t')), None) + if not meta or header is None: + raise ValueError('missing completed profile header') + metadata = {k: int(v) for k, v in re.findall(r'(\w+)=(\d+)', meta)} + rows = list(csv.DictReader(io.StringIO('\n'.join(lines[header:])), delimiter='\t')) + if not rows or len(rows) != metadata['frames']: + raise ValueError('frame count differs from completed profile header') + if metadata['capacity_reached'] or metadata['api_failures']: + raise ValueError('capture reached capacity or recorded a Vulkan API failure') + records = [{k: int(v) for k, v in row.items()} for row in rows] + for i, row in enumerate(records): + if row['frame'] != i or row['interval_ns'] <= 0: + raise ValueError('invalid frame sequence or interval') + if any(value < 0 for value in row.values()): + raise ValueError('negative measurement') + if sum(row[phase + '_ns'] for phase in PHASES) != row['interval_ns']: + raise ValueError('phase partition does not equal the frame interval') + if row['present_calls'] != 1 or row['present_interval_ns'] <= 0: + raise ValueError('one successful synchronous presentation per frame is required') + elapsed = sum(row['interval_ns'] for row in records) + if elapsed != metadata['elapsed_ns']: + raise ValueError('elapsed time differs from completed profile header') + phases = {name: describe([r[name + '_ns'] for r in records]) + for name in ('interval',) + PHASES + ('present_interval',)} + gaps = [r['present_interval_ns'] for r in records] + return { + 'frames': len(records), 'seconds': elapsed / 1e9, + 'fps': len(records) * 1e9 / elapsed, 'phases': phases, + 'presentation': { + 'completion_intervals_over_20ms': sum(gap > 20000000 for gap in gaps), + 'completion_intervals_over_25ms': sum(gap > 25000000 for gap in gaps), + 'estimated_extra_60hz_intervals': sum(max(0, int(gap * 60 / 1e9 + .5) - 1) + for gap in gaps), + 'limitation': 'CPU times at successful synchronous vkQueuePresentKHR return; ' + 'not hardware vblank counters or scanout timestamps. ' + 'Extra 60 Hz intervals are rounded estimates, not exact missed-vblank counts.', + }, + 'slowest_frames': sorted(records, key=lambda row: row['interval_ns'], reverse=True)[:10], + } + + +def main(): + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument('capture', type=Path) + args = parser.parse_args() + try: + result = analyze(args.capture.read_text()) + except (ValueError, KeyError, TypeError, OSError) as error: + parser.exit(1, f'GPU profile invalid: {error}\n') + print(json.dumps(result, indent=2)) + + +if __name__ == '__main__': + main() diff --git a/tools/apply-port-patches.py b/tools/apply-port-patches.py index bf7e439..da12d7f 100755 --- a/tools/apply-port-patches.py +++ b/tools/apply-port-patches.py @@ -2073,6 +2073,83 @@ EDITS = [ "}\n", " ps5_vulkan_profile_texture_end(ps5_texture_start);", ), + ( + "gfx/drivers/vulkan.c", + "if (ps5_draw_marks < 6 || (ps5_draw_marks % 1200) == 0)", + "if (ps5_draw_marks < 6) /* patches/series, 0057: startup-only ps5_draw_marks */", + "patches/series, 0057: startup-only ps5_draw_marks", + ), + ( + "gfx/drivers/vulkan.c", + "if (ps5_frames <= 3 || (ps5_frames % 300) == 0)", + "if (ps5_frames <= 3) /* patches/series, 0057: startup-only ps5_frames */", + "patches/series, 0057: startup-only ps5_frames", + ), + ( + "gfx/drivers/vulkan.c", + "if (ps5_flag_marks < 4 || (ps5_flag_marks % 600) == 0)", + "if (ps5_flag_marks < 4) /* patches/series, 0057: startup-only ps5_flag_marks */", + "patches/series, 0057: startup-only ps5_flag_marks", + ), + ( + "menu/drivers/rgui.c", + "if (ps5_render_marks < 3 || (ps5_render_marks % 600) == 0)", + "if (ps5_render_marks < 3) /* patches/series, 0057: startup-only ps5_render_marks */", + "patches/series, 0057: startup-only ps5_render_marks", + ), + ( + "menu/menu_driver.c", + "if (ps5_iter_marks < 3 || (ps5_iter_marks % 600) == 0)", + "if (ps5_iter_marks < 3) /* patches/series, 0057: startup-only ps5_iter_marks */", + "patches/series, 0057: startup-only ps5_iter_marks", + ), + ( + "gfx/drivers/vulkan.c", + "if (ps5_quad_marks < 4 || (ps5_quad_marks % 600) == 0)", + "if (ps5_quad_marks < 4) /* patches/series, 0057: startup-only ps5_quad_marks */", + "patches/series, 0057: startup-only ps5_quad_marks", + ), + ( + "retroarch.c", + " /* Second pass: All other arguments override the config file */\n", + " /* patches/series, 0058: the title's file logger must survive argv rebuilding.\n" + " * Keep frontend/core INFO, WARN and ERROR output for ongoing development. */\n" + " {\n" + " extern const char *ps5_frontend_build_identity(void);\n" + " verbosity_enable();\n" + " verbosity_enabled = true;\n" + " rarch_log_file_set_override(\"/app0/retroarch.log\");\n" + " rarch_log_file_init(true, false, NULL);\n" + " RARCH_LOG(\"[PS5] %s\\n\", ps5_frontend_build_identity());\n" + " }\n" + "\n" + " /* Second pass: All other arguments override the config file */\n", + "patches/series, 0058: the title's file logger", + ), + ( + "gfx/drivers/vulkan.c", + " /* patches/series, 0056: quiet vulkan_set_texture_frame */\n" + " {\n" + " static unsigned ps5_marks;\n" + " if (ps5_marks++ < 4)", + " /* patches/series, 0056: quiet vulkan_set_texture_frame */\n" + " {\n" + " static unsigned ps5_marks;\n" + " if (ps5_marks++ < 1) /* patches/series, 0059: once vulkan_set_texture_frame */", + "patches/series, 0059: once vulkan_set_texture_frame", + ), + ( + "gfx/drivers/vulkan.c", + " /* patches/series, 0056: quiet vulkan_menu_staging_ask */\n" + " {\n" + " static unsigned ps5_marks;\n" + " if (ps5_marks++ < 4)", + " /* patches/series, 0056: quiet vulkan_menu_staging_ask */\n" + " {\n" + " static unsigned ps5_marks;\n" + " if (ps5_marks++ < 1) /* patches/series, 0059: once vulkan_menu_staging_ask */", + "patches/series, 0059: once vulkan_menu_staging_ask", + ), ] diff --git a/tools/run-title.sh b/tools/run-title.sh index 6342dae..451c822 100755 --- a/tools/run-title.sh +++ b/tools/run-title.sh @@ -5,6 +5,7 @@ # tools/run-title.sh --no-build use what is already in dist/ # tools/run-title.sh --no-deploy run whatever the console already holds # tools/run-title.sh --watch 90 how long to let it run (default 30) +# tools/run-title.sh --gpu-profile 60 --watch 80 buffered timing, then collect logs # # Why this exists. Every earlier round of the console loop was four hand-driven # steps that needed a person: build, upload, launch, read. Two things went wrong @@ -36,16 +37,25 @@ cd "$root" build=1 deploy=1 watch=30 +profile=0 while (( $# )); do case "$1" in --no-build) build=0 ;; --no-deploy) deploy=0 ;; --watch) shift; watch=${1:?--watch needs seconds} ;; - *) echo "usage: ${0##*/} [--no-build] [--no-deploy] [--watch SECONDS]" >&2; exit 2 ;; + --gpu-profile) shift; profile=${1:?--gpu-profile needs seconds} ;; + *) echo "usage: ${0##*/} [--no-build] [--no-deploy] [--watch SECONDS] [--gpu-profile 1..60]" >&2; exit 2 ;; esac shift done +[[ $watch =~ ^[0-9]+$ && $profile =~ ^[0-9]+$ ]] || { echo "durations must be integers" >&2; exit 2; } +(( profile <= 60 )) || { echo "GPU profile duration must be 1..60 seconds" >&2; exit 2; } +if (( profile > 0 && watch < profile + 15 )); then + echo "--watch must allow the profile duration plus 15 seconds for startup/reporting" >&2 + exit 2 +fi + [[ -f .env ]] || { echo "error: no .env; set PS5_HOST in it" >&2; exit 2; } set -a; . ./.env; set +a host=${PS5_HOST:?PS5_HOST is not set in .env} @@ -97,6 +107,12 @@ fi [[ -f dist/$title_id/eboot.bin ]] || die "nothing built at dist/$title_id/" +# --- the console must be free ------------------------------------------------ +held=$(ctl_cmd procs) +count=$(running_count) +say "console holds: ${held:-}" +[[ $count == 0 ]] || die "the shared console is not confirmed idle; no upload or launch" + # --- deploy, then prove it --------------------------------------------------- if (( deploy )); then say "publishing to the console and reading it back" @@ -107,13 +123,7 @@ if (( deploy )); then say "the console's copy is byte for byte this build" fi -# --- the console must be free ------------------------------------------------ -held=$(ctl_cmd procs) -count=$(running_count) -say "console holds: ${held:-}" -if [[ -n $count && $count != 0 ]]; then - die "the console is running $count process(es); this console runs one title at a time" -fi +[[ $(running_count) == 0 ]] || die "the console became busy during deployment; not launching" # --- a run starts from a known console state --------------------------------- # /app0/args.txt is not in dist/ and deploy never deletes anything, so a copy @@ -124,17 +134,24 @@ fi # appeared. A run that does not ask for extras must not inherit them, so the file # is removed on every run - before the launch, because deleting it afterwards # would leave it for the next one if this run dies. -python3 - "$title_id" <<'PY' || say "note: could not clear /app0/args.txt; a stale one changes this run" +python3 - "$title_id" "$profile" <<'PY' import importlib.util, sys spec = importlib.util.spec_from_file_location("dt", "tools/deploy-title.py") dt = importlib.util.module_from_spec(spec); spec.loader.exec_module(dt) -from ps5_ftp import connect +from ps5_ftp import connect, remove_if_present +import io with connect(**dt.load_settings()) as ftp: try: ftp.delete(f"/data/homebrew/{sys.argv[1]}/args.txt") print(" cleared a leftover args.txt from the console") except Exception: pass + control = f"/data/homebrew/{sys.argv[1]}/gpu-profile.txt" + remove_if_present(ftp, control) + if int(sys.argv[2]): + remove_if_present(ftp, f"/data/homebrew/{sys.argv[1]}/gpu-profile.tsv") + ftp.storbinary(f"STOR {control}", io.BytesIO((sys.argv[2] + "\n").encode())) + print(f" armed buffered GPU profile for {sys.argv[2]} seconds") PY # --- listen first, then launch ---------------------------------------------- @@ -194,6 +211,34 @@ except Exception as error: raise SystemExit(1) PY +# --- preserve development logs and optional buffered timing ------------------ +python3 - "$title_id" "$profile" "$stamp" <<'PY' +import importlib.util, re, sys +from pathlib import Path +sys.path.insert(0, "tools") +from ps5_ftp import connect, remove_if_present +spec = importlib.util.spec_from_file_location("dt", "tools/deploy-title.py") +dt = importlib.util.module_from_spec(spec); spec.loader.exec_module(dt) +with connect(**dt.load_settings()) as ftp: + remove_if_present(ftp, f"/data/homebrew/{sys.argv[1]}/gpu-profile.txt") + names = ["retroarch.log"] + if int(sys.argv[2]): + names.append("gpu-profile.tsv") + for name in names: + target = Path("klog") / f"{name.rsplit('.', 1)[0]}-{sys.argv[3]}.{name.rsplit('.', 1)[1]}" + try: + with target.open("wb") as out: + ftp.retrbinary(f"RETR /data/homebrew/{sys.argv[1]}/{name}", out.write) + if name == "retroarch.log": + expected = re.search(r"build identity: ([a-f0-9]{64})", Path("build/title_build_identity.h").read_text())[1] + if f"build identity: {expected}" not in target.read_text(errors="replace"): + raise SystemExit("RetroArch log is stale or logging failed: current build identity absent") + print(f" saved {name} to {target}") + except Exception as error: + print(f" could not retrieve {name}: {type(error).__name__}") + raise SystemExit(f"Required development log {name} was not captured") +PY + # --- say plainly what happened ---------------------------------------------- if grep -aq 'fatal signal' "$capture"; then say "VERDICT: it started and then died; the signal block above names where"