[NTG-pdftex] processing speed

The Thanh Han hanthethanh at gmail.com
Fri Jul 3 12:07:33 CEST 2009


On Thu, Jul 02, 2009 at 12:31:20AM +0200, Reinhard Kotucha wrote:
> On 1 July 2009 Jérome Laurens wrote:
> 
>  > Hahn found a bug in synctex, I fixed it and made the tests with the  
>  > stable branch of pdftex
> 
> Hi Jérome,
> of course, if there had been a bug in synctex, it's good that it is
> fixed now.  

that is certainly a bug: memory was allocated and
deallocated with inconsistent size (allocated with
size=4memory_word and deallocated with size=2memory_word).
This didn't cause much visible harm because:

- the number of this occurence is low (1 per each paragraph)
- the memory was deallocated with smaller size (the other
  way around would have caused weird and hard-to-catch problems).

After running Reinhard's test for a while, the variable-size
memory is defragmented with a lot of nodes with size=2,
which made memory allocation slower and slower.

It's questionable whether synctex or pdftex should
fix this. I asked Jerome for this change because it seems
the simplest way to fix it (thanks to Taco's suggestion). It
could be done in pdftex too, but would be more complicated
and less efficient.

I have verified this with gprof, running Reinhard's test
file (slightly modified):

,--------
| \hbadness10000
| \vbadness10000
| \ifx\pdfoutput\undefined\else\pdfoutput=0 \fi
| \catcode`\%=12 \catcode`\&=12
| 
| \newcount\n
| \loop
|     \input sometext.tex
|     \immediate\write18{date +%s >&2}
|     \advance\n 1
| \ifnum\n < 100 \repeat
| \bye
`--------


Result for pdftex stable, without the fix:
,--------
| Each sample counts as 0.01 seconds.
|   %   cumulative   self              self     total
|  time   seconds   seconds    calls   s/call   s/call  name
|  38.89    229.27   229.27 708325637     0.00     0.00  zgetnode
|  25.85    381.66   152.39 90100100     0.00     0.00  ztrybreak
|   5.85    416.17    34.51        1    34.51   587.29  maincontrol
|   4.87    444.85    28.68 1253467536     0.00     0.00  zbadness
|   3.42    465.00    20.15  4566038     0.00     0.00  hlistout
|   3.40    485.03    20.03  4566038     0.00     0.00  zhpack
|   3.22    503.99    18.96   100000     0.00     0.00  zlinebreak
|   2.58    519.22    15.23 140432176     0.00     0.00  zmovement
|   2.09    531.52    12.30 464226970     0.00     0.00  getnext
|   1.58    540.82     9.30   354818     0.00     0.00  zflushnodelist
|   1.41    549.14     8.32 708325636     0.00     0.00  zfreenode
|   ...
`--------

Result for pdftex stable plus the fix:
,--------
| Each sample counts as 0.01 seconds.
|   %   cumulative   self              self     total
|  time   seconds   seconds    calls   s/call   s/call  name
|  38.97    130.20   130.20 90100100     0.00     0.00  ztrybreak
|   9.12    160.66    30.46        1    30.46   331.61  maincontrol
|   8.04    187.51    26.85 708325637     0.00     0.00  zgetnode
|   4.83    203.65    16.14  4566038     0.00     0.00  zhpack
|   4.79    219.66    16.01 1253467536     0.00     0.00  zbadness
|   4.74    235.51    15.85  4566038     0.00     0.00  hlistout
|   4.15    249.39    13.88   100000     0.00     0.00  zlinebreak
|   3.76    261.94    12.55 140432176     0.00     0.00  zmovement
|   3.34    273.09    11.16 464226970     0.00     0.00  getnext
|   3.22    283.86    10.77 708325636     0.00     0.00  zfreenode
|   ...
`--------

Result for tex:
,--------
| Each sample counts as 0.01 seconds.
|   %   cumulative   self              self     total
|  time   seconds   seconds    calls   s/call   s/call  name
|  37.44    108.71   108.71 90100100     0.00     0.00  ztrybreak
|   9.11    135.16    26.45        1    26.45   289.93  maincontrol
|   8.86    160.90    25.73 708325637     0.00     0.00  zgetnode
|   8.37    185.20    24.30 1253467536     0.00     0.00  zbadness
|   5.30    200.60    15.40  4566038     0.00     0.00  zhpack
|   4.83    214.63    14.04  4566038     0.00     0.00  hlistout
|   4.12    226.58    11.95   100000     0.00     0.00  zlinebreak
|   3.91    237.93    11.35 140432176     0.00     0.00  zmovement
|   3.62    248.46    10.53 464226970     0.00     0.00  getnext
|   2.75    256.44     7.98 708325636     0.00     0.00  zfreenode
`--------


without the fix, pdftex spends a lot of time of zgetnode().
With the fix, the result looks rather similar to tex. 

> However, I doubt that synctex was responsible for the
> problem I reported.  There must still be another problem.  Isn't
> synctex very new technology?  I could reproduce the problem with older
> versions of TeX Live.

yes it's quite possible that there is another problem.

> Please try:
> 
>       http://tug.org/~kotucha/testpgfplots.tex.gz
> 
> I suppose that it's a better test file than the one I prepared first.

it seems it shows a different problem. I let it run for a
while and see that the time processing each plot is slowly
increasing, but sometime it goes down as well. Here is what
I get after 100 plots:

,--------
| ===851968===
| ===786432===
| ===851968===
| ===917504===
| ===917504===
| ===983040===
| ===1048576===
| ===2097152===
| ...
| ===917504===
| ===851968===
| ===917504===
| ===851968===
| ===917504===
| ===851968===
`--------

(tested with pdftex stable, without the above fix).


> What I've found out so far is that
> 
>   1. the problem is not new,
> 
>   2. luatex has the same problem,
> 
>   3. the string pool is growing.
> 
> Because I don't know what exactly causes the problem, I can't even
> provide a minimal test file.  "Unfortunately" pgfplots depends on
> e-TeX and I don't have a "Knuth's TeX + e-TeX" binary.  Maybe there
> exists something like this in older TL releases.
> 
> Maybe even Knuth's TeX has this problem, but I don't know to prove it.
> 
> Hans and Taco said that the string pool is the culprit.  Yes, after
> adding some tiny things to the .tex file, I had to create a new format
> file with an increased string pool in order to get PDF files at all.
> It's definitely the string pool which causes trouble.
> 
> I don't know anything about TeX's innards but the name "string pool"
> implies that it contains human readable stuff.  If this is true, isn't
> it possible to convince TeX to dump the string pool to a file or to
> standard output, for instance, whenever a page is shipped out?  This
> probably helps to find out what's going on.

yes it can be done. However I suggest we make clear first
what the problem is. From your 2nd test file, it seems the
processing time is not slower that much. Anyway, I will
rerun it with a higher number of plots to see if it makes
any difference.


Regards,
Thanh

PS: fwiw, the gprof report for testpgfplots.tex looks like
this (after making 100 plots):

,--------
| Each sample counts as 0.01 seconds.
|   %   cumulative   self              self     total
|  time   seconds   seconds    calls   s/call   s/call  name
|  32.39    251.25   251.25 6082692346     0.00     0.00  getnext
|  15.36    370.37   119.12 1064097580     0.00     0.00  zflushlist
|   8.43    435.77    65.40 3911156736     0.00     0.00  getavail
|   6.47    485.99    50.22 376907688     0.00     0.00  macrocall
|   5.93    531.95    45.96 54922728     0.00     0.00  thetoks
|   3.24    557.07    25.12 1404732324     0.00     0.00  endtokenlist
|   2.65    577.61    20.55 156920995     0.00     0.00  zscantoks
|   2.57    597.55    19.94 543147090     0.00     0.00  expand
|   2.31    615.50    17.96 4801962525     0.00     0.00  gettoken
|   1.61    627.97    12.47 1426527970     0.00     0.00  getxtoken
|   1.61    640.44    12.47 899138347     0.00     0.00  zbegintokenlist
|   1.52    652.26    11.82 342016689     0.00     0.00  prefixedcommand
|   1.50    663.87    11.61 219961927     0.00     0.00  conditional
|   1.34    674.27    10.40     8580     0.00     0.00  checkoutervalidity
|   1.16    683.26     9.00 217157551     0.00     0.00  passtext
|   1.10    691.76     8.50 221130467     0.00     0.00  zgetnode
|   1.00    699.54     7.78 505593977     0.00     0.00  backinput
|   0.88    706.33     6.79        1     6.79   770.07  maincontrol
|   ...
`--------


More information about the ntg-pdftex mailing list