path: root/tex/context/base/mkxl/trac-inf.lmt

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.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)