ReadMe

Profile, a sampling profiler for AmigaOS/m68k
===============================================

    Profile [RATE=n] [SAMPLES=n] [CHANNEL=n] [STACK=n] [OUT=file]
            [FOLDED=file] [TOP=n] [QUIET] <program> [arguments]

Profile loads a program, records where each of its hunks landed, runs it, and
samples the program counter a thousand times a second while it runs.  The
program needs no recompilation, no instrumentation and no cooperation, and it
does not know it is being profiled.

    Profile MyProgram somefile.dat
    Profile OUT=RAM:p.prof RATE=2000 MyProgram somefile.dat

The ranked list of modules is printed on the machine.  OUT= writes the raw
profile for profreport.py on a cross-development host, which adds function
names from the executable's symbols.


A REPRODUCIBLE AMIBERRY RUN
---------------------------

Do not profile with Amiberry's JIT.  Make the setting explicit and check the
emulator log rather than relying on a quickstart profile's current default:

    export AMINETXDUO_AMIBERRY_EXTRA=cachesize=0
    # after the run: the Amiberry log must contain `JIT=0`

JIT changes both the code the host executes and when emulated interrupts see
the guest PC.  A profile taken with it is not an m68k instruction profile.

Prove the sampler on the exact emulator, ROM and CPU profile before using it
on a workload:

    cmake -S . -B build/prof \
        -DCMAKE_TOOLCHAIN_FILE=cmake/toolchain-m68k-amigaos.cmake \
        -DCMAKE_BUILD_TYPE=Release -DAMINETXDUO_LTO=OFF
    cmake --build build/prof --parallel --target Profile profspin
    AMINETXDUO_AMIBERRY_EXTRA=cachesize=0 \
        tools/profiler/selftest.sh -b build/prof -m A1200

The final `containment and proportionality` section must say `0 failures,
PASS`.  A plausible ranking without that proof is not evidence; an exception
frame read at the wrong offset still resolves to plausible-looking addresses.

For the repository's matched network workload, take the plain control and the
profile with every other input held constant:

    export AMINETXDUO_FITZ_PEER=user@third-machine
    export AMINETXDUO_AMIBERRY_EXTRA=cachesize=0
    tests/perf/run-stackprof.sh -s ours -p -T receive-plain \
        -b build/prof -m A1200 -k 2048 -C 32768 -r 3
    tests/perf/run-stackprof.sh -s ours    -T receive-prof  \
        -b build/prof -m A1200 -k 2048 -C 32768 -r 3

The peer must be a third physical machine, as run-stackprof.sh explains.  Set
`AMINETXDUO_FASTMEM` explicitly when memory is part of the comparison; `8` is
the ordinary accelerated A1200 arm and `0` is a materially different machine.
Never run two emulator measurements on the same host at once.  Interleaving
controls slow drift, but it cannot repair simultaneous CPU contention.

Keep the scope of the result with the profile.  Amiberry currently does not
reproduce the reported AmiNetXDuo versus AmiTCP_NG receive-throughput gap seen
on real X-Surf-100 hardware: under emulation AmiNetXDuo is faster.  An Amiberry
profile can therefore disprove an explanation of the emulated run, but it
cannot establish the cause of that hardware-only gap.  That requires a profile
from affected hardware, or a separate measurement that first reproduces the
same direction and approximate size of the gap.


A REPRODUCIBLE REAL-HARDWARE RECEIVE RUN
----------------------------------------

Use the same non-LTO `build/prof` binaries configured above.  Copy these four
files to the real Amiga without changing them:

    build/prof/tools/profiler/Profile
    build/prof/tools/profiler/profspin
    build/prof/src/tools/iperf
    build/prof/src/bsdsocket/bsdsocket.library

Install that library for the run and reboot so the loaded library is certainly
the file whose map and objects remain in `build/prof`.  Prove the sampler on
the real CPU before measuring the stack.  On a stock 14 MHz A1200, open a
dedicated shell and run:

    C:ChangeTaskPri 5
    C:Profile RATE=200 OUT=RAM:spin.prof \
        C:profspin SCALE=4 RANGES=RAM:spin.ranges

Bring `spin.prof` and `spin.ranges` back to the build host and run the
`profreport.py --contain` command printed by `tools/profiler/selftest.sh`, with
paths changed to those two files.  Require `0 failures, PASS` here too, then
close the dedicated shell.

The temporary priority is part of validating the sampler, not part of the
measurement.  On a networked stock A1200, background stack tasks can preempt
`profspin` enough to fail its proportionality check even when every sampled PC
is correct.  Priority 5 keeps the validation kernels running for their intended
intervals; `SCALE=4` supplies enough samples at 200 Hz to make their shares
stable.  Do not raise the shell priority for `iperf` or any real workload: that
would change the scheduling behaviour being measured.

For TCP receive, run the same transfer twice.  On the Amiga, the plain control
is:

    C:iperf -s -p 5001 -t 40

Start it first, then on a separate Linux machine run iperf 2 (not iperf3):

    iperf -c AMIGA_ADDRESS -p 5001 -t 30 -l 4096

For the sampled arm, replace only the Amiga command:

    C:Profile QUIET RATE=200 SAMPLES=8000 \
        OUT=RAM:iperf-rx.prof FOLDED=RAM:iperf-rx.folded \
        C:iperf -s -p 5001 -t 40

The repository's independent peer can replace the Linux iperf client while
keeping the payload length explicit:

    python3 tests/tools/iperfpeer.py send tcp AMIGA_ADDRESS \
        --port 5001 --seconds 30 --length 4096

Copy `iperf-rx.prof` back into the same checkout and resolve the executable and
the cooperating shared library from that exact build:

    LIBSPEC="exe=build/prof/src/bsdsocket/bsdsocket.library,"
    LIBSPEC="${LIBSPEC}map=build/prof/src/bsdsocket/bsdsocket.library.map,"
    LIBSPEC="${LIBSPEC}objdir=build/prof/src/bsdsocket"
    tools/profiler/profreport.py iperf-rx.prof \
        --exe build/prof/src/tools/iperf \
        --map build/prof/src/tools/iperf.map \
        --objdir build/prof/src/tools \
        --lib "$LIBSPEC"

Keep the plain and sampled throughput beside the profile.  Also record the
Amiga model, CPU and clock, accelerator, Fast RAM, card, SANA-II device name
and version, AmiNetXDuo commit and build options, Linux `iperf --version`, and
both exact commands.  Without those fields an emulator result or a different
driver can accidentally be compared with the hardware-only failure.

The profiler normally adds about four percent to wall time.  The plain run is
therefore the throughput number; the sampled run supplies shares and a check
that its overhead stayed modest.  `profreport.py` also reports true idle time
from the saved exception SR: Exec's idle `stop #$2000` is SR $2000.  Do not
infer idle from a task's blocked wall time or from the hottest Exec address.

The configuration above deliberately makes a non-LTO diagnostic build.  An
LTO binary is valid to sample, and global/assembly symbols still resolve.  Its
file-static functions live in temporary `*.ltrans.o` objects, however, and
those objects are gone by report time.  The reporter marks those samples
`UNRESOLVED` rather than assigning them a plausible wrong name.  No-LTO keeps
the ordinary object files and gives the complete function ranking.  It is a
diagnostic build, so compare its timing only with its own plain control.

`RATE=200` is deliberate for the stock 14 MHz 68EC020.  The 1000 Hz default
is useful on a faster accelerator, but asks this machine to take an interrupt
every millisecond while it is already CPU-bound.  A 200 Hz physical receive
profile still collected 4000 samples over twenty seconds and resolved the hot
path without turning the sampler into a leading cost.  Always keep the plain
control: the appropriate rate is a measured property of the machine, not its
model name.

Size `SAMPLES` for the whole command, not just the peer's transfer.  `Profile`
starts before `iperf` accepts and stops after `iperf` returns, so a 30-second
peer at 200 Hz needs more than 6000 slots; the 8000 above leaves ten seconds
for startup and teardown and costs 128 KB.  Once the buffer is full, sampling
continues only as a dropped-sample count.  A report saying all requested slots
were stored followed by a few hundred dropped samples normally means this
tail exceeded the buffer; it does not mean the interrupt handler missed that
many samples.  Raise `SAMPLES`, subject to the machine's free-memory limit,
and require the stored timestamps to span the workload before interpreting
the shares.


WHAT IT CAN PROFILE
-------------------

Anything the CPU executes while the program runs, wherever it is:

  * The program's own code, by hunk, relocated back to link-time addresses.
  * Kickstart.  Every AmigaOS library is a jump table, so exec.library/Forbid
    is named as exec.library/Forbid rather than as an address in ROM.
  * Shared libraries and devices, including ones loaded from disk while the
    program runs and ones with no symbols at all, those are named by module.
  * Inside a shared library, by function, if the library cooperates.  See
    SEEING INSIDE A SHARED LIBRARY below; without it a library is one bar.
  * Interrupt handlers, including the SANA-II driver's receive path: sampling
    is at level 4, which can interrupt a level-2 or level-3 handler.
  * Any number of tasks and processes at once.  Each sample records which task
    was running, so the profile splits by thread.

There is no list of things it cannot look inside.  It does not instrument
anything, so there is nothing for it to fail to instrument.


WHAT IT CANNOT PROFILE
----------------------

  * Code inside Exec's Disable().  Disable() turns interrupts off, so nothing
    is sampled there and that time is charged to whatever runs next.  This is
    MEASURED rather than assumed: every sample carries a timestamp, so the
    report says what fraction of the run was never sampled and where the
    longest gaps were.  Forbid()/Permit() does not mask interrupts and is
    sampled normally.

  * Code inside a level-5 or level-6 interrupt handler, disk sync, serial
    receive, CIA-B.  A level-4 interrupt cannot preempt those.  It shows up as
    a gap, and the gap is reported.

  * Call stacks.  This is a flat PC sampler: it records where the CPU was, not
    how it got there.  The exports below make a hierarchy out of what a sample
    does carry (task, context, module, function) rather than pretending to a
    call graph.

  * A program that calls Exit() rather than returning.  Profile runs the
    program in its own process with RunCommand(), so Exit() unwinds past it and
    the profile is not written.  It says so when it happens.

  * A program that does not return at all.  A resident DOS handler, `fitz
    mount`, is sampled correctly and forever, and nothing is written because
    the run never ends.  Break it and it returns normally: the handler and the
    profiler are the same process, so a CTRL-C to that task reaches both.

  * A program that wants all four audio channels.  See below.


THE AUDIO CHANNEL
-----------------

The sampling interrupt comes from an audio channel: two bytes of silence on
repeat at volume zero, and the DMA raises an interrupt each time it reloads.
Channel 3 by preference, then 2, 1, 0, and the channel is allocated through
audio.device so a program that wants it can have it.  CHANNEL=n demands one.

If every channel is taken, Profile refuses to sample rather than fighting for
the hardware and reporting whatever comes out.  If a program takes the channel
back mid-run, audio.device gives it to a higher-precedence claimant without
asking, a vertical-blank watchdog notices the rate collapse and the report
says so.  A profile of half a program that looks like a profile of all of it is
the failure this tool exists to avoid.

A CIA timer is not an alternative.  Two were tried and both stopped mid-run,
having produced enough correct samples to rank functions convincingly.


THE RATE
--------

1000 Hz on a 68010 and up, 250 Hz on a plain 68000, and RATE= overrides both.
Those are general defaults, not a recommendation for a saturated stock A1200;
the real-hardware receive procedure above starts that machine at 200 Hz.

WHAT THAT COSTS, measured rather than estimated, profspin timing itself with
and without the profiler attached, under FS-UAE:

    68EC020, 14 MHz, 1000 Hz    12.52 s -> 13.00 s      3.8%
    68000,    7 MHz,  250 Hz    16.66 s -> 17.30 s      3.8%

which is about 38 us per interrupt on the 020 and 150 us on the 68000, most of
it Exec's own level-4 dispatch rather than the eleven instructions in the
vector.  The two defaults land on the same figure because the 68000 is roughly
four times slower and samples four times less often.

Four percent is worth knowing and is not worth much worrying about: the cost
falls on whatever is running, so it is spread across the profile roughly in
proportion to the shares being measured and moves the RANKING very little.  It
does inflate absolute wall clock, so time a program with the profiler off.
Halve RATE= to halve the cost.

SAMPLES= caps the buffer.  By default Profile takes at most a third of free
memory: 16 bytes a sample, so 1000 Hz fills 16 KB a second.


THE HOST SIDE
-------------

    profreport.py profile.prof --exe MyProgram --map MyProgram.map \
        --objdir <where the .obj files are> --ndk <NDK include dir>

Function names need the executable's symbols, which is why this half runs on
the machine that built the program.  It recovers file-static functions too, by
walking the linker map for where each object landed and running nm on that
object, without that, every sample in a static lands silently on the
preceding global.

    profreport.py fitz.prof --ndk <NDK include dir> \
        --lib exe=<the library file>,map=<its map>,objdir=<its objects>

names functions inside a shared library as well, for a library that
cooperates.  --lib is repeatable and each one is checked the same way the
executable is: if the file's hunk sizes are not the ones the run recorded, it
says so and that library stays named by module rather than resolving every
address in it to a wrong name out of somebody else's build.


SEEING INSIDE A SHARED LIBRARY
------------------------------

A profile of a real application spends most of its time in libraries, and
naming that time needs the same two things the program itself needs: where the
hunks landed, and the symbols.

The symbols are the library's own file, which is what --lib takes.  Where the
hunks landed is the problem.  A library base is a private struct, Exec
publishes struct Library at the front and nothing after it, so the seglist,
which every library has because Expunge must return it, sits at an offset only
that library's own source knows.  Reading it from a hard-coded number would be
this tool asserting a layout it cannot check, and the first field anybody
inserted would move it silently: the walk would still find eight bytes shaped
like a segment header, still produce hunk bases, and still resolve every
address in the library to a wrong and entirely plausible name.

So the library says where it is, in a record that identifies itself.  Five
longwords anywhere in its own positive half, at any word boundary, a magic,
its own size, the base it is embedded in, the seglist, and a sum that makes the
five add to zero.  (Any WORD boundary: a longword on m68k is aligned to two
bytes, so a record of longwords is four-aligned only by luck, and scanning in
steps of four finds nothing and looks exactly like a library carrying no tag.)
Profile scans for it, refuses one whose base is not the base it was found in
(which is what rejects a copy that has been moved, such as a cloned library
base), and then checks the seglist it was given against something it already
knew: the hull of that library's own jump-table targets must lie inside the
hunks the walk produced.  A seglist that fails that is discarded.

struct ProfSegTag in prof.h is the whole convention.  A library adopting it
needs no header from here: declare five longwords, fill them in at init, and
if the base is ever cloned fix up the base field and the sum in the clone.

A LIBRARY THAT DOES NOT CARRY ONE IS STILL NAMED, by module, from the hull of
its jump-table targets, which is what it has always been and what every
third-party library will be.  The difference is a bar labelled with the
library's name against a list of its functions.


Two exports, for viewers that already exist:

    --folded out.txt     one line per unique stack, "a;b;c <count>".
                         speedscope.app reads it directly and gives icicle,
                         left-heavy and sandwich views; so do flamegraph.pl and
                         inferno.

    --trace out.json     Chrome Trace Event JSON.  ui.perfetto.dev and
                         speedscope.app both read it, and it is a real
                         timeline rather than an aggregate, if two threads
                         alternate per packet, this shows the switch rate on
                         its face.

Profile itself can write the folded file with FOLDED=, at module rather than
function granularity, so a machine with no cross-development host attached can
still produce something a browser will draw.

The folded stacks are "task;context;module;function".  THAT IS NOT A CALL
STACK.  A PC sampler records one address, so a literal folded stack would be
one frame deep and an icicle graph of it would be a bar chart.  Every level of
this hierarchy is measured; none of it is inferred.


PROVING IT
----------

A sampling profiler is the one measurement tool that can be comprehensively
wrong and still look right: read the exception frame two bytes off and every
recorded value is half an SR concatenated with half a PC, a number that lands
somewhere, resolves to some function, and ranks it convincingly.

profspin is the answer to that.  It is an ordinary program that links nothing
from the profiler, and it writes the exact byte range of each of its assembly
kernels from the linker's own labels:

    Profile OUT=RAM:spin.prof profspin RANGES=RAM:spin.ranges
    profreport.py RAM:spin.prof --contain RAM:spin.ranges ...

which checks that the samples landed inside the kernels that were running, and
that each kernel's share of the samples matches its share of the wall clock the
program measured for itself.  A wrong frame offset scores approximately zero
rather than a bit less.

Run it on your own machine before believing anything this tool tells you about
it.  It takes about twenty seconds and needs nothing but the two binaries.

SPDX-License-Identifier: MIT