#!/usr/bin/env bash # profile-x68000.sh - PC-sampling profiler for a running X68000 example. # # Human68k relocates a .X anywhere it likes and the ELF beside it is linked at # zero, so the first job is finding where the program actually landed. Every # xdev68k binary opens with the same "#NEWLIB" marker two bytes into .text, so # the script scans RAM for that -- but the marker appears TWICE, because the # loader leaves a copy of the file in a disk buffer, and picking the wrong one # silently attributes every sample to whatever symbol happens to sit at that # offset. So it collects every candidate and then lets the program counter # choose -- except the two ranges OVERLAP, so containment is not enough. What # separates them is that Human68k RELOCATES the copy it runs: at a known # relocation site the running image holds fileValue + base, while the disk # buffer still holds fileValue. From then on # it samples the PC once per emulated frame, buckets by offset into .text, and # attributes the buckets to functions with nm. # # Sampling once per frame is coarse (55 Hz), but this port runs a game frame in # 150 ms or more, so each frame still gets several samples and the shape of the # profile is clear. Read it as "which functions dominate", never as a timing. # # Usage: scripts/profile-x68000.sh program [seconds] [skipSeconds] # program the built .X: its path (a project's, say), or an # example's name # seconds emulated seconds to run, default 240 # skipSeconds ignore samples before this, default 130 (boot + menu) # Env: X68K_DIR dir holding HUMAN302.XDF + roms/ (default: the installer's toolchains/firmware/x68000) # Requires: the program built WITH symbols (.X.elf beside it). set -uo pipefail prog=${1:?usage: profile-x68000.sh program [seconds] [skipSeconds]} seconds=${2:-240} skip=${3:-130} repo=$(cd "$(dirname "${BASH_SOURCE[0]}")/.." && pwd) source "$repo/scripts/lib/joeyEnv.sh" joeyNeed MAME mame joeyNeed X68K_DIR x68kFirmware joeyNeedFile "$X68K_DIR/roms/x68000/cgrom.dat" x68kCgrom source "$repo/scripts/lib/x68kDisk.sh" bin=$(joeyProgramPath "$prog" x68000) || exit 2 PROG=$(basename "$bin" .X) elf=$bin.elf joeyNeed X68K_ROOT toolchain:x68000 export PATH="$X68K_ROOT/bin:$PATH" [[ -f $bin ]] || { echo "profile-x68000: $bin not built" >&2; exit 2; } [[ -f $elf ]] || { echo "profile-x68000: $elf missing (need symbols)" >&2; exit 2; } # .text size from the ELF, so a candidate base can be tested by containment. textSize=$(m68k-xelf-readelf -S "$elf" | awk '/\.text/ { print strtonum("0x" $7); exit }') [[ -n ${textSize:-} && $textSize -gt 0 ]] || { echo "profile-x68000: cannot read .text size" >&2; exit 2; } # A 32-bit relocation site in .text, and the value the .X file carries there. # The .X header is 64 bytes, so the file offset is 64 + the .text offset. relocSite=$(m68k-xelf-readelf -r "$elf" | awk '$2 ~ /01$/ && $3 == "R_68K_32" { print strtonum("0x" $1); exit }') [[ -n ${relocSite:-} ]] || { echo "profile-x68000: no R_68K_32 relocation to fingerprint with" >&2; exit 2; } relocValue=$(python3 -c " import sys d = open('$bin','rb').read() o = 64 + $relocSite print(int.from_bytes(d[o:o+4],'big')) ") # gMouseX is written once per input poll, i.e. once per game frame. mouseXOff=$(m68k-xelf-nm "$elf" | awk '$3 == "gMouseX" { print strtonum("0x" $1); exit }') [[ -n ${mouseXOff:-} ]] || { echo "profile-x68000: gMouseX not found; cannot count frames" >&2; exit 2; } work=$(mktemp -d -t joey-x68prof.XXXXXX) trap 'rm -rf "$work"' EXIT x68kBootDisk "$work/boot.xdf" 'B:' "B:\\$PROG.X" || exit 1 x68kDataDisk "$work/data.xdf" || exit 1 x68kXdf add "$work/data.xdf" "$bin" "$PROG.X" >/dev/null || exit 1 # The program's DATA tree sits next to it: its own folder's for a program # that ships in one (ID_FOLDER), the shared bin/DATA for the rest. if [[ -d $(dirname "$bin")/DATA ]]; then x68kAddTree "$work/data.xdf" "$(dirname "$bin")/DATA" DATA || exit 1 fi cat > "$work/prof.lua" <= 0x400000 then scanDone = true return end if mem:read_u32(scanAt) == 0x234E4557 and mem:read_u32(scanAt + 4) == 0x4C494200 then cands[#cands + 1] = scanAt - 2 end scanAt = scanAt + 2 end end -- Which candidate is the copy Human68k is RUNNING? At relocSite the .X file -- holds relocValue; the loaded image holds relocValue + its own base, because -- the loader patched it. The untouched disk buffer still matches the file. -- The PC must also be inside it, which rules out a stale image of an older -- build sitting in memory. local function pickBase() local pc = cpu.state[pcReg].value for _, c in ipairs(cands) do if pc >= c and pc < c + textSize then local got = mem:read_u32(c + relocSite) if got == ((relocValue + c) & 0xFFFFFFFF) then return c end end end return nil end emu.register_frame_done(function() local t = manager.machine.time:as_double() if base == nil then if not scanDone then scanSlice() return end base = pickBase() if base ~= nil then out:write(string.format("base %08X at %.1fs (of %d candidates)\n", base, t, #cands)) out:flush() -- gMouseX is written once per jlpInputPoll, which the game calls -- once a frame, so counting writes to it counts game frames. That -- turns "how much of the frame is X" into "and how long is a -- frame", which is the difference between a real speedup and one -- that only buys more idle time. fpsTap = mem:install_write_tap(base + mouseXOff, base + mouseXOff + 1, "fps", function(offset, data, mask) frames = frames + 1 return data end) fpsStart = t return end -- Nothing the PC is inside yet: the program is not loaded, or it is -- and the sweep predates it. Sweep again. The boot takes a couple of -- minutes, so the first few passes finding nothing is the normal case. cands = {} scanAt = 0x1000 scanDone = false return end if t < skipUntil then return end local pc = cpu.state[pcReg].value local key if pc >= base and pc < base + textSize then -- The EXACT offset, not a 64-byte bucket. Buckets straddle function -- boundaries, and a bucket credited to the symbol at its start hands -- one function's samples to its neighbour: that is how a vblank wait -- came out looking like an expensive input poll. key = pc - base else key = -1 -- ROM, IOCS, anything not ours end buckets[key] = (buckets[key] or 0) + 1 total = total + 1 if t >= stopAt then out:write(string.format("fps %.2f frames %d window %.1f tapAt %08X\n", (t > fpsStart) and (frames / (t - fpsStart)) or 0.0, frames, t - fpsStart, base + mouseXOff)) out:write(string.format("total %d\n", total)) for k, v in pairs(buckets) do out:write(string.format("%d %d\n", k, v)) end out:write("DONE\n") out:close() manager.machine:exit() end end) LUA ( cd "$work" && SDL_AUDIODRIVER=dummy timeout 3600 "$MAME" x68000 \ -bios ipl10 -rompath "$X68K_DIR/roms" \ -flop1 boot.xdf -flop2 data.xdf \ -video none -sound none -nothrottle -skip_gameinfo \ -autoboot_script prof.lua mame.log 2>&1 ) || true [[ -s $work/prof.txt ]] || { echo "profile-x68000: FAIL (no samples)" >&2; exit 1; } grep -q '^base ' "$work/prof.txt" || { echo "profile-x68000: FAIL (never found the load base)" >&2; exit 1; } m68k-xelf-nm -n "$elf" > "$work/syms.txt" python3 - "$work/prof.txt" "$work/syms.txt" <<'PY' import sys prof, symfile = sys.argv[1], sys.argv[2] syms = [] for line in open(symfile): p = line.split() if len(p) == 3 and p[1] in ('t', 'T'): syms.append((int(p[0], 16), p[2])) syms.sort() def owner(off): lo, hi = 0, len(syms) - 1 best = None while lo <= hi: mid = (lo + hi) // 2 if syms[mid][0] <= off: best = syms[mid][1] lo = mid + 1 else: hi = mid - 1 return best or "?" total = 0 fps = None hits = {} buckets = {} outside = 0 for line in open(prof): p = line.split() if p and p[0] == 'total': total = int(p[1]) elif len(p) == 2 and p[0].lstrip('-').isdigit(): off, n = int(p[0]), int(p[1]) buckets[off] = buckets.get(off, 0) + n if off < 0: outside += n else: hits[owner(off)] = hits.get(owner(off), 0) + n if total == 0: sys.exit("profile-x68000: no samples recorded") rows = sorted(hits.items(), key=lambda kv: -kv[1]) fpsText = f", game running at {fps:.1f} fps" if fps is not None and fps > 0.0 else " (frame count unavailable)" print(f"profile-x68000: {total} samples, {outside} ({outside*100.0/total:.1f}%) outside the program (ROM/IOCS){fpsText}") shown = 0 for name, n in rows[:25]: print(f" {n*100.0/total:5.1f}% {n:6d} {name}") shown += n print(f" {(total-outside-shown)*100.0/total:5.1f}% {total-outside-shown:6d} (everything else)") # The hottest 64-byte buckets, named as symbol+offset. Function totals say # which routine to look at; these say which LINE of it, which is the # difference between rewriting a loop and rewriting the wrong loop. print("\nhottest addresses (symbol + offset into it):") def ownerOff(off): lo, hi = 0, len(syms) - 1 best = None while lo <= hi: mid = (lo + hi) // 2 if syms[mid][0] <= off: best = syms[mid] lo = mid + 1 else: hi = mid - 1 return (best[1], off - best[0]) if best else ("?", 0) for off, n in sorted(buckets.items(), key=lambda kv: -kv[1])[:20]: if off < 0: continue name, delta = ownerOff(off) print(f" {n*100.0/total:5.1f}% {n:6d} {name}+0x{delta:x}") PY