Dragon-s-Lair-X68k/tools/bench/stream.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)
--   DLX_PACE         1 = hold the decoder to META.fps (default 0 = free-run)
--   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             = 0x18034, 0x18038
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 PACED     = (os.getenv("DLX_PACE") == "1")
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")
-- 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 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

-- ------------------------------------------------------------------ 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, 1); SP:write_u32(NFR, META.nframes)
  SP:write_u32(PACE, 0); SP:write_u32(PACEON, PACED and 1 or 0)
  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", PACED and ("PACED at "..META.fps.." fps")
                  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 %d KB, maxrec %d B",
                  RING_KB, RING, (KBPS > 0) and (KBPS.." KB/s") or "unlimited",
                  PREFILL // 1024, META.maxrec))
  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
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 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
      produce(t)
      if 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
        local tick = math.floor((t - t_rel) * META.fps)
        if tick > pace then
          pace = tick
          SP:write_u32(PACE, pace)
          -- 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
            slack_series[#slack_series+1] = {tick, ahead, 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
      produce(t)
      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.")
        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 == 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
        P(string.format("ring: %d wraps, %d B of hole (mean %.1f KB, %.1f%% of "
                        .."the ring)", holes, hole_bytes,
                        holes > 0 and hole_bytes/holes/1024 or 0,
                        100*(holes > 0 and hole_bytes/holes or 0)/RINGSZ))
        -- 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))
          -- 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
          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)))
          if n_ring > 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)", n_ring, 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
            local late = a - (t_rel + i / META.fps)
            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"))
        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 t > 900 then P("TIMEOUT flag="..string.format("%08X",fl)); M:exit() end
      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)