Frame stats: a Hitch line for every frame over 45 ms (disk reads, faults, GPU waits, readbacks)

João's log (10-29, LTO build): the spikes of 50-330 ms came with the game opening its b*.xpps
streaming blocks, with no shader compiles waiting. Each slow frame now prints what happened
during it: MB read from disk and the time reading and copying them into game memory, files
opened, guest read / write faults, GPU waits, wait-reg-mem, flip-label waits, readbacks, draws,
dispatches and submits (Advanced > Diagnostics > Frame statistics).

Co-Authored-By: Claude Opus 5.5 <[email protected]>
Claude-Session: https://claude.ai/code/session_01Eij6gW2nnTUK9BowHuBVZZ

gpu/shadps4/common/fault_monitor.cpp

@@ -652,6 +652,19 @@ std::ofstream OpenCsv() {
 
 } // namespace (ReportLoop helpers; gmc census below is public)
 
+// issn 0.3.6: the counters the frame-stats hitch lines compare across one slow frame
+// (core/libraries/videoout/driver.cpp). Counts are always on; times only with
+// SHADPS4_FAULT_TIMERS builds (0 otherwise).
+void HitchCounters(u64 out[HitchCounterCount]) {
+    const Sample s = Read();
+    const u64 values[HitchCounterCount] = {s.read,  s.write,     s.waits,    s.wait_ns,
+                                           s.wrm_count, s.vo_count, s.dl_calls, s.dl_bytes,
+                                           s.draws, s.submits,   s.disp_count};
+    for (u32 i = 0; i < HitchCounterCount; ++i) {
+        out[i] = values[i];
+    }
+}
+
 namespace {
 struct GmCensus {
     std::array<std::atomic<u64>, 16> wait_ticks{}, wait_n{};

gpu/shadps4/common/fault_monitor.h

@@ -115,6 +115,10 @@ void MarkGameMainThread();
 bool JobCensus();
 /// Called at guest thread start with its name; registers JobWorker* threads for the job census.
 void NoteGuestThread(const char* name);
+/// issn 0.3.6: read faults, write faults, GPU waits, wait ns, wait-reg-mem, VO label waits,
+/// downloads, download bytes, draws, submits, dispatches (for the hitch lines).
+inline constexpr u32 HitchCounterCount = 11;
+void HitchCounters(u64 out[HitchCounterCount]);
 /// Cycles spent in one NativeRecDraw / NativeRecShader call (job census only).
 void NoteNativeRecCycles(u64 cycles);
 u64 CensusTicks();

gpu/shadps4/core/libraries/videoout/driver.cpp

@@ -4,7 +4,9 @@
 #include <cstdlib>
 
 #include <chrono>
+#include <cstdint>
 #include <cstdio>
+#include <cstring>
 #include "common/assert.h"
 #include "common/debug.h"
 #include "common/fault_monitor.h"
@@ -21,6 +23,10 @@
 extern std::unique_ptr<Vulkan::Presenter> presenter;
 extern std::unique_ptr<AmdGpu::Liverpool> liverpool;
 
+// issn 0.3.6: the runtime's disk read totals (src/runtime_file.c).
+extern "C" void runtime_file_io_stats(std::uint64_t* bytes, std::uint64_t* read_ns,
+                                      std::uint64_t* copy_ns, std::uint64_t* opened);
+
 namespace Libraries::VideoOut {
 
 constexpr static bool Is32BppPixelFormat(PixelFormat format) {
@@ -320,6 +326,33 @@ void VideoOutDriver::Flip(const Request& req) {
         const auto now = Clock::now();
         const double frame_ms = std::chrono::duration<double, std::milli>(now - last).count();
         last = now;
+        // issn 0.3.6: one line per slow frame with what happened during it, to tell streaming
+        // (disk reads and copies into guest memory), guest faults, GPU waits and readbacks
+        // apart (João's log 10-29: the spikes came with the game opening its b*.xpps blocks).
+        static u64 prev_counters[Common::FaultMonitor::HitchCounterCount]{};
+        static u64 prev_io[4]{};
+        static u32 hitch_lines = 0;
+        u64 counters[Common::FaultMonitor::HitchCounterCount];
+        Common::FaultMonitor::HitchCounters(counters);
+        u64 io[4];
+        runtime_file_io_stats(&io[0], &io[1], &io[2], &io[3]);
+        if (frame_ms > 45.0 && frame_ms < 5000.0 && hitch_lines < 400 && prev_io[0] != 0) {
+            ++hitch_lines;
+            const auto d = [&](u32 i) { return counters[i] - prev_counters[i]; };
+            std::printf("Hitch: %.0f ms | disk %.1f MB, read %.1f ms, copy into game memory %.1f ms, "
+                        "%llu files opened | faults read %llu write %llu | GPU waits %llu "
+                        "(%.1f ms) wait-reg-mem %llu flip-label %llu | readbacks %llu (%.0f kB) "
+                        "| draws %llu dispatches %llu submits %llu\n",
+                        frame_ms, double(io[0] - prev_io[0]) / 1048576.0,
+                        double(io[1] - prev_io[1]) / 1e6, double(io[2] - prev_io[2]) / 1e6,
+                        (unsigned long long)(io[3] - prev_io[3]), (unsigned long long)d(0),
+                        (unsigned long long)d(1), (unsigned long long)d(2), double(d(3)) / 1e6,
+                        (unsigned long long)d(4), (unsigned long long)d(5),
+                        (unsigned long long)d(6), double(d(7)) / 1024.0, (unsigned long long)d(8),
+                        (unsigned long long)d(10), (unsigned long long)d(9));
+        }
+        std::memcpy(prev_counters, counters, sizeof(counters));
+        std::memcpy(prev_io, io, sizeof(io));
         worst_ms = std::max(worst_ms, frame_ms);
         over_33 += frame_ms > 33.4 ? 1 : 0;
         ++frames;

src/runtime_file.c

@@ -17,6 +17,7 @@
 #include <pthread.h>
 #include <unistd.h>
 #include <sys/stat.h>
+#include <time.h>
 #ifdef _WIN32
 #include <windows.h>
 /* 64-bit sizes and times; directories are never opened as CRT descriptors. */
@@ -354,17 +355,31 @@ static ssize_t host_write(int h,const void *buffer,uint64_t size) { return write
  * disk into GPU memory, and a lost read left a scene waiting forever). The copy faults to our
  * handler like any guest write. offset<0: from the current position. */
 enum { BOUNCE_SIZE=4<<20 };
+/* issn 0.3.6: time spent reading the disk and copying into guest memory, all threads (the
+ * frame-stats hitch lines, gpu/shadps4/core/libraries/videoout/driver.cpp). */
+static uint64_t io_read_ns,io_copy_ns;
+static uint64_t io_now_ns(void) { struct timespec t; clock_gettime(CLOCK_MONOTONIC,&t); return (uint64_t)t.tv_sec*1000000000u+(uint64_t)t.tv_nsec; }
+void runtime_file_io_stats(uint64_t *bytes,uint64_t *read_ns,uint64_t *copy_ns,uint64_t *opened) {
+    *bytes=__atomic_load_n(&bytes_read,__ATOMIC_RELAXED);
+    *read_ns=__atomic_load_n(&io_read_ns,__ATOMIC_RELAXED);
+    *copy_ns=__atomic_load_n(&io_copy_ns,__ATOMIC_RELAXED);
+    *opened=__atomic_load_n(&opens,__ATOMIC_RELAXED);
+}
 static int64_t bounce_read(int h,void *buffer,uint64_t size,int64_t offset) {
     static _Thread_local unsigned char *bounce;
     if (!bounce && !(bounce=malloc(BOUNCE_SIZE))) return -ENOMEM;
     uint64_t done=0;
     while (done<size) {
         const uint64_t chunk=size-done<BOUNCE_SIZE ? size-done : BOUNCE_SIZE;
+        const uint64_t t0=io_now_ns();
         const ssize_t n=offset<0 ? host_read(h,bounce,chunk) : pread(h,bounce,chunk,offset+(int64_t)done);
+        const uint64_t t1=io_now_ns();
+        __atomic_add_fetch(&io_read_ns,t1-t0,__ATOMIC_RELAXED);
         if (n<0) return done ? (int64_t)done : -errno;
         /* issn: into GPU-modified memory without a fault (ISSN_WRITE_MERGE). */
         if (n<64 || !issngpu_cpu_write((unsigned char *)buffer+done,bounce,-1,(uint64_t)n))
             memcpy((unsigned char *)buffer+done,bounce,(size_t)n);
+        __atomic_add_fetch(&io_copy_ns,io_now_ns()-t1,__ATOMIC_RELAXED);
         done+=(uint64_t)n;
         if ((uint64_t)n<chunk) break; /* end of file */
     }