Files
Dragon-s-Lair-X68k/tools/bench/stream.lua
T
prosolis 5921fab118 Put the transport on the 68000, and find PIO costs 87 clocks a byte
ROADMAP P4b. src/player/xfer.i answers src/player/ring.i's XF_* mailbox with a
real READ(10) to a real MB89352 in place of tools/bench/stream.lua's modelled
transport: 120 records, 4,488,588 B, pixel-exact out of a 256 KB ring, with a
real mid-stream seek in a second pass. The tiling is the SAME 18 wraps and
14.7 KB mean hole that 49.4's host producer and 55.4's modelled transport
produced -- a third transport, same placement, which is the assertion that
ring.i could not tell which side of the seam answered it.

What it costs is the finding. tools/bench/xfer_cost.sh subtracts the same 120
frames run twice and gets 87.28 clocks per delivered byte, against the 68000's
own cycle table for the loop, which says 87.15 -- 0.2% apart, so the cost is the
instruction stream and not MAME's device model, and it is the first number this
rig has produced that survives leaving the emulator. That is 391.8% of a 12 fps
frame; the machine's own V-DISP clock agrees from the other end at 2.57 fps.
Against the ladder, W=5 held is 22.4% of a frame and W=19 is 85.3%, so P4a is
worth 4.6x the worst DMA configuration in this tree and 17.5x the best -- where
before this session it was worth 9 against 19. W itself did not move by a clock.

"UNDERRUNS: 0/120" is vacuous with a synchronous transport, and stream.lua now
prints that argument next to the zero: a frame cannot start before its record
has landed because the decoder IS the transport. The counter that means
something is NO IDLE, 119/120 with a worst overrun of 441 whole ticks. Same
class of error as 49.7.2's free-running ring passing at 48 KB.

58.3: a record is not a sector -- 117 of 120 start part way into one, and
reading whole sectors into the ring corrupts the neighbours rather than wasting
bytes (49.2, no bounds check). scsi.i reads the covering sectors and stores only
the window, which is free in PIO and stops being free the moment P4a succeeds.
tools/analysis/26_sector_align.py prices the three ways out and sector-aligned
records win on both axes: +0.43% wire and zero clocks, against +1.34% and a
bounce copy at +5 clk/B. ROADMAP now carries a four-item re-encode bundle and
P4a should be attempted against a sector-aligned container.

check.sh gains two stages and was ALL GREEN before and after. decode.bin is
unchanged at 1,296 B and the same MD5.

Claude-Session: https://claude.ai/code/session_01194oWYW8DQXK1SZ2DnChW6
2026-08-24 23:15:53 -07:00

1114 lines
61 KiB
Lua

-- Drive src/player/stream.s: decode a whole window through a BOUNDED RING,
-- with a modelled SCSI pipe as the producer. STATUS item 3, FINDINGS 49.
--
-- tools/bench/decode.lua preloads the entire container into emulated RAM and
-- lets the 68000 walk a0 through all of it. That gate is pixel-exact over 120
-- frames (FINDINGS 45) and tests nothing about delivery -- 45.4.1 says so in as
-- many words. It is also RAM-bound for a reason that has nothing to do with the
-- player: 5,261,814 B of stream needs a 6 MB machine.
--
-- Here the container lives in a HOST file (tools/bench/prep_stream.py's disk
-- image) and this script plays the part of the MB89352 plus a DMAC channel:
-- it delivers bytes at a modelled rate into a ring of DLX_RING_KB, and the
-- 68000 decodes out of that ring and nothing else. The emulated machine holds
-- ~256 KB of stream instead of 5 MB, so a STOCK 2 MB machine runs the whole
-- window -- the RAM ceiling of FINDINGS 44.6.4/45 is a property of the old rig
-- and this one does not have it.
--
-- WHAT IS BEING TESTED, precisely: that the block loop and the span chain --
-- which read with a monotonically increasing a0 and no bounds check anywhere --
-- stay pixel-exact when a0 is inside a ring one twentieth the size of the
-- stream, and when the address it is handed jumps backwards to the ring base
-- roughly every sixth frame. A green run is not "the decoder still works"; it
-- is "the wrap policy in src/player/stream.s does not corrupt a single pixel of
-- a temporally recursive 120-frame decode".
--
-- THE WRAP POLICY IS `aligned` (tools/analysis/19_ring_stream.py): never start a
-- record that will not fit before the end of the ring; leave the hole and
-- restart at the base. The alternative, letting records wrap and mirroring the
-- ring head into a shadow, costs 5.57% of the frame budget forever against this
-- one's 9.1% of a buffer, and the decoder is already at 91.1% of budget at p90.
-- (Those two are s14_d5_all1500's; the gate container this rig usually runs
-- makes it 3.64% of the budget against 5.7% of the ring. Per container.)
--
-- MEASUREMENT SCOPE, unchanged from decode.lua: MAME's gvram_w/gvram_r carry no
-- timing, so decode times here are pure 68000 instruction cycles against
-- zero-wait-state memory -- a LOWER BOUND. The pipe, likewise, is a MODEL: a
-- constant byte rate on the emulated clock, not a simulation of the MB89352.
-- What it is honest about is ARRIVAL ORDER and RESIDENCY, which is what the
-- ring exists to manage; it says nothing about the clocks the DMAC steals from
-- the 68000 while it does it. That debit is FINDINGS 43.2's and is not modelled
-- here -- so a zero-stall result from this rig means "the bytes were in time",
-- NOT "the frame fits".
--
-- Env:
-- DLX_RING_KB ring size in KB (default 256, FINDINGS 21's)
-- DLX_STREAM_KBPS modelled pipe, KB/s REQUIRED -- no default.
-- 0 = unlimited, which isolates the WRAP question from the
-- DELIVERY one and is what the green light uses.
-- There is deliberately no default rate: this project has
-- never measured the delivery pipe, and the figure that used
-- to be defaulted to here was a user-supplied "4 Mbps" with
-- no provenance that was never a bus measurement at all
-- (FINDINGS 42.1). A default is how a folklore number ends up
-- silently underneath a table nobody restates it in.
-- DLX_PREFILL_KB bytes to deliver before releasing the CPU (default 0).
-- Host-owned ring only: with DLX_RINGOWN the machine does
-- its own prefill and DLX_PREFILL_FR is the knob.
-- DLX_RINGOWN 1 = THE 68000 OWNS THE RING (ROADMAP P5,
-- src/player/ring.i). This script stops placing records and
-- becomes a TRANSPORT: it answers one request at a time,
-- delivering XF_LEN bytes from XF_OFF to XF_DST in
-- len/rate seconds, and the machine decides which record,
-- where in the ring, and when. It also AUDITS every
-- placement the machine makes against its own index.
-- DLX_PREFILL_FR whole records the machine's prefill waits for before it
-- releases the decoder (default 2; see ring_prefill)
-- DLX_PACE 1 = hold the decoder to META.fps, with the HOST writing
-- the tick (default 0 = free-run)
-- 2 = hold it to META.fps with the 68000 writing its own
-- tick, off the CRTC's V-DISP (src/player/clock.i, ROADMAP
-- P3). Same gate, same ring, same deadlines; what changes
-- is that nothing outside the machine decides when a frame
-- may start. Deadlines are then taken from the ticks the
-- machine actually emitted rather than from a host model of
-- 12 fps -- which matters, because MAME's raster runs 2.22%
-- fast (see tools/bench/clock.lua) and a host model would
-- quietly grade every arrival against the wrong clock.
-- DLX_CUT_AT frame tick at which the pipe stops dead (a seek). Needs
-- DLX_PACE; unset = no cut.
-- DLX_CUT_FR how many frame times the cut lasts (default 1)
-- DLX_SLACK_CSV write the per-tick lookahead series to this path
-- DLX_SNAP_EVERY 1 = snapshot every frame tick (needs DLX_PACE). For
-- recording the player; not used by check.sh.
--
-- PACING, AND WHY THE UNPACED RIG COULD NOT ANSWER THE BUFFERING QUESTION
-- (FINDINGS 49.7.2). Free-running, src/player/stream.s asks for record i the
-- instant it finishes record i-1. It therefore outruns any finite pipe, the
-- ring never backs up, `overlaps` never refuses a placement, and every ring size
-- down to 48 KB passes while holding ONE record. That sweep tests wrap
-- correctness, which is real, and says nothing about buffering, which is what a
-- branch point needs. With DLX_PACE=1 the producer supplies a frame clock and
-- the decoder may not start frame i before tick i, so the ring fills to its own
-- capacity and FR_HEAD-FR_TAIL becomes the honest number: whole frames the
-- decoder could run on with delivery stopped dead. DLX_CUT_AT/DLX_CUT_FR then
-- stop it dead and check the answer against a real underrun.
M = manager.machine
SP = M.devices[":maincpu"].spaces["program"]
local function findfile(n)
for _,p in ipairs{"../tools/bench/"..n, "tools/bench/"..n, n} do
local f = io.open(p,"rb"); if f then f:close(); return p end
end
error(n.." not found")
end
local MODE = loadfile(findfile("crtc_mode.lua"))()
local META = loadfile("stream_meta.lua")()
local FLAG, ITER, NFR = 0x18000, 0x18008, 0x1800C
local RD_PTR, FR_HEAD, FR_TAIL = 0x18020, 0x18024, 0x18028
local STALLS, SPINS, DESC = 0x1802C, 0x18030, 0x18100
local PACE, PACEON, CLKON = 0x18034, 0x18038, 0x1803C
local CLK_VDISP, CLK_FPS, CLK_ERR = 0x18064, 0x18068, 0x1806C
local LATEFR, LATEMAX, LATE1ST = 0x18080, 0x18084, 0x18088
-- src/player/ring.i. The transport mailbox, then the producer's state and its
-- instruments. Nothing below 0x18300 changed: the decoder's handshake with the
-- ring (FR_HEAD/FR_TAIL/DESC) is the same one FINDINGS 49 and 51 measured, which
-- is what makes a self-filled run a test of ring.i and not of a new rig.
local XF_SLOT, XF_SLSZ = 0x18300, 16
local XF_GO, XF_ACK, XF_QD = 0x18320, 0x18324, 0x18328
local A_RINGOWN, A_RNG_B, A_RNG_SZ, A_IDX_B = 0x1832C, 0x18330, 0x18334, 0x18338
local A_RQ_NEXT, A_WCUR, A_RCUR = 0x1833C, 0x18340, 0x18344
local A_NHOLE, A_NHOLEB, A_NFULL = 0x18354, 0x18358, 0x1835C
local A_NPOLL, A_NISSUE = 0x18360, 0x18364
local A_SLKMIN, A_SLKAT = 0x18368, 0x1836C
local A_PFREC, A_PFDONE = 0x18370, 0x18374
local A_NSEEK, A_SKWAIT = 0x18378, 0x1837C
-- src/player/xfer.i, the transport that lives in the machine.
local A_XFSCSI, A_XSLBA0 = 0x18380, 0x18384
local A_XSNXFER, A_XSNBYTE = 0x18388, 0x1838C
local A_XSNWIRE, A_XSERR, A_XSERRAT = 0x18390, 0x18394, 0x18398
-- The scene header's record index, pushed into RAM before the CPU is launched.
-- It sits ABOVE the codebooks rather than in the low RAM around ring.i's own
-- tables: setup() runs one raster frame before launch() and the IPL is still
-- executing in that gap, so anything written below ~$20000 can be overwritten
-- before the 68000 ever sees it. That cost an hour: the machine read a table of
-- zeroes and asked the transport for a 0-byte record.
local IDXRAM = 0x30000 -- the DLX4 index, in RAM
local DESCN = 64
local CB1, CB4 = 0x20000, 0x22000
local RING = 0x40000
local GVRAM, GPAL = 0xC00000, 0xE82000
local CPUHZ = 10000000
local FRAME12 = CPUHZ / META.fps
local AUDIO_KBPS = 7.8 -- ratectl.AUDIO_KBPS; the pipe carries it too
local RING_KB = tonumber(os.getenv("DLX_RING_KB") or "") or 256
local KBPS = tonumber(os.getenv("DLX_STREAM_KBPS") or "")
if KBPS == nil then
print("[STR] DLX_STREAM_KBPS is not set and has no default. Set it to the "
.."delivery rate you want to model, or to 0 for an unlimited pipe "
.."(which is what tools/bench/check.sh uses -- it gates the WRAP "
.."policy, and an unlimited pipe removes delivery as a variable).")
manager.machine:exit()
return
end
local PREFILL = (tonumber(os.getenv("DLX_PREFILL_KB") or "") or 0) * 1024
local SELFCLK = (os.getenv("DLX_PACE") == "2")
local PACED = (os.getenv("DLX_PACE") == "1") or SELFCLK
local CUT_AT = tonumber(os.getenv("DLX_CUT_AT") or "")
local CUT_FR = tonumber(os.getenv("DLX_CUT_FR") or "") or 1
local SLACK_CSV = os.getenv("DLX_SLACK_CSV")
local RINGOWN = (os.getenv("DLX_RINGOWN") == "1")
local PREFILL_FR = tonumber(os.getenv("DLX_PREFILL_FR") or "") or 2
-- Passes over the scene. With DLX_RINGOWN each pass after the first begins
-- with a REAL seek in src/player/stream.s: the channel is waited quiet, the
-- ring is declared empty and the lookahead 51.3 says takes seconds of play to
-- accumulate is thrown away and rebuilt from the prefill. The check that
-- matters afterwards is the one this rig always makes -- the last frame of the
-- last pass has to be pixel-exact, and a SKIP block is a claim about the
-- previous frame, so it is only right if every frame after the seek was.
local ITERS = tonumber(os.getenv("DLX_ITER") or "") or 1
-- How many requests the player may have outstanding at once. 1 is the obvious
-- loop and leaves the channel idle from every completion until the next poll;
-- 2 keeps the next request queued so it never stops. Both are real designs and
-- the difference between them is what this rig measures.
local QDEPTH = tonumber(os.getenv("DLX_QDEPTH") or "") or 2
-- WHO MOVES THE BYTES. "model" is this script: a transport that delivers
-- XF_LEN bytes in XF_LEN/rate seconds and acks from emulated time, which is
-- what FINDINGS 49/51/55 were all measured through. "scsi" is ROADMAP P4b --
-- src/player/xfer.i and src/player/scsi.i on the 68000, a real MB89352, a real
-- volume, and NOTHING of this script in the transfer path.
--
-- The two are not interchangeable and the log must never let them look it. The
-- modelled transport OVERLAPS with the CPU, which is what a DMAC channel does;
-- the real one here does not, because 57.3 leaves the CPU moving every byte
-- itself. So a "scsi" run measures CORRECTNESS off a real volume and the CPU
-- cost of a PIO transport, and it measures NO rate: every rate-shaped number in
-- this script's report is suppressed rather than printed against a transport
-- that has no model behind it.
local XFER = os.getenv("DLX_XFER") or "model"
local SCSIX = (XFER == "scsi")
-- src/player/scsi.i's SCE_* codes, so a failure names itself.
local SCERRNAME = {[0]="OK", "SELECTION TIMEOUT -- no target answered",
"UNEXPECTED PHASE", "POLL TIMEOUT -- a phase never arrived",
"NON-ZERO SCSI STATUS"}
-- One snapshot per frame tick instead of one at the end of the run. This is a
-- DOCUMENTATION artefact -- 120 PNGs of a paced player, for a recording -- and
-- it is deliberately not on any path tools/bench/check.sh takes. Needs
-- DLX_PACE: snapshotting a free-running decoder would sample the screen at
-- whatever rate the 68000 happened to finish frames at, which is not a frame
-- rate and would misrepresent the player as faster than it is.
local SNAP_EVERY = (os.getenv("DLX_SNAP_EVERY") == "1")
local RINGSZ = RING_KB * 1024
-- Video's share of the pipe. Debiting audio is not optional bookkeeping: the
-- ADPCM stream comes off the same disk and out of the same budget (FINDINGS 33).
local BPS = (KBPS > 0) and (KBPS - AUDIO_KBPS) * 1024 or math.huge
local code do local f=io.open("stream.bin","rb"); code=f:read("a"); f:close() end
local cb do local f=io.open("stream_cb.bin","rb"); cb=f:read("a"); f:close() end
local DISK = assert(io.open("stream_disk.bin","rb"))
local idxblob do
local f = io.open("stream_idx.bin","rb")
if f then idxblob = f:read("a"); f:close() end
end
if RINGOWN and not idxblob then
print("[STR] DLX_RINGOWN needs the DLX4 record index (stream_idx.bin). "
.."Re-run tools/bench/prep_stream.py on a DLX4 container: the machine "
.."cannot derive record lengths by walking a stream it has not fetched.")
manager.machine:exit(); return
end
local YOFF = (MODE.height - META.H) // 2
local function T() local t=M.time; return t.seconds + t.attoseconds/1e18 end
local function P(s) print("[STR] "..s) end
local function push(addr, s, from, len)
local i, n = from, len
while n >= 4 do
SP:write_u32(addr, (string.unpack(">I4", s, i)))
addr, i, n = addr+4, i+4, n-4
end
while n > 0 do
SP:write_u8(addr, string.byte(s,i)); addr, i, n = addr+1, i+1, n-1
end
end
-- ------------------------------------------------------------ the producer
-- Ring occupancy is tracked as an explicit list of records still owned by the
-- decoder, rather than as a modular write-minus-read distance. Under `aligned`
-- the ring is not a simple modulus -- a wrap leaves a HOLE of arbitrary size --
-- so a distance would have to carry the holes as a correction term and would be
-- the easiest thing in this file to get quietly wrong. Six-ish live records is
-- a short list; an O(n) overlap test on it is exact and obviously exact.
-- arrival[i] = emulated time at which record i became RESIDENT. This, not the
-- decoder's spin counter, is what answers the delivery question. stream.s has
-- no frame clock: it asks for the next record the instant it finishes the last
-- one, so it outruns any finite pipe and "stalled" is what a decoder that is
-- merely EARLY looks like. A shipping player waits for vblank at 12 fps and
-- spends that same time idle. So the honest test is not "did the decoder ever
-- wait" but "was record i resident by its 12 fps deadline", which is a question
-- about arrival times alone and does not need the decoder paced.
local arrival = {}
local live, wcur, nsent = {}, 0, 0
local n_rate, n_ring = 0, 0
local holes, hole_bytes, credit = 0, 0, 0
local last_t, pf_t0, delivered = nil, nil, 0
local function overlaps(off, len)
for _,r in ipairs(live) do
if off < r.off + r.len and r.off < off + len then return true end
end
return false
end
local function reap()
local tail = SP:read_u32(FR_TAIL)
local i = 1
while i <= #live do
if live[i].idx < tail then
-- RD_PTR is the decoder's byte-granular release, and nothing here needs
-- it -- this producer has the index and works in whole records. Checking
-- it makes it a cross-check instead of a field nothing reads: a real
-- producer without an index (a DMAC chasing the CPU) has only this.
--
-- It holds for the LAST record retired in a pass and not for the others.
-- RD_PTR is a single released-to pointer, so it names the end of record
-- tail-1; if several records were consumed since the previous reap -- and
-- under a paced decoder with a stopped pipe, several is normal -- the
-- earlier ones are long overwritten by it. Asserting per record made the
-- check a test of how often reap happened to run.
if live[i].idx == tail - 1 then
local rp = SP:read_u32(RD_PTR)
local want = RING + live[i].off + live[i].len
if rp ~= want then
P(string.format("RD_PTR MISMATCH after frame %d: decoder released "
.."%08X, record ends %08X", live[i].idx, rp, want))
M:exit()
end
end
table.remove(live, i)
else
i = i + 1
end
end
end
-- Cut window: the pipe stops dead, as it does across a seek. Credit is FROZEN
-- rather than left to accumulate -- a drive that is repositioning is not
-- banking bytes it will burst on arrival, and letting credit build would hand
-- the ring back everything the cut took the moment it ended, which is the one
-- way to make a seek look free.
local cut_t0, cut_t1, cut_done = nil, nil, false
local function produce(now)
local dt = now - (last_t or now); last_t = now
local cut = (cut_t0 and now >= cut_t0 and now < cut_t1)
-- A seek stops DELIVERY. It does not stop the decoder, which goes on draining
-- the ring and releasing bytes behind itself, so reap() runs either way --
-- skipping it would have the ring look full for the whole cut and hide the
-- one thing the cut is for.
if not cut then credit = credit + dt * BPS end
reap()
if cut then return end
while nsent < META.nframes do
local rec = META.index[nsent + 1]
-- WHICH RESOURCE REFUSED, counted separately. A producer that stops
-- because it has no credit is RATE-bound and a bigger ring buys nothing; one
-- that stops because the decoder still owns the bytes is RING-bound and a
-- faster pipe buys nothing. The two look identical from the decoder's side
-- -- both are simply "no new record" -- and they have opposite fixes.
if credit < rec.len then n_rate = n_rate + 1; break end
-- `aligned`: refuse to start a record that will not finish inside the ring.
-- The hole is charged only once the record is actually PLACED. Charging it
-- at the point the wrap is decided counts one hole per retry while the
-- decoder still owns the ring base -- which is every tick of a fast pipe --
-- and reported 105 wraps over 120 records where there are 18.
local w, hole = wcur, 0
if w + rec.len > RINGSZ then w, hole = 0, RINGSZ - wcur end
if overlaps(w, rec.len) then n_ring = n_ring + 1; break end -- decoder owns them
if hole > 0 then holes = holes + 1; hole_bytes = hole_bytes + hole end
DISK:seek("set", rec.off)
push(RING + w, DISK:read(rec.len), 1, rec.len)
-- The descriptor MUST be visible before the count that advertises it. Here
-- the CPU is stopped while this runs so the order is academic; on hardware
-- it is not, and stream.s reads them in the opposite order for that reason.
SP:write_u32(DESC + (nsent % DESCN) * 4, RING + w)
live[#live+1] = {idx=nsent, off=w, len=rec.len}
wcur, nsent = w + rec.len, nsent + 1
credit, delivered = credit - rec.len, delivered + rec.len
SP:write_u32(FR_HEAD, nsent)
arrival[nsent] = now -- record nsent-1 is now resident
end
end
-- -------------------------------------------------------------- transport
-- THE OTHER HALF OF ROADMAP P5. With DLX_RINGOWN the producer above is not
-- used at all: src/player/ring.i decides which record to fetch, where to put it
-- and when it is safe, and this becomes the part that is genuinely not the
-- CPU's -- an SPC and one DMAC channel moving bytes at a rate.
--
-- IT IS BUILT OUT OF MEMORY TAPS, not out of the machine-frame notifier, and
-- that is a measurement decision rather than a stylistic one. A notifier sees
-- the machine once per raster frame, 17.64 ms (54.5), and the thing being
-- measured here is the gap between a transfer COMPLETING and the CPU issuing
-- the next one -- which is a fraction of a frame slot. Sampling it at 17.64 ms
-- would have quantised the very quantity in question, and in the flattering
-- direction if the ack were early or the pessimistic one if late.
--
-- write tap on XF_GO fires inside the 68000's write, so the issue time is
-- exact. The bytes are copied in there and then: the
-- CPU cannot observe them before its ack anyway, because
-- it does not advertise the record until it retires.
-- read tap on XF_ACK synthesises the completion word from emulated time --
-- `done` iff now >= t_done -- so the CPU learns of the
-- completion on the exact cycle it happens, the way it
-- would from a status register.
-- A 68000 bus access is 16 bits, so a longword is two tap calls: the write is
-- acted on at the LOW half (written second, so the whole value is there) and
-- the read latches its answer at the HIGH half so the two halves cannot
-- straddle a completion.
local xf = {go = 0, ack = 0, busy = 0.0, gap = 0.0, gapmax = 0.0, ngap = 0,
latch = 0, tfree = 0, copylate = 0.0, ncopylate = 0}
-- q[n] = the n-th request (n counts from 1): when the CPU issued it, when the
-- transport will have finished it, and whether its bytes have been moved yet.
local q = {}
local npass = 1
local function xf_deliver(off, dst, len, now)
DISK:seek("set", off)
push(dst, DISK:read(len), 1, len)
end
-- The host as AUDITOR rather than as producer. Every placement the machine
-- makes is checked against this script's own record index and its own list of
-- records the decoder has not finished with -- the same overlap test the host
-- producer used to make its decisions with, now used only to grade them. A
-- wrong placement corrupts pixels rather than faulting (49.2), so it has to be
-- caught where it is made.
local function audit(idx, off, dst, len)
local rec = META.index[idx + 1]
if not rec then return string.format("record %d does not exist", idx) end
if off ~= rec.off then
return string.format("record %d: machine asked for disc offset %d, the "
.."index says %d", idx, off, rec.off) end
if len ~= rec.len then
return string.format("record %d: machine asked for %d B, the index says %d",
idx, len, rec.len) end
local w = dst - RING
if w < 0 or w + len > RINGSZ then
return string.format("record %d: placed at ring offset %d..%d, outside a "
.."%d B ring", idx, w, w + len, RINGSZ) end
local tail = SP:read_u32(FR_TAIL)
local i = 1
while i <= #live do
if live[i].idx < tail then table.remove(live, i) else i = i + 1 end
end
for _, r in ipairs(live) do
if w < r.off + r.len and r.off < w + len then
return string.format("record %d at %d..%d overlaps record %d at %d..%d, "
.."which the decoder has not consumed",
idx, w, w + len, r.idx, r.off, r.off + r.len) end
end
live[#live+1] = {idx = idx, off = w, len = len}
return nil
end
-- THE TAP OBJECTS ARE KEPT ALIVE HERE ON PURPOSE. install_*_tap returns a
-- handle and the tap dies with it: dropping it on the floor leaves the taps
-- working until Lua's collector next runs, and then the mailbox silently stops
-- answering. That looks exactly like a wedged producer -- the machine polled
-- 2.4 million times for an ack that had already been computed.
-- THE TAP OBJECTS ARE KEPT ALIVE HERE ON PURPOSE. install_*_tap returns a
-- handle and the tap dies with it: dropping it on the floor leaves the taps
-- working until Lua's collector next runs, and then the mailbox silently stops
-- answering. That looks exactly like a wedged producer -- the machine polled
-- 2.4 million times for an ack that had already been computed.
local TAPS = {}
local function install_transport()
-- NOTHING IN A TAP CALLBACK TOUCHES THE MEMORY SPACE. MAME 0.277 segfaults
-- if a tap reads or writes the space it was triggered from -- a nested access
-- part way through the CPU's own -- and it does it intermittently, which is
-- the worst way to find out. So the taps do pure Lua: the write tap stamps
-- the EXACT emulated time the 68000 issued a request, the read tap answers
-- the completion count from those stamps, and every actual memory access is
-- done from the machine-frame notifier.
--
-- What that buys is the thing worth having: issue and completion times are
-- both exact, so the gap between a transfer finishing and the next one
-- starting -- the disc standing still because nobody has asked it for
-- anything -- is measured at cycle resolution rather than at 17.64 ms.
TAPS[#TAPS+1] = SP:install_write_tap(XF_GO, XF_GO + 3, "dlx_xf_go",
function(offset, data, mask)
if offset ~= XF_GO + 2 then return data end -- low half, written second
-- ...and it must be the INCREMENT, not any other write to the word.
-- ring_init clears the mailbox at boot, which lands on this address with
-- the request fields still empty; without this test the transport answered
-- that clear as if it were a request and audited a 0-byte record 0.
if data ~= ((xf.go + 1) & 0xFFFF) then return data end
xf.go = xf.go + 1
q[xf.go] = {tissue = T(), served = false}
return data
end)
TAPS[#TAPS+1] = SP:install_read_tap(XF_ACK, XF_ACK + 3, "dlx_xf_ack",
function(offset, data, mask)
if offset == XF_ACK then
-- Latched on the high half so the two halves of one longword read cannot
-- straddle a completion. Requests complete IN ORDER: one channel, one
-- transfer at a time, however many are queued.
local now = T()
while true do
local r = q[xf.ack + 1]
if not (r and r.served and now >= r.tdone) then break end
xf.ack = xf.ack + 1
end
xf.latch = xf.ack
return (xf.latch >> 16) & 0xFFFF
end
return xf.latch & 0xFFFF
end)
end
-- Service every request the machine has issued but this script has not yet
-- looked at: read what was asked for, grade the placement, move the bytes, and
-- work out when the channel will have finished it. Called from the
-- machine-frame notifier, which is where this script may touch memory.
local function transport_service(t)
local n = xf.ack + 1
while q[n] do
local r = q[n]
if r.served then n = n + 1; goto continue end
local slot = XF_SLOT + ((n - 1) % 2) * XF_SLSZ
local off, dst = SP:read_u32(slot), SP:read_u32(slot + 4)
local len, idx = SP:read_u32(slot + 8), SP:read_u32(slot + 12)
if idx == 0 and n > 1 then
-- A new pass: everything the auditor knows about the ring is about the
-- scene we just left. The decoder has not consumed the new records and
-- the old ones are no longer anybody's.
live, nsent, arrival = {}, 0, {}
npass = npass + 1
P(string.format("SEEK PASS %d: the machine seeked back to record 0 at "
.."%.3f s and is refilling from empty", npass, r.tissue))
end
local err = audit(idx, off, dst, len)
if err then
P("MISPLACED: "..err)
P(" The machine owns the ring in this run, so this is a policy bug in "
.."src/player/ring.i, not a rig one -- and it would have shown up as "
.."wrong pixels, because the block loop reads without a bounds check.")
M:exit(); return
end
-- ONE CHANNEL: a transfer starts when the channel is free AND the request
-- exists, so a queued request starts the instant its predecessor lands and
-- a late one starts when it is issued. The difference is the gap, and the
-- gap is the player's, not the medium's -- no host-filled run could see it,
-- because the host producer placed records whenever it liked.
local startt = math.max(r.tissue, xf.tfree)
if xf.tfree > 0 then
local g = startt - xf.tfree
if g > 0 and nsent < META.nframes then
xf.gap, xf.ngap = xf.gap + g, xf.ngap + 1
if g > xf.gapmax then xf.gapmax = g end
end
end
local dur = (BPS == math.huge) and 0 or (len / BPS)
local done = startt + dur
-- A cut is a seek: the transfer freezes for its duration rather than
-- carrying on invisibly. Freezing is the conservative reading and the one
-- 51.6 settled on for the host producer -- a drive that is repositioning is
-- not banking bytes it will burst on arrival.
if cut_t0 and done > cut_t0 and startt < cut_t1 then
done = done + (cut_t1 - math.max(startt, cut_t0))
end
xf_deliver(off, dst, len, t)
r.tdone, r.served = done, true
xf.tfree = done
xf.busy = xf.busy + dur
nsent = math.max(nsent, idx + 1)
arrival[idx + 1] = done -- resident when the last byte lands
delivered = delivered + len
-- The one place this rig is coarser than the machine: a record whose
-- modelled transfer was shorter than the wait for this notifier was already
-- "done" by the time the bytes could be moved. Counted, not absorbed.
if t > done then
xf.copylate, xf.ncopylate = xf.copylate + (t - done), xf.ncopylate + 1
end
n = n + 1
::continue::
end
end
-- ------------------------------------------------------------------ setup
local function setup()
MODE.apply(SP)
push(CB1, cb, 1, META.cb1_len)
push(CB4, cb, 1 + META.cb1_len, META.cb4_len)
local palo = 1 + META.cb1_len + META.cb4_len
for c = 0, 255 do
SP:write_u16(GPAL + c*2, (string.unpack(">I2", cb, palo + c*2)))
end
for y = 0, MODE.height-1 do
local base, v = GVRAM + y*1024, 0
if y < YOFF or y >= YOFF+META.H then v = META.dark end
for x = 0, MODE.width-1 do SP:write_u16(base + x*2, v) end
end
for i = 1, #code do SP:write_u8(0x10000+i-1, string.byte(code,i)) end
SP:write_u32(FLAG, 0); SP:write_u32(FR_HEAD, 0); SP:write_u32(FR_TAIL, 0)
SP:write_u32(ITER, ITERS); SP:write_u32(NFR, META.nframes)
SP:write_u32(PACE, 0); SP:write_u32(PACEON, PACED and 1 or 0)
SP:write_u32(CLKON, SELFCLK and 1 or 0)
SP:write_u32(CLK_FPS, META.fps)
SP:write_u32(A_RINGOWN, RINGOWN and 1 or 0)
if RINGOWN then
-- The scene header the machine reads: the DLX4 record index, exactly the
-- bytes the container carries, pushed into RAM the way a loaded scene
-- header would be. ring_init turns it into the disc-offset table a seek
-- needs; nothing here derives a record boundary for the machine.
push(IDXRAM, idxblob, 1, #idxblob)
SP:write_u32(A_IDX_B, IDXRAM)
SP:write_u32(A_RNG_B, RING)
SP:write_u32(A_RNG_SZ, RINGSZ)
SP:write_u32(A_PFREC, PREFILL_FR)
SP:write_u32(XF_QD, QDEPTH)
if SCSIX then
-- The stream begins at LBA 0 of the volume, because tools/bench/mkvol.sh
-- lays tmp/stream_disk.bin down from sector 0 and nothing else is on it.
-- It is a WORD the machine reads rather than a constant in xfer.i: a
-- shipping volume has a filesystem in front of the stream, and the base
-- LBA is the one number that changes when it does.
SP:write_u32(A_XFSCSI, 1)
SP:write_u32(A_XSLBA0, 0)
else
install_transport()
end
end
P(string.format("stream.bin=%d B, codebooks %d+%d B, disk %d B, %d frames",
#code, META.cb1_len, META.cb4_len, META.disk_len, META.nframes))
P(string.format("decoder %s%s", SELFCLK
and ("SELF-PACED at "..META.fps.." fps off V-DISP")
or PACED and ("PACED at "..META.fps.." fps by the host")
or "FREE-RUNNING (tests wrap, not buffering -- 49.7.2)",
CUT_AT and string.format(", pipe cut at tick %d for %.2f fr",
CUT_AT, CUT_FR) or ""))
P(string.format("ring %d KB at %06X, pipe %s, prefill %s, maxrec %d B",
RING_KB, RING, (KBPS > 0) and (KBPS.." KB/s") or "unlimited",
RINGOWN and (PREFILL_FR.." records (the machine's own)")
or ((PREFILL // 1024).." KB"), META.maxrec))
if RINGOWN then
if SCSIX then
P(string.format("REAL TRANSPORT (ROADMAP P4b, src/player/xfer.i): the "
.."68000 fetches every record itself with READ(10) off a "
.."CZ-6BS1. This script moves NO bytes and models NO "
.."rate. %d B of DLX4 index at %06X.", #idxblob, IDXRAM))
P(" the queue depth cannot deepen anything here: the transport is "
.."SYNCHRONOUS (xfer.i), so a queued request is drained by the same "
.."instruction stream that would be decoding. FINDINGS 55.3's 1-vs-2 "
.."result is about a transport that OVERLAPS; this one does not.")
else
P(string.format("ring OWNED BY THE 68000 (src/player/ring.i): this script "
.."is a transport with a %d-deep request queue, %d B of "
.."DLX4 index at %06X", QDEPTH, #idxblob, IDXRAM))
end
end
if META.maxrec > RINGSZ then
P("RING TOO SMALL: one record does not fit. stream.s needs a whole record "
.."contiguous."); M:exit()
end
end
local function launch()
local cpu = M.devices[":maincpu"]
cpu.state["SR"].value = 0x2700 -- supervisor, ALL interrupts masked
cpu.state["SP"].value = 0x8000
cpu.state["PC"].value = 0x10000
end
local st, t0, t_rel = "boot", nil, 0
-- tick_t[i+1] = emulated time of frame tick i, filled in as they are observed.
-- Under a self-clock this replaces the host's `t_rel + i/fps` as the deadline:
-- the machine's clock is the one the player is actually held to, and MAME's
-- raster is 2.22% fast, so grading arrivals against a host model of 12 fps
-- would flatter every record by that much.
local tick_t = {}
local pace, min_ahead, min_at = -1, math.huge, -1
-- DLX_XFER=scsi: the machine's seek counter, and the transfer count it stood at
-- when that seek happened. -1 means "not sampled yet", so the first sample
-- rebases without announcing a pass that did not happen.
local xs_nseek, xs_base = -1, 0
local sum_ahead, n_ahead = 0, 0
local slack_series = {}
SUB = emu.add_machine_frame_notifier(function()
local ok, err = pcall(function()
local t = T()
if RINGOWN and not SCSIX then transport_service(t) end
if SCSIX and st ~= "boot" then
-- The machine's own count of completed transfers, which is what `nsent`
-- means in a run where this script sends nothing. Sampled rather than
-- derived, so the slack window still closes when the producer runs out of
-- records to place instead of running on into the drain tail.
--
-- REBASED AT EVERY SEEK, and it has to be: XS_NXFER is cumulative over
-- the whole run, so on a second pass it is already >= nframes and the
-- slack sampling below -- gated on `nsent < META.nframes` -- would never
-- fire again. It did not, and the second pass reported a ceiling of 0
-- frames and a build time of -1 ticks, which is an empty series printing
-- as a result. ring.i's own seek counter is the exact place to rebase:
-- a seek discards every outstanding request by definition.
local ns = SP:read_u32(A_NSEEK)
if ns ~= xs_nseek then
-- ANNOUNCE ONLY A SEEK WITH PLAY BEHIND IT. A pass opens with two
-- seeks that are not branch points -- ring_init's, and stream.s's at
-- the top of `outer` -- and both happen before a single record has been
-- fetched. Announcing those numbered the first pass "SEEK PASS 2" and
-- the real one "3". XS_NXFER separates them exactly: a seek taken with
-- transfers already behind it is the one that threw a ring away.
if xs_nseek >= 0 and SP:read_u32(A_XSNXFER) > 0 then
npass = npass + 1
P(string.format("SEEK PASS %d: the machine seeked at %.3f s and is "
.."refilling from empty", npass, t))
end
xs_nseek, xs_base = ns, SP:read_u32(A_XSNXFER)
end
nsent = SP:read_u32(A_XSNXFER) - xs_base
if nsent < 0 then nsent = 0 end
end
if st == "boot" then
if t < 3.0 then return end
setup(); last_t, pf_t0 = t, t; st = "prefill"; return
end
if st == "prefill" then
if not RINGOWN then produce(t) end
-- RINGOWN: there is nothing for the host to prefill. The machine issues
-- its own requests, so it has to be running first; ring_prefill then
-- holds the decoder until PF_REC records are resident, which is the same
-- policy in the place a player would keep it.
if RINGOWN or delivered >= PREFILL then
P(string.format("prefill done: %.1f KB in %.3f s, releasing the CPU",
delivered/1024, t - pf_t0))
launch(); t_rel = t; st = "running"
end
return
end
if st == "running" then
if PACED then
-- WHO WRITES THE TICK. Host-paced, the tick is a host model of
-- META.fps and this script advances it. Self-paced, the 68000 has
-- already advanced it off the raster and this script only READS it --
-- the frame gate in src/player/stream.s cannot tell the two apart,
-- which is the point: the same bytes are gated either way.
local tick = SELFCLK and SP:read_u32(PACE)
or math.floor((t - t_rel) * META.fps)
if tick < pace then
-- src/player/stream.s rebased the clock for a new pass: tick 0 is the
-- instant the decoder was released after the seek's prefill, not the
-- start of the run. Everything sampled per tick starts again with it.
pace, tick_t = -1, {}
min_ahead, min_at = math.huge, -1
sum_ahead, n_ahead, slack_series = 0, 0, {}
end
if tick > pace then
pace = tick
if not SELFCLK then SP:write_u32(PACE, pace) end
-- The emulated time this tick actually happened, which is what a
-- record's deadline is measured against under a self-clock. Ticks
-- can arrive more than one apart if the host misses a frame, so the
-- whole run is filled rather than just the newest.
for k = #tick_t, tick do tick_t[k+1] = t end
-- Taken BEFORE this tick's frame is decoded, so snapshot n is the
-- finished picture of frame n-1. tick 0 is skipped: nothing has been
-- drawn yet and it would record a black screen as a decoded frame.
if SNAP_EVERY and tick > 0 then M.video:snapshot() end
-- Sampled AT the tick, before this frame is decoded: FR_TAIL is the
-- count of frames already done, FR_HEAD the count resident, so the
-- difference is exactly how many further frames the decoder could
-- draw if the pipe went silent at this instant. Whole records, not
-- bytes -- the contiguity constraint of 49.2 means a partial record
-- buys nothing.
local ahead = SP:read_u32(FR_HEAD) - SP:read_u32(FR_TAIL)
-- Only sampled while the producer still HAS records to place. Once
-- it has sent the last one the lookahead drains to zero for reasons
-- that are about the window ending, not about the ring's capacity or
-- the pipe's rate -- and the minimum over the whole run would then
-- always be the drain tail, which is the one part of it that tells
-- you nothing.
if nsent < META.nframes then
if ahead < min_ahead then min_ahead, min_at = ahead, tick end
sum_ahead, n_ahead = sum_ahead + ahead, n_ahead + 1
-- Column 3 is "has the producer been refused for space yet",
-- which is what makes a later minimum meaningful: before the first
-- refusal the ring is still filling. With the ring owned by the
-- machine that counter is ring.i's, not this script's.
slack_series[#slack_series+1] =
{tick, ahead, RINGOWN and SP:read_u32(A_NFULL) or n_ring, n_rate}
end
if CUT_AT and tick >= CUT_AT and not cut_t0 then
cut_t0, cut_t1 = t, t + CUT_FR / META.fps
P(string.format("PIPE CUT at tick %d for %.2f frame times "
.."(%.1f ms), with %d frames resident ahead",
tick, CUT_FR, 1000*CUT_FR/META.fps, ahead))
end
end
end
if not RINGOWN then produce(t) end
if RINGOWN and os.getenv("DLX_RINGDBG") == "1" then
dbg_n = (dbg_n or 0) + 1
if dbg_n % 30 == 0 then
P(string.format("DBG t=%.2f flag=%X go=%d ack=%d tfree=%.3f queued=%s "
.."head=%d tail=%d rq=%d poll=%d full=%d wcur=%d rcur=%d",
t, SP:read_u32(FLAG), xf.go, xf.ack, xf.tfree,
tostring(q[xf.ack+1] ~= nil), SP:read_u32(FR_HEAD),
SP:read_u32(FR_TAIL), SP:read_u32(A_RQ_NEXT),
SP:read_u32(A_NPOLL), SP:read_u32(A_NFULL),
SP:read_u32(A_WCUR), SP:read_u32(A_RCUR)))
end
end
if cut_t0 and not cut_done and t >= cut_t1 then cut_done = true end
local fl = SP:read_u32(FLAG)
if fl == 1 and not t0 then t0 = t; return end
if fl == 0xEE then
P("BITSTREAM DESYNC -- the decoder consumed the wrong number of bytes.")
if RINGOWN then
local tail, head = SP:read_u32(FR_TAIL), SP:read_u32(FR_HEAD)
P(string.format(" tail=%d head=%d rq=%d wcur=%d rcur=%d go=%d ack=%d",
tail, head, SP:read_u32(A_RQ_NEXT), SP:read_u32(A_WCUR),
SP:read_u32(A_RCUR), xf.go, xf.ack))
P(string.format(" DESC[%d]=%08X, the index says record %d is at ring "
.."offset ? len %d", tail,
SP:read_u32(DESC + (tail % 64)*4), tail,
META.index[tail+1] and META.index[tail+1].len or -1))
local ls = {}
for _, r in ipairs(live) do
ls[#ls+1] = string.format("%d@%d+%d", r.idx, r.off, r.len) end
P(" host thinks live: "..table.concat(ls, " "))
end
P(" Under a ring that is the whole point: it means a record was placed "
.."or described wrongly, not that the codec changed.")
M:exit(); return
end
if fl == 0xE2 then
local e = SP:read_u32(CLK_ERR)
P("FRAME CLOCK REFUSED: CLK_ERR="..e..(e == 1 and
" (the CRTC is not in a 31.5 kHz mode, so the divider's 31500 "
.."lines/s would be wrong)" or e == 2 and
" (fps*VTOTAL does not fit the 16-bit accumulator)" or ""))
M:exit(); return
end
if fl == 0xE3 then
P("RING INIT REFUSED: the record index has more entries than "
.."src/player/ring.i's disc-offset table (ROFFMAX) can hold.")
M:exit(); return
end
if fl == 0xE1 then
P("PRODUCER STALLED OUT -- stream.s spun SPINMAX times with no new "
.."record. Delivered "..nsent.."/"..META.nframes..".")
M:exit(); return
end
if fl == 0xFF then
local dt = t - (t0 or t)
local stalls = SP:read_u32(STALLS)
local spins = SP:read_u32(SPINS)
if PACED then
-- Paced, the wall clock measures the PACE, not the decode: the loop
-- spends whatever is left of each slot spinning in `pacewait`. The
-- decode cost of this container is decode.lua's and FINDINGS 45's;
-- printing a cycles/frame here would just report 1/fps back.
P(string.format("decoded %d frames in %.4f s emulated at a %d fps "
.."pace (%.2f s nominal) -- the clock here measures "
.."the PACE, not the decode",
META.nframes, dt, META.fps, META.nframes/META.fps))
else
P(string.format("decoded %d frames in %.4f s emulated -> %.0f cycles/"
.."frame = %.1f%% of a %dfps frame",
META.nframes, dt, dt*CPUHZ/META.nframes,
100*(dt*CPUHZ/META.nframes)/FRAME12, META.fps))
end
if SELFCLK then
-- The clock's own report, in the run where it actually paced a
-- decoder rather than a busy loop. The rate is against MAME's fast
-- raster; tools/bench/clock_run.sh is where it gets de-skewed.
local vd = SP:read_u32(CLK_VDISP)
local vt = SP:read_u16(0xE80008) + 1 -- VTOTAL, as clk_init read it
-- DELIBERATELY NOT A RATE. 120 ticks is far too short a window to
-- quote fps from: the run's start and end each straddle a tick, so
-- +/-1 on 119 intervals is +/-8000 ppm and would read as drift the
-- clock does not have. What IS exact here is a count of refreshes
-- against a count of ticks. The rate figure comes from
-- tools/bench/clock_run.sh, over thousands of them.
P(string.format("FRAME CLOCK: %d V-DISP interrupts drove %d ticks "
.."(%.4f refreshes/frame; the divider's own ratio is "
.."31500/(%d*%d) = %.4f), %.0f clocks/frame of "
.."interrupt at FINDINGS 54's 181.35 each",
vd, pace + 1, vd/(pace + 1), META.fps, vt,
31500/(META.fps*vt), 181.35*vd/(pace+1)))
end
local rholes, rhole_b = holes, hole_bytes
if RINGOWN then
rholes, rhole_b = SP:read_u32(A_NHOLE), SP:read_u32(A_NHOLEB)
end
P(string.format("ring: %d wraps, %d B of hole (mean %.1f KB, %.1f%% of "
.."the ring)", rholes, rhole_b,
rholes > 0 and rhole_b/rholes/1024 or 0,
100*(rholes > 0 and rhole_b/rholes or 0)/RINGSZ))
if RINGOWN then
-- The producer's own account of itself. These are read out of the
-- machine's RAM, not kept here: the point of the run is that this
-- script did not make any of these decisions.
local pf = SP:read_u32(A_PFDONE)
local npoll, nissue = SP:read_u32(A_NPOLL), SP:read_u32(A_NISSUE)
local nfull = SP:read_u32(A_NFULL)
local slk, slkat = SP:read_u32(A_SLKMIN), SP:read_u32(A_SLKAT)
local nseek, skw = SP:read_u32(A_NSEEK), SP:read_u32(A_SKWAIT)
P(string.format("MACHINE-OWNED RING: %d records placed by the 68000, "
.."%d polls, %d refused for space (ring-bound), "
.."%d seeks", nissue, npoll, nfull, nseek))
P(string.format("PREFILL: released the decoder at %d records "
.."(policy: %d); LEAST SLACK %d records at frame %d",
pf, PREFILL_FR, slk, slkat))
-- THE NUMBER THIS RIG EXISTS TO PRODUCE. The channel only moves
-- bytes while a request is outstanding and only the CPU can issue the
-- next one, so the disc stands still between the completion of one
-- record and the issue of the next. That gap is a property of the
-- PLAYER's loop, not of the medium, and no host-filled run could see
-- it -- the host producer placed records whenever it liked.
local span = (arrival[nissue] or t) - (t0 or t)
if SCSIX then
-- WHAT A REAL TRANSPORT CAN AND CANNOT BE ASKED HERE. The modelled
-- transport knew when every byte landed because it decided; this one
-- does not report, and MAME's device models are functional rather
-- than transfer-timing accurate, so even if it did the number would
-- not be a rate (docs/BENCHMARK.md, 42.5). So CHANNEL IDLE,
-- DEADLINE and REQUIRED PREFILL are not printed at all rather than
-- printed as zeros -- a zero here reads as "the channel never
-- stopped", which would be a claim about a medium this rig has
-- never timed.
local nb, nw = SP:read_u32(A_XSNBYTE), SP:read_u32(A_XSNWIRE)
local nx = SP:read_u32(A_XSNXFER)
P(string.format("REAL TRANSPORT: %d READ(10)s by the 68000, %d B "
.."into the ring", nx, nb))
-- THE COST THE CONTAINER PAYS FOR NOT BEING SECTOR-ALIGNED. A
-- record starts wherever the previous one ended, rounded up to 4;
-- a target answers in 512 B blocks. So the command covers the
-- sectors the record lies in and src/player/scsi.i's window drops
-- the rest. In PIO those bytes cost nothing but wire; they are
-- still bytes the disc moved that no frame contains.
P(string.format("SECTOR OVERHEAD: %d B off the disc for %d B of "
.."record = %.2f%% the medium moved and no frame "
.."contains", nw, nb,
nb > 0 and 100*(nw - nb)/nb or 0))
local e, eat = SP:read_u32(A_XSERR), SP:read_u32(A_XSERRAT)
if e ~= 0 then
P(string.format("TRANSPORT FAILED: SC_ERR=%d on request %d (%s)",
e, eat, SCERRNAME[e] or "see src/player/scsi.i"))
end
if skw > 0 then
P(string.format(" the last seek waited %d polls for the channel "
.."to go quiet before it could start", skw))
end
goto ringdone
end
P(string.format("CHANNEL IDLE: %.1f ms over %d gaps (worst %.1f ms) = "
.."%.1f%% of the %.2f s the transport was needed for; "
.."busy %.1f ms",
xf.gap*1000, xf.ngap, xf.gapmax*1000,
span > 0 and 100*xf.gap/span or 0, span,
xf.busy*1000))
-- THE RIG'S OWN RESOLUTION, PRINTED RATHER THAN LEFT IMPLICIT.
-- The transport's timing is exact (memory taps), but the BYTES are
-- moved from the machine-frame notifier, so a record whose modelled
-- transfer is shorter than the wait for that notifier is acked later
-- than the model says it landed. Every millisecond here is a
-- millisecond the decoder may have waited that the medium would not
-- have made it wait.
if xf.ncopylate > 0 then
P(string.format("RIG RESOLUTION: %d of %d transfers were acked late "
.."because the bytes are moved on the notifier, by "
.."%.1f ms in total (mean %.1f ms) -- an artefact of "
.."this rig, not of the player",
xf.ncopylate, nissue, xf.copylate*1000,
xf.copylate*1000/xf.ncopylate))
end
if skw > 0 then
P(string.format(" the last seek waited %d polls for the channel "
.."to go quiet before it could start", skw))
end
::ringdone::
end
-- The decoder's own spin counter, kept for what it is: evidence that
-- stream.s outran the pipe, NOT evidence of an underrun. See the note
-- on `arrival` above.
if PACED then
-- Paced, a stall is an UNDERRUN: the frame's slot arrived and its
-- record had not. Free-running it is earliness (49.6) and means the
-- opposite thing, so the two are never printed in the same words.
P(string.format("UNDERRUNS: %d/%d frames waited past their %d fps slot "
.."(%d polls)", stalls, META.nframes, META.fps, spins))
if SCSIX then
-- AND IT IS VACUOUS HERE, WHICH IS WORTH MORE THAN THE ZERO IS.
-- A synchronous transport cannot underrun by construction: the
-- decoder does not go on until the record is in its hand, because
-- it fetched the record itself. What it does instead is MISS THE
-- SLOT, and that is the NO IDLE line above -- 442 whole ticks of
-- overrun is not a late present, it is a player running at a
-- fraction of its frame rate. Quoting "0 underruns" from a
-- DLX_XFER=scsi run without this line would be the most flattering
-- possible reading of the least flattering result in the tree.
local ticks = pace + 1
P(string.format(" 0 IS VACUOUS: the transport is synchronous, so a "
.."frame cannot start before its record has landed "
.."-- the decoder IS the transport. The honest rate "
.."is %d frames in %d slots of %d fps = %.2f fps.",
META.nframes, ticks, META.fps,
ticks > 0 and META.fps*META.nframes/ticks or 0))
end
-- The other way a paced frame can go wrong, and it is not the same
-- failure. An UNDERRUN is the pipe: the record was not there. This
-- is the CPU: the record was there, the slot was already open, and
-- the decoder had no idle left in the frame before. Under a
-- host-written tick every slot is 83.33 ms; under the machine's own
-- clock they alternate 72.13 and 90.16 ms, 37.9% of them short, and
-- this is what the short ones cost (FINDINGS 54).
local late, latemax = SP:read_u32(LATEFR), SP:read_u32(LATEMAX)
local late1 = SP:read_u32(LATE1ST)
P(string.format("NO IDLE: %d/%d frames found their slot already open "
.."-- the frame before used all of it; worst overrun "
.."%d whole tick%s, first at frame %d", late,
META.nframes, latemax, latemax == 1 and "" or "s",
late1 == 0xFFFFFFFF and -1 or late1))
-- WHAT THE MINIMUM OVER A RUN IS, AND IS NOT. At release the ring
-- holds only what the prefill put there, so the early ticks report a
-- buffer that has not been built yet, not a ring or a pipe that
-- cannot build it. A seek empties the ring the same way, so that
-- transient is the branch-point case rather than an artefact to be
-- trimmed -- but it has to be told apart from the CEILING, which is
-- what the ring is worth once it is full.
--
-- Which resource stopped the producer says which is which, and only
-- RING refusals count: a rate refusal fires on nearly every tick
-- (credit accrues continuously and records are placed whole), so it
-- marks nothing. A ring refusal means the ring actually filled.
local ceiling, ceil_at = 0, -1
for _,e in ipairs(slack_series) do
if e[2] > ceiling then ceiling, ceil_at = e[2], e[1] end
end
local ss_min, ss_at = math.huge, -1
for _,e in ipairs(slack_series) do
if e[3] > 0 and e[2] < ss_min then ss_min, ss_at = e[2], e[1] end
end
if ss_min == math.huge then ss_min, ss_at = -1, -1 end
P(string.format("SEEK SLACK: ceiling %d frames (%.0f ms), first "
.."reached at tick %d; mean %.1f over the window",
ceiling, 1000*ceiling/META.fps, ceil_at,
sum_ahead/math.max(1,n_ahead)))
-- WHOSE REFUSAL COUNT. With the ring owned by the machine the host
-- producer's counters are not merely stale, they are zero -- it never
-- placed anything -- so the classification has to come from
-- src/player/ring.i's own N_FULL. Reading n_ring here in a RINGOWN
-- run would have reported RATE-BOUND on every run by construction.
local ring_ref = RINGOWN and SP:read_u32(A_NFULL) or n_ring
if ring_ref > 0 then
P(string.format(" RING-BOUND: the ring filled (%d refusals). Once "
.."full it survives delivery stopped dead for %d "
.."frames = %.0f ms; min after first fill %d "
.."(tick %d)", ring_ref, ceiling,
1000*ceiling/META.fps, ss_min, ss_at))
else
P(string.format(" RATE-BOUND: the ring NEVER filled in %d frames. "
.."A bigger ring buys nothing at this pipe; the "
.."buffer is still accumulating when the window "
.."ends.", META.nframes))
end
P(string.format(" BUILD TIME: %d ticks = %.2f s of play to reach the "
.."ceiling from empty -- which is what a branch point "
.."costs before the NEXT seek is affordable",
ceil_at, ceil_at/META.fps))
if SLACK_CSV then
local fh = io.open(SLACK_CSV, "w")
fh:write("tick,ahead,ring_refusals,rate_refusals\n")
for _,e in ipairs(slack_series) do
fh:write(string.format("%d,%d,%d,%d\n", e[1], e[2], e[3], e[4]))
end
fh:close()
P("slack series -> "..SLACK_CSV)
end
else
P(string.format("decoder waited on %d/%d frames (%d polls) -- it is "
.."free-running, so this is earliness, not underrun",
stalls, META.nframes, spins))
end
-- The delivery result. Deadline for record i is release + i/fps.
-- Only this script can compute it, because only this script knows when
-- a byte landed -- and in a DLX_XFER=scsi run it does not. Printing it
-- from an empty arrival table would report "0/120 records late", which
-- is the most flattering possible reading of no data at all.
if SCSIX then
P("DEADLINE: not measured. The transport is in the machine and does "
.."not report arrival times, and MAME's SCSI is not transfer-timing "
.."accurate, so there is no honest deadline to grade against here. "
.."The sharp instrument that DOES survive is the decoder's own "
.."UNDERRUNS count above -- the machine takes it, and it is exact.")
st = "settle"; return
end
local misses, worst, prefill_s = 0, 0.0, 0.0
for i = 0, META.nframes-1 do
local a = arrival[i+1]
if a then
-- INSTRUMENT NOTE, and it only bites under the self-clock.
-- tick_t[] is when this script OBSERVED the machine's tick, which
-- is the next machine-frame boundary after it -- up to 17.64 ms
-- late (54.5). So these deadlines are generous by that much and
-- this count UNDERSTATES lateness. The sharp instrument for the
-- same question is the decoder's own stall counter, which is exact
-- because the machine takes it: at 488 KB/s with a one-deep request
-- queue this reported 6 records late where the 68000 counted 59
-- frames that had to wait. Host-paced (DLX_PACE=1) the deadline is
-- a host model and is exact, so FINDINGS 49.6's table is unaffected.
local due = SELFCLK and tick_t[i+1] or (t_rel + i / META.fps)
if not due then due = t_rel + i / META.fps end
local late = a - due
if late > 0 then
misses = misses + 1
if late > worst then worst = late end
end
if late > prefill_s then prefill_s = late end
end
end
P(string.format("DEADLINE at %d fps: %d/%d records late, worst by "
.."%.1f ms (%.2f frame times)", META.fps, misses,
META.nframes, worst*1000, worst*META.fps))
-- The smallest start delay that makes every deadline: FINDINGS 21's
-- "required prefill", measured on the emulated clock through the real
-- ring rather than simulated from record sizes.
P(string.format("REQUIRED PREFILL: %.1f ms = %.2f frame times = %.1f KB "
.."at %s", prefill_s*1000, prefill_s*META.fps,
(KBPS > 0) and (prefill_s * BPS / 1024) or 0.0,
(KBPS > 0) and (KBPS.." KB/s") or "an unlimited pipe"))
-- ONE FRAME OF SETTLE BEFORE THE CAPTURE, and it is not cosmetic.
-- MAME renders a screen scanline by scanline and the machine-frame
-- notifier fires at the END of that frame, so a bitmap for a frame in
-- which GVRAM changed holds some lines drawn before the change and some
-- after. Snapshotting it captures a TEAR -- and the symptom is a
-- pixel-exactness failure in the bottom blocks plus a broken double-scan
-- pairing, which reads exactly like a decoder bug and is not one. It
-- only bites when the decoder finishes its last frame LATE in a screen
-- frame, which is why it never showed up until a run with underruns in
-- it. Waiting one whole frame renders the finished picture with nothing
-- writing to GVRAM.
st = "settle"; return
end
if t > 900 then P("TIMEOUT flag="..string.format("%08X",fl)); M:exit() end
return
end
if st == "settle" then
M.video:snapshot()
P("snapshot taken after the sequential pass -- last frame, decoded "
.."entirely out of a "..RING_KB.." KB ring")
st = "snapped"; return
end
if st == "snapped" then M:exit(); return end
end)
if not ok then print("[STR] LUA ERROR: "..tostring(err)); M:exit() end
end)