joeylib2/scripts/profile-x68000.sh

#!/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 [example] [seconds] [skipSeconds]
#            example      .X base name in build/x68000/bin, default staxi
#            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 example built WITH symbols (build/x68000/bin/<NAME>.X.elf).
set -uo pipefail

prog=${1:-staxi}
seconds=${2:-240}
skip=${3:-130}
PROG=$(echo "$prog" | tr '[:lower:]' '[:upper:]')

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=$(joeyExampleProgram "$prog" x68000) || exit 2
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 Space Taxi,
# 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" <<LUA
local cpu = manager.machine.devices[":maincpu"]
local mem = cpu.spaces["program"]
local out = io.open("prof.txt", "w")
-- MAME's 68000 core does NOT expose a register called "PC": it has CURPC
-- (where the CPU is now) and rPC. Asking for the wrong one throws inside the
-- frame callback, once per frame, forever -- the run just gets slower and
-- writes no samples. Resolve it once, loudly.
local pcReg = nil
for _, name in ipairs({ "CURPC", "rPC", "PC" }) do
    if cpu.state[name] ~= nil then
        pcReg = name
        break
    end
end
if pcReg == nil then
    out:write("no program-counter register on this CPU\n")
    out:close()
    manager.machine:exit()
end

local base = nil
local cands = {}
local textSize = $textSize
local mouseXOff = $mouseXOff
local frames = 0
local fpsStart = 0
local relocSite = $relocSite
local relocValue = $relocValue
local scanAt = 0x1000
local buckets = {}
local total = 0
local skipUntil = $skip
local stopAt = $seconds

-- "#NEWLIB" sits two bytes into every xdev68k .text. 0x234E4557 is the long at
-- offset 2, and 0x4C494200 follows it.
-- A slice per frame so MAME keeps running, and it WRAPS: Human68k does not
-- load the program until the boot finishes, which is a couple of minutes in,
-- so a single pass over RAM finds nothing and must start again.
local scanDone = false
local function scanSlice()
    local limit = scanAt + 0x40000
    while scanAt < limit do
        if scanAt >= 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 </dev/null >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