lualibs-trac-inf.lua

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 = string.format, string.lower, string.find
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

if os.type ~= "windows" then

    -- doesn't work well yet on unix (system time vs process time so a mtxrun
    -- timing with nested call gives the wrong result)

elseif lua.getpreciseticks then

    ticks   = lua.getpreciseticks
    seconds = lua.getpreciseseconds

elseif FFISUPPORTED then

    -- Do we really care when not in luametatex? For now we do, so:

    local okay, kernel = pcall(ffi.load,"kernel32")

    if kernel then

        local tonumber = ffi.number or tonumber

        ffi.cdef[[
            int QueryPerformanceFrequency(int64_t *lpFrequency);
            int QueryPerformanceCounter(int64_t *lpPerformanceCount);
        ]]

        local target = ffi.new("__int64[1]")

        ticks = function()
            if kernel.QueryPerformanceCounter(target) == 1 then
                return tonumber(target[0])
            else
                return 0
            end
        end

        local target = ffi.new("__int64[1]")

        seconds = function(ticks)
            if kernel.QueryPerformanceFrequency(target) == 1 then
                return ticks / tonumber(target[0])
            else
                return 0
            end
        end

    end

else

    -- excessive timing costs some 1-2 percent runtime

end


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
        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, banner: %s",
                LUATEXENGINE, LUATEXVERSION, LUATEXFUNCTIONALITY, lower(status.banner))
        end)
        register("used hash slots", function()
            return format("%s of %s + %s", status.cs_count, status.hash_size,status.hash_extra)
        end)
        register("callbacks", statistics.callbacks)
        if JITSUPPORTED then
            local jitstatus = jit.status
            if jitstatus then
                local jitstatus = { jitstatus() }
                if jitstatus[1] then
                    register("luajit options", concat(jitstatus," ",2))
                end
            end
        end
        -- so far
        register("lua properties",function()
            local hash = 2^status.luatex_hashchars
            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)",
                jit and "luajit" or "lua", LUAVERSION, statistics.memused(), hash, 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
    return format("%s MB, ctx: %s MB, max: %s MB",
        round(collectgarbage("count")/1000),
        round(status.luastate_bytes/1000000),
        status.luastate_bytes_max and round(status.luastate_bytes_max/1000000) 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

function status.getreadstate()
    return {
        filename   = status.filename   or "?",
        linenumber = status.linenumber or 0,
        iocode     = status.inputid    or 0,
    }
end