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 | ... `--------