Dragon-s-Lair-X68k/tools/bench/clock.lua

-- Drive src/player/clockgate.s: measure the 68000's own FRAME CLOCK.
-- ROADMAP P3.
--
-- Two things are being measured and they need different instruments.
--
-- THE RATE AND THE CADENCE are counted, not timed.  The clock's tick is a
-- V-DISP interrupt, and MAME's Lua sees the machine once per screen frame --
-- which is once per V-DISP.  So the host's sampling granularity is exactly the
-- clock's own granularity, and the cadence comes out as integers: how many
-- refreshes each frame tick waited.  There is no timing error to argue about
-- in a count of 4s and 5s.
--
-- THE COST IS TIMED BY THE 68000, because the host cannot.  1/55.46 s of host
-- granularity is 18 ms and the interrupt costs microseconds.  So the 68000 runs
-- a one-instruction loop for a window of thousands of refreshes and the host
-- reads the iteration count at both ends; the interrupt cost falls out of the
-- difference between a run with the clock armed and one without.  See the head
-- of src/player/clockgate.s for the arithmetic.  This script emits the raw
-- counts; tools/bench/clock_cost.py does the subtraction, so that the two runs
-- it needs can be separate MAME invocations.
--
-- MEASUREMENT SCOPE.  This is MAME 0.277's emulated X68000, not real hardware.
-- What is being priced is the interrupt sequence of MAME's cycle-accurate
-- M68000 core (src/devices/cpu/m68000, the `M68000` device x68k.cpp:1133 asks
-- for) against zero-wait-state RAM.  Real DRAM adds wait states to the six bus
-- cycles of the exception and the four of the handler alike, so this is a LOWER
-- BOUND in the same way every other 68000 figure in this project is.
--
-- Env:
--   DLX_CLK_ON   1 = arm the frame clock, 0 = leave it off (the calibration
--                run).  REQUIRED -- the two runs are not interchangeable and a
--                default would let one be reported as the other.
--   DLX_CLK_FPS  frame rate to ask clk_init for (default 12)
--   DLX_CLK_WIN  measurement window, in raster frames (default 3000 = 54.1 s)
--   DLX_CLK_OUT  where to write the raw counts (default tmp/clock_run.txt)

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 CGFLAG, CGON, CGCNT     = 0x18070, 0x18074, 0x18078
local CLK_PACE                = 0x18034
local CLK_ACC, CLK_INCR       = 0x18060, 0x18062
local CLK_VDISP, CLK_FPS      = 0x18064, 0x18068
local CLK_ERR                 = 0x1806C
local CPUHZ                   = 10000000

local ONS = os.getenv("DLX_CLK_ON")
local FPS = tonumber(os.getenv("DLX_CLK_FPS") or "") or 12
local WIN = tonumber(os.getenv("DLX_CLK_WIN") or "") or 3000
local OUT = os.getenv("DLX_CLK_OUT") or "clock_run.txt"

local function P(s) print("[CLK] "..s) end

if ONS ~= "0" and ONS ~= "1" then
  P("DLX_CLK_ON must be 0 (calibration, clock off) or 1 (clock armed). The "
    .."cost figure is the DIFFERENCE between the two runs, so neither is "
    .."meaningful alone and neither gets to be the default.")
  M:exit()
  return
end
local ON = (ONS == "1")

local code do local f=io.open("clockgate.bin","rb"); code=f:read("a"); f:close() end

local function T() local t=M.time; return t.seconds + t.attoseconds/1e18 end

-- Settling frames between the gate reporting `running` and the window opening.
-- The CPU may still be inside clk_init when the host first sees CGFLAG=1, and
-- the first V-DISP edge after arming lands wherever the raster happens to be.
-- Two frames puts the window entirely inside the steady state.
local SETTLE = 2

local st, n = "boot", 0
local f_ready, f0, f1 = nil, nil, nil
local c0, c1, v0, v1, p0, p1, t0, t1
-- Cadence: refreshes between consecutive frame ticks.  Recorded as a histogram
-- and as the raw first few, because the interesting claim is not the mean (the
-- divider makes that exact by construction) but that the SPREAD is only ever
-- the two values either side of fps*VTOTAL/HFREQ.
local last_pace, last_pace_f, cad, seen_tick = nil, nil, {}, false

SUB = emu.add_machine_frame_notifier(function()
  local ok, err = pcall(function()
    n = n + 1
    if st == "boot" then
      if T() < 3.0 then return end
      MODE.apply(SP)
      for i = 1, #code do SP:write_u8(0x10000+i-1, string.byte(code,i)) end
      SP:write_u32(CGFLAG, 0)
      SP:write_u32(CGON, ON and 1 or 0)
      SP:write_u32(CLK_FPS, FPS)
      local cpu = M.devices[":maincpu"]
      cpu.state["SR"].value = 0x2700    -- clk_init lowers it to $2500 itself
      cpu.state["SP"].value = 0x8000
      cpu.state["PC"].value = 0x10000
      P(string.format("clockgate.bin=%d B, clock %s, asking for %d fps, "
                      .."window %d raster frames", #code,
                      ON and "ARMED" or "OFF (calibration run)", FPS, WIN))
      st = "wait"; return
    end
    if st == "wait" then
      local fl = SP:read_u32(CGFLAG)
      if fl == 0xEE then
        local e = SP:read_u32(CLK_ERR)
        P("clk_init REFUSED: CLK_ERR="..e..(e == 1 and
          " (CRTC is not in a 31.5 kHz mode, so HFREQ=31500 would be wrong)" or
          e == 2 and " (fps*VTOTAL does not fit the 16-bit accumulator)" or ""))
        M:exit(); return
      end
      if fl ~= 1 then
        if T() > 60 then P("TIMEOUT: the gate never started"); M:exit() end
        return
      end
      f_ready = n; st = "settle"; return
    end
    if st == "settle" then
      if n < f_ready + SETTLE then return end
      f0, t0 = n, T()
      c0 = SP:read_u32(CGCNT)
      v0 = SP:read_u32(CLK_VDISP)
      p0 = SP:read_u32(CLK_PACE)
      last_pace, last_pace_f = p0, n
      if ON then
        P(string.format("armed: incr=%d (fps*VTOTAL), acc=%d, first tick "
                        .."pending", SP:read_u16(CLK_INCR),
                        SP:read_u16(CLK_ACC)))
      end
      st = "run"; return
    end
    if st == "run" then
      if ON then
        local pc = SP:read_u32(CLK_PACE)
        if pc ~= last_pace then
          -- The FIRST change is dropped.  Its interval runs from the window
          -- opening rather than from a tick, so it measures where the window
          -- happened to start and would show up as a spurious short bucket.
          if seen_tick then
            -- More than one tick in a single refresh would mean fps above the
            -- raster rate; give it its own bucket rather than averaging it in.
            local gap = n - last_pace_f
            if pc - last_pace > 1 then gap = 0 end
            cad[gap] = (cad[gap] or 0) + 1
          end
          seen_tick = true
          last_pace, last_pace_f = pc, n
        end
      end
      if n < f0 + WIN then return end
      f1, t1 = n, T()
      c1 = SP:read_u32(CGCNT)
      v1 = SP:read_u32(CLK_VDISP)
      p1 = SP:read_u32(CLK_PACE)
      st = "done"

      local frames  = f1 - f0
      local secs    = t1 - t0
      local clocks  = secs * CPUHZ
      local iters   = c1 - c0
      local ints    = v1 - v0
      local ticks   = p1 - p0
      P(string.format("window: %d raster frames, %.6f s emulated -> %.0f "
                      .."68000 clocks", frames, secs, clocks))
      -- THE INSTRUMENT IS 2.22% FAST AND IT IS WORTH SAYING SO EVERY RUN.
      -- The CRTC registers describe a 31,500 lines/s raster of VTOTAL lines.
      -- MAME does not run it at that rate: x68k_crtc.cpp refresh_mode()
      -- computes the frame period as (scr.max_x * scr.max_y) dots with
      -- scr.max_x = m_htotal - 8, one character cell short and an INCLUSIVE
      -- rectangle bound used as a count.  So the emulated raster is fast by
      -- htotal/(htotal-8) -- 368/360 in this mode -- and every rate derived
      -- from it here is fast by the same factor.  The divider under test is
      -- built on the registers, so its HARDWARE rate is the asked-for one and
      -- what this rig can check is that it tracks whatever raster it is given.
      local vtotal = SP:read_u16(0xE80008) + 1
      local htotal = (SP:read_u16(0xE80000) + 1) * 8
      local hw_hz  = 31500 / vtotal
      local skew   = htotal / (htotal - 8)
      P(string.format("        raster period %.4f ms = %.4f Hz", 1000*secs/frames,
                      frames/secs))
      P(string.format("        the CRTC registers describe 31500/%d = %.4f Hz; "
                      .."MAME is fast by htotal/(htotal-8) = %d/%d = %.4f",
                      vtotal, hw_hz, htotal, htotal-8, skew))
      P(string.format("        loop iterations %d", iters))
      if ON then
        P(string.format("        V-DISP interrupts %d, frame ticks %d", ints,
                        ticks))
        -- The self-check that makes the rest of it worth reading: the interrupt
        -- count and the host's screen-frame count are supposed to be the SAME
        -- clock seen from two sides.  If they disagree by more than the one
        -- edge the window boundaries can straddle, the tick is not the raster.
        if math.abs(ints - frames) > 1 then
          P(string.format("FAIL: %d V-DISP interrupts over %d raster frames. "
                          .."The tick is not coming from the raster.", ints,
                          frames))
          M:exit(); return
        end
        -- Two numbers, and confusing them is the whole trap.  The measured rate
        -- is against MAME's fast raster; dividing the skew out gives the rate
        -- the same code produces on a machine whose raster matches its own
        -- registers, which is the number the player is judged on.
        local meas = ticks/secs
        P(string.format("        measured rate %.6f fps against MAME's raster "
                        .."(%+.0f ppm vs the asked %d)", meas,
                        1e6*(meas/FPS - 1), FPS))
        P(string.format("        de-skewed    %.6f fps  ->  %+.1f ppm from %d, "
                        .."which is the tick quantisation of %d ticks and not "
                        .."drift", meas/skew, 1e6*(meas/skew/FPS - 1), FPS,
                        ticks))
        local ks = {}
        for k in pairs(cad) do ks[#ks+1] = k end
        table.sort(ks)
        local s = ""
        for _,k in ipairs(ks) do
          s = s .. string.format("%d:%d ", k, cad[k])
        end
        P("        cadence, refreshes per frame tick: "..s)
      end

      local fh = io.open(OUT, "w")
      fh:write(string.format("on %d\nfps %d\nframes %d\nsecs %.15g\n"
                             .."clocks %.15g\niters %d\nints %d\nticks %d\n"
                             .."vtotal %d\nhtotal %d\nhw_hz %.15g\nskew %.15g\n",
                             ON and 1 or 0, FPS, frames, secs, clocks, iters,
                             ints, ticks, vtotal, htotal, hw_hz, skew))
      for k, v in pairs(cad) do fh:write(string.format("cad %d %d\n", k, v)) end
      fh:close()
      P("counts -> "..OUT)
      P("done")
      M:exit(); return
    end
  end)
  if not ok then print("[CLK] LUA ERROR: "..tostring(err)); M:exit() end
end)