Re: bottlenecks

[Rik Kabel via ntg-context <ntg-context@ntg.nl>]

[-- Attachment #1.1: Type: text/plain, Size: 10592 bytes --]

Hans,

Here are the stats for a 346 page book. Fonts are all cached. 
Compilation is via a make file which processes this as:

    context --noconsole --overloadmode=error --batchmode --nonstopmode
    --nosynctex misquotation_bodyonly.mkvi > nul

and is run under W11 x64 on an i7-8550U. The only tables are contents 
and acronyms, and such, nothing complex. No graphics. Compact fonts are 
enabled.

    mkiv lua stats  > used config file:
    selfautoparent:/texmf/web2c/texmfcnf.lua
    mkiv lua stats  > used cache path:
    C:/ConTeXt_LMTX/tex/texmf-cache/luametatex-cache/context/5fe67e0bfe781ce0dde776fb1556f32e
    mkiv lua stats  > resource resolver: loadtime 0.042 seconds, 1 scans
    with scantime 0.035 seconds, 0 shared scans, 37 found files, scanned
    paths: C:/Users/micro/texmf
    mkiv lua stats  > stored bytecode data: 507 modules (0.236 sec), 106
    tables (0.015 sec), 613 chunks (0.251 sec)
    mkiv lua stats  > traced context: maxstack: 4107, freed: 2452,
    unreachable: 1655
    mkiv lua stats  > cleaned up reserved nodes: 78 nodes, 8 lists of 438
    mkiv lua stats  > node memory usage: 6869 attribute, 4608 dir, 4612
    glue, 84 gluespec, 2304 glyph, 3072 hlist, 3 kern, 647 mathspec, 5
    penalty, 2 temp
    mkiv lua stats  > node list callback tasks: 13 unique task lists, 37
    instances (re)created, 87130 calls
    mkiv lua stats  > h-node processing time: 3.010 seconds including kernel
    mkiv lua stats  > inserted spaces in output: 106016
    mkiv lua stats  > attribute processing time: 0.236 seconds front-
    and backend
    mkiv lua stats  > driver time: 2.099 seconds
    mkiv lua stats  > used backend: pdf
    mkiv lua stats  > jobdata time: 0.191 seconds saving, 0.051 seconds
    loading
    mkiv lua stats  > callbacks: file: 34388, saved: 191153, direct: 8,
    function: 173575, value: 345, message: 0, bytecode: 613, late 0,
    total: 400082 (1184 per page)
    mkiv lua stats  > randomizer: resumed with value 0.88558194690977
    mkiv lua stats  > v-node processing time: 0.194 seconds
    mkiv lua stats  > loaded patterns: agr:gr:62 cn::58 de::3 deo:de:9
    en::1 es::64 fr::63 it::66 la::67 ru::22, load time: 0.000
    mkiv lua stats  > structure elements: 28145 element chains identified
    mkiv lua stats  > interactive elements: 3982 references, 4873
    destinations
    mkiv lua stats  > margin data: 497 entries, 0 pending
    mkiv lua stats  > loaded fonts: 14 files: antykwatorunska-bold.otf,
    antykwatorunskacond-bold.otf, antykwatorunskacond-regular.otf,
    libertinusmath-regular.otf, libertinusmono-regular.otf,
    libertinussans-italic.otf, libertinussans-regular.otf,
    libertinusserif-italic.otf, libertinusserif-regular.otf,
    libertinusserif-semibold.otf, zentb___.otf, keteraramtsova.ttf,
    msjh.ttc, times.ttf
    mkiv lua stats  > font engine: otf 3.131, afm 1.513, tfm 1.000, 84
    instances, 67 shared in backend, 3 common vectors, 64 common hashes,
    load time 0.947 seconds
    mkiv lua stats  > text directions: 4.273 seconds
    mkiv lua stats  > math tweaking time: 0.152 seconds, 18 math goodie
    tables
    mkiv lua stats  > pdf annotations: 3982 links (3982 unique), 0 special
    mkiv lua stats  > font embedding time: 0.058 seconds, 13 fonts
    mkiv lua stats  > result saved in file: misquotation_bodyonly.pdf,
    compresslevel 1, objectcompresslevel 3
    mkiv lua stats  > positions: 4034 collected, 1722 deltas, 4025
    shared partials, 112 partial entries
    mkiv lua stats  > used platform: win64, type: windows, binary
    subtree: texmf-win64
    mkiv lua stats  > used engine: luametatex version: 2.1004,
    functionality level: 20221214, format id: 679, compiler: gcc
    mkiv lua stats  > tex properties: 740852 hash slots used of 2097152,
    51846 control sequences, approximate memory usage: 73 MB
    mkiv lua stats  > lua properties: engine: lua 5.4, used memory: 315
    MB, ctx: 288 MB, max: 288 MB, symbol mask: utf (τεχ)
    mkiv lua stats  > runtime: 19.332 seconds, 338 processed pages, 338
    shipped pages, 17.484 pages/second

and here are the stats for the same book with pdf images replacing some 
of the text (I still don't have rights to some images, so preparing 
either way):

    mkiv lua stats  > used config file:
    selfautoparent:/texmf/web2c/texmfcnf.lua
    mkiv lua stats  > used cache path:
    C:/ConTeXt_LMTX/tex/texmf-cache/luametatex-cache/context/5fe67e0bfe781ce0dde776fb1556f32e
    mkiv lua stats  > resource resolver: loadtime 0.044 seconds, 1 scans
    with scantime 0.037 seconds, 0 shared scans, 62 found files, scanned
    paths: C:/Users/micro/texmf
    mkiv lua stats  > stored bytecode data: 507 modules (0.236 sec), 106
    tables (0.015 sec), 613 chunks (0.251 sec)
    mkiv lua stats  > traced context: maxstack: 4112, freed: 2457,
    unreachable: 1655
    mkiv lua stats  > cleaned up reserved nodes: 78 nodes, 8 lists of 438
    mkiv lua stats  > node memory usage: 6869 attribute, 4608 dir, 4612
    glue, 84 gluespec, 2304 glyph, 3072 hlist, 3 kern, 647 mathspec, 5
    penalty, 2 temp
    mkiv lua stats  > node list callback tasks: 13 unique task lists, 37
    instances (re)created, 86856 calls
    mkiv lua stats  > h-node processing time: 2.899 seconds including kernel
    mkiv lua stats  > inserted spaces in output: 104350
    mkiv lua stats  > attribute processing time: 0.225 seconds front-
    and backend
    mkiv lua stats  > driver time: 2.050 seconds
    mkiv lua stats  > used backend: pdf
    mkiv lua stats  > jobdata time: 0.210 seconds saving, 0.053 seconds
    loading
    mkiv lua stats  > callbacks: file: 34137, saved: 190338, direct: 33,
    function: 173845, value: 337, message: 0, bytecode: 613, late 0,
    total: 399303 (1188 per page)
    mkiv lua stats  > randomizer: resumed with value 0.88558194690977
    mkiv lua stats  > v-node processing time: 0.266 seconds
    mkiv lua stats  > loaded patterns: agr:gr:62 cn::58 de::3 deo:de:9
    en::1 es::64 fr::63 it::66 la::67 ru::22, load time: 0.000
    mkiv lua stats  > structure elements: 28023 element chains identified
    mkiv lua stats  > interactive elements: 3997 references, 4875
    destinations
    mkiv lua stats  > margin data: 497 entries, 0 pending
    mkiv lua stats  > loaded fonts: 14 files: antykwatorunska-bold.otf,
    antykwatorunskacond-bold.otf, antykwatorunskacond-regular.otf,
    libertinusmath-regular.otf, libertinusmono-regular.otf,
    libertinussans-italic.otf, libertinussans-regular.otf,
    libertinusserif-italic.otf, libertinusserif-regular.otf,
    libertinusserif-semibold.otf, zentb___.otf, keteraramtsova.ttf,
    msjh.ttc, times.ttf
    mkiv lua stats  > font engine: otf 3.131, afm 1.513, tfm 1.000, 84
    instances, 67 shared in backend, 3 common vectors, 64 common hashes,
    load time 0.991 seconds
    mkiv lua stats  > text directions: 4.016 seconds
    mkiv lua stats  > math tweaking time: 0.155 seconds, 18 math goodie
    tables
    mkiv lua stats  > graphics processing time: 3.767 seconds including
    tex, 25 processed images, 25 unique asked, 25 bad names
    mkiv lua stats  > pdf annotations: 3997 links (3997 unique), 0 special
    mkiv lua stats  > font embedding time: 0.061 seconds, 12 fonts
    mkiv lua stats  > result saved in file: misquotation_bodyonly.pdf,
    compresslevel 1, objectcompresslevel 3
    mkiv lua stats  > positions: 3983 collected, 1672 deltas, 3973
    shared partials, 110 partial entries
    mkiv lua stats  > used platform: win64, type: windows, binary
    subtree: texmf-win64
    mkiv lua stats  > used engine: luametatex version: 2.1004,
    functionality level: 20221214, format id: 679, compiler: gcc
    mkiv lua stats  > tex properties: 740852 hash slots used of 2097152,
    51853 control sequences, approximate memory usage: 73 MB
    mkiv lua stats  > lua properties: engine: lua 5.4, used memory: 221
    MB, ctx: 195 MB, max: 219 MB, symbol mask: utf (τεχ)
    mkiv lua stats  > runtime: 23.057 seconds, 336 processed pages, 336
    shipped pages, 14.572 pages/second

Significant time is attributed to text directions (there are a few 
excerpts in Hebrew), and to graphics processing in the second case.

In neither case do the sum of the times listed in the stats come close 
to the total runtime (in the second example, 14.774 seconds of 23.057 
are accounted), so there are other unidentified processes involved.

In any case, the processing time has been improving greatly over the 
last couple of years, and LMTX is significantly faster that MkIV in all 
of my work.

-- 
Rik

On 2022-12-16 15:02, Hans Hagen via ntg-context wrote:
> On 12/16/2022 8:36 PM, Henning Hraban Ramm via ntg-context wrote:
>> 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  > runtime: 30.592 seconds, 366 processed pages, 366 
>> shipped pages, 11.964 pages/second
>
>> (2)
>> This is a 720 page novel (first run with this LMTX version, some 
>> fonts were still uncached):
>>
>
>> mkiv lua stats  > runtime: 19.275 seconds, 720 processed pages, 720 
>> shipped pages, 37.355 pages/second
> so what if you add to the top
>
> \enableexperiments[fonts.compact]
>
> Hans
>
> -----------------------------------------------------------------
>                                           Hans Hagen | PRAGMA ADE
>               Ridderstraat 27 | 8061 GH Hasselt | The Netherlands
>        tel: 038 477 53 69 | www.pragma-ade.nl | www.pragma-pod.nl
> -----------------------------------------------------------------
>
> ___________________________________________________________________________________ 
>
> 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
> ___________________________________________________________________________________ 
>

[-- Attachment #1.2: Type: text/html, Size: 13759 bytes --]

[-- Attachment #2: Type: text/plain, Size: 496 bytes --]

___________________________________________________________________________________
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
___________________________________________________________________________________