Menu-framerate — DEVICE per-pair fence timing + GPU clock/busy capture
======================================================================
Device: Retroid Pocket 5 (kona), Snapdragon 865 / Adreno 650, not rooted.
APK: android/app/build/outputs/apk/debug/app-debug.apk, rt64 diag bba84ab
     (per-pair sync=NN.NNms column added to g64prof enumeration), copyWithGPU=0.
Screen: Select Adventure Diary (20 framebuffer pairs/frame).
Captured: 2026-07-19 ~23:11-23:20 local, this session (adb via Windows host).

KGSL sysfs facts:
  governor            = msm-adreno-tz (utilization-based)
  min_freq            = 305000000
  max_freq            = 670000000
  available_freqs     = 670 587 525 490 441.6 400 305 MHz

NATURAL EXPERIMENT — GPU_hw execution time vs core clock (governor-driven, not forced):
  clock 400 MHz, busy 65-69%  ->  GPU_hw = 35.4 ms  ->  14.8 FPS  (present ~67 ms)
  clock 305 MHz, busy 67-69%  ->  GPU_hw = 43.2 ms  ->  12.0 FPS  (present ~82 ms)
  => GPU_hw scales PARTIALLY with core clock (1.22x slower at 0.76x clock).
     2-point fit: GPU_hw ~= 10.4 ms fixed + 10013/clock_MHz ms.
     Projection at max 670 MHz: GPU_hw ~= 25 ms  (=> a real, currently-unused FPS lever).
  => busy stays ~68% at BOTH clocks; governor never ramps past 400 (util < ramp threshold).
     This is why "performance mode makes no difference" IF the mode does not pin min_freq high.

PER-PAIR FENCE TIMING (the decisive [HELD] #13 measurement):
  - Every frame has EXACTLY ONE expensive fence ~34-39 ms = 53-67% of all per-pair sync.
  - The other 19 fences are ~1-3 ms each (~25 ms aggregate, CPU-side serialization).
  - The expensive fence is ALWAYS a 2-draw-call pair; its pair-index/buffer VARIES
    (usually pair[2] 001E46F0 w=8, sometimes pair[1] main w=320, sometimes pair[3] w=256).
  - The 144-draw-call UI pair (pair 19) costs ~1.4 ms.
  => Per-fence cost is DECOUPLED from draw count (refutes "GPU compute scales with draws").
     The single big fence is where the CPU catches up to the serially-draining GPU backlog;
     the ~35 ms GPU_hw is per-renderpass overhead x 20 pairs, part-fixed + part-clock-scalable,
     NOT proportional to draws.

Per-frame max-fence vs sum(sync) (n_over8 = fences >8ms):
  sum=63.1 max=38.7 (61%) n_over8=1
  sum=64.4 max=34.4 (53%) n_over8=1
  sum=71.8 max=37.7 (52%) n_over8=1
  sum=62.0 max=38.3 (62%) n_over8=1
  sum=57.8 max=36.5 (63%) n_over8=1
  sum=61.5 max=37.4 (61%) n_over8=1
  sum=54.9 max=36.5 (67%) n_over8=1
  (12/12 captured frames: exactly one >8ms fence.)

RAW: two representative enumeration frames + the steady-state summary lines follow.
======================================================================
--- steady-state summary lines (23:13-23:20) ---
07-19 23:13:44.701  6187  6295 I Goemon64-stdio: [g64prof] render present=67.38ms (14.8 fps)  rendererCPU=37.79ms  GPU=35.41ms  workload=38.22ms  match=0.13ms
07-19 23:13:45.331  6187  6295 I Goemon64-stdio: [g64prof] fullSync 14.9/s  pairs/frame=20.0  fences/frame=20.0  naturalFences/frame=12.0  pairSync=63.84ms/frame (gpuWait=45.97 cpuCopy=0.50 uploadWait=1.63)  copyWithGPU=0
07-19 23:13:45.707  6187  6295 I Goemon64-stdio: [g64prof] render present=67.36ms (14.8 fps)  rendererCPU=37.80ms  GPU=35.43ms  workload=38.22ms  match=0.13ms
07-19 23:13:46.362  6187  6295 I Goemon64-stdio: [g64prof] fullSync 14.5/s  pairs/frame=20.0  fences/frame=20.0  naturalFences/frame=12.0  pairSync=65.89ms/frame (gpuWait=46.12 cpuCopy=0.43 uploadWait=1.40)  copyWithGPU=0
07-19 23:13:46.760  6187  6295 I Goemon64-stdio: [g64prof] render present=67.69ms (14.8 fps)  rendererCPU=37.76ms  GPU=35.39ms  workload=38.17ms  match=0.13ms
07-19 23:13:47.389  6187  6295 I Goemon64-stdio: [g64prof] fullSync 13.6/s  pairs/frame=20.0  fences/frame=20.0  naturalFences/frame=12.0  pairSync=70.59ms/frame (gpuWait=49.29 cpuCopy=0.43 uploadWait=1.53)  copyWithGPU=0
07-19 23:13:47.805  6187  6295 I Goemon64-stdio: [g64prof] render present=68.52ms (14.6 fps)  rendererCPU=37.68ms  GPU=35.37ms  workload=38.07ms  match=0.12ms
07-19 23:13:48.441  6187  6295 I Goemon64-stdio: [g64prof] fullSync 14.3/s  pairs/frame=20.0  fences/frame=20.0  naturalFences/frame=12.0  pairSync=67.35ms/frame (gpuWait=43.11 cpuCopy=0.41 uploadWait=0.29)  copyWithGPU=0
07-19 23:13:48.807  6187  6295 I Goemon64-stdio: [g64prof] render present=68.52ms (14.6 fps)  rendererCPU=37.71ms  GPU=35.40ms  workload=38.12ms  match=0.12ms
07-19 23:13:49.445  6187  6295 I Goemon64-stdio: [g64prof] fullSync 14.9/s  pairs/frame=20.0  fences/frame=20.0  naturalFences/frame=12.0  pairSync=64.11ms/frame (gpuWait=40.73 cpuCopy=0.43 uploadWait=0.11)  copyWithGPU=0
07-19 23:13:49.814  6187  6295 I Goemon64-stdio: [g64prof] render present=68.65ms (14.6 fps)  rendererCPU=37.75ms  GPU=35.40ms  workload=38.17ms  match=0.13ms
07-19 23:13:50.503  6187  6295 I Goemon64-stdio: [g64prof] fullSync 15.1/s  pairs/frame=20.0  fences/frame=20.0  naturalFences/frame=12.0  pairSync=63.48ms/frame (gpuWait=41.26 cpuCopy=0.43 uploadWait=0.18)  copyWithGPU=0
07-19 23:13:50.877  6187  6295 I Goemon64-stdio: [g64prof] render present=68.47ms (14.6 fps)  rendererCPU=37.71ms  GPU=35.35ms  workload=38.10ms  match=0.13ms
07-19 23:13:51.552  6187  6295 I Goemon64-stdio: [g64prof] fullSync 15.3/s  pairs/frame=20.0  fences/frame=20.0  naturalFences/frame=12.0  pairSync=62.87ms/frame (gpuWait=45.20 cpuCopy=0.42 uploadWait=0.09)  copyWithGPU=0
07-19 23:13:51.922  6187  6295 I Goemon64-stdio: [g64prof] render present=68.13ms (14.7 fps)  rendererCPU=37.70ms  GPU=35.33ms  workload=38.09ms  match=0.13ms
07-19 23:13:52.614  6187  6295 I Goemon64-stdio: [g64prof] fullSync 15.1/s  pairs/frame=20.0  fences/frame=20.0  naturalFences/frame=12.0  pairSync=63.72ms/frame (gpuWait=41.35 cpuCopy=0.40 uploadWait=0.16)  copyWithGPU=0
07-19 23:13:52.978  6187  6295 I Goemon64-stdio: [g64prof] render present=67.91ms (14.7 fps)  rendererCPU=37.64ms  GPU=35.25ms  workload=38.02ms  match=0.13ms
07-19 23:13:53.656  6187  6295 I Goemon64-stdio: [g64prof] fullSync 15.4/s  pairs/frame=20.0  fences/frame=20.0  naturalFences/frame=12.0  pairSync=61.67ms/frame (gpuWait=45.07 cpuCopy=0.47 uploadWait=0.07)  copyWithGPU=0
07-19 23:13:54.036  6187  6295 I Goemon64-stdio: [g64prof] render present=67.63ms (14.8 fps)  rendererCPU=37.67ms  GPU=35.27ms  workload=38.05ms  match=0.13ms
07-19 23:13:54.677  6187  6295 I Goemon64-stdio: [g64prof] fullSync 14.7/s  pairs/frame=20.0  fences/frame=20.0  naturalFences/frame=12.0  pairSync=65.32ms/frame (gpuWait=43.90 cpuCopy=0.43 uploadWait=0.07)  copyWithGPU=0
07-19 23:13:55.051  6187  6295 I Goemon64-stdio: [g64prof] render present=67.38ms (14.8 fps)  rendererCPU=37.73ms  GPU=35.31ms  workload=38.10ms  match=0.13ms
07-19 23:13:55.694  6187  6295 I Goemon64-stdio: [g64prof] fullSync 14.7/s  pairs/frame=20.0  fences/frame=20.0  naturalFences/frame=12.0  pairSync=65.03ms/frame (gpuWait=46.54 cpuCopy=0.44 uploadWait=0.11)  copyWithGPU=0
07-19 23:13:56.064  6187  6295 I Goemon64-stdio: [g64prof] render present=66.63ms (15.0 fps)  rendererCPU=37.61ms  GPU=35.22ms  workload=38.00ms  match=0.13ms
07-19 23:13:56.703  6187  6295 I Goemon64-stdio: [g64prof] fullSync 14.9/s  pairs/frame=20.0  fences/frame=20.0  naturalFences/frame=12.0  pairSync=64.56ms/frame (gpuWait=45.84 cpuCopy=0.44 uploadWait=0.09)  copyWithGPU=0

--- two representative full enumeration frames (with sync= column) ---
07-19 23:13:45.331  6187  6295 I Goemon64-stdio:   pair[ 0] sync=  --   calls=1    color=002D1800 fmt=0 siz=2 w=320 depth=002D1800 fillRect=1 natural=0 flush=ColorChanged
07-19 23:13:45.331  6187  6295 I Goemon64-stdio:   pair[ 1] sync= 38.74ms  calls=2    color=00261000 fmt=0 siz=2 w=320 depth=002D1800 fillRect=0 natural=0 flush=SampleColor
07-19 23:13:45.331  6187  6295 I Goemon64-stdio:   pair[ 2] sync=  2.49ms  calls=2    color=001E46F0 fmt=0 siz=2 w=8 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:45.331  6187  6295 I Goemon64-stdio:   pair[ 3] sync=  1.25ms  calls=2    color=001E46F0 fmt=0 siz=2 w=256 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:45.331  6187  6295 I Goemon64-stdio:   pair[ 4] sync=  1.39ms  calls=4    color=00261000 fmt=0 siz=2 w=320 depth=002D1800 fillRect=0 natural=0 flush=ColorChanged
07-19 23:13:45.331  6187  6295 I Goemon64-stdio:   pair[ 5] sync=  1.25ms  calls=2    color=001E46F0 fmt=0 siz=2 w=8 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:45.331  6187  6295 I Goemon64-stdio:   pair[ 6] sync=  1.45ms  calls=2    color=001E46F0 fmt=0 siz=2 w=256 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:45.331  6187  6295 I Goemon64-stdio:   pair[ 7] sync=  1.45ms  calls=4    color=00261000 fmt=0 siz=2 w=320 depth=002D1800 fillRect=0 natural=0 flush=ColorChanged
07-19 23:13:45.331  6187  6295 I Goemon64-stdio:   pair[ 8] sync=  0.85ms  calls=2    color=001E46F0 fmt=0 siz=2 w=8 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:45.331  6187  6295 I Goemon64-stdio:   pair[ 9] sync=  1.15ms  calls=2    color=001E46F0 fmt=0 siz=2 w=256 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:45.331  6187  6295 I Goemon64-stdio:   pair[10] sync=  1.23ms  calls=4    color=00261000 fmt=0 siz=2 w=320 depth=002D1800 fillRect=0 natural=0 flush=ColorChanged
07-19 23:13:45.331  6187  6295 I Goemon64-stdio:   pair[11] sync=  0.87ms  calls=2    color=001E46F0 fmt=0 siz=2 w=8 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:45.331  6187  6295 I Goemon64-stdio:   pair[12] sync=  2.14ms  calls=2    color=001E46F0 fmt=0 siz=2 w=256 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:45.331  6187  6295 I Goemon64-stdio:   pair[13] sync=  1.43ms  calls=4    color=00261000 fmt=0 siz=2 w=320 depth=002D1800 fillRect=0 natural=0 flush=ColorChanged
07-19 23:13:45.331  6187  6295 I Goemon64-stdio:   pair[14] sync=  1.36ms  calls=2    color=001E46F0 fmt=0 siz=2 w=8 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:45.331  6187  6295 I Goemon64-stdio:   pair[15] sync=  1.51ms  calls=2    color=001E46F0 fmt=0 siz=2 w=256 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:45.331  6187  6295 I Goemon64-stdio:   pair[16] sync=  1.42ms  calls=4    color=00261000 fmt=0 siz=2 w=320 depth=002D1800 fillRect=0 natural=0 flush=SampleColor
07-19 23:13:45.331  6187  6295 I Goemon64-stdio:   pair[17] sync=  0.96ms  calls=2    color=001E46F0 fmt=0 siz=2 w=8 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:45.331  6187  6295 I Goemon64-stdio:   pair[18] sync=  0.92ms  calls=2    color=001E46F0 fmt=0 siz=2 w=256 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:45.331  6187  6295 I Goemon64-stdio:   pair[19] sync=  1.19ms  calls=144  color=00261000 fmt=0 siz=2 w=320 depth=002D1800 fillRect=0 natural=0 flush=DLEnd
07-19 23:13:45.707  6187  6295 I Goemon64-stdio: [g64prof] render present=67.36ms (14.8 fps)  rendererCPU=37.80ms  GPU=35.43ms  workload=38.22ms  match=0.13ms
07-19 23:13:46.362  6187  6295 I Goemon64-stdio: [g64prof] fullSync 14.5/s  pairs/frame=20.0  fences/frame=20.0  naturalFences/frame=12.0  pairSync=65.89ms/frame (gpuWait=46.12 cpuCopy=0.43 uploadWait=1.40)  copyWithGPU=0
07-19 23:13:46.362  6187  6295 I Goemon64-stdio: [g64prof] pair enumeration (one representative frame, 20 pairs):
07-19 23:13:46.362  6187  6295 I Goemon64-stdio:   pair[ 0] sync=  --   calls=1    color=002D1800 fmt=0 siz=2 w=320 depth=002D1800 fillRect=1 natural=0 flush=ColorChanged
07-19 23:13:46.362  6187  6295 I Goemon64-stdio:   pair[ 1] sync= 34.39ms  calls=2    color=00261000 fmt=0 siz=2 w=320 depth=002D1800 fillRect=0 natural=0 flush=SampleColor
07-19 23:13:46.362  6187  6295 I Goemon64-stdio:   pair[ 2] sync=  4.33ms  calls=2    color=001E46F0 fmt=0 siz=2 w=8 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:46.362  6187  6295 I Goemon64-stdio:   pair[ 3] sync=  2.31ms  calls=2    color=001E46F0 fmt=0 siz=2 w=256 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:46.362  6187  6295 I Goemon64-stdio:   pair[ 4] sync=  1.29ms  calls=4    color=00261000 fmt=0 siz=2 w=320 depth=002D1800 fillRect=0 natural=0 flush=ColorChanged
07-19 23:13:46.362  6187  6295 I Goemon64-stdio:   pair[ 5] sync=  1.58ms  calls=2    color=001E46F0 fmt=0 siz=2 w=8 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:46.362  6187  6295 I Goemon64-stdio:   pair[ 6] sync=  1.05ms  calls=2    color=001E46F0 fmt=0 siz=2 w=256 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:46.362  6187  6295 I Goemon64-stdio:   pair[ 7] sync=  1.27ms  calls=4    color=00261000 fmt=0 siz=2 w=320 depth=002D1800 fillRect=0 natural=0 flush=ColorChanged
07-19 23:13:46.362  6187  6295 I Goemon64-stdio:   pair[ 8] sync=  0.87ms  calls=2    color=001E46F0 fmt=0 siz=2 w=8 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:46.362  6187  6295 I Goemon64-stdio:   pair[ 9] sync=  1.36ms  calls=2    color=001E46F0 fmt=0 siz=2 w=256 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:46.362  6187  6295 I Goemon64-stdio:   pair[10] sync=  1.15ms  calls=4    color=00261000 fmt=0 siz=2 w=320 depth=002D1800 fillRect=0 natural=0 flush=ColorChanged
07-19 23:13:46.362  6187  6295 I Goemon64-stdio:   pair[11] sync=  1.77ms  calls=2    color=001E46F0 fmt=0 siz=2 w=8 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:46.362  6187  6295 I Goemon64-stdio:   pair[12] sync=  1.25ms  calls=2    color=001E46F0 fmt=0 siz=2 w=256 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:46.362  6187  6295 I Goemon64-stdio:   pair[13] sync=  3.24ms  calls=4    color=00261000 fmt=0 siz=2 w=320 depth=002D1800 fillRect=0 natural=0 flush=ColorChanged
07-19 23:13:46.362  6187  6295 I Goemon64-stdio:   pair[14] sync=  2.60ms  calls=2    color=001E46F0 fmt=0 siz=2 w=8 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:46.362  6187  6295 I Goemon64-stdio:   pair[15] sync=  1.18ms  calls=2    color=001E46F0 fmt=0 siz=2 w=256 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:46.362  6187  6295 I Goemon64-stdio:   pair[16] sync=  2.08ms  calls=4    color=00261000 fmt=0 siz=2 w=320 depth=002D1800 fillRect=0 natural=0 flush=SampleColor
07-19 23:13:46.362  6187  6295 I Goemon64-stdio:   pair[17] sync=  0.81ms  calls=2    color=001E46F0 fmt=0 siz=2 w=8 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:46.362  6187  6295 I Goemon64-stdio:   pair[18] sync=  0.94ms  calls=2    color=001E46F0 fmt=0 siz=2 w=256 depth=002D1800 fillRect=0 natural=1 flush=ColorChanged
07-19 23:13:46.362  6187  6295 I Goemon64-stdio:   pair[19] sync=  0.93ms  calls=144  color=00261000 fmt=0 siz=2 w=320 depth=002D1800 fillRect=0 natural=0 flush=DLEnd
07-19 23:13:46.760  6187  6295 I Goemon64-stdio: [g64prof] render present=67.69ms (14.8 fps)  rendererCPU=37.76ms  GPU=35.39ms  workload=38.17ms  match=0.13ms
07-19 23:13:47.389  6187  6295 I Goemon64-stdio: [g64prof] fullSync 13.6/s  pairs/frame=20.0  fences/frame=20.0  naturalFences/frame=12.0  pairSync=70.59ms/frame (gpuWait=49.29 cpuCopy=0.43 uploadWait=1.53)  copyWithGPU=0
07-19 23:13:47.389  6187  6295 I Goemon64-stdio: [g64prof] pair enumeration (one representative frame, 20 pairs):

======================================================================
PERF-MODE UPDATE (same session, user toggled Retroid "high performance"):
This SUPERSEDES the 2-point fit above with a 3rd clock point and OVERTURNS the
prior [HELD] #12 "DVFS is out / perf mode makes no difference".

  Mode              clock    busy    GPU_hw    big-fence   FPS
  normal (parked)   305 MHz  67-69%  43.2 ms   ~37 ms      12.0
  normal (parked)   400 MHz  65-69%  35.4 ms   ~37 ms      14.8
  HIGH PERFORMANCE  587 MHz  67-69%  21.5 ms   ~22.5 ms    25.8   <-- ~2x FPS

  - High-performance mode NEARLY DOUBLED menu FPS (12-15 -> 26). DVFS is the
    DOMINANT lever, not "out". The earlier user report that perf mode "makes no
    difference" is contradicted on THIS screen with THIS toggle.
  - 3-point fit: GPU_hw ~= 13778 / clock_MHz  (fixed term ~ -2 ms, i.e. ~0).
    => GPU_hw is ~purely core-clock-bound compute (near-zero fixed submit latency).
    Predicted at max 670 MHz: ~20.6 ms (diminishing past 587).
  - busy stays ~68% at ALL THREE clocks => the ~32% serialization bubble is a
    CONSTANT PROPORTION, clock-invariant. The GPU is ~68%-utilized by real compute
    and ~32% idle on CPU-side per-fence serialization, at every clock.
  - The one-big-fence pattern PERSISTS and SCALES with clock (37 -> 22.5 ms):
    it is the frame's clock-bound GPU compute surfacing at the first sync where the
    CPU catches up to the serially-draining GPU. Still always a 2-draw-call pair,
    index varies (pair 1/2/3). Draw-count-decoupled but clock-bound => the compute
    is per-renderpass composite/pixel work across the 20 upscaled render targets
    (the color-cycling background), NOT per-N64-draw.

CORRECTED CONCLUSIONS ([HELD] #12/#13 both resolved):
  #13: the per-fence cost is NOT fixed latency and NOT draw-scaled; it is
       clock-bound per-renderpass GPU compute (GPU_hw ∝ 1/clock), concentrated at
       one CPU/GPU sync catch-up point per frame.
  #12: DVFS is the DOMINANT lever (perf mode ~2x). In default power mode the
       msm-adreno-tz utilization governor parks the clock at 305-400 MHz because
       GPU busy (~68%) never crosses its ramp threshold -> clock-bound work starves.

TWO STACKABLE LEVERS (net-new framing):
  A. GPU clock: request higher clock in default mode via Android ADPF /
     PerformanceHintManager (report the real per-frame work duration so the
     governor/hint ramps), or recommend the device perf profile. Measured ~2x.
  B. Fewer renderpasses/fences (linear-loadBlock, submit-loop rework, copies-on):
     removes the ~32% serialization bubble (~13 ms CPU-side) AND raises utilization,
     which in default mode could also let the governor ramp on its own. copies-on's
     measured +24% is the CPU-side slice of this lever.
  Stacked, plausibly reaches gameplay's ~30 FPS on this screen.
