Re: bottlenecks

[Henning Hraban Ramm via ntg-context <ntg-context@ntg.nl>]

Am 16.12.22 um 18:10 schrieb Hans Hagen via ntg-context:
> So the challenge is how to determine bottlenecks. Are there users on 
> this list that have document runs of more than 10 seconds (as reference: 
> the luametatex manual takes < 9 seconds for 350 pages and loads plenty 
> fonts and has many tables) or have many (small) runs and are annoyed by 
> the runtime? And if so, what does one guess are the bottlenecks?

(1)
This is my 366 page ConTeXt book:

mkiv lua stats  > used config file: 
home:texmf/web2c/texmfcnf.lua;selfautoparent:/texmf/web2c/texmfcnf.lua
mkiv lua stats  > used cache path: 
/Users/hraban/lmtx/tex/texmf-cache/luametatex-cache/context/c821363a6b068765c2a3bbfe3917fcf5
mkiv lua stats  > resource resolver: loadtime 0.046 seconds, 1 scans 
with scantime 0.037 seconds, 0 shared scans, 165 found files, scanned 
paths: /Users/hraban/texmf
mkiv lua stats  > stored bytecode data: 507 modules (0.378 sec), 106 
tables (0.017 sec), 613 chunks (0.395 sec)
mkiv lua stats  > traced context: maxstack: 3112, freed: 1448, 
unreachable: 1664
mkiv lua stats  > cleaned up reserved nodes: 202 nodes, 22 lists of 517
mkiv lua stats  > node memory usage: 1137 attribute, 46 dir, 559 glue, 
82 gluespec, 177 glyph, 236 hlist, 3 kern, 647 mathspec, 48 penalty, 2 
submlist, 2 temp
mkiv lua stats  > node list callback tasks: 13 unique task lists, 180 
instances (re)created, 216502 calls
mkiv lua stats  > h-node processing time: 2.544 seconds including kernel
mkiv lua stats  > synctex tracing: 46 referenced files, 22 files 
ignored, 41808 objects flushed, logfile: prd_de.synctex
mkiv lua stats  > attribute processing time: 0.201 seconds front- and 
backend
mkiv lua stats  > driver time: 5.265 seconds
mkiv lua stats  > used backend: pdf
mkiv lua stats  > jobdata time: 0.271 seconds saving, 0.056 seconds loading
mkiv lua stats  > callbacks: file: 26780, saved: 405242, direct: 524, 
function: 281755, value: 2288, message: 0, bytecode: 613, late 0, total: 
717202 (1960 per page)
mkiv lua stats  > randomizer: resumed with value 0.57895496379132
mkiv lua stats  > v-node processing time: 1.464 seconds
mkiv lua stats  > loaded tex modules: 10 requested, all found (*-filter 
*-libs-imp-zint *-module-catcodes *-s-fonts-show *-s-symbols-show 
*-scite *-syntax-groups *-syntax-highlight *-vim *-visual)
mkiv lua stats  > loaded patterns: de::3 en::1, load time: 0.000
mkiv lua stats  > xml load time: 0.002 seconds, 1 files, 1 converted
mkiv lua stats  > lxml preparation time: 0.000 seconds, 0 nodes, 31 
lpath calls, 4 cached calls
mkiv lua stats  > interactive elements: 2536 references, 2870 destinations
mkiv lua stats  > margin data: 295 entries, 1 pending
mkiv lua stats  > loaded fonts: 31 files: latinmodern-math.otf, 
lmmono10-italic.otf, lmmono10-regular.otf, lmmonocaps10-regular.otf, 
lmmonolt10-bold.otf, lmmonolt10-boldoblique.otf, 
lmmonoltcond10-regular.otf, lmmonoslant10-regular.otf, 
lmroman10-bold.otf, lmroman10-italic.otf, lmroman10-regular.otf, 
lmromancaps10-regular.otf, lmsans10-oblique.otf, lmsans10-regular.otf, 
cc-icons.ttf, dejavusansmono.ttf, marvosym.ttf, font awesome 5 
brands-regular-400.otf, font awesome 5 free-regular-400.otf, font 
awesome 5 free-solid-900.otf, cambria.ttc, cambriab.ttf, cambriai.ttf, 
cambriaz.ttf, segoe ui bold italic.ttf, segoe ui bold.ttf, segoe ui 
italic.ttf, segoe ui.ttf, segoepr.ttf, symbola.otf, 
unifrakturmaguntia.ttf (suspicious x height)
mkiv lua stats  > font engine: otf 3.131, afm 1.513, tfm 1.000, 193 
instances, 157 shared in backend, 11 common vectors, 146 common hashes, 
load time 15.349 seconds
mkiv lua stats  > body font sizes: defined: 10pt 11pt 12pt 14.4pt 17.3pt 
20.7pt 4pt 5pt 6pt 7pt 8pt 9pt, undefined: 11.2pt 14pt 16.8pt
mkiv lua stats  > visualization time: 0.154 seconds
mkiv lua stats  > metapost: 0.678 seconds, loading: 0.092, execution: 
0.651, n: 528, average: 0.003, instances: 2, luacalls: 37745 (file: 
31092, text: 0, script: 3507, log: 3146), memory: 8.825 M
mkiv lua stats  > math tweaking time: 8.659 seconds, 116 math goodie tables
mkiv lua stats  > math processing time: 0.012 seconds
mkiv lua stats  > graphics processing time: 2.885 seconds including tex, 
247 processed images, 69 unique asked, 42 bad names
mkiv lua stats  > pdf annotations: 2536 links (2535 unique), 0 special
mkiv lua stats  > font embedding time: 0.084 seconds, 31 fonts
mkiv lua stats  > result saved in file: prd_de.pdf, compresslevel 1, 
objectcompresslevel 0
mkiv lua stats  > positions: 6786 collected, 3635 deltas, 6678 shared 
partials, 46 partial entries
mkiv lua stats  > used platform: osx-64, type: unix, binary subtree: 
texmf-osx-64
mkiv lua stats  > used engine: luametatex version: 2.1004, functionality 
level: 20221208, format id: 678, compiler: clang
mkiv lua stats  > tex properties: 740852 hash slots used of 2097152, 
59643 control sequences, approximate memory usage: 217 MB
mkiv lua stats  > lua properties: engine: lua 5.4, used memory: 800 MB, 
ctx: 767 MB, max: 767 MB, symbol mask: utf (τεχ)
mkiv lua stats  > runtime: 30.592 seconds, 366 processed pages, 366 
shipped pages, 11.964 pages/second
system          | total runtime: 219.556 seconds of 219.819 seconds

real	3m39,829s
user	3m23,086s
sys	0m12,772s

I guess it needs too much time on calling zint for all the QR codes that 
I probably will get rid of anyway. Otherwise it loads nearly all 
modules. So it’s an extreme case.


(2)
This is a 720 page novel (first run with this LMTX version, some fonts 
were still uncached):

mkiv lua stats  > used config file: 
home:texmf/web2c/texmfcnf.lua;selfautoparent:/texmf/web2c/texmfcnf.lua
mkiv lua stats  > used cache path: 
/Users/hraban/lmtx/tex/texmf-cache/luametatex-cache/context/c821363a6b068765c2a3bbfe3917fcf5
mkiv lua stats  > resource resolver: loadtime 0.045 seconds, 1 scans 
with scantime 0.036 seconds, 0 shared scans, 27 found files, scanned 
paths: /Users/hraban/texmf
mkiv lua stats  > stored bytecode data: 507 modules (0.388 sec), 106 
tables (0.016 sec), 613 chunks (0.404 sec)
mkiv lua stats  > traced context: maxstack: 1659, freed: 4, unreachable: 
1655
mkiv lua stats  > cleaned up reserved nodes: 74 nodes, 8 lists of 435
mkiv lua stats  > node memory usage: 14 attribute, 2 glue, 83 gluespec, 
3 kern, 647 mathspec, 3 penalty, 2 temp
mkiv lua stats  > node list callback tasks: 13 unique task lists, 11 
instances (re)created, 64714 calls
mkiv lua stats  > h-node processing time: 11.444 seconds including kernel
mkiv lua stats  > attribute processing time: 0.433 seconds front- and 
backend
mkiv lua stats  > driver time: 13.557 seconds
mkiv lua stats  > used backend: pdf
mkiv lua stats  > jobdata time: 0.018 seconds saving, 0.004 seconds loading
mkiv lua stats  > callbacks: file: 6035, saved: 123944, direct: 4, 
function: 37443, value: 721, message: 0, bytecode: 613, late 0, total: 
168760 (234 per page)
mkiv lua stats  > randomizer: resumed with value 0.69074136591922
mkiv lua stats  > v-node processing time: 0.273 seconds
mkiv lua stats  > loaded patterns: de::3 en::1, load time: 0.000
mkiv lua stats  > interactive elements: 2 references, 1 destinations
mkiv lua stats  > loaded fonts: 8 files: latinmodern-math.otf, 
lmroman10-regular.otf, supernett_cn_light.otf, alegreya-bold.ttf, 
alegreya-italic.ttf, alegreya-regular.ttf, alegreyasans-light.ttf, 
alegreyasc-regular.ttf
mkiv lua stats  > font engine: otf 3.131, afm 1.513, tfm 1.000, 31 
instances, 20 shared in backend, 5 common vectors, 15 common hashes, 
load time 0.797 seconds
mkiv lua stats  > math tweaking time: 0.167 seconds, 12 math goodie tables
mkiv lua stats  > graphics processing time: 0.003 seconds including tex, 
2 processed images, 1 unique asked, 0 bad names
mkiv lua stats  > pdf annotations: 2 links (2 unique), 0 special
mkiv lua stats  > font embedding time: 0.017 seconds, 6 fonts
mkiv lua stats  > result saved in file: prd_02_pyka.pdf, compresslevel 
1, objectcompresslevel 3
mkiv lua stats  > positions: 4 collected, 0 deltas, 0 shared partials, 0 
partial entries
mkiv lua stats  > used platform: osx-64, type: unix, binary subtree: 
texmf-osx-64
mkiv lua stats  > used engine: luametatex version: 2.1004, functionality 
level: 20221208, format id: 678, compiler: clang
mkiv lua stats  > tex properties: 740852 hash slots used of 2097152, 
55184 control sequences, approximate memory usage: 51 MB
mkiv lua stats  > lua properties: engine: lua 5.4, used memory: 124 MB, 
ctx: 109 MB, max: 181 MB, symbol mask: utf (τεχ)
mkiv lua stats  > runtime: 19.275 seconds, 720 processed pages, 720 
shipped pages, 37.355 pages/second
system          | total runtime: 59.113 seconds of 59.220 seconds


real	0m59,229s
user	0m57,610s
sys	0m1,379s


Made on a Mac mini from 2012 (2,3 GHz i7, 16 GB RAM), but with SSDs.

Hraban
___________________________________________________________________________________
If your question is of interest to others as well, please add an entry to the Wiki!

maillist : ntg-context@ntg.nl / https://www.ntg.nl/mailman/listinfo/ntg-context
webpage  : https://www.pragma-ade.nl / http://context.aanhet.net
archive  : https://bitbucket.org/phg/context-mirror/commits/
wiki     : https://contextgarden.net
___________________________________________________________________________________