362 lines
14 KiB
Bash
Executable file
362 lines
14 KiB
Bash
Executable file
#!/usr/bin/env bash
|
|
# Part of JoeyLib, Copyright (c) 2026 Scott Duensing, under the MIT License.
|
|
# See LICENSE.md for license information.
|
|
# SPDX-License-Identifier: MIT
|
|
#
|
|
# 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 every PROFILE_PERIOD_US of emulated time (a Lua coroutine
|
|
# that emu.wait()s between samples; a period that is not a multiple of the
|
|
# frame's spreads them over the whole frame, where a sample a frame landed on
|
|
# the same instructions every time), buckets by offset into .text, and
|
|
# attributes the buckets to functions with nm. 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)
|
|
# PROFILE_PERIOD_US sample period in emulated microseconds, default 997
|
|
# PROFILE_SAMPLES a file to keep the raw samples in (offset count
|
|
# lines, -1 outside the program; the load base)
|
|
# Requires: the program built WITH symbols (<NAME>.X.elf beside it).
|
|
set -uo pipefail
|
|
|
|
prog=${1:?usage: profile-x68000.sh program [seconds] [skipSeconds]}
|
|
seconds=${2:-240}
|
|
skip=${3:-130}
|
|
periodUs=${PROFILE_PERIOD_US:-997}
|
|
|
|
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=$(od -An -tu4 -N4 --endian=big -j $((64 + relocSite)) "$bin" | tr -d ' ')
|
|
|
|
# jlgMouseX is written once per input poll, i.e. once per game frame.
|
|
mouseXOff=$(m68k-xelf-nm "$elf" | awk '$3 == "jlgMouseX" { print strtonum("0x" $1); exit }')
|
|
[[ -n ${mouseXOff:-} ]] || { echo "profile-x68000: jlgMouseX 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" <<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
|
|
|
|
-- The samples come every PROFILE_PERIOD_US of emulated time, from a
|
|
-- coroutine that emu.wait()s between them, not once a frame: a frame-synced
|
|
-- game loop puts the same instructions under every frame's sample, so a
|
|
-- short routine came out as a few hot addresses or none at all.
|
|
local samplerStarted = false
|
|
local sampler = coroutine.create(function()
|
|
while true do
|
|
emu.wait($periodUs / 1000000.0)
|
|
local t = manager.machine.time:as_double()
|
|
if t >= skipUntil then
|
|
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
|
|
end
|
|
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()
|
|
return
|
|
end
|
|
end
|
|
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()
|
|
-- jlgMouseX 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 not samplerStarted then
|
|
samplerStarted = true
|
|
local ok, err = coroutine.resume(sampler)
|
|
if not ok then
|
|
out:write("sampler error: " .. tostring(err) .. "\n")
|
|
out:close()
|
|
manager.machine:exit()
|
|
end
|
|
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; }
|
|
if [[ -n ${PROFILE_SAMPLES:-} ]]; then
|
|
cp "$work/prof.txt" "$PROFILE_SAMPLES"
|
|
fi
|
|
|
|
m68k-xelf-nm -n "$elf" > "$work/syms.txt"
|
|
LC_ALL=C awk '
|
|
# Most first; equal ones in the order first seen.
|
|
function byCount(i1, v1, i2, v2) {
|
|
if (count[v1] != count[v2]) {
|
|
return count[v2] - count[v1]
|
|
}
|
|
return first[v1] - first[v2]
|
|
}
|
|
# The last symbol at or below an offset (the highest address; of equal
|
|
# ones, the last name in order), as its index; 0 for none.
|
|
function owner(off, lo, hi, mid, best) {
|
|
lo = 1
|
|
hi = symCount
|
|
best = 0
|
|
while (lo <= hi) {
|
|
mid = int((lo + hi) / 2)
|
|
if (symAddr[mid] <= off) {
|
|
best = mid
|
|
lo = mid + 1
|
|
} else {
|
|
hi = mid - 1
|
|
}
|
|
}
|
|
return best
|
|
}
|
|
function bySymbol(i1, v1, i2, v2) {
|
|
if (symAddr[v1] != symAddr[v2]) {
|
|
return symAddr[v1] - symAddr[v2]
|
|
}
|
|
return symName[v1] < symName[v2] ? -1 : (symName[v1] > symName[v2])
|
|
}
|
|
FNR == NR {
|
|
if (NF == 3 && ($2 == "t" || $2 == "T")) {
|
|
rawCount++
|
|
rawAddr[rawCount] = strtonum("0x" $1)
|
|
rawName[rawCount] = $3
|
|
}
|
|
next
|
|
}
|
|
FNR == 1 {
|
|
for (i = 1; i <= rawCount; i++) {
|
|
symAddr[i] = rawAddr[i]
|
|
symName[i] = rawName[i]
|
|
order[i] = i
|
|
}
|
|
symCount = rawCount
|
|
asort(order, sorted, "bySymbol")
|
|
for (i = 1; i <= symCount; i++) {
|
|
addr[i] = symAddr[sorted[i]]
|
|
name[i] = symName[sorted[i]]
|
|
}
|
|
for (i = 1; i <= symCount; i++) {
|
|
symAddr[i] = addr[i]
|
|
symName[i] = name[i]
|
|
}
|
|
}
|
|
$1 == "total" {
|
|
total = $2 + 0
|
|
next
|
|
}
|
|
NF == 2 && $1 ~ /^-*[0-9]+$/ {
|
|
off = $1 + 0
|
|
n = $2 + 0
|
|
key = "b" off
|
|
if (!(key in count)) {
|
|
first[key] = ++seen
|
|
buckets[++bucketCount] = key
|
|
bucketOff[key] = off
|
|
}
|
|
count[key] += n
|
|
if (off < 0) {
|
|
outside += n
|
|
next
|
|
}
|
|
s = owner(off)
|
|
key = "s" (s > 0 ? symName[s] : "?")
|
|
if (!(key in count)) {
|
|
first[key] = ++seen
|
|
hits[++hitCount] = key
|
|
}
|
|
count[key] += n
|
|
}
|
|
END {
|
|
if (total == 0) {
|
|
print "profile-x68000: no samples recorded" > "/dev/stderr"
|
|
exit 1
|
|
}
|
|
printf "profile-x68000: %d samples, %d (%.1f%%) outside the program (ROM/IOCS) (frame count unavailable)\n", total, outside, outside * 100.0 / total
|
|
asort(hits, ranked, "byCount")
|
|
shown = 0
|
|
for (i = 1; i <= hitCount && i <= 25; i++) {
|
|
printf " %5.1f%% %6d %s\n", count[ranked[i]] * 100.0 / total, count[ranked[i]], substr(ranked[i], 2)
|
|
shown += count[ranked[i]]
|
|
}
|
|
printf " %5.1f%% %6d (everything else)\n", (total - outside - shown) * 100.0 / total, total - outside - shown
|
|
# 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):"
|
|
asort(buckets, ranked, "byCount")
|
|
for (i = 1; i <= bucketCount && i <= 20; i++) {
|
|
off = bucketOff[ranked[i]]
|
|
if (off < 0) {
|
|
continue
|
|
}
|
|
s = owner(off)
|
|
printf " %5.1f%% %6d %s+0x%x\n", count[ranked[i]] * 100.0 / total, count[ranked[i]], (s > 0 ? symName[s] : "?"), (s > 0 ? off - symAddr[s] : 0)
|
|
}
|
|
}' "$work/syms.txt" "$work/prof.txt"
|