-- 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 -- 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 -- 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) install_transport() 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 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 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 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 then transport_service(t) 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) 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 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)) -- 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. 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)