trac-inf.lua /size: 9740 b    last modification: 2021-10-28 13:50
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 = string.format, string.lower, string.find
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
45local ticks   = clock
46local seconds = function(n) return n or 0 end
47
48if os.type ~= "windows" then
49
50    -- doesn't work well yet on unix (system time vs process time so a mtxrun
51    -- timing with nested call gives the wrong result)
52
53elseif lua.getpreciseticks then
54
55    ticks   = lua.getpreciseticks
56    seconds = lua.getpreciseseconds
57
58elseif FFISUPPORTED then
59
60    -- Do we really care when not in luametatex? For now we do, so:
61
62    local okay, kernel = pcall(ffi.load,"kernel32")
63
64    if kernel then
65
66        local tonumber = ffi.number or tonumber
67
68        ffi.cdef[[
69            int QueryPerformanceFrequency(int64_t *lpFrequency);
70            int QueryPerformanceCounter(int64_t *lpPerformanceCount);
71        ]]
72
73        local target = ffi.new("__int64[1]")
74
75        ticks = function()
76            if kernel.QueryPerformanceCounter(target) == 1 then
77                return tonumber(target[0])
78            else
79                return 0
80            end
81        end
82
83        local target = ffi.new("__int64[1]")
84
85        seconds = function(ticks)
86            if kernel.QueryPerformanceFrequency(target) == 1 then
87                return ticks / tonumber(target[0])
88            else
89                return 0
90            end
91        end
92
93    end
94
95else
96
97    -- excessive timing costs some 1-2 percent runtime
98
99end
100
101
102local function starttiming(instance,reset)
103    local timer = timers[instance or "notimer"]
104    local it = timer.timing
105    if reset then
106        it = 0
107        timer.loadtime = 0
108    end
109    if it == 0 then
110        timer.starttime = ticks()
111        if not timer.loadtime then
112            timer.loadtime = 0
113        end
114    end
115    timer.timing = it + 1
116end
117
118local function stoptiming(instance)
119    local timer = timers[instance or "notimer"]
120    local it = timer.timing
121    if it > 1 then
122        timer.timing = it - 1
123    else
124        local starttime = timer.starttime
125        if starttime and starttime > 0 then
126            local stoptime  = ticks()
127            local loadtime  = stoptime - starttime
128            timer.stoptime  = stoptime
129            timer.loadtime  = timer.loadtime + loadtime
130            timer.timing    = 0
131            timer.starttime = 0
132        end
133    end
134end
135
136local function benchmarktimer(instance)
137    local timer = timers[instance or "notimer"]
138    local it = timer.timing
139    if it > 1 then
140        timer.timing = it - 1
141    else
142        local starttime = timer.starttime
143        if starttime and starttime > 0 then
144            timer.offset = ticks() - starttime
145        else
146            timer.offset = 0
147        end
148    end
149end
150
151local function elapsed(instance)
152    if type(instance) == "number" then
153        return instance
154    else
155        local timer = timers[instance or "notimer"]
156        return timer and seconds(timer.loadtime - 2*(timer.offset or 0)) or 0
157    end
158end
159
160local function currenttime(instance)
161    if type(instance) == "number" then
162        return instance
163    else
164        local timer = timers[instance or "notimer"]
165        local it = timer.timing
166        if it > 1 then
167            -- whatever
168        else
169            local starttime = timer.starttime
170            if starttime and starttime > 0 then
171                return seconds(timer.loadtime + ticks() - starttime -  2*(timer.offset or 0))
172            end
173        end
174        return 0
175    end
176end
177
178local function elapsedtime(instance)
179    return format("%0.3f",elapsed(instance))
180end
181
182local function elapsedindeed(instance)
183    return elapsed(instance) > statistics.threshold
184end
185
186local function elapsedseconds(instance,rest) -- returns nil if 0 seconds
187    if elapsedindeed(instance) then
188        return format("%0.3f seconds %s", elapsed(instance),rest or "")
189    end
190end
191
192statistics.hastiming      = hastiming
193statistics.resettiming    = resettiming
194statistics.starttiming    = starttiming
195statistics.stoptiming     = stoptiming
196statistics.currenttime    = currenttime
197statistics.elapsed        = elapsed
198statistics.elapsedtime    = elapsedtime
199statistics.elapsedindeed  = elapsedindeed
200statistics.elapsedseconds = elapsedseconds
201statistics.benchmarktimer = benchmarktimer
202
203-- general function .. we might split this module
204
205function statistics.register(tag,fnc)
206    if statistics.enable and type(fnc) == "function" then
207        local rt = registered[tag] or (#statusinfo + 1)
208        statusinfo[rt] = { tag, fnc }
209        registered[tag] = rt
210        if #tag > n then n = #tag end
211    end
212end
213
214local report = logs.reporter("mkiv lua stats")
215
216function statistics.show()
217    if statistics.enable then
218        -- this code will move
219        local register = statistics.register
220        register("used platform", function()
221            return format("%s, type: %s, binary subtree: %s",
222                os.platform or "unknown",os.type or "unknown", environment.texos or "unknown")
223        end)
224        register("used engine", function()
225            return format("%s version: %s, functionality level: %s, banner: %s",
226                LUATEXENGINE, LUATEXVERSION, LUATEXFUNCTIONALITY, lower(status.banner))
227        end)
228        register("used hash slots", function()
229            return format("%s of %s + %s", status.cs_count, status.hash_size,status.hash_extra)
230        end)
231        register("callbacks", statistics.callbacks)
232        if JITSUPPORTED then
233            local jitstatus = jit.status
234            if jitstatus then
235                local jitstatus = { jitstatus() }
236                if jitstatus[1] then
237                    register("luajit options", concat(jitstatus," ",2))
238                end
239            end
240        end
241        -- so far
242        register("lua properties",function()
243            local hash = 2^status.luatex_hashchars
244            local mask = load([[τεχ = 1]]) and "utf" or "ascii"
245            return format("engine: %s %s, used memory: %s, hash chars: min(%i,40), symbol mask: %s (%s)",
246                jit and "luajit" or "lua", LUAVERSION, statistics.memused(), hash, mask, mask == "utf" and "τεχ" or "tex")
247        end)
248        register("runtime",statistics.runtime)
249        logs.newline() -- initial newline
250        for i=1,#statusinfo do
251            local s = statusinfo[i]
252            local r = s[2]()
253            if r then
254                report("%s: %s",s[1],r)
255            end
256        end
257     -- logs.newline() -- final newline
258        statistics.enable = false
259    end
260end
261
262function statistics.memused() -- no math.round yet -)
263    local round = math.round or math.floor
264    return format("%s MB, ctx: %s MB, max: %s MB",
265        round(collectgarbage("count")/1000),
266        round(status.luastate_bytes/1000000),
267        status.luastate_bytes_max and round(status.luastate_bytes_max/1000000) or "unknown"
268    )
269end
270
271starttiming(statistics)
272
273function statistics.formatruntime(runtime) -- indirect so it can be overloaded and
274    return format("%s seconds", runtime)   -- indeed that happens in cure-uti.lua
275end
276
277function statistics.runtime()
278    stoptiming(statistics)
279 -- stoptiming(statistics) -- somehow we can start the timer twice, but where
280    local runtime = lua.getruntime and lua.getruntime() or elapsedtime(statistics)
281    return statistics.formatruntime(runtime)
282end
283
284local report = logs.reporter("system")
285
286function statistics.timed(action,all)
287    starttiming("run")
288    action()
289    stoptiming("run")
290    local runtime = tonumber(elapsedtime("run"))
291    if all then
292        local alltime = tonumber(lua.getruntime and lua.getruntime() or elapsedtime(statistics))
293        if alltime and alltime > 0 then
294            report("total runtime: %0.3f seconds of %0.3f seconds",runtime,alltime)
295            return
296        end
297    end
298    report("total runtime: %0.3f seconds",runtime)
299end
300
301-- goodie
302
303function statistics.tracefunction(base,tag,...)
304    for i=1,select("#",...) do
305        local name = select(i,...)
306        local stat = { }
307        local func = base[name]
308        setmetatableindex(stat,function(t,k) t[k] = 0 return 0 end)
309        base[name] = function(n,k,v) stat[k] = stat[k] + 1 return func(n,k,v) end
310        statistics.register(formatters["%s.%s"](tag,name),function() return serialize(stat,"calls") end)
311    end
312end
313
314function status.getreadstate()
315    return {
316        filename   = status.filename   or "?",
317        linenumber = status.linenumber or 0,
318        iocode     = status.inputid    or 0,
319    }
320end
321
322