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
10
11
12
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
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
46
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
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)
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
153
154function statistics.register(tag,fnc)
155 if statistics.enable and type(fnc) == "function" then
156
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
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
187 register("lua properties",function()
188
189 local mask = load([[τεχ = 1]]) and "utf" or "ascii"
190
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()
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
204 statistics.enable = false
205 end
206end
207
208function statistics.memused()
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)
221 return format("%s seconds", runtime)
222end
223
224function statistics.runtime()
225 stoptiming(statistics)
226
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
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
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
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
308local mplib = mplib
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()
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
401
402
403
404
405
406
407
408
409 |