Re: bottlenecks

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

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

On 2022-12-16 17:07, Hans Hagen via ntg-context wrote:
> On 12/16/2022 10:08 PM, Rik Kabel via ntg-context wrote:
>> 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 
>
> ok, not the fastest i7 out there, more the tablet one, right?
>
>> and acronyms, and such, nothing complex. No graphics. Compact fonts 
>> are enabled.
>
> can you check compact mode .. when compact fonts are not enabled, do 
> you get the same
>
> >     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,
>
> i wonder why so many instances
>
>>     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
>
> this is suspicious ... i fixed a dir leak recently but having 3K boxes 
> dangling ...
>
>> 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.
>
> these stats are an indication because below a threshold (time 
> accuracy) nothing is measured
>
>> 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.
> sure, that is to be expected although it depends a bit on the use 
> case, for instance the backend is slower (but does much more) so 
> initially lmtx was actually slower but at some point we started 
> gaining (and i can probably gain a little more)
>
> i wonder why directions bump time because much of what tex does is 
> sort of agnostic for directions (the backend needs more time but i 
> don't see that in your stats)
>
> when you run with --profile you get a much slower run but might get 
> some info from the extra log
>
> Hans
>

The laptop was hot stuff in 2017 with 16GB RAM, 1TB SSD, and a 4K touch 
screen -- today, not so hot. Due to be replaced next year.

Here are the numbers without compact fonts enabled. Not much difference.

    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.045 seconds, 1 scans
    with scantime 0.037 seconds, 0 shared scans, 37 found files, scanned
    paths: C:/Users/micro/texmf
    mkiv lua stats  > stored bytecode data: 507 modules (0.243 sec), 106
    tables (0.016 sec), 613 chunks (0.259 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.454 seconds including kernel
    mkiv lua stats  > inserted spaces in output: 106016
    mkiv lua stats  > attribute processing time: 0.295 seconds front-
    and backend
    mkiv lua stats  > driver time: 2.487 seconds
    mkiv lua stats  > used backend: pdf
    mkiv lua stats  > jobdata time: 0.290 seconds saving, 0.053 seconds
    loading
    mkiv lua stats  > callbacks: file: 34388, saved: 191153, direct: 8,
    function: 173574, value: 345, message: 0, bytecode: 613, late 0,
    total: 400081 (1184 per page)
    mkiv lua stats  > randomizer: resumed with value 0.88558194690977
    mkiv lua stats  > v-node processing time: 0.250 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 1.076 seconds
    mkiv lua stats  > text directions: 4.987 seconds
    mkiv lua stats  > math tweaking time: 0.187 seconds, 18 math goodie
    tables
    mkiv lua stats  > pdf annotations: 3982 links (3982 unique), 0 special
    mkiv lua stats  > font embedding time: 0.195 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: 314
    MB, ctx: 288 MB, max: 288 MB, symbol mask: utf (τεχ)
    mkiv lua stats  > runtime: 23.731 seconds, 338 processed pages, 338
    shipped pages, 14.243 pages/second

I do have some macros that are likely to make you (and others who are 
more adept at such things) cringe. Happy to share more of the source if 
it is helpful.

I have also run with --profile and have attached that log as well as the 
complete execution log (zipped together as logs.zip).

-- 
Rik

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

[-- Attachment #2: logs.zip --]
[-- Type: application/x-zip-compressed, Size: 69783 bytes --]

[-- Attachment #3: 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
___________________________________________________________________________________