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, sortedhash = table.concat, table.sortedhash
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: lua %s, format %s, used memory: %s, symbol mask: %s (%s)",
192 LUAVERSION, LUAFORMAT, 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", "mvl",
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 local l = status .getlinebreakstate()
321 local p = status .getbalancestate()
322 local h = status .gethyphenationstate()
323 do
324
325 local estatus = s.expandstate
326 local tstatus = s.texstate
327 local lstatus = s.luastate
328 local rstatus = s.readstate
329
330 local pstatus = logs.private.getpagetiming()
331
332 local iocode = status.iocodes[rstatus.iocode]
333
334 local mpinstances, mpmemory = metapost.getstatistics(true)
335
336 report("")
337 if when == "finish" then
338 report("status after finishing run")
339 else
340 report("status after shipping out page %s",tex.getcount("realpageno"))
341 end
342 show(s, { "max", "min", "set", "stp", false, "mem", "itm", "ext", "all", false, "ini", "ptr", "top" })
343 report(" current input type : %s", iocode)
344 if iocode == "file" then
345 report(" current file name : %s", rstatus.filename or "")
346 report(" current line number : %s", rstatus.linenumber)
347 end
348 report("")
349 report(" approximate memory : %s (%s MB)", tstatus.approximate, tstatus.approximate // 1048576)
350 report("")
351 report(" expansion depth : min: %s, max: %s, set: %s, top: %s", estatus.min, estatus.max, estatus.set, estatus.top)
352 report("")
353 report(" luabytecode registers : %s", lstatus.bytecodes)
354 report(" luabytecode bytes : %s (%s MB)", lstatus.bytecodebytes, lstatus.bytecodebytes // 1048576)
355 report(" luastate bytes now : %s (%s MB)", lstatus.statebytes, lstatus.statebytes // 1048576)
356 report(" luastate bytes max : %s (%s MB)", lstatus.statebytesmax, lstatus.statebytesmax // 1048576)
357 report("")
358 report(" file callbacks : %s", c.file)
359 report(" saved callbacks : %s", c.saved)
360 report(" direct callbacks : %s", c.direct)
361 report(" function callbacks : %s", c["function"])
362 report(" value callbacks : %s", c.value)
363 report(" message callbacks : %s", c.message)
364 report(" bytecode callbacks : %s", c.bytecode)
365 report("")
366 report(" mp instances : %s", mpinstances)
367 report(" mp estimated memory : %s (%s MB)", mpmemory, mpmemory // 1048576)
368 report(" mp file callbacks : %s", m.file)
369 report(" mp text callbacks : %s", m.text)
370 report(" mp script callbacks : %s", m.script)
371 report(" mp log callbacks : %s", m.log)
372 report("")
373 report(" total callbacks : %s", c.count)
374 report(" mp total callbacks : %s", m.count)
375 report(" backend callbacks : %s", b.count)
376 report("")
377 end
378 do
379 local done = false
380 local round = math.round
381 local n_calls = 0
382 local n_first = 0
383 local n_second = 0
384 local n_final = 0
385 local n_specification = 0
386 local n_sub = 0
387 for k, v in sortedhash(l) do
388 if type(v) == "table" then
389 local calls = v.calls or 0
390 if v.calls > 0 then
391 local calls, first, second, final, specification, sub = v.calls, v.first, v.second, v.final, v.specification,v.sub
392 if not done then
393 report(" linebreak statistics : context calls first second final passonly subpass")
394 report("")
395 done = true
396 end
397 report(" linebreak statistics : %-8s %8i %8i %8i %8i %8i %8i",k,calls,first,second,final,specification,sub)
398 n_calls = n_calls + calls
399 n_first = n_first+ first
400 n_second = n_second + second
401 n_final = n_final + final
402 n_specification = n_specification + specification
403 n_sub = n_sub + sub
404 end
405 end
406 end
407 if done then
408 report("")
409 report(" linebreak statistics : %8i %8i %8i %8i %8i %8i",n_calls,n_first,n_second,n_final,n_specification,n_sub)
410 end
411 end
412 do
413 if p.calls > 0 then
414 report("")
415 for k, v in table.sortedhash(p) do
416 if v ~= 0 then
417 report(" balance state : %-14s %7i",k,v)
418 end
419 end
420 end
421 end
422 do
423
424 report("")
425 for k, v in table.sortedhash(h) do
426 if v ~= 0 then
427 report(" hyphenation state : %-10s %7i",k,v)
428 done = true
429 end
430 end
431
432 end
433 do
434 if pstatus then
435 report("")
436 report(" page numbers : realpage %s, userpage %s, subpage %s",pstatus.page.real,pstatus.page.user,pstatus.page.sub)
437 report(" page timing : total %0.03f, page %0.03f, average %0.03f",pstatus.time.elapsed,pstatus.time.page,pstatus.time.average)
438 end
439 end
440 report("")
441end
442
443trackers.register("system.usage", function(v)
444 if v and not registered then
445 logs.private.enablepagetiming()
446 if v ~= "summary" then
447 luatex.registerpageactions(function()
448 if enabled then
449 statistics.showusage("page")
450 end
451 end)
452 end
453 luatex.registerstopactions(function()
454 if enabled then
455 statistics.showusage("finish")
456 end
457 end)
458 registered = true
459 end
460 enabled = v
461end)
462
463
464
465
466
467
468
469
470
471
472 |
