SGDK profiler: find the function that causes slowdown

When an SGDK game slows down, SGDK can tell you the CPU load, but not which function used the time. I built mdprof, a small SGDK profiler that runs a ROM headless in the Genesis Plus GX emulator and charges every 68000 cycle to a function from the symbol.txt that SGDK’s build already writes. Per frame it reports the load, whether the frame was dropped, how much DMA went out during active display, and the functions that ate the frame. On a test ROM with known costs, it counted 60 of the 60 dropped frames that the ROM’s own counters saw, and timed a fixed 68000 loop at 5,114 cycles against about 5,117 by hand. It runs at about 1,550 frames per second on a 2-core laptop, 26 times real time, so a 30-second play-through takes a couple of seconds and fits in a script or CI.

This is the first post in a new series on Mega Drive, SNES, NES and Master System homebrew, where I build small tools for the problems that hit people who port or write games for these consoles, often with an AI assistant. Performance comes first, because it is where plausible-looking code fails on the real machine.

Why Mega Drive developers have no profiler

Threads on the SpritesMind forum keep asking the same thing. One poster noted that Mega Drive emulators don’t support profiling, and the advice since then is to time code by hand with SGDK’s timer functions or to watch the load meter that VDP_showCPULoad() draws on screen. That meter gives one number for the whole frame. It does not say that the division in your sprite loop costs more than everything else together.

There is one real tool: md-profiler (MIT, last updated in 2021) records call traces from a modified BlastEm in its debugger and shows them in Perfetto. It is a tracing profiler you drive by hand, with Windows builds. I wanted something narrower: no window, no debugger, a ROM and a symbol file in, a frame-budget report out, so it can run after every build.

How mdprof measures a frame

Genesis Plus GX already has a debug hook that runs before every 68000 instruction; it is off unless the core is built with HOOK_CPU=1. mdprof is a 490-line libretro frontend in C that loads that build, runs the ROM with no window and no sound, and installs this hook:

static void hook(hook_type_t type, int width, unsigned int address, unsigned int value) {
  if (type == HOOK_M68K_E) {
    int64_t now = m68k.cycles;                  /* master clocks, 7 per 68000 cycle */
    int64_t d = now - last_cycles;              /* what the previous instruction cost */
    int s = pc_to_sym(last_pc);                 /* the function it belongs to */
    fn_total[s] += d; fn_frame[s] += d;
    if (is_idle(s)) cur.idle_mclk += d; else cur.busy_mclk += d;
    int idle_now = is_idle(pc_to_sym(address));
    if (!idle_now && prev_idle) cur.loop_start = 1;   /* the game left the wait: a new loop */
    ...
  }
}

The cycle counter includes everything the emulator charges the CPU for: wait states, the DRAM refresh delay, and the time the 68000 is frozen while DMA copies from its bus. Time inside VDP_waitVBlank, SGDK’s wait for the next frame, is idle. Everything else is busy, including the vertical interrupt and SGDK’s DMA flush.

A frame is dropped when the game never left VDP_waitVBlank during it: no new game loop started at that VBlank, so the TV showed the previous picture again. For DMA, the hook also sees every write to VRAM, CRAM and VSRAM; writes that happen while the core holds the 68000 for a DMA count as DMA bytes, and the scanline at that moment says whether they landed in VBlank or during active display.

The first version had four mistakes that the test ROM caught. I describe them at the end.

Does the profiler count cycles correctly?

To check it, I wrote a test ROM (my own code and art, built with the SGDK Docker image) whose workloads have known costs, and that stores SGDK’s own figures in RAM every frame: SYS_getCPULoad(), the VBlank counter vtimer and a game-loop counter. mdprof logs those RAM words next to its own numbers.

The fixed-cost check is burn(500). GCC compiled it to move.w #500,d0, a dbra loop and rts: 8 + (500 x 10

• 14) + 16 = 5,038 cycles from the 68000 timing tables. Genesis Plus GX adds the Mega Drive’s DRAM refresh delay, about 2 cycles every 128, which gives about 5,117. mdprof measured 5,114.0 cycles per call, averaged over 1,368 calls.

For dropped frames, the ROM’s own count is the number of VBlanks minus the number of finished game loops:

Test ROM phase	Frames	Dropped (mdprof)	Dropped (ROM counters)
A: 24 sprites, light	240	1	0
B: growing 32-bit divisions	300	60	60
B2: same work, reciprocal table	120	0	0
C: plane redraw, one call per tile	132	12	11
C2: same redraw, one fill call	120	0	0
D: DMA queue from 4 KB to 9.5 KB	480	0	0

The two cells that differ by one are at phase edges: the ROM’s count is a difference between a phase’s first and last frame, so it can miss a drop that falls on the edge.

How much does a division cost in an SGDK game loop?

Phase B puts a 32-bit division in the per-sprite loop, which is harmless on a modern CPU: one division for each of 24 sprites, and every 30 frames one more division per sprite. On the 68000 that becomes a call to libgcc’s __divsi3, which calls __udivsi3. Here is what one game loop cost, next to SGDK’s own load figure:

Divisions per sprite	Loop cost (% of a frame)	Frames per loop	SGDK load
1	28.7	1	23.0
3	53.4	1	50.0
5	78.1	1	75.1
6	90.4	1	88.0
7	103.1	2	103.3
8	115.4	2	111.8

Each extra division per sprite adds 15,865 cycles to the loop, 661 cycles per division. At 7 per sprite the loop needs 103% of a frame and the game drops to 30 frames per second, which is what a player would see as slowdown. Over the whole run, __udivsi3 and __divsi3 together took 8.3% of all cycles, more than anything except the wait itself and the DMA flush.

The usual fix is a table of reciprocals and a 16-bit multiply (mulu.w), which the 68000 does in one instruction. Phase B2 does the same 8 steps per sprite that way: 139 cycles per step, and the loop costs 33.7% of a frame instead of 115%. The result is an approximation (a fixed-point reciprocal), which is fine for movement and not for everything.

SGDK’s figure follows the same curve but reads 2 to 6 points lower below 100%, and it cannot show light loads at all. Its code turns the scanline where the wait begins into a load figure by adding a fixed 32 lines, and reports any loop that ends inside VBlank as 16 lines. In the light phase A, SGDK said 7.3% where mdprof counted 12.9%.

Why does redrawing a plane tile by tile cause slowdown?

Phase C redraws the 40x28 background plane every 20th frame with one VDP_setTileMapXY() call per tile, 1,120 calls. Phase C2 does the same with a single VDP_fillTileMapRect().

Redraw	Cycles	Frames	Dropped per redraw
1,120 x VDP_setTileMapXY()	334,924	2.6	2
1 x VDP_fillTileMapRect()	54,806	0.43	0

The per-tile version costs about 299 cycles per tile, because each call sets the VRAM address again before writing one word. mdprof’s busiest frames were all in that function, 127,700 of a frame’s 128,005 cycles. Both numbers include the time the 68000 waits for the VDP’s write FIFO during active display, which Genesis Plus GX models; I did not check that part against hardware.

How much DMA fits in VBlank with SGDK?

SGDK’s documentation gives two figures: “VBlank period allows to transfer up to 7.2 KB on NTSC system” (the default cap, DMA_TRANSFER_CAPACITY_NTSC 7200 in dma.h) and “about 7.6 KB of data … during VBlank (in H40)” in the comment on DMA_flushQueue(). In a 2016 SpritesMind thread on XGM, SGDK’s author estimated that the interrupt handler and the sound driver cost about 2 of the 38 VBlank lines.

Phase D turns the cap off (DMA_setMaxTransferSize(0)) and queues a ROM-to-VRAM copy that grows by 512 bytes every 40 frames. The figures include SGDK’s 192-byte sprite table upload each frame:

Queued per frame	DMA in VBlank	DMA during active display	Last scanline with DMA
4,288 to 6,848 bytes	all of it	0	VBlank
7,360	7,142	218	12
8,384	7,139	1,245	69
9,920	7,135	2,785	154

So about 7,140 bytes fit in VBlank with SGDK’s own flush, close to its 7.2 KB cap, and well under the raw 7.6 KB, because SGDK starts the flush only after the interrupt handler and its VBlank bookkeeping. Past that, DMA runs during active display at about 18 bytes per line, and the 68000 is frozen until it ends: 2.8 KB too many held the CPU until line 154 of 224. SGDK’s default cap would have dropped those transfers instead.

On a real game: SGDK’s platformer sample

The test ROM is built to break. To see what a normal game looks like, I ran SGDK’s own platformer sample (MIT, from the SGDK repository at tag v2.10, the newest sample that builds with the Docker image I used) for 1,200 frames with a scripted pad: walk right, walk left, jump.

mean CPU load 12.5% (busy cycles / frame cycles)
dropped frames (no new game loop started at that VBlank; idle = VDP_waitVBlank,VDP_waitVSync): 0
frame 1099: 24894 busy cycles (19% of a frame), idle entered at line 13
       6700  prepareMapDataRowEx_MTI8_BI8
       3879  main.isra.0
       2922  DMA_queueDmaFast

The busiest frames are the ones where the camera scrolls into a new map row and SGDK decodes it. One thing the profile shows is that SGDK builds with link-time optimisation, which inlined the sample’s own updatePlayer() into main (it has no symbol of its own), so main.isra.0 stands for most of the game logic. md-profiler’s README warns about the same thing. For a finer profile, mark the functions you care about NO_INLINE while you measure.

What I got wrong while building it

Four bugs, all caught by comparing with the test ROM’s own counters:

1. Frame boundaries. Genesis Plus GX starts its frame at the beginning of VBlank, not at line 0, and an SGDK game is already inside VDP_waitVBlank at that moment. My first “line where the work ended” was 224 on almost every frame. It now records the move from game code into the wait, not the first time the wait is seen.
2. Dropped frames. I first counted frames where the game never reached the wait. That found 43 of the 60 drops in phase B: when a loop finishes just after VBlank starts, SGDK’s wait skips to the next VBlank, so the game reaches the wait and still drops a frame. Counting VBlanks where no new loop started gave 60 of 60.
3. DMA detection. I used the core’s dma_length to tell DMA writes from CPU writes, but the core subtracts the length before it copies. The working test is that the core has frozen the CPU until the DMA end cycle.
4. One frame off. DMA queued in game frame N is sent at the next VBlank, so it shows up in the next frame’s row. My first DMA table paired them wrongly and showed 4,186 bytes for a 4,096-byte queue.

Two smaller ones: the core’s libretro glue only reads the scripted pad if the frontend says it supports input bitmasks, and building the core with its hook on needs -fcommon because the hook variable is defined in a header.

Limits

• These are emulator figures. Genesis Plus GX is careful about timing, but I have no console to compare with.
• Only NTSC, H40 and SGDK games were tested. Other engines need their own wait function passed with --idle.
• Function names come from symbol.txt. Code that the compiler inlined is charged to the function it was inlined into, and local labels in assembly files are merged into the function they sit in.
• The DMA scanline in VBlank is coarse: the core runs a whole VBlank’s worth of DMA at once, so the last line only means something during active display.

Run it on your game

Everything builds in Docker; the emulator source is cloned at a pinned commit and not changed:

WORK=~/.cache/mdprof profiler/build.sh
docker run --rm -v "$WORK:/w" -v "$PWD/out:/rom" -w /w gcc:14 ./mdprof gpgx/genesis_plus_gx_libretro.so \
  /rom/rom.bin /rom/symbol.txt 1800 --from 60 --input 60-600:R --input 200-210:C --csv /rom/frames.csv

The project folder has the profiler, the test ROM, both runs and every per-frame CSV. The next post in this series turns these measurements into a lint for slow SGDK code, with a cost table for divisions, multiplies and SGDK calls, tested on 40 games written by Claude. The third checks the art instead of the code: a pixel art checker for the palette and tile limits of the Mega Drive, NES, Master System and SNES, with an export that SGDK’s rescomp accepts.