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-<stamp>.tsv

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.

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/<step>/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.

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-<run-stamp>.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-<stamp>.log`, `gpu-profile-<stamp>.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.

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-<stamp>.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/.

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-<stamp>.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)"
+  ]
+}

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": []
+}

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

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,

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

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<unsigned long long>(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<unsigned long long>(value));
+            std::fprintf(out, "\t%llu\t%u\n",
+                         static_cast<unsigned long long>(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<int>(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,

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")
 

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)

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)

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()

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",
+    ),
 ]
 
 

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:-<no answer>}"
+[[ $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:-<no answer>}"
-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"