diag(ps5): isolate guest CPU-write buffer/texture/shader stalls [core-ready] [full-build] [test-all-on]

.github/workflows/encore-core-preflight.yml

@@ -36,6 +36,7 @@ jobs:
           python3 -B tools/check-ps5-vulkan-cache-phases.py
           python3 -B tools/check-ps5-build-sha-provenance.py
           python3 -B tools/check-ps5-guest-cache-domains.py
+          python3 -B tools/check-ps5-guest-write-subphases.py
           python3 -B tools/check-ps5-fast-first-pipelines.py
           python3 -B tools/check-ps5-quiet-frame-pressure.py
           python3 -B tools/check-ps5-quiet-cpu-io-clocks.py

MEMORY.md

@@ -2672,3 +2672,9 @@ R349 original EOL audit: 69 normalized CRLF files of 77017 paths; 45849-byte ori
 
 - Native R368 emits exactly one EDEN_BUILD_SOURCE source_sha=40hex in detailed heap.log and source_sha=40hex in boot-trace.txt. FC27 offline tools/analyze-fc27-stutter.py parses/validates the SHA, rejects mixed-source rotated/concatenated logs, prints FC27_BUILD source_sha=... for every analysis, and labels old pre-R368 files unverified_pre_R368. The opt-in --require-build-source rejects unverified or unknown SHA; --boot-trace verifies one matching trace source_sha. Legacy usage still permits historical descriptive counts with an explicit unverified banner, no false build comparisons. CLI --self-test covers valid, legacy, bad hash, duplicate incompatible hashes. Read-only Python analytics change: ZERO PS5 runtime/graphics effects.
 - R368 native build CI #38249363907 SUCCESS and source CI #38249364111 SUCCESS. The R369 read-only analyzer was committed locally without canceling that native build, then published after the build finished.
+
+### 2026-10-12 R370 — one combined FC27 test can isolate CPU write cache WAIT vs WORK without violating coherence
+
+- Pre-R359 FTP session forensic: across 115 and 210 distinct 5s windows, CPU guest write callback elapsed ns correlates strongly with late50, while callback volume does not; source also shows RasterizerVulkan::OnCPUWrite acquires buffer mutex, returns TRUE on GPU modified region hazard without texture invalidation, otherwise acquires texture mutex, marks dirty GPU image pages, then invalidates shader pipeline code ranges. R364 tells which cache domain is contended but not whether intra-lock work is costly.
+- R370 adds five OPT-IN sampled phases (one in 64 guest OnCPUWrite invocations, separate from GPU draw 1/16 sampling), reusing CachePhaseTimer and existing EDEN_GPU_CACHE_PHASE reporting: guest_write_buffer_wait, guest_write_buffer_work, guest_write_texture_wait, guest_write_texture_work, guest_write_shader_invalidate. Each sample's same flag spans all phases of that callback; early GPU-write hazard records ONLY buffer phases. Phase report totals are sampled durations, not total CPU use; compare per-window samples, window_ns and late50 across synchronized frame IDs. Adds zero clocks or counter writes to production quiet path; only one cheap detailed_gpu_profile load on ordinary writes, without cache locks reordered, fences removed, texture hazards bypassed or pipeline metadata invalidated differently.
+- Native versioned vendor/encore-active/eden-vulkan/vulkan_rasterizer.cpp, and generator tools/prepare-vulkan-port.py, must remain byte-equivalent for 40 fork sources. Dedicated source-extracted C++ host fixture tools/check-ps5-guest-write-subphases.py validates 1/64 sampling, two cache locks' original write ordering, full early return on GPU write hazards, and no diagnostic clocks in quiet, using ASan/UBSan. Existing R310/R364/R355 host regressions and core CI still required. This is instrumentation for a SINGLE later combined test, not a demonstrated FC27 FPS/pixelation fix.

docs/PS5_R364_2026-10-12_FC27_CACHE_DOMAIN_FORENSICS.md

@@ -44,3 +44,7 @@ No effect on PS5 runtime. Do not attempt to eliminate coherence locks or short-c
 The previously used phrase R359 console measurements was NOT source-proven for these FTP logs. BootTrace::Begin embeds compile-time __DATE__ / __TIME__. The two actual build stamps (Oct 12 01:29:32 and 03:18:21) precede final R359 commit 03:52:15 UTC on the GitHub CI runner. Preserve numerical observations but label them pre-R359 installed binaries of unknown exact SHA. Do not claim R359's SMT fix was activated or that R363 improved FC27 at these timestamps.
 
 During the last-session 115 matched 5s samples, windows under 25 FPS had ~64,476 GPU draws and 1,216 dispatch calls per window versus ~51,949 draws and 721 dispatch calls in windows near 30 FPS. The preceding session reproduced higher draw/dispatch workload in slow windows (65,639/1,260 vs 54,219/730). Controlling simultaneously for draw and dispatch counts using normalized least-squares residuals, partial correlations of guest CPU-write elapsed time with late50 remained +0.762 and +0.760 (later/earlier), and aggregate cache-blocked time +0.694/+0.713. These data strengthen a contention-latency hypothesis but do not prove directional cause. No release policy or GPU cache ownership changed by this analysis.
+
+## R370 — distinguish a lock's wait from the work performed inside it
+
+With detailed logging enabled, each guest CPU write takes one in 64 sampled measurements covering in strict original order: buffer mutex acquisition, buffer-cache region work, texture mutex acquisition, texture-cache image work, shader-code invalidation. R364 per-domain cumulative wait counters remain unchanged. These phases appear as EDEN_GPU_CACHE_PHASE with their own window_samples and window_ns and the exact last renderer frame ID. The buffer GPU-modified early return has no texture or shader sample; this is expected, not a missing diagnostic. Native quiet writes still take the original locks and update no sample clocks or atomics. Source-extracted ASan/UBSan C++ fixture verifies this original call ordering and early return. This resolves a prior instrumentation blind spot; live costs await a compiled new binary and one user-initiated combined console session.

headless/performance.cpp

@@ -1070,8 +1070,8 @@ void ReportGpuThread(unsigned frame) {
     for (unsigned slot = 0; slot < render_conditions.size(); ++slot)
         std::printf("%s%llu", slot ? "," : "", render_conditions[slot].load(std::memory_order_relaxed));
     std::printf("\n");
-    // These are 1-in-16 draw SAMPLES, not every draw's cost. Report cumulative
-    // totals plus maximum sampled latency; pair with frame IDs/time windows.
+    // These are 1-in-16 GPU draw and 1-in-64 guest-write SAMPLES, not
+    // full totals. Each phase reports its own sample count and window cost.
     // Never issue a kernel query or print per-draw logging while the locks live.
     if (detailed_gpu_profile.load(std::memory_order_relaxed)) {
         constexpr const char* cache_phase_names[] = {
@@ -1081,7 +1081,10 @@ void ReportGpuThread(unsigned frame) {
             "texture_cpu_refresh", "texture_alias_scan", "texture_alias_copy",
             "stage_texture_handles", "bind_texture_buffers", "bind_stage_descriptors",
             "refresh_render_targets", "check_feedback_loop", "commit_graphics_draw",
-            "descriptor_ring_finish", "descriptor_ring_preflight"
+            "descriptor_ring_finish", "descriptor_ring_preflight",
+            "guest_write_buffer_wait", "guest_write_buffer_work",
+            "guest_write_texture_wait", "guest_write_texture_work",
+            "guest_write_shader_invalidate"
         };
         static_assert(std::size(cache_phase_names) == cache_phase_totals.size());
         constexpr const char* drop_names[] = {

headless/performance.h

@@ -160,7 +160,9 @@ enum class CachePhase : unsigned {
     DynamicStates, QueryAndDraw,
     TextureCpuRefresh, TextureAliasScan, TextureAliasCopy,
     StageTextureHandles, BindTextureBuffers, BindStageDescriptors,
-    RefreshRenderTargets, CheckFeedbackLoop, CommitGraphicsDraw, DescriptorRingFinish, DescriptorRingPreflight, Count
+    RefreshRenderTargets, CheckFeedbackLoop, CommitGraphicsDraw, DescriptorRingFinish, DescriptorRingPreflight,
+    GuestWriteBufferWait, GuestWriteBufferWork, GuestWriteTextureWait,
+    GuestWriteTextureWork, GuestWriteShaderInvalidate, Count
 };
 struct CachePhaseTotal {
     std::atomic<unsigned long long> samples{}, total_ns{}, max_ns{};
@@ -173,6 +175,13 @@ inline bool ShouldSampleCacheDraw() noexcept {
     // Sampling avoids injecting high-frequency clock calls into the render path.
     return (++sequence & 15u) == 0u;
 }
+inline bool ShouldSampleGuestWrite() noexcept {
+    if (!detailed_gpu_profile.load(std::memory_order_relaxed)) return false;
+    static thread_local unsigned sequence = 0;
+    // One in 64 guest CPU-write callbacks, independent of the GPU-owner
+    // per-16 draw sequence. An entire callback shares the same sample flag.
+    return (++sequence & 63u) == 0u;
+}
 class CachePhaseTimer {
 public:
     explicit CachePhaseTimer(CachePhase phase, bool enabled = cache_draw_sample_active)

tools/check-ps5-guest-write-subphases.py

@@ -0,0 +1,156 @@
+#!/usr/bin/env python3
+"""R370: compile actual sampled guest OnCPUWrite with fake caches and locks."""
+from pathlib import Path
+import os,subprocess,sys,tempfile
+
+root=Path(__file__).resolve().parents[1]
+active=(root/'vendor/encore-active/eden-vulkan/vulkan_rasterizer.cpp').read_text()
+generator=(root/'tools/prepare-vulkan-port.py').read_text()
+perf=(root/'headless/performance.h').read_text()
+report=(root/'headless/performance.cpp').read_text()
+method_start=active.index('bool RasterizerVulkan::OnCPUWrite(DAddr addr, u64 size) {')
+method_end=active.index('\nvoid RasterizerVulkan::OnCacheInvalidation(',method_start)
+method=active[method_start:method_end]
+assert 'ShouldSampleGuestWrite()' in method
+assert method.count('CachePhaseTimer') == 5
+assert method.count('GuestCacheLock(') == 2
+assert method.index('GuestWriteBufferWait') < method.index('GuestWriteBufferWork')
+assert method.index('GuestWriteBufferWork') < method.index('GuestWriteTextureWait')
+assert method.index('GuestWriteTextureWait') < method.index('GuestWriteTextureWork')
+assert method.index('GuestWriteTextureWork') < method.index('GuestWriteShaderInvalidate')
+assert method.index('buffer_cache.OnCPUWrite(addr, size)') < method.index('texture_cache.WriteMemory(addr, size)')
+assert method.index('texture_cache.WriteMemory(addr, size)') < method.index('pipeline_cache.InvalidateRegion(addr, size)')
+for token in ('GuestWriteBufferWait','GuestWriteBufferWork','GuestWriteTextureWait',
+              'GuestWriteTextureWork','GuestWriteShaderInvalidate','ShouldSampleGuestWrite'):
+    assert token in perf and token in active and token in generator,token
+for name in ('guest_write_buffer_wait','guest_write_buffer_work','guest_write_texture_wait',
+             'guest_write_texture_work','guest_write_shader_invalidate'):
+    assert '"'+name+'"' in report,name
+guest_lock=perf[perf.index('struct GuestCacheDomainTotals {'):
+                perf.index('// R310:')]
+cache_phase=perf[perf.index('enum class CachePhase : unsigned {'):
+                 perf.index('// R361:')]
+cpp=r"""
+#include <array>
+#include <atomic>
+#include <cassert>
+#include <chrono>
+#include <cstddef>
+#include <cstdint>
+#include <mutex>
+#include <cstdio>
+#if !defined(__x86_64__)
+#define __builtin_ia32_pause() ((void)0)
+#endif
+using DAddr=std::uint64_t;
+using u64=std::uint64_t;
+#define DEBUG_ASSERT(x) assert(x)
+namespace Common {
+struct Clock {
+    mutable std::atomic<unsigned long long> calls{};
+    std::chrono::nanoseconds GetTimeNS() const {
+        calls.fetch_add(1,std::memory_order_relaxed);
+        return std::chrono::duration_cast<std::chrono::nanoseconds>(
+           std::chrono::steady_clock::now().time_since_epoch());
+    }
+};
+inline Clock g_wall_clock{};
+}
+namespace Eden::Performance {
+inline std::atomic<bool> detailed_gpu_profile{false};
+inline std::atomic<unsigned> cache_lock_spins{0};
+inline std::atomic<unsigned long long> cache_lock_contended{0}, cache_lock_blocked{0};
+inline std::atomic<unsigned long long> cache_lock_wait_ns{0};
+struct Totals { std::atomic<unsigned long long> calls{}; };
+inline Totals guest_cpu_write;
+struct DiagnosticTimer {
+    explicit DiagnosticTimer(Totals& tally) {
+        if (detailed_gpu_profile.load(std::memory_order_relaxed))
+            tally.calls.fetch_add(1,std::memory_order_relaxed);
+    }
+};
+__GUEST_LOCK__
+__CACHE_PHASE__
+}
+struct FakeBuffer {
+    std::mutex mutex;
+    bool hazard{};
+    unsigned writes{};
+    bool OnCPUWrite(DAddr,u64) { ++writes; return hazard; }
+};
+struct FakeTexture {
+    std::mutex mutex;
+    unsigned writes{};
+    void WriteMemory(DAddr,u64) { ++writes; }
+};
+struct FakePipeline {
+    unsigned invalidations{};
+    void InvalidateRegion(DAddr,u64) { ++invalidations; }
+};
+struct RasterizerVulkan {
+    FakeBuffer buffer_cache{};
+    FakeTexture texture_cache{};
+    FakePipeline pipeline_cache{};
+    bool OnCPUWrite(DAddr,u64);
+};
+__ON_CPU_WRITE__
+int main() {
+    using namespace Eden::Performance;
+    RasterizerVulkan r;
+    for (int i=0;i<128;++i) assert(!r.OnCPUWrite(1,4));
+    assert(Common::g_wall_clock.calls.load()==0);
+    assert(guest_cpu_write.calls.load()==0);
+    for (const auto& phase:cache_phase_totals) assert(phase.samples.load()==0);
+    assert(r.buffer_cache.writes==128 && r.texture_cache.writes==128 &&
+           r.pipeline_cache.invalidations==128);
+    detailed_gpu_profile.store(true);
+    for (int i=0;i<128;++i) assert(!r.OnCPUWrite(1,4));
+    const CachePhase groups[] = {
+        CachePhase::GuestWriteBufferWait, CachePhase::GuestWriteBufferWork,
+        CachePhase::GuestWriteTextureWait, CachePhase::GuestWriteTextureWork,
+        CachePhase::GuestWriteShaderInvalidate
+    };
+    for (CachePhase p:groups) assert(
+        cache_phase_totals[static_cast<unsigned>(p)].samples.load()==2);
+    assert(r.buffer_cache.writes==256 && r.texture_cache.writes==256 &&
+           r.pipeline_cache.invalidations==256);
+    assert(cache_lock_contended.load()==0 && cache_lock_blocked.load()==0);
+    assert(guest_cpu_write.calls.load()==128);
+    const auto reads=Common::g_wall_clock.calls.load();
+    assert(reads>0);
+    // Under a guest GPU-modified buffer hazard, the ORIGINAL immediate
+    // early-return must skip texture and shader invalidation.
+    r.buffer_cache.hazard=true;
+    for (int i=0;i<64;++i) assert(r.OnCPUWrite(1,4));
+    assert(r.buffer_cache.writes==320);
+    assert(r.texture_cache.writes==256 &&
+           r.pipeline_cache.invalidations==256);
+    for (unsigned i=0;i<5;++i) {
+        const auto count=cache_phase_totals[static_cast<unsigned>(groups[i])].samples.load();
+        assert(count==(i<2?3u:2u));
+    }
+    detailed_gpu_profile.store(false);
+    const auto quiet_clock_reads=Common::g_wall_clock.calls.load();
+    for (int i=0;i<64;++i) assert(r.OnCPUWrite(1,4));
+    assert(Common::g_wall_clock.calls.load()==quiet_clock_reads);
+    assert(r.texture_cache.writes==256 &&
+           r.pipeline_cache.invalidations==256);
+    for (unsigned i=0;i<5;++i) {
+        const auto count=cache_phase_totals[static_cast<unsigned>(groups[i])].samples.load();
+        assert(count==(i<2?3u:2u));
+    }
+    puts("R370_GUEST_WRITE_PHASES_HOST_PASS");
+}
+""".replace('__GUEST_LOCK__',guest_lock).replace('__CACHE_PHASE__',cache_phase).replace('__ON_CPU_WRITE__',method)
+# Test source-extracted exact method without graphically modifying any image/view.
+env=os.environ.copy()
+if sys.platform=='darwin' and not env.get('SDKROOT'):
+    sdk=Path('/Library/Developer/CommandLineTools/SDKs/MacOSX15.4.sdk')
+    if sdk.is_dir():env['SDKROOT']=str(sdk)
+with tempfile.TemporaryDirectory(prefix='eden-r370-write-') as d:
+    f=Path(d)/'phases.cpp';o=Path(d)/'phases';f.write_text(cpp)
+    subprocess.run(['c++','-std=c++20','-O1','-pthread','-Wall','-Wextra','-Werror',
+                    '-fsanitize=address,undefined',str(f),'-o',str(o)],
+                   env=env,check=True,timeout=40)
+    subprocess.run([str(o)],check=True,env=env,timeout=15)
+print('PASS R370: original CPU-write ordering/early return, 1-in-64 sampling, quiet counters untouched')

tools/prepare-vulkan-port.py

@@ -78,7 +78,7 @@ void RasterizerVulkan::DispatchCompute() {"""),
     ('#include <algorithm>', '#include <algorithm>\n#include "performance.h"'),
     # Guest threads take the cache locks here (tracked-page writes, flush-area reads).
     ('bool RasterizerVulkan::OnCPUWrite(DAddr addr, u64 size) {',
-     'bool RasterizerVulkan::OnCPUWrite(DAddr addr, u64 size) {\n    ::Eden::Performance::DiagnosticTimer guest_write_timer(::Eden::Performance::guest_cpu_write);'),
+     'bool RasterizerVulkan::OnCPUWrite(DAddr addr, u64 size) {\n    ::Eden::Performance::DiagnosticTimer guest_write_timer(::Eden::Performance::guest_cpu_write);\n    const bool sample_guest_write = ::Eden::Performance::ShouldSampleGuestWrite();'),
     ('VideoCore::RasterizerDownloadArea RasterizerVulkan::GetFlushArea(DAddr addr, u64 size) {',
      'VideoCore::RasterizerDownloadArea RasterizerVulkan::GetFlushArea(DAddr addr, u64 size) {\n    ::Eden::Performance::DiagnosticTimer guest_read_timer(::Eden::Performance::guest_cpu_read);'),
     # ... and wait for those locks spinning briefly before sleeping (performance.h GuestCacheLock).
@@ -86,11 +86,26 @@ void RasterizerVulkan::DispatchCompute() {"""),
      '        ::Eden::Performance::GuestCacheLock(texture_cache.mutex, true);\n'
      '        std::lock_guard lock{texture_cache.mutex, std::adopt_lock};\n        auto area = texture_cache.GetFlushArea(addr, size);'),
     ('        std::scoped_lock lock{buffer_cache.mutex};\n        if (buffer_cache.OnCPUWrite(addr, size)) {',
+     '        ::Eden::Performance::CachePhaseTimer buffer_wait{\n'
+     '            ::Eden::Performance::CachePhase::GuestWriteBufferWait, sample_guest_write};\n'
      '        ::Eden::Performance::GuestCacheLock(buffer_cache.mutex, false);\n'
-     '        std::lock_guard lock{buffer_cache.mutex, std::adopt_lock};\n        if (buffer_cache.OnCPUWrite(addr, size)) {'),
+     '        buffer_wait.Stop();\n'
+     '        std::lock_guard lock{buffer_cache.mutex, std::adopt_lock};\n'
+     '        ::Eden::Performance::CachePhaseTimer buffer_work{\n'
+     '            ::Eden::Performance::CachePhase::GuestWriteBufferWork, sample_guest_write};\n'
+     '        if (buffer_cache.OnCPUWrite(addr, size)) {'),
     ('        std::scoped_lock lock{texture_cache.mutex};\n        texture_cache.WriteMemory(addr, size);\n    }\n    pipeline_cache.InvalidateRegion(addr, size);',
+     '        ::Eden::Performance::CachePhaseTimer texture_wait{\n'
+     '            ::Eden::Performance::CachePhase::GuestWriteTextureWait, sample_guest_write};\n'
      '        ::Eden::Performance::GuestCacheLock(texture_cache.mutex, true);\n'
-     '        std::lock_guard lock{texture_cache.mutex, std::adopt_lock};\n        texture_cache.WriteMemory(addr, size);\n    }\n    pipeline_cache.InvalidateRegion(addr, size);'),
+     '        texture_wait.Stop();\n'
+     '        std::lock_guard lock{texture_cache.mutex, std::adopt_lock};\n'
+     '        ::Eden::Performance::CachePhaseTimer texture_work{\n'
+     '            ::Eden::Performance::CachePhase::GuestWriteTextureWork, sample_guest_write};\n'
+     '        texture_cache.WriteMemory(addr, size);\n    }\n'
+     '    ::Eden::Performance::CachePhaseTimer shader_invalidate{\n'
+     '        ::Eden::Performance::CachePhase::GuestWriteShaderInvalidate, sample_guest_write};\n'
+     '    pipeline_cache.InvalidateRegion(addr, size);'),
     # From upstream ProsperoEden 0dd9dd0 (#102): submitting after 4096 draws
     # can exceed the PS5 GPU watchdog (VK_ERROR_DEVICE_LOST). Cap command
     # buffers at 512 draws, keeping Encore's current worker handoff cadence

vendor/encore-active/eden-vulkan/vulkan_rasterizer.cpp

@@ -914,19 +914,32 @@ void RasterizerVulkan::InnerInvalidation(std::span<const std::pair<DAddr, std::s
 
 bool RasterizerVulkan::OnCPUWrite(DAddr addr, u64 size) {
     ::Eden::Performance::DiagnosticTimer guest_write_timer(::Eden::Performance::guest_cpu_write);
+    const bool sample_guest_write = ::Eden::Performance::ShouldSampleGuestWrite();
     DEBUG_ASSERT(addr != 0 || size != 0);
     {
+        ::Eden::Performance::CachePhaseTimer buffer_wait{
+            ::Eden::Performance::CachePhase::GuestWriteBufferWait, sample_guest_write};
         ::Eden::Performance::GuestCacheLock(buffer_cache.mutex, false);
+        buffer_wait.Stop();
         std::lock_guard lock{buffer_cache.mutex, std::adopt_lock};
+        ::Eden::Performance::CachePhaseTimer buffer_work{
+            ::Eden::Performance::CachePhase::GuestWriteBufferWork, sample_guest_write};
         if (buffer_cache.OnCPUWrite(addr, size)) {
             return true;
         }
     }
     {
+        ::Eden::Performance::CachePhaseTimer texture_wait{
+            ::Eden::Performance::CachePhase::GuestWriteTextureWait, sample_guest_write};
         ::Eden::Performance::GuestCacheLock(texture_cache.mutex, true);
+        texture_wait.Stop();
         std::lock_guard lock{texture_cache.mutex, std::adopt_lock};
+        ::Eden::Performance::CachePhaseTimer texture_work{
+            ::Eden::Performance::CachePhase::GuestWriteTextureWork, sample_guest_write};
         texture_cache.WriteMemory(addr, size);
     }
+    ::Eden::Performance::CachePhaseTimer shader_invalidate{
+        ::Eden::Performance::CachePhase::GuestWriteShaderInvalidate, sample_guest_write};
     pipeline_cache.InvalidateRegion(addr, size);
     return false;
 }