if not modules then modules = { } end modules ['trac-inf'] = { version = 1.001, comment = "companion to trac-inf.mkiv", author = "Hans Hagen, PRAGMA-ADE, Hasselt NL", copyright = "PRAGMA ADE / ConTeXt Development Team", license = "see context related readme files" } -- As we want to protect the global tables, we no longer store the timing -- in the tables themselves but in a hidden timers table so that we don't -- get warnings about assignments. This is more efficient than using rawset -- and rawget. local type, tonumber, select = type, tonumber, select local format, lower, find, gsub, rep = string.format, string.lower, string.find, string.gsub, string.rep local concat = table.concat local clock = os.gettimeofday or os.clock -- should go in environment local setmetatableindex = table.setmetatableindex local serialize = table.serialize local formatters = string.formatters statistics = statistics or { } local statistics = statistics statistics.enable = true statistics.threshold = 0.01 local statusinfo, n, registered, timers = { }, 0, { }, { } setmetatableindex(timers,function(t,k) local v = { timing = 0, loadtime = 0, offset = 0 } t[k] = v return v end) local function hastiming(instance) return instance and timers[instance] end local function resettiming(instance) timers[instance or "notimer"] = { timing = 0, loadtime = 0, offset = 0 } end -- local ticks = clock -- local seconds = function(n) return n or 0 end local ticks = lua.getpreciseticks local seconds = lua.getpreciseseconds local function starttiming(instance,reset) local timer = timers[instance or "notimer"] local it = timer.timing if reset then it = 0 timer.loadtime = 0 end if it == 0 then timer.starttime = ticks() if not timer.loadtime then timer.loadtime = 0 end end timer.timing = it + 1 end local function stoptiming(instance) local timer = timers[instance or "notimer"] local it = timer.timing if it > 1 then timer.timing = it - 1 else local starttime = timer.starttime if starttime and starttime > 0 then local stoptime = ticks() local loadtime = stoptime - starttime timer.stoptime = stoptime timer.loadtime = timer.loadtime + loadtime timer.timing = 0 timer.starttime = 0 end end end local function benchmarktimer(instance) local timer = timers[instance or "notimer"] local it = timer.timing if it > 1 then timer.timing = it - 1 else local starttime = timer.starttime if starttime and starttime > 0 then timer.offset = ticks() - starttime else timer.offset = 0 end end end local function elapsed(instance) if type(instance) == "number" then return instance else local timer = timers[instance or "notimer"] return timer and seconds(timer.loadtime - 2*(timer.offset or 0)) or 0 end end local function currenttime(instance) if type(instance) == "number" then return instance else local timer = timers[instance or "notimer"] local it = timer.timing if it > 1 then -- whatever else local starttime = timer.starttime if starttime and starttime > 0 then return seconds(timer.loadtime + ticks() - starttime - 2*(timer.offset or 0)) end end return 0 end end local function elapsedtime(instance) return format("%0.3f",elapsed(instance)) end local function elapsedindeed(instance) return elapsed(instance) > statistics.threshold end local function elapsedseconds(instance,rest) -- returns nil if 0 seconds if elapsedindeed(instance) then return format("%0.3f seconds %s", elapsed(instance),rest or "") end end statistics.hastiming = hastiming statistics.resettiming = resettiming statistics.starttiming = starttiming statistics.stoptiming = stoptiming statistics.currenttime = currenttime statistics.elapsed = elapsed statistics.elapsedtime = elapsedtime statistics.elapsedindeed = elapsedindeed statistics.elapsedseconds = elapsedseconds statistics.benchmarktimer = benchmarktimer -- general function .. we might split this module function statistics.register(tag,fnc) if statistics.enable and type(fnc) == "function" then -- second load can overload: local rt = registered[tag] or (#statusinfo + 1) statusinfo[rt] = { tag, fnc } registered[tag] = rt if #tag > n then n = #tag end end end local report = logs.reporter("mkiv lua stats") function statistics.show() if statistics.enable then -- this code will move local register = statistics.register register("used platform", function() return format("%s, type: %s, binary subtree: %s", os.platform or "unknown",os.type or "unknown", environment.texos or "unknown") end) register("used engine", function() return format("%s version: %s, functionality level: %s, format id: %s, compiler: %s", LUATEXENGINE, LUATEXVERBOSE, LUATEXFUNCTIONALITY, LUATEXFORMATID, status.used_compiler) end) register("tex properties", function() local t = status.gethashstate() local l = status.getlookupstate() local m = status.gettexstate() return format("%s hash slots used of %s, %s control sequences, approximate memory usage: %i MB", t.top, t.max, l.ptr, m.approximate // (1024 * 1024)) end) register("callbacks", statistics.callbacks) -- so far register("lua properties",function() -- local hash = lua.gethashchars() local mask = load([[τεχ = 1]]) and "utf" or "ascii" -- return format("engine: %s %s, used memory: %s, hash chars: min(%i,40), symbol mask: %s (%s)", return format("engine: %s %s, used memory: %s, symbol mask: %s (%s)", "lua", LUAVERSION, statistics.memused(), mask, mask == "utf" and "τεχ" or "tex") end) register("runtime",statistics.runtime) logs.newline() -- initial newline for i=1,#statusinfo do local s = statusinfo[i] local r = s[2]() if r then report("%s: %s",s[1],r) end end -- logs.newline() -- final newline statistics.enable = false end end function statistics.memused() -- no math.round yet -) local round = math.round or math.floor local luastate = status.getluastate() return format("%s MB, ctx: %s MB, max: %s MB", round(collectgarbage("count")//1024), round(luastate.statebytes//1048576), luastate.statebytesmax and round(luastate.statebytesmax//1048576) or "unknown" ) end starttiming(statistics) function statistics.formatruntime(runtime) -- indirect so it can be overloaded and return format("%s seconds", runtime) -- indeed that happens in cure-uti.lua end function statistics.runtime() stoptiming(statistics) -- stoptiming(statistics) -- somehow we can start the timer twice, but where local runtime = lua.getruntime and lua.getruntime() or elapsedtime(statistics) return statistics.formatruntime(runtime) end local report = logs.reporter("system") function statistics.timed(action,all) starttiming("run") action() stoptiming("run") local runtime = tonumber(elapsedtime("run")) if all then local alltime = tonumber(lua.getruntime and lua.getruntime() or elapsedtime(statistics)) if alltime and alltime > 0 then report("total runtime: %0.3f seconds of %0.3f seconds",runtime,alltime) return end end report("total runtime: %0.3f seconds",runtime) end -- goodie function statistics.tracefunction(base,tag,...) for i=1,select("#",...) do local name = select(i,...) local stat = { } local func = base[name] setmetatableindex(stat,function(t,k) t[k] = 0 return 0 end) base[name] = function(n,k,v) stat[k] = stat[k] + 1 return func(n,k,v) end statistics.register(formatters["%s.%s"](tag,name),function() return serialize(stat,"calls") end) end end -- now here status.iocodes = setmetatableindex(tex.getiovalues(), function() return "unknown" end) local report = logs.reporter("system") local list = { "string", "pool", "hash", "lookup", "node", "token", "buffer", "input", "file", "nest", "parameter", "save", "font", "language", "mark", "insert", -- "extra", "sparse", } local function show(data,fields) local line = rep("-",3+11*#list) local columns = rep("%11s",#list) report("") report("%w%s",2,line) report("%w"..columns,5,unpack(list)) report("%w%s",2,line) for i=1,#fields do local f = fields[i] if f then local t = { } for i=1,#list do local n = data[list[i].."state"][f] t[i] = n < 0 and formatters["%w"](11) or formatters["%11i"](n) end report(" %3s"..columns,f,unpack(t)) else report("") end end report("%w%s",2,line) report("") end function statistics.showmemory(when) report("") report("memory configuration") show(status.list(), { "max", "min", "set", "stp" }) end local registered = false local enabled = false local finished = false local status = status -- needed for --sandbox local mplib = mplib -- needed for --sandbox function statistics.showusage(when) if finished and when == "finish" then return else finished = true end local s = status.list() local c = status.getcallbackstate() -- status.callbacks local m = mplib.getcallbackstate() local b = backends.getcallbackstate() -- local estatus = s.expandstate local tstatus = s.texstate local lstatus = s.luastate local rstatus = s.readstate -- local pstatus = logs.private.getpagetiming() -- local iocode = status.iocodes[rstatus.iocode] -- local mpinstances, mpmemory = metapost.getstatistics(true) -- report("") if when == "finish" then report("status after finishing run") else report("status after shipping out page %s",tex.getcount("realpageno")) end show(s, { "max", "min", "set", "stp", false, "mem", "all", false, "ini", "ptr", "top" }) report(" current input type : %s", iocode) if iocode == "file" then report(" current file name : %s", rstatus.filename or "") report(" current line number : %s", rstatus.linenumber) end report("") report(" approximate memory : %s (%s MB)", tstatus.approximate, tstatus.approximate // 1048576) report("") report(" expansion depth : min: %s, max: %s, set: %s, top: %s", estatus.min, estatus.max, estatus.set, estatus.top) report("") report(" luabytecode registers : %s", lstatus.bytecodes) report(" luabytecode bytes : %s (%s MB)", lstatus.bytecodebytes, lstatus.bytecodebytes // 1048576) report(" luastate bytes now : %s (%s MB)", lstatus.statebytes, lstatus.statebytes // 1048576) report(" luastate bytes max : %s (%s MB)", lstatus.statebytesmax, lstatus.statebytesmax // 1048576) report("") report(" file callbacks : %s", c.file) report(" saved callbacks : %s", c.saved) report(" direct callbacks : %s", c.direct) report(" function callbacks : %s", c["function"]) report(" value callbacks : %s", c.value) report(" message callbacks : %s", c.message) report(" bytecode callbacks : %s", c.bytecode) report("") report(" mp instances : %s", mpinstances) report(" mp estimated memory : %s (%s MB)", mpmemory, mpmemory // 1048576) report(" mp file callbacks : %s", m.file) report(" mp text callbacks : %s", m.text) report(" mp script callbacks : %s", m.script) report(" mp log callbacks : %s", m.log) report("") report(" total callbacks : %s", c.count) report(" mp total callbacks : %s", m.count) report(" backend callbacks : %s", b.count) report("") if pstatus then report(" page numbers : realpage %s, userpage %s, subpage %s",pstatus.page.real,pstatus.page.user,pstatus.page.sub) report(" page timing : total %0.03f, page %0.03f, average %0.03f",pstatus.time.elapsed,pstatus.time.page,pstatus.time.average) report("") end end trackers.register("system.usage", function(v) if v and not registered then logs.private.enablepagetiming() if v ~= "summary" then luatex.registerpageactions(function() if enabled then statistics.showusage("page") end end) end luatex.registerstopactions(function() if enabled then statistics.showusage("finish") end end) registered = true end enabled = v end) -- can't be done here: -- -- luatex.registerstopactions(function() -- if not enabled then -- logs.push("logfile") -- statistics.showusage("finish") -- logs.pop() -- end -- end)