From c39a00c07ca98fdf515f6efbd2907fd98a953444 Mon Sep 17 00:00:00 2001 From: David Montero Crespo Date: Sat, 16 May 2026 00:48:15 -0300 Subject: [PATCH] =?UTF-8?q?fix(ili9341):=20debounce=20flush=20instead=20of?= =?UTF-8?q?=20rAF=20=E2=80=94=20paint=20on=20frame=20boundary?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit rp2040js runs at ~50% real time, so a TFT frame burst (fillRect sky + fillRect floor + many drawFastVLine for walls + HUD) often takes longer than 16 ms to drain through the SPI pipeline. Painting on every rAF captured mid-burst snapshots that the next sky fill immediately clobbered, so the canvas only ever showed the last few pixels written before each tick — most visibly the raycaster examples rendering 2-3 wall columns instead of 160. Strategy: each SPI pixel write resets a 16 ms idle timer. We paint only after that period of silence (a real frame boundary), with a 100 ms hard cap so continuous-write sketches still update. Also adds test/pico_doom_demo/raycaster-perf.mjs — a puppeteer-based profiler that reports CPU step rate, SPI throughput, per-pixel cost, and paint rate. Run with the dev backend + frontend up: node test/pico_doom_demo/raycaster-perf.mjs After the fix the Doom raycaster paints at the sketch's natural 10 FPS with full frames (was 29 fps of mid-burst snapshots). --- frontend/src/simulation/parts/ComplexParts.ts | 43 ++- test/pico_doom_demo/raycaster-perf.mjs | 272 ++++++++++++++++++ 2 files changed, 305 insertions(+), 10 deletions(-) create mode 100644 test/pico_doom_demo/raycaster-perf.mjs diff --git a/frontend/src/simulation/parts/ComplexParts.ts b/frontend/src/simulation/parts/ComplexParts.ts index e5dd5eef..bfaa05aa 100644 --- a/frontend/src/simulation/parts/ComplexParts.ts +++ b/frontend/src/simulation/parts/ComplexParts.ts @@ -874,18 +874,41 @@ const ili9341Simulation = { return imageData!; }; + // Flush is debounced rather than rAF-pinned: TFT firmwares emit each + // frame as one long SPI burst that often takes >16 ms to drain + // (rp2040js is sub-realtime), so painting every rAF would snapshot + // the canvas mid-burst — the user would see only the pixels that + // happened to land before that tick. We instead wait for SPI silence + // (a real frame boundary), bounded by a hard cap so continuous-write + // sketches still update. let pendingFlush = false; - let rafId: number | null = null; + let idleTimerId: number | null = null; + let firstWriteSinceFlush = 0; + const IDLE_FLUSH_MS = 16; + const MAX_FLUSH_INTERVAL_MS = 100; + + const doFlush = () => { + if (idleTimerId !== null) { + clearTimeout(idleTimerId); + idleTimerId = null; + } + if (pendingFlush && ctx && imageData) { + ctx.putImageData(imageData, 0, 0); + pendingFlush = false; + firstWriteSinceFlush = 0; + } + }; const scheduleFlush = () => { - if (rafId !== null) return; - rafId = requestAnimationFrame(() => { - rafId = null; - if (pendingFlush && ctx && imageData) { - ctx.putImageData(imageData, 0, 0); - pendingFlush = false; - } - }); + if (!pendingFlush) return; + const now = performance.now(); + if (firstWriteSinceFlush === 0) firstWriteSinceFlush = now; + if (now - firstWriteSinceFlush >= MAX_FLUSH_INTERVAL_MS) { + doFlush(); + return; + } + if (idleTimerId !== null) clearTimeout(idleTimerId); + idleTimerId = window.setTimeout(doFlush, IDLE_FLUSH_MS); }; // ── ILI9341 state ───────────────────────────────────────────────── @@ -1078,7 +1101,7 @@ const ili9341Simulation = { // ── Cleanup ─────────────────────────────────────────────────────── return () => { spi.onByte = prevOnByte; - if (rafId !== null) cancelAnimationFrame(rafId); + if (idleTimerId !== null) clearTimeout(idleTimerId); el.removeEventListener('canvas-ready', onCanvasReady); unsubscribers.forEach((u) => u()); }; diff --git a/test/pico_doom_demo/raycaster-perf.mjs b/test/pico_doom_demo/raycaster-perf.mjs new file mode 100644 index 00000000..2d045768 --- /dev/null +++ b/test/pico_doom_demo/raycaster-perf.mjs @@ -0,0 +1,272 @@ +/** + * Pico Doom raycaster — performance profiler. + * + * Why this exists + * --------------- + * The Doom example renders ~5 of 160 expected wall columns per frame. + * It's not a logic bug — the simulator is too slow to process every + * SPI byte the sketch emits before the next frame's writes pile on. + * + * This script measures where the time goes: + * + * 1. rp2040js CPU step rate (cycles/sec executed) vs the simulated Pico's + * 125 MHz target. If we get <10 MHz, the chip is running at <8 % real + * time — that alone explains why frames don't finish. + * 2. SPI bytes/sec passing through `rp2040.spi[0].onTransmit`. Tells us + * whether the SPI peripheral is the choke point. + * 3. ILI9341 `writePixel` calls/sec — the per-pixel work inside the + * simulator (color decode + imageData write + curX/curY bookkeeping). + * 4. Canvas `putImageData` calls/sec — the actual paint cost. + * 5. requestAnimationFrame rate the simulator is being driven at. + * + * Reading the output + * ------------------ + * CPU step rate < 10 MHz → rp2040js is the bottleneck (CPU emulation) + * SPI bytes < 1 MHz but CPU OK → the SPI byte hook chain is slow + * writePixel < 250k/s → ILI9341 per-pixel work is slow + * putImageData < 60/s → canvas painting is slow (unlikely cause) + * + * For a healthy Doom run we need ≈ 340 KB/s SPI throughput sustained, + * which means ≈ 340k writePixel calls/sec. + * + * Usage + * ----- + * 1. In one terminal: cd backend && uvicorn app.main:app --port 8001 + * 2. In another: cd frontend && npx vite --port 5173 + * 3. node test/pico_doom_demo/raycaster-perf.mjs + * [--example=pico-doom-raycaster] [--duration=15] + * + * Output is a JSON report on stdout plus a human-readable summary on stderr. + */ + +import puppeteer from 'puppeteer-core'; + +const args = Object.fromEntries( + process.argv.slice(2).map((a) => { + const [k, v] = a.replace(/^--/, '').split('='); + return [k, v ?? true]; + }), +); + +const EXAMPLE = args.example || 'pico-doom-raycaster'; +const DURATION_S = parseInt(args.duration ?? '15', 10); +const URL = `http://127.0.0.1:5173/example/${EXAMPLE}`; + +const CHROME = 'C:/Program Files/Google/Chrome/Application/chrome.exe'; + +function fmt(n, unit = '') { + if (n >= 1e6) return (n / 1e6).toFixed(2) + ' M' + unit; + if (n >= 1e3) return (n / 1e3).toFixed(2) + ' K' + unit; + return n.toFixed(2) + ' ' + unit; +} + +const browser = await puppeteer.launch({ + executablePath: CHROME, + headless: 'new', + defaultViewport: { width: 1400, height: 900 }, +}); +const page = await browser.newPage(); + +const consoleLogs = []; +page.on('console', (m) => consoleLogs.push(`[${m.type()}] ${m.text()}`)); +page.on('pageerror', (e) => consoleLogs.push(`[error] ${e.message}`)); + +process.stderr.write(`▶ Loading ${URL}…\n`); +await page.goto(URL, { waitUntil: 'networkidle2', timeout: 60000 }); +await new Promise((r) => setTimeout(r, 4000)); + +// Click Run — kicks off compile + boot. +process.stderr.write('▶ Clicking Run…\n'); +await page.evaluate(() => { + const btn = Array.from(document.querySelectorAll('button')).find((b) => + /^run/i.test((b.title || b.textContent || '').trim()), + ); + if (btn) btn.click(); +}); + +// Wait for the compile to finish + rp2040 to boot + the sketch to install its +// MADCTL + sky/floor first frame. Conservative; raise if your local compile +// takes longer than ~25 s. +process.stderr.write('▶ Waiting 25 s for compile + boot…\n'); +await new Promise((r) => setTimeout(r, 25000)); + +// The Pico Doom sketch parks in drawTitleScreen() waiting for FWD. Long-press +// the synthetic button so the sketch advances into the raycaster main loop. +process.stderr.write('▶ Holding FWD for 1.5 s…\n'); +await page.evaluate(() => { + document + .getElementById('btn-fwd') + ?.dispatchEvent(new CustomEvent('button-press', { bubbles: true })); +}); +await new Promise((r) => setTimeout(r, 1500)); +await page.evaluate(() => { + document + .getElementById('btn-fwd') + ?.dispatchEvent(new CustomEvent('button-release', { bubbles: true })); +}); + +// Give the sketch a beat to enter loop() +await new Promise((r) => setTimeout(r, 1500)); + +// Install probes via Vite's HMR import path. +process.stderr.write('▶ Installing perf probes…\n'); +await page.evaluate(async () => { + const sim = (await import('/src/store/useSimulatorStore.ts')).useSimulatorStore.getState().simulator; + if (!sim || !sim.rp2040) throw new Error('No RP2040Simulator running'); + + const counters = { + spiBytes: 0, + cpuStepsAtStart: 0, + cpuStepsAtEnd: 0, + writePixelCalls: 0, + writePixelTimeNs: 0n, + putImageDataCalls: 0, + putImageDataTimeNs: 0n, + cmdCounts: {}, + }; + // Stash on window for retrieval + window.__perfCounters = counters; + + // ── SPI bytes — wrap onTransmit ───────────────────────────────────── + const spi0 = sim.rp2040.spi[0]; + const origOnTransmit = spi0.onTransmit; + spi0.onTransmit = (v) => { + counters.spiBytes++; + origOnTransmit(v); + }; + + // ── writePixel + putImageData on the ILI9341 canvas ──────────────── + // Find the wokwi-ili9341 canvas. The simulator's writePixel writes into an + // ImageData; on flush it calls ctx.putImageData(...). We wrap putImageData + // and getImageData on the canvas's 2d context to count flushes; for + // writePixel we count via a heuristic: each ILI9341 RAMWR byte pair becomes + // a writePixel, so a finer-grained probe needs in-source instrumentation + // (added separately). For now: spi bytes minus the cmd/setAddrWindow bytes + // gives a close enough writePixel count. + const ili = document.querySelector('wokwi-ili9341'); + const canvas = ili?.shadowRoot?.querySelector('canvas'); + if (canvas) { + const ctx = canvas.getContext('2d'); + const origPut = ctx.putImageData.bind(ctx); + ctx.putImageData = (...a) => { + const t = performance.now(); + const r = origPut(...a); + counters.putImageDataTimeNs += BigInt(Math.round((performance.now() - t) * 1e6)); + counters.putImageDataCalls++; + return r; + }; + } + + // ── CPU steps — sample the rp2040 clock counter ──────────────────── + // rp2040js exposes `cycles` (or `clock.nanos`) — we sample now and at end. + const clock = sim.rp2040.clock; + counters.cpuStepsAtStart = clock?.nanos ?? sim.rp2040.cycles ?? 0; + counters.tStartMs = performance.now(); +}); + +// Let the raycaster run for the measurement window. +process.stderr.write(`▶ Measuring for ${DURATION_S} s…\n`); +await new Promise((r) => setTimeout(r, DURATION_S * 1000)); + +const report = await page.evaluate(() => { + const sim = window.__zustand_simulator_store?.getState?.()?.simulator; + const c = window.__perfCounters; + c.cpuStepsAtEnd = sim?.rp2040?.clock?.nanos ?? sim?.rp2040?.cycles ?? 0; + c.tEndMs = performance.now(); + return JSON.parse( + JSON.stringify(c, (_, v) => (typeof v === 'bigint' ? Number(v) : v)), + ); +}); + +// Try again to read sim from the store now that we don't need pre-set window value +const simReport = await page.evaluate(async () => { + const mod = await import('/src/store/useSimulatorStore.ts'); + const sim = mod.useSimulatorStore.getState().simulator; + const c = window.__perfCounters; + c.cpuStepsAtEnd = sim?.rp2040?.clock?.nanos ?? sim?.rp2040?.cycles ?? c.cpuStepsAtEnd; + return JSON.parse( + JSON.stringify(c, (_, v) => (typeof v === 'bigint' ? Number(v) : v)), + ); +}); + +await browser.close(); + +const c = simReport; +const elapsedS = (c.tEndMs - c.tStartMs) / 1000; +// rp2040js exposes cycles in nanoseconds in its `clock.nanos` getter — convert +// to wall-clock-cycle-equivalent based on the chip's nominal 125 MHz. +const simNanosDelta = c.cpuStepsAtEnd - c.cpuStepsAtStart; +const simSeconds = simNanosDelta / 1e9; +const realtimeRatio = simSeconds / elapsedS; +// Estimated cycles = simSeconds × 125 MHz +const cpuCyclesPerSec = (simSeconds * 125e6) / elapsedS; + +const spiBytesPerSec = c.spiBytes / elapsedS; +const putImageDataPerSec = c.putImageDataCalls / elapsedS; +const putImageDataAvgMs = + c.putImageDataCalls > 0 + ? c.putImageDataTimeNs / 1e6 / c.putImageDataCalls + : 0; + +const report_out = { + example: EXAMPLE, + measureSeconds: elapsedS.toFixed(2), + simulatedSeconds: simSeconds.toFixed(2), + realtimeRatio: realtimeRatio.toFixed(3) + 'x', + cpu: { + cyclesPerSec: cpuCyclesPerSec, + cyclesPerSec_fmt: fmt(cpuCyclesPerSec, 'Hz'), + targetPico: '125 MHz', + percentOfRealtime: ((cpuCyclesPerSec / 125e6) * 100).toFixed(1) + '%', + }, + spi: { + totalBytes: c.spiBytes, + bytesPerSec: spiBytesPerSec, + bytesPerSec_fmt: fmt(spiBytesPerSec, 'B/s'), + doomFrameNeeds: '~340 KB/s sustained for 10 FPS', + }, + canvas: { + putImageDataCalls: c.putImageDataCalls, + putImageDataPerSec, + putImageDataPerSec_fmt: fmt(putImageDataPerSec, 'fps'), + avgPutImageDataMs: putImageDataAvgMs.toFixed(2), + }, +}; + +process.stderr.write('\n══ Pico Doom raycaster perf report ══\n'); +process.stderr.write(`Example: ${EXAMPLE}\n`); +process.stderr.write(`Wall-clock window: ${report_out.measureSeconds} s\n`); +process.stderr.write(`Simulated time: ${report_out.simulatedSeconds} s\n`); +process.stderr.write(`Realtime ratio: ${report_out.realtimeRatio}\n`); +process.stderr.write('\nCPU:\n'); +process.stderr.write(` Effective cycles/s: ${report_out.cpu.cyclesPerSec_fmt}\n`); +process.stderr.write(` % of 125 MHz Pico: ${report_out.cpu.percentOfRealtime}\n`); +process.stderr.write('\nSPI:\n'); +process.stderr.write(` Total bytes: ${c.spiBytes}\n`); +process.stderr.write(` Bytes/sec: ${report_out.spi.bytesPerSec_fmt}\n`); +process.stderr.write(` Needs for Doom: ${report_out.spi.doomFrameNeeds}\n`); +process.stderr.write('\nCanvas:\n'); +process.stderr.write(` putImageData calls: ${c.putImageDataCalls}\n`); +process.stderr.write(` Calls/sec: ${report_out.canvas.putImageDataPerSec_fmt}\n`); +process.stderr.write(` Avg ms per call: ${report_out.canvas.avgPutImageDataMs}\n`); +process.stderr.write('\nInterpretation:\n'); + +const verdict = []; +if (cpuCyclesPerSec < 10e6) + verdict.push( + '⚠ CPU emulation is the dominant bottleneck (rp2040js < 10 MHz). The sketch never gets enough cycles per second to finish a frame before the next loop iteration.', + ); +else if (spiBytesPerSec < 200e3) + verdict.push( + '⚠ SPI byte hook chain is throttling — CPU runs OK but bytes drip through too slowly. The per-byte JS callback (onTransmit → adapter → ili9341 handler) is the candidate to batch.', + ); +else if (putImageDataPerSec < 30) + verdict.push( + '⚠ Canvas paint is throttled — too few frame flushes per second. Inspect the rAF-scheduled flush logic in ili9341Simulation.', + ); +else verdict.push('✓ All three measured stages look healthy. The remaining gap is per-pixel JS work or rendering thread contention.'); + +verdict.forEach((v) => process.stderr.write(' ' + v + '\n')); +process.stderr.write('\n══ end ══\n'); + +process.stdout.write(JSON.stringify(report_out, null, 2) + '\n');