trac-inf.lmt /size: 13 Kb    last modification: 2023-12-21 09:44
1if not modules then modules = { } end modules ['trac-inf'] = {
2    version   = 1.001,
3    comment   = "companion to trac-inf.mkiv",
4    author    = "Hans Hagen, PRAGMA-ADE, Hasselt NL",
5    copyright = "PRAGMA ADE / ConTeXt Development Team",
6    license   = "see context related readme files"
7}
8
9-- As we want to protect the global tables, we no longer store the timing
10-- in the tables themselves but in a hidden timers table so that we don't
11-- get warnings about assignments. This is more efficient than using rawset
12-- and rawget.
13
14local type, tonumber, select = type, tonumber, select
15local format, lower, find, gsub, rep = string.format, string.lower, string.find, string.gsub, string.rep
16local concat = table.concat
17local clock  = os.gettimeofday or os.clock -- should go in environment
18
19local setmetatableindex = table.setmetatableindex
20local serialize         = table.serialize
21local formatters        = string.formatters
22
23statistics              = statistics or { }
24local statistics        = statistics
25
26statistics.enable       = true
27statistics.threshold    = 0.01
28
29local statusinfo, n, registered, timers = { }, 0, { }, { }
30
31setmetatableindex(timers,function(t,k)
32    local v = { timing = 0, loadtime = 0, offset = 0 }
33    t[k] = v
34    return v
35end)
36
37local function hastiming(instance)
38    return instance and timers[instance]
39end
40
41local function resettiming(instance)
42    timers[instance or "notimer"] = { timing = 0, loadtime = 0, offset = 0 }
43end
44
45-- local ticks   = clock
46-- local seconds = function(n) return n or 0 end
47
48local ticks   = lua.getpreciseticks
49local seconds = lua.getpreciseseconds
50
51local function starttiming(instance,reset)
52    local timer = timers[instance or "notimer"]
53    local it = timer.timing
54    if reset then
55        it = 0
56        timer.loadtime = 0
57    end
58    if it == 0 then
59        timer.starttime = ticks()
60        if not timer.loadtime then
61            timer.loadtime = 0
62        end
63    end
64    timer.timing = it + 1
65end
66
67local function stoptiming(instance)
68    local timer = timers[instance or "notimer"]
69    local it = timer.timing
70    if it > 1 then
71        timer.timing = it - 1
72    else
73        local starttime = timer.starttime
74        if starttime and starttime > 0 then
75            local stoptime  = ticks()
76            local loadtime  = stoptime - starttime
77            timer.stoptime  = stoptime
78            timer.loadtime  = timer.loadtime + loadtime
79            timer.timing    = 0
80            timer.starttime = 0
81        end
82    end
83end
84
85local function benchmarktimer(instance)
86    local timer = timers[instance or "notimer"]
87    local it = timer.timing
88    if it > 1 then
89        timer.timing = it - 1
90    else
91        local starttime = timer.starttime
92        if starttime and starttime > 0 then
93            timer.offset = ticks() - starttime
94        else
95            timer.offset = 0
96        end
97    end
98end
99
100local function elapsed(instance)
101    if type(instance) == "number" then
102        return instance
103    else
104        local timer = timers[instance or "notimer"]
105        return timer and seconds(timer.loadtime - 2*(timer.offset or 0)) or 0
106    end
107end
108
109local function currenttime(instance)
110    if type(instance) == "number" then
111        return instance
112    else
113        local timer = timers[instance or "notimer"]
114        local it = timer.timing
115        if it > 1 then
116            -- whatever
117        else
118            local starttime = timer.starttime
119            if starttime and starttime > 0 then
120                return seconds(timer.loadtime + ticks() - starttime -  2*(timer.offset or 0))
121            end
122        end
123        return 0
124    end
125end
126
127local function elapsedtime(instance)
128    return format("%0.3f",elapsed(instance))
129end
130
131local function elapsedindeed(instance)
132    return elapsed(instance) > statistics.threshold
133end
134
135local function elapsedseconds(instance,rest) -- returns nil if 0 seconds
136    if elapsedindeed(instance) then
137        return format("%0.3f seconds %s", elapsed(instance),rest or "")
138    end
139end
140
141statistics.hastiming      = hastiming
142statistics.resettiming    = resettiming
143statistics.starttiming    = starttiming
144statistics.stoptiming     = stoptiming
145statistics.currenttime    = currenttime
146statistics.elapsed        = elapsed
147statistics.elapsedtime    = elapsedtime
148statistics.elapsedindeed  = elapsedindeed
149statistics.elapsedseconds = elapsedseconds
150statistics.benchmarktimer = benchmarktimer
151
152-- general function .. we might split this module
153
154function statistics.register(tag,fnc)
155    if statistics.enable and type(fnc) == "function" then
156        -- second load can overload:
157        local rt = registered[tag] or (#statusinfo + 1)
158        statusinfo[rt] = { tag, fnc }
159        registered[tag] = rt
160        if #tag > n then n = #tag end
161    end
162end
163
164local report = logs.reporter("mkiv lua stats")
165
166function statistics.show()
167    if statistics.enable then
168        -- this code will move
169        local register = statistics.register
170        register("used platform", function()
171            return format("%s, type: %s, binary subtree: %s",
172                os.platform or "unknown",os.type or "unknown", environment.texos or "unknown")
173        end)
174        register("used engine", function()
175            return format("%s version: %s, functionality level: %s, format id: %s, compiler: %s",
176                LUATEXENGINE, LUATEXVERBOSE, LUATEXFUNCTIONALITY, LUATEXFORMATID, status.used_compiler)
177        end)
178        register("tex properties", function()
179            local t = status.gethashstate()
180            local l = status.getlookupstate()
181            local m = status.gettexstate()
182            return format("%s hash slots used of %s, %s control sequences, approximate memory usage: %i MB",
183                t.top, t.max, l.ptr, m.approximate // (1024 * 1024))
184        end)
185        register("callbacks", statistics.callbacks)
186        -- so far
187        register("lua properties",function()
188         -- local hash = lua.gethashchars()
189            local mask = load([[τεχ = 1]]) and "utf" or "ascii"
190         -- return format("engine: %s %s, used memory: %s, hash chars: min(%i,40), symbol mask: %s (%s)",
191            return format("engine: %s %s, used memory: %s, symbol mask: %s (%s)",
192                "lua", LUAVERSION, statistics.memused(), mask, mask == "utf" and "τεχ" or "tex")
193        end)
194        register("runtime",statistics.runtime)
195        logs.newline() -- initial newline
196        for i=1,#statusinfo do
197            local s = statusinfo[i]
198            local r = s[2]()
199            if r then
200                report("%s: %s",s[1],r)
201            end
202        end
203     -- logs.newline() -- final newline
204        statistics.enable = false
205    end
206end
207
208function statistics.memused() -- no math.round yet -)
209    local round    = math.round or math.floor
210    local luastate = status.getluastate()
211    return format("%s MB, ctx: %s MB, max: %s MB",
212        round(collectgarbage("count")//1024),
213        round(luastate.statebytes//1048576),
214        luastate.statebytesmax and round(luastate.statebytesmax//1048576) or "unknown"
215    )
216end
217
218starttiming(statistics)
219
220function statistics.formatruntime(runtime) -- indirect so it can be overloaded and
221    return format("%s seconds", runtime)   -- indeed that happens in cure-uti.lua
222end
223
224function statistics.runtime()
225    stoptiming(statistics)
226 -- stoptiming(statistics) -- somehow we can start the timer twice, but where
227    local runtime = lua.getruntime and lua.getruntime() or elapsedtime(statistics)
228    return statistics.formatruntime(runtime)
229end
230
231local report = logs.reporter("system")
232
233function statistics.timed(action,all)
234    starttiming("run")
235    action()
236    stoptiming("run")
237    local runtime = tonumber(elapsedtime("run"))
238    if all then
239        local alltime = tonumber(lua.getruntime and lua.getruntime() or elapsedtime(statistics))
240        if alltime and alltime > 0 then
241            report("total runtime: %0.3f seconds of %0.3f seconds",runtime,alltime)
242            return
243        end
244    end
245    report("total runtime: %0.3f seconds",runtime)
246end
247
248-- goodie
249
250function statistics.tracefunction(base,tag,...)
251    for i=1,select("#",...) do
252        local name = select(i,...)
253        local stat = { }
254        local func = base[name]
255        setmetatableindex(stat,function(t,k) t[k] = 0 return 0 end)
256        base[name] = function(n,k,v) stat[k] = stat[k] + 1 return func(n,k,v) end
257        statistics.register(formatters["%s.%s"](tag,name),function() return serialize(stat,"calls") end)
258    end
259end
260
261-- now here
262
263status.iocodes = setmetatableindex(tex.getiovalues(), function() return "unknown" end)
264
265local report = logs.reporter("system")
266
267local list   = {
268    "string", "pool", "hash", "lookup", "node", "token",
269    "buffer", "input", "file", "nest", "parameter", "save", "font", "language", "mark", "insert",
270 -- "extra", "sparse",
271}
272
273local function show(data,fields)
274    local line    = rep("-",3+11*#list)
275    local columns = rep("%11s",#list)
276    report("")
277    report("%w%s",2,line)
278    report("%w"..columns,5,unpack(list))
279    report("%w%s",2,line)
280    for i=1,#fields do
281        local f = fields[i]
282        if f then
283            local t = { }
284            for i=1,#list do
285                local n = data[list[i].."state"][f]
286                t[i] = n < 0 and formatters["%w"](11) or formatters["%11i"](n)
287            end
288            report("  %3s"..columns,f,unpack(t))
289        else
290            report("")
291        end
292    end
293    report("%w%s",2,line)
294    report("")
295end
296
297function statistics.showmemory(when)
298    report("")
299    report("memory configuration")
300    show(status.list(), { "max", "min", "set", "stp" })
301end
302
303local registered = false
304local enabled    = false
305local finished   = false
306
307local status = status -- needed for --sandbox
308local mplib  = mplib  -- needed for --sandbox
309
310function statistics.showusage(when)
311    if finished and when == "finish" then
312        return
313    else
314        finished = true
315    end
316    local s = status.list()
317    local c = status.getcallbackstate() -- status.callbacks
318    local m = mplib.getcallbackstate()
319    local b = backends.getcallbackstate()
320    --
321    local estatus = s.expandstate
322    local tstatus = s.texstate
323    local lstatus = s.luastate
324    local rstatus = s.readstate
325    --
326    local pstatus = logs.private.getpagetiming()
327    --
328    local iocode  = status.iocodes[rstatus.iocode]
329    --
330    local mpinstances, mpmemory = metapost.getstatistics(true)
331    --
332    report("")
333    if when == "finish" then
334        report("status after finishing run")
335    else
336        report("status after shipping out page %s",tex.getcount("realpageno"))
337    end
338    show(s, { "max", "min", "set", "stp", false, "mem", "all", false, "ini", "ptr", "top" })
339    report("  current input type    : %s", iocode)
340    if iocode == "file" then
341        report("  current file name     : %s", rstatus.filename or "")
342        report("  current line number   : %s", rstatus.linenumber)
343    end
344    report("")
345    report("  approximate memory    : %s (%s MB)", tstatus.approximate, tstatus.approximate // 1048576)
346    report("")
347    report("  expansion depth       : min: %s, max: %s, set: %s, top: %s", estatus.min, estatus.max, estatus.set, estatus.top)
348    report("")
349    report("  luabytecode registers : %s", lstatus.bytecodes)
350    report("  luabytecode bytes     : %s (%s MB)", lstatus.bytecodebytes, lstatus.bytecodebytes // 1048576)
351    report("  luastate bytes now    : %s (%s MB)", lstatus.statebytes,    lstatus.statebytes    // 1048576)
352    report("  luastate bytes max    : %s (%s MB)", lstatus.statebytesmax, lstatus.statebytesmax // 1048576)
353    report("")
354    report("  file callbacks        : %s", c.file)
355    report("  saved callbacks       : %s", c.saved)
356    report("  direct callbacks      : %s", c.direct)
357    report("  function callbacks    : %s", c["function"])
358    report("  value callbacks       : %s", c.value)
359    report("  message callbacks     : %s", c.message)
360    report("  bytecode callbacks    : %s", c.bytecode)
361    report("")
362    report("  mp instances          : %s", mpinstances)
363    report("  mp estimated memory   : %s (%s MB)", mpmemory, mpmemory // 1048576)
364    report("  mp file callbacks     : %s", m.file)
365    report("  mp text callbacks     : %s", m.text)
366    report("  mp script callbacks   : %s", m.script)
367    report("  mp log callbacks      : %s", m.log)
368    report("")
369    report("  total callbacks       : %s", c.count)
370    report("  mp total callbacks    : %s", m.count)
371    report("  backend callbacks     : %s", b.count)
372    report("")
373    if pstatus then
374        report("  page numbers          : realpage %s, userpage %s, subpage %s",pstatus.page.real,pstatus.page.user,pstatus.page.sub)
375        report("  page timing           : total %0.03f, page %0.03f, average %0.03f",pstatus.time.elapsed,pstatus.time.page,pstatus.time.average)
376        report("")
377    end
378end
379
380trackers.register("system.usage", function(v)
381    if v and not registered then
382        logs.private.enablepagetiming()
383        if v ~= "summary" then
384            luatex.registerpageactions(function()
385                if enabled then
386                    statistics.showusage("page")
387                end
388            end)
389        end
390        luatex.registerstopactions(function()
391            if enabled then
392                statistics.showusage("finish")
393            end
394        end)
395        registered = true
396    end
397    enabled = v
398end)
399
400-- can't be done here:
401--
402-- luatex.registerstopactions(function()
403--     if not enabled then
404--         logs.push("logfile")
405--         statistics.showusage("finish")
406--         logs.pop()
407--     end
408-- end)
409