bench: per-frame variance + blitter trace + perf counter lookup

The +15% inlining win shipped in the previous commit didn't fix the
real-world AvP audio stutter, because audio dropouts are governed
by *worst-case* frame time, not average.  This commit lands the
diagnostic infrastructure that found the actual cost driver.

* test_benchmark now records per-frame timing and reports
  p50 / p99 / p999 / max ms-per-frame plus the count of frames
  that blew the 16.67 ms (60 Hz) budget.

* perf_counters.h gains `perf_counters_find(name)` so the harness
  can snapshot a counter before/after each retro_run() call and
  report per-frame deltas.

* test_benchmark uses the new lookup to print the slowest frames
  along with their blitter call count and inner-iteration count,
  and the slow-vs-avg ratio.

* Makefile gains BLITTER_TRACE=1 toggle that wires
  -DBLITTER_TRACE; src/tom/blitter.c grows a per-blit elapsed-ms
  dump that fires for any single BlitterMidsummer2 call exceeding
  a threshold, so we can tell whether worst-case frame spikes are
  one giant blit or many small ones.

What this revealed for AvP gameplay (state7, accurate blitter,
1200 frames after 120 warmup, M-series host):

   avg 5.1 ms, p99 17.0 ms, p999 18.2 ms, max 18.4 ms
   25 / 1200 frames over 16.67 ms (2%)

   Avg per frame:    403 blits,   49,774 inner iters
   Slow per frame:  2009 blits,  247,508 inner iters  (5x)

The slow frames are perfectly periodic and consistent (5x the work
on every spike, every spike same exact count).  No single blit is
slow -- the BLITTER_TRACE dump prints zero lines even at a 0.3 ms
threshold.  AvP is just doing 5x more blitter work on roughly
every 24th frame.  That's the audio dropout root cause: the inlining
helped average throughput but the periodic 5x spikes still blow
the budget.

Co-Authored-By: Claude Opus 4.7 <[email protected]>

Author: JoeMatt

Makefile

@@ -60,6 +60,15 @@ ifeq ($(BENCH_PROFILE),1)
    CFLAGS += -DBENCH_PROFILE
 endif
 
+# Per-blit slow-path tracing in BlitterMidsummer2.
+# `make BLITTER_TRACE=1` enables an stderr dump of any single blit
+# whose wall time exceeds ~1.5 ms (configurable via the threshold in
+# src/tom/blitter.c).  Useful for finding pathological blit commands
+# that dominate frame-time variance.  macOS-only (uses mach_*).
+ifeq ($(BLITTER_TRACE),1)
+   CFLAGS += -DBLITTER_TRACE
+endif
+
 # Symbol export gating.
 #
 #   GNU ld (Linux, Windows MSYS2, ARM, ...) honours --version-script:

exports-test.list

@@ -36,3 +36,4 @@ _vjs
 _perf_counters_dump
 _perf_counters_reset
 _perf_counters_register
+_perf_counters_find

link-test.T

@@ -39,5 +39,6 @@
       perf_counters_dump;
       perf_counters_reset;
       perf_counters_register;
+      perf_counters_find;
    local: *;
 };

src/core/perf_counters.c

@@ -6,6 +6,7 @@
  * In !BENCH_PROFILE builds the bodies are no-ops and no PERF_COUNTER
  * calls perf_counters_register, so the registry stays empty.
  */
+#include <string.h>
 #include "perf_counters.h"
 
 #ifdef BENCH_PROFILE
@@ -50,3 +51,17 @@ void perf_counters_dump(FILE *out)
    (void)out;
 #endif
 }
+
+unsigned long long *perf_counters_find(const char *name)
+{
+#ifdef BENCH_PROFILE
+   perf_counter_entry_t *e;
+   if (!name) return (unsigned long long *)0;
+   for (e = perf_head; e; e = e->next)
+      if (e->name && strcmp(e->name, name) == 0)
+         return e->value;
+#else
+   (void)name;
+#endif
+   return (unsigned long long *)0;
+}

src/core/perf_counters.h

@@ -48,6 +48,10 @@ typedef struct perf_counter_entry
 void perf_counters_register(perf_counter_entry_t *entry);
 void perf_counters_dump(FILE *out);
 void perf_counters_reset(void);
+/* Return a pointer to the named counter's value, or NULL if unknown.
+ * Lets harnesses snapshot a counter before/after retro_run for
+ * per-frame deltas without exporting individual symbols. */
+unsigned long long *perf_counters_find(const char *name);
 
 #ifdef BENCH_PROFILE
 

src/tom/blitter.c

@@ -1676,9 +1676,19 @@ Unused[0]	:= DUMMY (unused[0]);
 END;*/
 }
 
+#ifdef BLITTER_TRACE
+#include <mach/mach_time.h>
+#include <stdio.h>
+static double bm2_trace_threshold_ms = 0.3; /* dump any blit slower than this */
+static uint64_t bm2_trace_t0;
+#endif
+
 void BlitterMidsummer2(void)
 {
    uint32_t cmd = (PERF_INC(blitter_calls), GET32(blitter_ram, COMMAND));
+#ifdef BLITTER_TRACE
+   bm2_trace_t0 = mach_absolute_time();
+#endif
 
 
    // Line states passed in via the command register
@@ -2685,6 +2695,29 @@ A1_outside	:= OR6 (a1_outside, a1_x{15}, a1xgr, a1xeq, a1_y{15}, a1ygr, a1yeq);
    SET16(blitter_ram, A2_PIXEL + 2, a2_x);
    SET16(blitter_ram, A2_PIXEL + 0, a2_y);
 
+#ifdef BLITTER_TRACE
+   {
+      static mach_timebase_info_data_t tb;
+      uint64_t t1 = mach_absolute_time();
+      double ms;
+      if (tb.denom == 0) mach_timebase_info(&tb);
+      ms = (double)(t1 - bm2_trace_t0) * (double)tb.numer / (double)tb.denom / 1e6;
+      if (ms >= bm2_trace_threshold_ms) {
+         uint16_t pcount = GET16(blitter_ram, PIXLINECOUNTER + 2);
+         uint16_t lcount = GET16(blitter_ram, PIXLINECOUNTER);
+         uint8_t pixsize = (blitter_ram[A1_FLAGS + 3] & 0x38) >> 3;
+         fprintf(stderr,
+            "[BLITTER_TRACE] %.2f ms cmd=%08x pixsize=%u inner=%u outer=%u "
+            "src(en=%d enx=%d enz=%d) dst(en=%d enz=%d wrz=%d) "
+            "gourd=%d gourz=%d srcshade=%d bcompen=%d dcompen=%d\n",
+            ms, cmd, pixsize, pcount, lcount,
+            (int)srcen, (int)srcenx, (int)srcenz,
+            (int)dsten, (int)dstenz, (int)dstwrz,
+            (int)gourd, (int)gourz, (int)srcshade,
+            (int)bcompen, (int)dcompen);
+      }
+   }
+#endif
 }
 
 // Various pieces of the blitter puzzle are teased out here...

test/tools/test_benchmark.c

@@ -38,6 +38,7 @@ static size_t (*pretro_serialize_size)(void);
 static bool (*pretro_unserialize)(const void *, size_t);
 /* Optional: only present when the core was built with BENCH_PROFILE=1. */
 static void (*pperf_counters_dump)(FILE *);
+static unsigned long long *(*pperf_counters_find)(const char *);
 
 /* Options state */
 static int bios_option_set = 0;
@@ -312,8 +313,9 @@ int main(int argc, char **argv)
    LOAD_SYM(retro_serialize_size);
    LOAD_SYM(retro_unserialize);
 
-   /* Optional perf-counter dump; absent unless built with BENCH_PROFILE=1. */
+   /* Optional perf-counter access; absent unless built with BENCH_PROFILE=1. */
    pperf_counters_dump = dlsym(handle, "perf_counters_dump");
+   pperf_counters_find = dlsym(handle, "perf_counters_find");
 
    pretro_set_environment(environment_cb);
    pretro_set_video_refresh(video_refresh);
@@ -492,29 +494,137 @@ int main(int argc, char **argv)
       fprintf(stderr, "--- Warmup complete ---\n");
    }
 
-   /* Timed run */
-   fprintf(stderr, "--- Benchmarking %d frames ---\n", num_frames);
-   t_start = timer_now();
-
-   for (i = 0; i < num_frames; i++)
-      pretro_run();
-
-   t_end = timer_now();
-
-   elapsed = timer_elapsed_sec(t_start, t_end);
-   fps = (double)num_frames / elapsed;
-   ms_per_frame = (elapsed * 1000.0) / (double)num_frames;
-
-   /* Print results */
-   printf("\n=== BENCHMARK RESULTS ===\n");
-   printf("Blitter mode:    %s\n",
-          strcmp(blitter_value, "enabled") == 0 ? "fast" : "accurate");
-   printf("Frames measured: %d\n", num_frames);
-   printf("Warmup frames:   %d\n", warmup_frames);
-   printf("Total time:      %.3f s\n", elapsed);
-   printf("Frames/sec:      %.2f\n", fps);
-   printf("Time/frame:      %.3f ms\n", ms_per_frame);
-   printf("=========================\n");
+   /* Timed run with per-frame samples to expose variance.  Audio
+    * dropouts in real frontends are caused by *worst-case* frames
+    * exceeding the 16.6 ms (60 Hz) budget, not by the average. */
+   {
+      double *frame_ms = (double *)malloc((size_t)num_frames * sizeof(double));
+      unsigned long long *blit_calls_at_frame = (unsigned long long *)malloc((size_t)num_frames * sizeof(unsigned long long));
+      unsigned long long *blit_inner_at_frame = (unsigned long long *)malloc((size_t)num_frames * sizeof(unsigned long long));
+      double frame_budget_ms = 1000.0 / 60.0;
+      int over_budget = 0;
+      double max_ms = 0.0;
+      double p50_ms = 0.0, p99_ms = 0.0, p999_ms = 0.0;
+      unsigned long long *blit_calls_ctr = pperf_counters_find ? pperf_counters_find("blitter_calls") : NULL;
+      unsigned long long *blit_inner_ctr = pperf_counters_find ? pperf_counters_find("blitter_inner") : NULL;
+      unsigned long long blit_calls_prev = blit_calls_ctr ? *blit_calls_ctr : 0;
+      unsigned long long blit_inner_prev = blit_inner_ctr ? *blit_inner_ctr : 0;
+
+      if (!frame_ms || !blit_calls_at_frame || !blit_inner_at_frame)
+      {
+         fprintf(stderr, "ERROR: malloc failed for per-frame timing\n");
+         pretro_unload_game(); pretro_deinit();
+         free((void *)info.data); dlclose(handle);
+         return 1;
+      }
+
+      fprintf(stderr, "--- Benchmarking %d frames ---\n", num_frames);
+      t_start = timer_now();
+
+      for (i = 0; i < num_frames; i++)
+      {
+         uint64_t f0 = timer_now();
+         uint64_t f1;
+         pretro_run();
+         f1 = timer_now();
+         frame_ms[i] = timer_elapsed_sec(f0, f1) * 1000.0;
+         if (blit_calls_ctr) {
+            blit_calls_at_frame[i] = *blit_calls_ctr - blit_calls_prev;
+            blit_calls_prev = *blit_calls_ctr;
+         } else blit_calls_at_frame[i] = 0;
+         if (blit_inner_ctr) {
+            blit_inner_at_frame[i] = *blit_inner_ctr - blit_inner_prev;
+            blit_inner_prev = *blit_inner_ctr;
+         } else blit_inner_at_frame[i] = 0;
+      }
+
+      t_end = timer_now();
+
+      elapsed = timer_elapsed_sec(t_start, t_end);
+      fps = (double)num_frames / elapsed;
+      ms_per_frame = (elapsed * 1000.0) / (double)num_frames;
+
+      /* Quicksort copy so the original order is preserved for any
+       * later analysis (currently we don't print it, but cheap). */
+      {
+         double *sorted = (double *)malloc((size_t)num_frames * sizeof(double));
+         int j;
+         if (sorted)
+         {
+            memcpy(sorted, frame_ms, (size_t)num_frames * sizeof(double));
+            /* Insertion sort (small N typical). */
+            for (i = 1; i < num_frames; i++)
+            {
+               double key = sorted[i];
+               j = i - 1;
+               while (j >= 0 && sorted[j] > key) { sorted[j + 1] = sorted[j]; j--; }
+               sorted[j + 1] = key;
+            }
+            p50_ms  = sorted[(int)((double)num_frames * 0.50)];
+            p99_ms  = sorted[(int)((double)num_frames * 0.99)];
+            p999_ms = sorted[(int)((double)num_frames * 0.999)];
+            max_ms  = sorted[num_frames - 1];
+            free(sorted);
+         }
+      }
+      for (i = 0; i < num_frames; i++)
+         if (frame_ms[i] > frame_budget_ms) over_budget++;
+
+      /* Print results */
+      printf("\n=== BENCHMARK RESULTS ===\n");
+      printf("Blitter mode:    %s\n",
+             strcmp(blitter_value, "enabled") == 0 ? "fast" : "accurate");
+      printf("Frames measured: %d\n", num_frames);
+      printf("Warmup frames:   %d\n", warmup_frames);
+      printf("Total time:      %.3f s\n", elapsed);
+      printf("Frames/sec:      %.2f\n", fps);
+      printf("Time/frame avg:  %.3f ms\n", ms_per_frame);
+      printf("Time/frame p50:  %.3f ms\n", p50_ms);
+      printf("Time/frame p99:  %.3f ms\n", p99_ms);
+      printf("Time/frame p999: %.3f ms\n", p999_ms);
+      printf("Time/frame max:  %.3f ms\n", max_ms);
+      printf("Over 16.67 ms:   %d / %d frames (%.2f%%)\n",
+             over_budget, num_frames, 100.0 * over_budget / num_frames);
+      printf("=========================\n");
+
+      /* If we have per-frame blitter counters, dump the slowest frames
+       * so we can correlate blit volume with frame-time spikes. */
+      if (over_budget > 0 && blit_calls_ctr) {
+         int j;
+         double avg_calls = 0.0, avg_inner = 0.0;
+         double slow_calls = 0.0, slow_inner = 0.0;
+         int slow_n = 0;
+         printf("\n--- Worst frames (>16.67ms) -----------------------------\n");
+         printf("  idx  frame_ms  blit_calls  blit_inner_iter\n");
+         for (j = 0; j < num_frames; j++) {
+            avg_calls += blit_calls_at_frame[j];
+            avg_inner += blit_inner_at_frame[j];
+            if (frame_ms[j] > frame_budget_ms) {
+               slow_calls += blit_calls_at_frame[j];
+               slow_inner += blit_inner_at_frame[j];
+               slow_n++;
+               if (slow_n <= 12)
+                  printf("  %4d  %7.2f   %10llu   %15llu\n",
+                         j, frame_ms[j],
+                         blit_calls_at_frame[j],
+                         blit_inner_at_frame[j]);
+            }
+         }
+         printf("---\n");
+         printf("Avg per frame (all):    blits=%.0f  inner_iter=%.0f\n",
+                avg_calls / num_frames, avg_inner / num_frames);
+         if (slow_n > 0)
+            printf("Avg per frame (slow):   blits=%.0f  inner_iter=%.0f  (%dx, %dx vs avg)\n",
+                   slow_calls / slow_n, slow_inner / slow_n,
+                   (int)((slow_calls / slow_n) / (avg_calls / num_frames + 1e-9)),
+                   (int)((slow_inner / slow_n) / (avg_inner / num_frames + 1e-9)));
+         printf("=========================================================\n");
+      }
+
+      free(frame_ms);
+      free(blit_calls_at_frame);
+      free(blit_inner_at_frame);
+   }
 
    if (pperf_counters_dump)
       pperf_counters_dump(stderr);