virtualjaguar-libretro/docs/profiling.md

Profiling guide

How to measure where the Virtual Jaguar libretro core actually spends time.

Investigating a report from tvOS, Android or a console port? Start with On-device profiling. Everything else in this guide is host-side (macOS/Linux, Instruments/perf/sample) and cannot reach a device you can't attach a profiler to. Context for the wider effort: #509.

On-device profiling — RetroArch's performance counters

The core registers eight timing counters through RETRO_ENVIRONMENT_GET_PERF_INTERFACE, and RetroArch renders them in its own UI on every platform including tvOS. This is the only route that measures the device that is actually slow.

Nothing to build: it ships in release builds and is inert until a frontend offers the interface.

Capturing

1. In RetroArch, Settings → Frontend → Performance Counters → On (older builds: Settings → Logging → Performance Counters).
2. Load content, play the part that is slow, then quit the core — totals are also written to the RetroArch log at unload, which is usually easier to retrieve off a locked-down device than reading them off the TV.
3. Settings → Logging → Log Verbosity → On if you want the log copy.

Two traps that make a capture silently worthless

Both were found by reading RetroArch's runloop.c, and neither announces itself — the failure looks like a working run.

1. perfcnt_enable is mandatory, and off means zero, not "off".

runloop_performance_counter_register()  -- NEVER gated
core_performance_counter_start/stop()   -- gated on perfcnt_enable
runloop_perf_log()                      -- returns early if disabled

Registration always succeeds, so the core sets vjPerfActive = 1, every probe fires, and every counter stays at zero. A capture taken with the setting off is indistinguishable from a core whose instrumentation is broken. Set it in the menu, or put perfcnt_enable = "true" in retroarch.cfg — the scripts below do the latter.

Corollary for shipping builds: under RetroArch the core's fast path is not the "never-taken branch" described in perf_iface.h. RetroArch accepts the interface even with counters disabled, so vjPerfActive is 1 and each probe makes a real indirect call that returns immediately. That is ~2,000 such calls per frame — negligible at slice granularity, but it is not zero, and it is only zero on frontends that actually decline env 28.

2. The log prints an AVERAGE, not a total.

#define PERF_LOG_FMT "[PERF] Avg (%s): %llu ticks, %llu runs.\n"

Total ticks = avg × runs. This matters more than it sounds: the blitter is few calls that are individually expensive and the GPU is very many cheap ones, so ranking by the printed figure inverts the exact comparison the counters exist to make. On yarc.j64 the blitter's average is ~32× the GPU's while its total is ~4× smaller.

Automated capture

Two scripts drive the whole loop and share one report parser, so the iOS/tvOS and Raspberry Pi paths print the same table.

# iOS / tvOS, through your own RetroArch checkout
test/tools/device_perf.sh doctor                      # devices + build id
test/tools/device_perf.sh build   tvos                # + build-identity assert
test/tools/device_perf.sh install tvos -d "Bedroom"   # sign, inject, deploy
test/tools/device_perf.sh cfg            -d "Bedroom" # perfcnt_enable=true
test/tools/device_perf.sh capture        -d "Bedroom" # prints the manual step
test/tools/device_perf.sh pull           -d "Bedroom" -o run.log
test/tools/device_perf.sh report run.log --json run.json

# Raspberry Pi (or any Linux ARM box you can ssh to)
test/tools/rpi_perf.sh build --arch aarch64           # container; artefacts only
test/tools/rpi_perf.sh doctor  [email protected]   # real-hardware gate
test/tools/rpi_perf.sh deploy  [email protected]
test/tools/rpi_perf.sh profile [email protected] --frames 1800

rpi_perf.sh runs perf_iface_witness on the Pi rather than RetroArch — it is a complete env-28 frontend in a single file, so it needs no frontend, no GUI and no config, and trap 1 above cannot apply to it.

It will refuse to report timings from emulated hardware. bench and profile both gate on doctor, which requires a Raspberry Pi /proc/device-tree/model and a non-virtualised systemd-detect-virt. An aarch64 container on your Mac will build the core happily and produce entirely meaningless numbers; the gate exists because the dangerous outcome is not a wrong number, it is a confident one.

The counters

Counter	What it brackets
vj_m68k_slice	One 68K slice from the event loop
vj_gpu_exec	All GPU RISC execution, every entry path
vj_dsp_exec	All DSP RISC execution, every entry path
vj_gpu_sync	The part of vj_gpu_exec pulled in by a 68K bus access
vj_dsp_sync	The part of vj_dsp_exec pulled in by a 68K bus access
vj_op_halfline	One Object Processor halfline render
vj_blitter	One blit, whichever engine is selected
vj_dac_mix	One frame of audio mixing

Reading them — they deliberately overlap

These do not sum to frame time and are not a pie chart. The Jaguar's processors do not run in disjoint phases, and two nestings are real:

• A 68K access into GPU/DSP local RAM runs RISC cycles inline via GPUSyncToM68K() / DSPSyncToM68K(), so vj_m68k_slice contains RISC time.
• The Object Processor runs the GPU inline from a halfline callback, so vj_op_halfline contains GPU time.

vj_gpu_sync / vj_dsp_sync exist to make the first one measurable rather than merely disclosed. To decompose:

real 68K work     ~=  vj_m68k_slice - vj_gpu_sync - vj_dsp_sync
slice-driven GPU  ~=  vj_gpu_exec   - vj_gpu_sync

vj_gpu_exec and vj_dsp_exec need no correction — every path that runs RISC cycles goes through them.

Two caveats worth stating plainly

Enabling the counters costs time. vj_gpu_exec alone brackets ~1,700 calls per frame, each taking two clock reads. Use the numbers for relative attribution between subsystems, not as an absolute frame budget, and don't compare a counters-on session against a counters-off one for total speed.

It cannot perturb the emulation. The instrumentation touches no emulated state — test/tools/perf_iface_witness asserts that the framebuffer is byte-identical with counters on and off, so a capture is measuring the same machine you were playing.

Sample shape

From perf_iface_witness on yarc.j64, 120 frames — the ordering is the point, not the absolute numbers:

vj_gpu_exec      calls=201045  total=475217000   <- dominates
vj_blitter       calls=1433    total=100466000   <- few calls, expensive each
vj_op_halfline   calls=31440   total=26878000
vj_m68k_slice    calls=200390  total=6772000     <- small
vj_dsp_exec      calls=200390  total=4333000
vj_dac_mix       calls=120     total=14000
vj_gpu_sync      calls=0       total=0           <- this title never syncs
vj_dsp_sync      calls=0       total=0

Benchmark-ROM caveat (#533). yarc.j64 is an amplifier, not a benchmark: 73.3% of its GPU time is jr (a spin loop) and its DSP share is ~0.08%, so a DSP or blitter change measures as "no effect" on it. The #532 GPU hoist scored −4.33% on yarc against −3.77% on jagniccc — same change, and the gap is that bias. Use yarc to make a GPU-loop effect visible; never to size one. The figures on this page taken on yarc are still valid for what they measured, but are not a whole-core picture.

make benchmark now defaults to jagniccc.j64 @ 900 frames with a 300-frame warmup — the warmup matters, because jagniccc is still in BIOS boot (zero GPU-interpreter instructions) at 90 frames. Use test/tools/ir_ab.sh --profile to check any ROM/window before trusting it.

Adding a counter

Add a slot to the enum in src/core/perf_iface.h, an identifier to vjperf_idents[], and a VJP_ENTER/VJP_LEAVE pair at the site. Read the placement rule in that header first — the probe goes after a function's top-of-function guards, and there must be no return between ENTER and LEAVE, or the slot leaks its nesting depth and silently measures nothing for the rest of the session. perf_iface_witness gates that.

TL;DR — make benchmark

Wall-clock baseline you can run on every commit:

make benchmark                              # default: jagniccc.j64, 900 frames, 300 warmup
make benchmark BENCH_ROM=test/roms/yarc.j64 # GPU-loop amplifier -- see the caveat below
make benchmark BENCH_FRAMES=3000            # longer run (smoother numbers)
make benchmark BENCH_BLITTER=accurate       # A/B against the "accurate" path.  Measured
                                             # on arm64 (#511): fast is never slower, and
                                             # ~2.2x faster in blit-heavy scenes despite
                                             # being scalar while accurate is NEON.
make benchmark BENCH_ROM=test/roms/private/Atari\ Karts.jag

Reports Frames/sec, Time/frame, total wall time. Boots the core via dlopen, runs N frames headless (no video presentation, no audio output), so you measure pure emulator work.

Use it as a delta: capture baseline before your change, run again after. Don't trust absolute numbers across hosts (CPU, thermals, scheduler, big.LITTLE pinning). Do trust same-host commit-to-commit deltas.

The harness lives at test/tools/test_benchmark.c. Read it if you want to measure something specific (per-subsystem timing, only-DSP, etc.) — it's <400 lines.

Load-proof A/B — test/tools/ir_ab.sh (instruction counts)

make benchmark and opt_ab.sh measure wall time, so they need a quiet host — and that dependency has produced two wrong answers. #515 measured -O3 at +12.5% sequentially and −11.7% interleaved from the same two binaries, minutes apart; #520's timing phase was blocked outright (load 19.08 on 12 cores) and never ran.

ir_ab.sh sidesteps the problem by counting work instead of timing it. The emulator is deterministic, so a fixed ROM and frame count is a fixed number of instructions, and valgrind --tool=cachegrind counts exactly that in simulation — bit-identical run to run. It needs no privileges (unlike perf stat, which hosted CI runners lock down), so it works on a busy dev box and on a free GitHub runner.

test/tools/ir_ab.sh 'OPT_LEVEL=-O2' 'OPT_LEVEL=-O3'   # flag flip (opt_ab.sh's convention)
test/tools/ir_ab.sh --ref libretro/develop HEAD        # source change / PR vs base
test/tools/ir_ab.sh --selftest                         # instrument check: Ir must be IDENTICAL
IR_ROM=test/roms/yarc.j64 test/tools/ir_ab.sh --profile   # where does this ROM's Ir go?

No valgrind on the host? On macOS the script re-execs itself inside a Linux container (podman or docker) automatically; only $WORK and the ROM cross the boundary.

Deliberately no load-average gate. opt_ab.sh refuses above one load per core and is right to — it measures a clock. Ir does not depend on how busy the machine is, and that is the entire point. Don't add one back.

Validated, not assumed

property	how	result
Determinism	same source both arms (--selftest)	Ir identical: 1,633,893,288 twice. I1/D1/LL miss counts identical too.
Sensitivity	throwaway commit adding one volatile increment per emulated GPU opcode	+1.815% (+159,337,672 Ir), correctly signed

The sensitivity control is the one that matters: an instrument that has never shown it can detect a change will report "no change" forever and look perfectly healthy. It also calibrates the tool — the added waste is ~3 instructions per GPU opcode, putting yarc@90 at roughly 53.1 million GPU opcodes, which turns later deltas into per-instruction arithmetic rather than percentages. (Treat that as a calibration figure, not an exact count: 159,337,672 / 3 is not an integer, so the per-opcode cost is not exactly 3 on every path — the compiler is free to fold the increment differently depending on surrounding code.)

What Ir is not

Ir is not wall time. It models neither branch prediction nor ILP nor real cache behaviour (the simulated D1/LL columns close only part of that gap). A change can legitimately raise Ir and still be faster (inlining, unrolling), and removing dependent loads helps latency more than it helps instruction count — so a small Ir delta there understates the win. This is a gate and a regression detector; wall-clock confirmation still belongs on real hardware.

Absolute Ir is architecture-specific — an arm64 container and an x86_64 runner disagree by construction. Only the within-run A/B delta means anything. The Ir denominator also includes the measuring harness (frame_hash_ab's own hashing is ~4.4% of total on the default workload), so an ir_ab percentage is a share of emulator plus instrument, not directly comparable to a sampling profiler's "% of process time".

Picking the ROM is part of the measurement (#533)

--profile gives per-function Ir for one workload with no source changes and no sampling bias. Measured:

workload	GPU interp	DSP interp	blitter	68K	total Ir
jagniccc.j64 @ 90	0%	0%	0%	~38%	1.6e9
jagniccc.j64 @ 300	38.6%	22.3%	7.1%	~5.9%	19.5e9
jagniccc.j64 @ 600	40.2%	23.7%	10.3%	~2%	52.3e9
yarc.j64 @ 90	71.2%	0.08%	17.5%	~0%	8.8e9

jagniccc.j64 is the Jaguar port of Leonard/Oxygene's NICCC 2000 ST demo (test/vendor/JaguarDemos/jagniccc2000), and it renders on the GPU with the 68K parked in stop #$2000 — but only after its boot window. At 90 frames it is still in BIOS boot and executes zero GPU-interpreter instructions, which is exactly the shape of an inert gate. At 300 it reaches the steady-state mix, which is why that is the default here and in CI.

yarc.j64 is the GPU amplifier, but note #533's point: its opcode mix is jr-heavy, so per-instruction loop overhead is an unusually large share of its GPU time and a loop-bookkeeping change scores high on it relative to a real game. Use it to make a GPU-loop effect visible, not to size it.

In CI

.github/workflows/ir-ab.yml runs the A/B on PRs touching src/tom/gpu.c, src/tom/blitter.c, src/tom/op.c, src/jerry/dsp.c, src/m68000/** or the Makefiles, and reports the delta as a job summary. Because the variance is zero the flagging threshold is tight (0.5%), but the job is advisory, not blocking — see "what Ir is not" above. Flip IR_GATE: '1' if that policy ever changes.

macOS — Instruments / sample

Instruments (Time Profiler) is the easiest way to get a flame graph on macOS.

The wrapper at scripts/profile-mac.sh builds the core, runs the benchmark under xctrace, and writes a .trace bundle you can open in Instruments:

scripts/profile-mac.sh                                    # default: Time Profiler, accurate blitter
scripts/profile-mac.sh --template "CPU Counters"          # PMU: cycles, instructions, branch misses
scripts/profile-mac.sh --rom test/roms/yarc.j64 --open    # auto-open the trace

Manual invocation if you'd rather attach to a running process:

make benchmark BENCH_FRAMES=6000 BENCH_WARMUP=120 &
BENCH_PID=$!

xcrun xctrace record --template "Time Profiler" --attach $BENCH_PID --output bench.trace --time-limit 30s
open bench.trace

The default symbolication is good — you'll see OPProcessFixedBitmap, BlitterMidsummer2, DSPExec etc. as top hot frames if they're slow.

For a quick text dump without the GUI:

sample $BENCH_PID 5 -file /tmp/sample.txt
# 5-second sample.  Read /tmp/sample.txt for collapsed call stacks.

Bespoke counters — BENCH_PROFILE=1

Sampling profilers tell you where time goes; counters tell you how often something happens. When you want exact iteration counts (e.g., "did my fast-path actually skip the inner loop?"), use the perf_counters system in src/core/perf_counters.h.

make benchmark BENCH_PROFILE=1 BENCH_BLITTER=accurate BENCH_FRAMES=300
# ...
# [perf] counter dump:
# [perf]   blitter_phrase_writes                    3034993
# [perf]   blitter_phrase_reads                     931821
# [perf]   blitter_inner_io                         3966814
# [perf]   blitter_inner                            4131151
# [perf]   blitter_outer                            337722
# [perf]   blitter_calls                            131628

The macros are zero-overhead when BENCH_PROFILE is undefined (default build) — every PERF_INC becomes ((void)0), every PERF_COUNTER becomes a typedef. Use them freely in hot paths to instrument hypotheses.

Adding a counter:

#include "perf_counters.h"

PERF_COUNTER(my_event);             /* file scope */

void hot(void) {
    PERF_INC(my_event);             /* in-loop */
    PERF_ADD(my_event, n);          /* batch */
}

The harness (test/tools/test_benchmark.c) calls perf_counters_dump(stderr) at exit; counter values appear right before the BENCHMARK RESULTS block.

When to reach for this vs. Time Profiler:

Question	Tool
"Where are we spending cycles?"	xctrace Time Profiler
"How many times does the inner loop run per frame?"	BENCH_PROFILE=1
"What fraction of inner iterations are no-ops?"	BENCH_PROFILE=1
"Are we hitting L1 / branch-mispredicting?"	xctrace CPU Counters
"Did this optimization change behavior, not just timing?"	BENCH_PROFILE=1 (deltas in counts)

Linux — perf + flamegraph

sudo apt install -y linux-tools-common linux-tools-generic
git clone https://github.com/brendangregg/FlameGraph /tmp/flamegraph

make benchmark BENCH_FRAMES=6000 BENCH_WARMUP=120 &
BENCH_PID=$!

perf record -F 999 -g -p $BENCH_PID -- sleep 30
perf script | /tmp/flamegraph/stackcollapse-perf.pl | /tmp/flamegraph/flamegraph.pl > flame.svg
open flame.svg

-F 999 = 999 Hz sample rate (avoid 1000 Hz lockstep aliasing with display refresh). -g = capture call graphs.

Hot paths to know

Suspicious-by-default places when something gets slow:

Subsystem	File	Notes
Object Processor (sprites, bitmaps)	src/tom/op.c	OPProcessFixedBitmap, OPProcessScaledBitmap, OPDiscoverObjects. Dominant on heavy-OP scenes (Wolf3D, Tempest 2000).
Blitter	src/tom/blitter.c, blitter_mmio.c, blitter_simd_*.c	Two paths: fast (blitter_generic, the upstream-derived path) and accurate (BlitterMidsummer2). SIMD (blitter_simd_{sse2,neon,scalar}.c) is currently wired only into the accurate blitter's pixel kernel — see issue #124 for the plan to widen SIMD coverage.
68K	src/m68000/cpuemu.c	Machine-generated UAE. ~1.8 MB of source. If this is hot, there's not much to do beyond JIT (out of scope).
GPU (RISC, 26.6 MHz)	src/tom/gpu.c	GPUExec per-instruction. Hot when game uses GPU heavily (most do).
DSP (RISC, audio)	src/jerry/dsp.c	DSPExec per-instruction. See src/jerry/dsp_acc40.h for the 40-bit MAC.
Frame loop	src/core/jaguar.c	JaguarExecuteNew is the event-driven driver. If the event queue is hot, look at src/core/event.c.

SIMD A/B testing

The blitter has three implementations, selected at build time via BLITTER_SIMD:

make BLITTER_SIMD=neon -j4 && make benchmark   # ARM
make BLITTER_SIMD=sse2 -j4 && make benchmark   # x86_64
make BLITTER_SIMD=scalar -j4 && make benchmark # portable fallback

Auto-detection picks NEON on aarch64 / SSE2 on x86_64 / scalar elsewhere (see Makefile.common). Force the scalar build to verify SIMD is actually winning — when the gap closes, your bottleneck moved elsewhere.

Build flavors

Goal	Flags
Production perf	make (default; -O2 -DNDEBUG -ffast-math -fomit-frame-pointer)
Profiling (good symbols, near-prod perf)	make RELEASE_DEBUG_INFO=1 (-O2 -g). Strips later if shipping.
Sanitizers	make CC="clang -fsanitize=address,undefined -O1 -g" (catches bugs, halves perf)
Coverage	make COVERAGE=1 (-O0 -g --coverage). Don't profile this — coverage instrumentation overhead is ~3× and not representative.
Debug stepping	make DEBUG=1 (-O0 -g)

Cycle / instruction counts

The core is event-driven, not cycle-accurate (docs/source-layout.md covers the rationale). JaguarExecuteNew runs the 68K to the next event, then GPU, then fires callbacks. Don't expect cycle-counter results to match real hardware — measure wall-clock instead.

If you do need cycle-level inspection:

# Linux: cycles + instructions per loop iteration
perf stat -e cycles,instructions,branches,branch-misses ./test/tools/test_benchmark ./virtualjaguar_libretro.so test/roms/yarc.j64 600

# macOS: Instruments has a "CPU Counters" template
xcrun xctrace record --template "CPU Counters" --launch -- ./test/tools/test_benchmark ...

Regression triage

If make benchmark shows a regression after your change:

1. Run twice — check for noise. Same-host runs typically vary <2%. >5% delta is real signal.
2. Bisect by commit: git bisect start HEAD <known-good-commit>, mark good/bad with make benchmark results until you isolate the offender.
3. Check both blitters (BENCH_BLITTER=fast vs accurate) — sometimes a regression only shows on one path.
4. Profile, don't guess — the bottleneck is rarely where you'd expect on this codebase.

See also

• CLAUDE.md — hardware model + repo layout
• docs/source-layout.md — file-by-file source tour
• docs/emulation-bug-hunt-todos.md — known performance / accuracy follow-ups
• test/tools/test_benchmark.c — the harness itself