-- Voxel world mode: the instrumentation core. -- -- Ships DARK. Every entry point is one boolean test away from doing -- nothing, and the boolean is false unless a run explicitly asks for -- measurement (DS_PERF in the environment, or a ds_perf.flag file in the -- save directory for a device that has no environment to set). A mod that -- measures itself in every player's session is a mod that costs every -- player the measurement, so the default has to be off and the off path -- has to be free. -- -- What it measures, and why those three things: -- -- * LABELS -- named spans (a bake, a mesh build, a shader compile), -- accumulated as {n, total, max}. `max` is the one that matters: a -- bake that costs 40ms ONCE is a visible hitch, and an average hides -- it completely. -- * FRAMES -- a ring of the last N whole-frame times, stamped once per -- rendered frame. Frame time is the only number the player actually -- experiences; every label total is a hypothesis about which frames. -- * COUNTERS -- plain integers a caller bumps (sun-pass redraws, atlas -- rebakes). Cheaper than a span when the question is "how often", -- not "how long". -- -- Spans are wall time, and on a GPU that means submission time, not -- completion time -- the driver is free to finish the work later. So a -- GPU-side saving shows up in the FRAME numbers rather than in the label -- for the pass that caused it, and both are reported. local Perf = {} local clock = (love and love.timer and love.timer.getTime) or os.clock -- Read through pcall: the loader's sandbox does not hand a mod `os`, and -- instrumentation must never be the reason the mod fails to load. Same -- shape as OverworldBattle's DS_BATTLE_DEBUG probe. local function envFlag(name) local ok, value = pcall(function() return os.getenv(name) end) if not ok then return nil end if value == nil or value == "" or value == "0" then return nil end return value end local function flagFile() if not (love and love.filesystem and love.filesystem.getInfo) then return false end local ok, info = pcall(love.filesystem.getInfo, "ds_perf.flag") return ok and info ~= nil end Perf.enabled = (envFlag("DS_PERF") ~= nil) or flagFile() Perf.labels = {} -- label -> { n, total, max } Perf.order = {} -- insertion order, so a report reads chronologically Perf.counters = {} -- name -> integer Perf.frames = {} -- ring of frame times, seconds Perf.frameCount = 0 Perf.RING = 4096 -- The segment a frame belongs to ("map:ROUTE_1:first"). A benchmark -- names the phase it is driving; every frame and every label span -- recorded while that name is set is attributed to it, which is what -- turns "the walk was slow" into "the walk was slow ONLY on the frames -- right after ROUTE_1 came into view". Perf.segment = nil Perf.segments = {} -- name -> { frames = {}, labels = {}, order = {} } local function segmentEntry() local name = Perf.segment if not name then return nil end local s = Perf.segments[name] if not s then s = { name = name, frames = {}, labels = {}, order = {} } Perf.segments[name] = s Perf.segments[#Perf.segments + 1] = s -- array half preserves order end return s end function Perf.setSegment(name) Perf.segment = name if name then segmentEntry() end end -- ---------------------------------------------------------------- spans -- -- Call shape at the measured site: -- -- local t0 = Perf.now() -- ... the work ... -- Perf.add("TerrainAtlas.staticAtlas", t0) -- -- When disabled, now() returns nil and add() returns on the nil -- two -- function calls and a branch, no table touched, no string built. Sites -- that would run thousands of times a frame (per draw call, per vertex) -- are still too hot for that and are deliberately NOT instrumented; the -- frame ring covers them in aggregate. function Perf.now() if not Perf.enabled then return nil end return clock() end local function bump(store, order, label, dt) local s = store[label] if not s then s = { n = 0, total = 0, max = 0 } store[label] = s order[#order + 1] = label end s.n = s.n + 1 s.total = s.total + dt if dt > s.max then s.max = dt end end function Perf.add(label, t0) if t0 == nil then return end local dt = clock() - t0 bump(Perf.labels, Perf.order, label, dt) local seg = segmentEntry() if seg then bump(seg.labels, seg.order, label, dt) end end -- Wrap a function in a table, in place. Used by drivers to instrument -- module internals they do not own; the mod's own code calls now()/add() -- directly so the label is visible at the site. function Perf.wrap(tbl, name, label) local orig = tbl and tbl[name] if not orig then return false end tbl[name] = function(...) if not Perf.enabled then return orig(...) end local t0 = clock() local a, b, c, d = orig(...) Perf.add(label or name, t0) return a, b, c, d end return true end -- ------------------------------------------------------------- counters function Perf.count(name, by) if not Perf.enabled then return end Perf.counters[name] = (Perf.counters[name] or 0) + (by or 1) end -- --------------------------------------------------------------- frames -- -- Called once per RENDERED frame (the endFrame seam), not once per -- logic update: a scripted run can step the game many times per render, -- and a frame the player never saw cannot have hitched for them. local lastFrame = nil function Perf.frame() if not Perf.enabled then return end local t = clock() if lastFrame then local dt = t - lastFrame local n = Perf.frameCount + 1 Perf.frameCount = n Perf.frames[(n - 1) % Perf.RING + 1] = dt local seg = segmentEntry() if seg then seg.frames[#seg.frames + 1] = dt end end lastFrame = t end -- Discard the pending frame stamp: after a long blocking operation the -- next frame delta would include it and libel the renderer. function Perf.resync() lastFrame = Perf.enabled and clock() or nil end -- ------------------------------------------------------------ reporting local function percentile(sorted, p) local n = #sorted if n == 0 then return 0 end local i = math.ceil(p * n) if i < 1 then i = 1 end if i > n then i = n end return sorted[i] end -- Frame statistics in MILLISECONDS. p95/p99 rather than the average -- because smoothness is a tail property: a run that averages 9ms and -- spikes to 60ms four times reads as stuttering, and its average reads -- as fine. function Perf.frameStats(list) local src = list or Perf.frames local sorted = {} for i = 1, #src do sorted[i] = src[i] * 1000 end table.sort(sorted) local n = #sorted local total = 0 for i = 1, n do total = total + sorted[i] end local over16, over33 = 0, 0 for i = 1, n do if sorted[i] > 16.7 then over16 = over16 + 1 end if sorted[i] > 33.3 then over33 = over33 + 1 end end return { n = n, avg = n > 0 and total / n or 0, p50 = percentile(sorted, 0.50), p95 = percentile(sorted, 0.95), p99 = percentile(sorted, 0.99), worst = n > 0 and sorted[n] or 0, over16 = over16, over33 = over33, } end function Perf.reset() Perf.labels, Perf.order = {}, {} Perf.counters = {} Perf.frames, Perf.frameCount = {}, 0 Perf.segments = {} Perf.segment = nil lastFrame = nil end local function sortedLabels(store, order) local out = {} for _, lbl in ipairs(order) do out[#out + 1] = lbl end table.sort(out, function(a, b) return store[a].total > store[b].total end) return out end function Perf.printReport(title) print(("[perf] ==== %s ===="):format(tostring(title or "report"))) local f = Perf.frameStats() print(("[perf] frames n=%d avg=%.2fms p50=%.2f p95=%.2f p99=%.2f worst=%.2f >16.7ms=%d >33.3ms=%d") :format(f.n, f.avg, f.p50, f.p95, f.p99, f.worst, f.over16, f.over33)) for _, seg in ipairs(Perf.segments) do local s = Perf.frameStats(seg.frames) print(("[perf] seg %-28s n=%4d avg=%6.2f p95=%6.2f p99=%6.2f worst=%7.2f >16.7=%3d >33.3=%3d") :format(seg.name, s.n, s.avg, s.p95, s.p99, s.worst, s.over16, s.over33)) end print("[perf] ---- labels (ms, sorted by total) ----") for _, lbl in ipairs(sortedLabels(Perf.labels, Perf.order)) do local s = Perf.labels[lbl] print(("[perf] %-46s n=%6d total=%9.1f max=%8.2f") :format(lbl, s.n, s.total * 1000, s.max * 1000)) end local names = {} for k in pairs(Perf.counters) do names[#names + 1] = k end table.sort(names) if #names > 0 then print("[perf] ---- counters ----") end for _, k in ipairs(names) do print(("[perf] %-46s %d"):format(k, Perf.counters[k])) end end -- ------------------------------------------------------------------ json -- -- Hand-rolled rather than pulled from the engine: the report has to be -- readable by a diff tool between two runs, and that means stable key -- ORDER, which a generic serializer does not promise. local function q(s) return '"' .. tostring(s):gsub('[%c"\\]', function(c) if c == '"' then return '\\"' end if c == "\\" then return "\\\\" end return ("\\u%04x"):format(c:byte()) end) .. '"' end local function num(x) return ("%.4f"):format(x) end local function statsJson(f) return ("{\"n\":%d,\"avg\":%s,\"p50\":%s,\"p95\":%s,\"p99\":%s,\"worst\":%s,\"over16\":%d,\"over33\":%d}") :format(f.n, num(f.avg), num(f.p50), num(f.p95), num(f.p99), num(f.worst), f.over16, f.over33) end local function labelsJson(store, order) local parts = {} for _, lbl in ipairs(sortedLabels(store, order)) do local s = store[lbl] parts[#parts + 1] = ("%s:{\"n\":%d,\"total\":%s,\"max\":%s}") :format(q(lbl), s.n, num(s.total * 1000), num(s.max * 1000)) end return "{" .. table.concat(parts, ",") .. "}" end function Perf.toJson(meta) local parts = {} parts[#parts + 1] = "{" parts[#parts + 1] = "\"meta\":{" local m = {} for k, v in pairs(meta or {}) do m[#m + 1] = q(k) .. ":" .. (type(v) == "number" and num(v) or q(v)) end table.sort(m) parts[#parts + 1] = table.concat(m, ",") .. "}," parts[#parts + 1] = "\"frames\":" .. statsJson(Perf.frameStats()) .. "," parts[#parts + 1] = "\"segments\":{" local segs = {} for _, seg in ipairs(Perf.segments) do segs[#segs + 1] = q(seg.name) .. ":{\"frames\":" .. statsJson(Perf.frameStats(seg.frames)) .. ",\"labels\":" .. labelsJson(seg.labels, seg.order) .. "}" end parts[#parts + 1] = table.concat(segs, ",") .. "}," parts[#parts + 1] = "\"labels\":" .. labelsJson(Perf.labels, Perf.order) .. "," local cs = {} for k, v in pairs(Perf.counters) do cs[#cs + 1] = q(k) .. ":" .. v end table.sort(cs) parts[#parts + 1] = "\"counters\":{" .. table.concat(cs, ",") .. "}" parts[#parts + 1] = "}" return table.concat(parts, "") end -- Written through love.filesystem (the save directory) rather than io: -- a driver run and an Android session both have one, and neither is -- guaranteed a writable working directory. function Perf.write(name, meta) local body = Perf.toJson(meta) if love and love.filesystem then pcall(love.filesystem.createDirectory, "ds_bench") local ok = pcall(love.filesystem.write, "ds_bench/" .. name .. ".json", body) if ok then print("[perf] wrote " .. tostring(love.filesystem.getSaveDirectory()) .. "/ds_bench/" .. name .. ".json") return true end end print("[perf] JSON " .. name .. ": " .. body) return false end -- ----------------------------------------------------------- draw stats -- -- love.graphics.getStats() resets per frame, so it is only meaningful -- read at the END of a frame -- which is where Perf.frame() runs. function Perf.drawStats() if not (love and love.graphics and love.graphics.getStats) then return end local s = love.graphics.getStats() Perf.count("stat.drawcalls", s.drawcalls or 0) Perf.count("stat.canvasswitches", s.canvasswitches or 0) Perf.count("stat.shaderswitches", s.shaderswitches or 0) Perf.count("stat.frames", 1) Perf.texturememory = s.texturememory Perf.canvases = s.canvases Perf.images = s.images end return Perf