diff options
Diffstat (limited to 'Master/texmf-dist/tex/context/base/mkxl/trac-inf.lmt')
-rw-r--r-- | Master/texmf-dist/tex/context/base/mkxl/trac-inf.lmt | 425 |
1 files changed, 425 insertions, 0 deletions
diff --git a/Master/texmf-dist/tex/context/base/mkxl/trac-inf.lmt b/Master/texmf-dist/tex/context/base/mkxl/trac-inf.lmt new file mode 100644 index 00000000000..ebcd21e07af --- /dev/null +++ b/Master/texmf-dist/tex/context/base/mkxl/trac-inf.lmt @@ -0,0 +1,425 @@ +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 + +ticks = lua.getpreciseticks +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, LUATEXVERSION, 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.state_bytes//1048576), + luastate.state_bytes_max and round(luastate.state_bytes_max//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") + +function statistics.showusage(when) + 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 + report("") + local list = { + "stringstate", "poolstate", "hashstate", "lookupstate", + "nodestate", "extrastate", "tokenstate", + "bufferstate", "inputstate", "filestate", + "neststate", "parameterstate", "savestate", + "fontstate", "languagestate", "markstate", "sparsestate", + } + local fields = { "max", "min", "set", "stp", false, "mem", "all", false, "ini", "ptr", "top" } + local line = rep("-",190) + do + local t = { } + for i=1,#list do + t[i] = gsub(list[i],"state","") + end + report("%w%s",2,line) + report("%w%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s",5,unpack(t)) + report("%w%s",2,line) + end + for i=1,#fields do + local f = fields[i] + if f then + local t = { } + for i=1,#list do + local n = s[list[i]][f] + t[i] = n < 0 and formatters["%w"](11) or formatters["%11i"](n) + end + report(" %3s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s",f,unpack(t)) + else + report("") + end + end + report("%w%s",2,line) + report("") + 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.bytecode_bytes, lstatus.bytecode_bytes // 1048576) + report(" luastate bytes now : %s (%s MB)", lstatus.state_bytes, lstatus.state_bytes // 1048576) + report(" luastate bytes max : %s (%s MB)", lstatus.state_bytes_max, lstatus.state_bytes_max // 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("") + 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 + +function statistics.showmemory(when) + local s = status.list() + -- + report("") + report("memory configuration") + report("") + local list = { + "stringstate", "poolstate", "hashstate", "lookupstate", + "nodestate", "tokenstate", + "bufferstate", "inputstate", "filestate", + "neststate", "parameterstate", "savestate", + "fontstate", "languagestate", "markstate", + } + local fields = { "max", "min", "set", "stp" } + local line = rep("-",168) + do + local t = { } + for i=1,#list do + t[i] = gsub(list[i],"state","") + end + report("%w%s",2,line) + report("%w%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s",5,unpack(t)) + report("%w%s",2,line) + end + for i=1,#fields do + local f = fields[i] + if f then + local t = { } + for i=1,#list do + local n = s[list[i]][f] + t[i] = n < 0 and formatters["%w"](11) or formatters["%11i"](n) + end + report(" %3s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s%11s",f,unpack(t)) + else + report("") + end + end + report("%w%s",2,line) + report("") +end + +local registered = false +local enabled = false + +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) |