I have a 220 MB PS file with 36 pages. gs8 ps2pdf takes 30 minutes. On the same Linux server, after over 7 hours, gs9.04 is about 1/3 way done (estimating from the size of the partial pdf). When we divide the PS into ranges of pages, gs9 takes about 2X as long as gs8 on each range, so the problem is not triggered by a specific page. I am not sure if this is related to ICC like bug 691914 because that is one of the more significant differences between gs 8 and 9. The file is too large to attach here or email, and the problem happens only with the entire file, so we can't make a small example. If you want, we can send the file by mail on a CD.
Please find a way to deliver this file to GS developers. The file is too big to attach to the bug report. You can put it on HTTP or FTP server for download or mail the file to Artifex Software on CD. See http://www.artifex.com
I put the files on dropbox. The main problem happened between gs8.33 and gs8.57. gs9.04 is 50 X slower than gs7.05. gs8.33 is 3.1 X slower than gs7.05. gs8.57 is 11 X slower than gs8.33. gs9.04 is 1.5 X slower than gs8.57. pdftops times on my laptop (2.2 GHz Core2Duo, 2 GB RAM, 32-bit Fedora 14 Linux): gs7.05 1.2 min gs8.14 0.3 min (core dump, no output) gs8.33 3.7 min gs8.57 40 min gs8.71 53 min gs9.04 60 min I posted a bzip2-compressed version of the original PS and the generated PDFs. http://dl.dropbox.com/u/45968874/pcab.ps.bz2 http://dl.dropbox.com/u/45968874/pcab-gs705.pdf http://dl.dropbox.com/u/45968874/pcab-gs833.pdf http://dl.dropbox.com/u/45968874/pcab-gs857.pdf http://dl.dropbox.com/u/45968874/pcab-gs871.pdf http://dl.dropbox.com/u/45968874/pcab-gs904.pdf 55935529 pcab-gs705.pdf 52781021 pcab-gs833.pdf 52753227 pcab-gs857.pdf 52767560 pcab-gs871.pdf 52902948 pcab-gs904.pdf 111605951 pcab.ps.bz2 I tracked the memory usage with "top" and the size of the generated PDF. It doesn't look like gs is consuming an excessive amount of memory. gs9 is the first version that I built with the fonts embedded, which is probably why it is about 20 MB larger than the other versions. MB virt / MB res / PDF size in MB / runtime gs9.04 45 / 19 / 0 / initial 87 / 62 / 6.2 / 2 min 87 / 62 / 7.1 / 5 min 87 / 62 / 7.7 / 7 min 98 / 72 / 12.7 / 23 min 98 / 73 / 16.6 / 38 min 98 / 73 / 19.9 / 50 min / / 52.9 / 60 min gs8.71 27 / 11 / 0 / initial 69 / 52 / 5.8 / 1 min 69 / 53 / 6.7 / 4 min 78 / 61 / 13.7 / 25 min 78 / 61 / 17.5 / 39 min / / 52.8 / 53 min gs8.57 14 / 9 / 0 / initial 55 / 49 / 10.0 / 5 min 55 / 49 / 13.9 / 17 min 55 / 50 / 17.1 / 27 min / / 52.7 / 40 min viewing with gs8.57 reports **** Warning: Fonts with Subtype = /TrueType should be embedded. The following fonts were not embedded: Helvetica **** This file had errors that were repaired or ignored. **** The file was produced by: **** >>>> GPL Ghostscript 8.57 <<<< **** Please notify the author of the software that produced this **** file that it does not conform to Adobe's published PDF **** specification. gs8.33 12 / 8 / 0 / initial 57 / 51 / 14 / 2 min 57 / 51 / 20 / 3 min 60 / 54 / 52.8 / 3 min 41 seconds viewing with gs8.33 gets a lot of errors Substituting .notdef for E Substituting .notdef for T Substituting .notdef for H every page gets Page 36 **** Warning: Fonts with Subtype = /TrueType should be embedded. But Helvetica is not embedded. Loading Helvetica font from /u1/gnu/gs/fonts.site/Helvetica... 3002580 1627203 4047912 1731257 3 done. the end gets **** This file had errors that were repaired or ignored. **** The file was produced by: **** >>>> AFPL Ghostscript BETA RELEASE 8.33 <<<< **** Please notify the author of the software that produced this **** file that it does not conform to Adobe's published PDF **** specification. gs8.14 12 / 9 / 0 / initial x / core dump at 20 seconds gs7.05 10 / 6 / 0 / initial / / 55.9 / 1 min 10 sec poppler pdftops reports similar errors on all of the PDFs. $ pdftops -v pdftops version 0.18.0 Copyright 2005-2011 The Poppler Developers - http://poppler.freedesktop.org Copyright 1996-2004 Glyph & Cog, LLC $ time pdftops pcab.pdf test.ps Error (11659380): Unknown operator '�' Error (11659380): Internal: got 'EI' operator Error (11659380): Unknown operator '�' Error (11659380): Internal: got 'EI' operator real 0m45.520s user 0m35.338s sys 0m8.494s The PS is 220 MB with 36 pages. On an older server with a 1.6 GHz Pentium 4, 1.5 GB RAM, CentOS 4.9: ps2pdf with gs 8.54 takes 25 min and produces a 53 MB PDF. ps2pdf with gs 9.04 is about 1/3 way done after 7 hours. Ranges of pages take about twice as long with gs 9 than with gs 8. Distiller 8 on a Mac takes about 20 minutes and produces a 12 MB PDF. William
Created attachment 8023 [details] run-time profile I attached a run-time profile of gs9.04 ps2pdf on the 220 MB PS file. It seems to spend a lot of time doing garbage collection. William % cumulative self self total time seconds seconds calls Ks/call Ks/call name 17.86 510.23 510.23 93655313 0.00 0.00 ptr_string_unmark 13.46 894.79 384.56 2658657675 0.00 0.00 chunk_locate_ptr 8.65 1141.95 247.16 3717710611 0.00 0.00 ptr_string_mark 5.68 1304.20 162.25 19331 0.00 0.00 gs_gc_reclaim 5.56 1463.06 158.86 3722999802 0.00 0.00 copied_glyph_name_enum_ptrs 5.52 1620.90 157.84 4057150176 0.00 0.00 gc_string_mark 4.44 1747.74 126.84 3722999802 0.00 0.00 copied_glyph_element_enum_ptrs 3.90 1859.16 111.43 2185736364 0.00 0.00 igc_reloc_string 3.58 1961.35 102.19 2846294133 0.00 0.00 basic_enum_ptrs 3.07 2049.19 87.84 973863000 0.00 0.00 basic_reloc_ptrs 2.53 2121.60 72.41 2811505640 0.00 0.00 igc_reloc_struct_ptr 2.32 2187.82 66.22 77344802 0.00 0.00 gc_locate
Created attachment 8024 [details] run-time profile with -dNOGC Adding -dNOGC to the command line reduces the cpu time from 2857.61 sec to 207.62 sec (13.8 X faster) while increasing memory usage from 98 MB to 121 MB (1.2 X). I have attached a run-time profile of a run with -dNOGC. Since I did the other timing runs with garbage collection enabled, I suspect that the faster run time with -dNOGC in gs9.04 is a symptom of something in gs9.04 making a lot more memory allocations than gs8.33 rather than a problem with the memory allocation and garbage collection. William
I just committed a patch to reduce the GC overhead _without_ totally disabling the GC. Please see bug 691978. Please try the git origin/master or try the patch for rev 4d0f6ec One of us may get around to checking the performance with the origin/master, but if you can check, we'd appreciate it.
I built gs 9.04 fresh from the gs 9.04 distribution and ghostpdl.git-4d0f6ec.patch from http://git.ghostscript.com/?p=ghostpdl.git;a=commit;h=4d0f6ec from bug 691978 . The patch applied cleanly, except for psi/psitop.c which is present only in ghostpdl. Unfortunately, the patch had no effect on the processing time of the 220 MB pcab.ps test file. "grep -c vmreclaim pcab.ps" returns 0, so I think that my test file does not call vmreclaim. William
I built more versions of gs to narrow down the cause of the regression. It was introduced in gs8.56. gs8.54 processes the file in 3 minutes. gs8.56 processes the file in 32 minutes. (There was no gs8.55 release.) (I rebuilt these with gcc-4.6.1, which generates code about 25% faster than the gcc 3.3 or 3.4 that I originally used to build the gs8 releases that I timed in the other comments where gs8.33 took 3.7 min and gs8.57 took 40 min.) I compared the gs8.54 and 8.56 source. The most likely cause is a redesign of color space objects as described in a comment in gs8.56/src/gscspace.h: * Previous versions had a complicated lifecycle discipline for * colorspaces. All that is now replaced with a simple allocation and * reference counting discipline. All colorspace objects are allocated * on the heap and reference counted. References to colorspace objects * are pointers. There is no stack allocation, inline allocation inside * structs, or copying of contents. A less likely cause is a change in the implementation of restore objects as described in a comment in gs8.56/src/isave.h: * In PLRM3, Adobe did the reasonable thing and changed save objects to * composite. However, this means that 'restore' must treat save objects on * the stack differently in LL2 vs. LL3 (yes, the Genoa LL2 and LL3 tests * require this!). See zvmem.c:restore_check_stack. William
Hi Michael, when yo get a chance I'd like to talk about this one.
A few functions are called about 3722999802 times, while the PS file is only 221355113 bytes, which comes to about 16.8 calls per byte of the file. From the counts of function calls, it seems as if something is creating an allocation for each pixel of at least some of the images. If the allocation is done inside a loop, would it be possible to move the allocation outside the loop? I didn't see anything obvious in the profile, but I am hoping that it can be fixed by optimizing a small number of higher-level functions.
This is looking less like the color problem I thought it was, it will probably be fastest if Marcos isolates the problem to a single revision - reassigning.
I'm having trouble reproducing this. Using this command line: gs856 -sDEVICE=pdfwrite -o test856.pdf ./pcab.ps produces the following: 8.15: prints error message 8.54: seg faults 8.56: 1:05:59 9.02: 1:31:29 9.04: 1:24:55
gs 8.54 works for me. The only patch that I applied to the C source was adding a small section to gs8.14/src/gdevxini.c to work better with ghostview that should affect only the x11 device. $ gs854 -sDEVICE=pdfwrite -o test854.pdf ./pcab.ps GPL Ghostscript 8.54 (2006-05-17) Copyright (C) 2006 artofcode LLC, Benicia, CA. All rights reserved. This software comes with NO WARRANTY: see the file PUBLIC for details. WARNING: /Unicode /Decoding resource is not accessible but it is useful for generating ToUnicode CMap. Loading NimbusSanL-Regu font from /u1/gnu/gs8.54/fonts/n019003l.pfb... 2594044 987024 2506796 1209954 2 done. Loading NimbusSanL-Bold font from /u1/gnu/gs8.54/fonts/n019004l.pfb... 2610708 1065074 2526892 1224357 2 done. Loading NimbusSanL-ReguItal font from /u1/gnu/gs8.54/fonts/n019023l.pfb... 2627372 1143526 2546988 1238477 2 done. Loading StandardSymL font from /u1/gnu/gs8.54/fonts/s050000l.pfb... 2627372 1136525 2567084 1089482 2 done. $ ls -l test854.pdf -rw-rw-rw- 1 william william 52753474 Nov 8 15:44 test854.pdf The difference might be the fonts. I built gs 8.54 and earlier without including the initialization files, while I built gs 8.56 and higher with the initialization files. $ gs854 -h GPL Ghostscript 8.54 (2006-05-17) Copyright (C) 2006 artofcode LLC, Benicia, CA. All rights reserved. Usage: gs [switches] [file1.ps file2.ps ...] Most frequently used switches: (you can use # in place of =) -dNOPAUSE no pause after page | -q `quiet', fewer messages -g<width>x<height> page size in pixels | -r<res> pixels/inch resolution -sDEVICE=<devname> select device | -dBATCH exit after last file -sOutputFile=<file> select output file: - for stdout, |command for pipe, embed %d or %ld for page # Input formats: PostScript PostScriptLevel1 PostScriptLevel2 PostScriptLevel3 PDF Default output device: x11 Available devices: bbox bit bitcmyk bitrgb bj10e bj200 bjc600 bjc800 bmp16 bmp16m bmp256 bmp32b bmpgray bmpmono bmpsep1 bmpsep8 cdeskjet cdj550 cdjcolor cdjmono cljet5 cljet5c deskjet devicen djet500 epswrite faxg3 faxg32d faxg4 ijs jpeg jpeggray laserjet lj5gray lj5mono ljet2p ljet3 ljet3d ljet4 ljet4d ljetplus nullpage pbm pbmraw pcx16 pcx24b pcx256 pcxcmyk pcxgray pcxmono pdfwrite pgm pgmraw pgnm pgnmraw pj pjxl pjxl300 pkm pkmraw pksm pksmraw png16 png16m png256 png48 pngalpha pnggray pngmono pnm pnmraw ppm ppmraw ps2write psdcmyk psdrgb psgray psmono psrgb pswrite pxlcolor pxlmono spotcmyk tiff12nc tiff24nc tiff32nc tiffcrle tiffg3 tiffg32d tiffg4 tiffgray tifflzw tiffpack tiffsep uniprint x11 x11alpha x11cmyk x11gray2 x11gray4 x11mono xcf Search path: . : /u1/gnu/gs8.54 : /u1/gnu/gs8.54/lib : /u1/gnu/gs8.54/fonts : /u/scs/gs/fonts : /u/scs/gs/fonts.site : /u1/gnu/fonts.site : /u2/cpagdata/sfna/scs-fonts/fonts : /u/scs/gs/fonts.site-allentown : /usr/local/share/ghostscript/8.54/lib : /usr/local/share/ghostscript/8.54/Resource : /usr/local/share/ghostscript/fonts For more information, see /usr/local/share/ghostscript/8.54/doc/Use.htm. Report bugs to bug-gs@ghostscript.com, using the form in Bug-form.htm. $ gs856 -h GPL Ghostscript 8.56 (2007-03-14) Copyright (C) 2007 artofcode LLC, Benicia, CA. All rights reserved. Usage: gs [switches] [file1.ps file2.ps ...] Most frequently used switches: (you can use # in place of =) -dNOPAUSE no pause after page | -q `quiet', fewer messages -g<width>x<height> page size in pixels | -r<res> pixels/inch resolution -sDEVICE=<devname> select device | -dBATCH exit after last file -sOutputFile=<file> select output file: - for stdout, |command for pipe, embed %d or %ld for page # Input formats: PostScript PostScriptLevel1 PostScriptLevel2 PostScriptLevel3 PDF Default output device: x11 Available devices: bbox bit bitcmyk bitrgb bj10e bj200 bjc600 bjc800 bmp16 bmp16m bmp256 bmp32b bmpgray bmpmono bmpsep1 bmpsep8 cdeskjet cdj550 cdjcolor cdjmono cfax cljet5 cljet5c deskjet devicen djet500 epswrite faxg3 faxg32d faxg4 ijs jpeg jpeggray laserjet lj5gray lj5mono ljet2p ljet3 ljet3d ljet4 ljet4d ljetplus nullpage pbm pbmraw pcx16 pcx24b pcx256 pcxcmyk pcxgray pcxmono pdfwrite pgm pgmraw pgnm pgnmraw pj pjxl pjxl300 pkm pkmraw pksm pksmraw png16 png16m png256 png48 pngalpha pnggray pngmono pnm pnmraw ppm ppmraw ps2write psdcmyk psdrgb psgray psmono psrgb pswrite pxlcolor pxlmono spotcmyk tiff12nc tiff24nc tiff32nc tiffcrle tiffg3 tiffg32d tiffg4 tiffgray tifflzw tiffpack tiffsep uniprint x11 x11alpha x11cmyk x11gray2 x11gray4 x11mono xcf Search path: . : /u1/gnu/gs8.56 : /u1/gnu/gs8.56/lib : /u1/gnu/gs8.56/fonts : /u/scs/gs/fonts : /u/scs/gs/fonts.site : /u1/gnu/fonts.site : /u2/cpagdata/sfna/scs-fonts/fonts : /u/scs/gs/fonts.site-allentown : %rom%lib/ : /usr/local/share/ghostscript/8.56/lib : /usr/local/share/ghostscript/8.56/Resource : /usr/local/share/ghostscript/fonts Initialization files are compiled into the executable. For more information, see /usr/local/share/ghostscript/8.56/doc/Use.htm. Report bugs to bug-gs@ghostscript.com, using the form in Bug-form.htm.
Is there anything else that I can provide? gs7.05 distributed by RedHat with RH Linux 9 has no problems with the file. William $ time /usr/bin/gs -dNOPAUSE -sOutputFile=test705.pdf -sDEVICE=pdfwrite ./pcab.ps GNU Ghostscript 7.05 (2002-04-22) Copyright (C) 2002 artofcode LLC, Benicia, CA. All rights reserved. This software comes with NO WARRANTY: see the file PUBLIC for details. Loading NimbusRomNo9L-Regu font from /usr/share/fonts/default/Type1/n021003l.pfb... 2408988 1052641 1642520 347466 0 done. Loading NimbusSanL-Regu font from /usr/share/fonts/default/Type1/n019003l.pfb... 2783948 1378519 1662616 358654 0 done. Using NimbusSansL-Regu font for NimbusSanL-Regu. ... Loading NimbusSanL-ReguItal font from /usr/share/fonts/default/Type1/n019023l.pfb... 3265968 1672850 1843480 434072 1 done. Loading StandardSymL font from /usr/share/fonts/default/Type1/s050000l.pfb... 3306160 1719478 1903768 462007 1 done. GS>quit real 12m6.989s user 9m57.350s sys 0m19.310s $ ls -l test705.pdf -rw-rw-rw- 1 william users 56020745 Nov 11 16:04 test705.pdf $ cat /etc/redhat-release Red Hat Linux release 9 (Shrike) $ cat /proc/cpuinfo | grep Pent model name : Intel(R) Pentium(R) 4 CPU 1.60GHz
Please try -c 32000000 setvmthreshold on the command line and let us know if that makes a difference in the performance in 9.04. Also, since we are having trouble running this file with 8.54 could you please use 'git bisect' to isolate the change that caused the regression?
I ran time gs -sDEVICE=pdfwrite -o test.pdf -c 32000000 setvmthreshold -f ./pcab.ps with gs 9.04 + the vmreclaim patch from comment 5 and didn't see any difference from the timing that I reported originally without the -c sequence in the unpatched 9.04 release. I'll try the git bisect, but it might be a while. William
I finally figure out that the reason I couldn't reproduce this with versions of gs before 8.56 was a problem with the 64 bit version; the 32 version worked and my performance data matches that of the comment #2. I've since gone through the various commits between 7.00 and master and have found that there were 5 changes that contributed to the performance degradation with this file (see attached timing.png and timing.csv for details). The most significant degradation was with commit 362ab50f5bd97fb6c3498d51cb849ed6a774b679, which resulted in the run time changing from 136 seconds to 1670 seconds: commit 362ab50f5bd97fb6c3498d51cb849ed6a774b679 Author: Ray Johnston <ray.johnston@artifex.com> Date: Wed Feb 21 15:02:42 2007 +0000 Fix for language_switch build 'invalidrestore. Allow filter allocation in systemVM as needed by .runstring and .runstringbegin in gs_init.ps. This fixes problem intoduced by rev 7629. EXPECTED DIFFERENCES. None. Note that CET 23-12W that was fixed with rev 7629 is OK with this change since the 'use_space' is not limited by 'save_space'. git-svn-id: http://svn.ghostscript.com/ghostscript/trunk@7728 a1074d23-0009-0410-80fe-cf8c14f379e6
Created attachment 8342 [details] timing.png
Created attachment 8343 [details] timing.csv
Marcos, thanks! I really appreciate it. Let me know if there is anything that I can do to help. I should have said that I have been doing exclusively 32-bit builds for compatibility with older servers.
This test file is no longer available. If the submitter still has it, please provide it and re-open the bug so we can assess the current performance level.
Ray, sorry, I no longer have the file because it was large and it was 8 years ago. On the positive side, the application that generated that file is still in daily use, and ps2pdf continues to process it quickly. If you want, I can try to pull a current example of the file to do a new set of comparisons. Regards, William
(In reply to Ray Johnston from comment #20) > This test file is no longer available. I found it! I reposted it at https://www.dropbox.com/s/3l2rhackml93jrt/pcab.ps.xz?dl=0 Regards, William
William Bader, thank you for using Ghostscript and keeping historic records. This problem was fixed in v.9.20, and the bug report can be closed now. Here are the results of my overnight run on i7 965 @ 3.20GHz under 64-bit GNU/Linux system with the following command line: gs -sDEVICE=pdfwrite -o /dev/null pcab.ps Ghostscript 8.62 (2008-02-29) 53m3.697s Ghostscript 8.63 (2008-08-01) 52m27.439s Ghostscript 8.64 (2009-02-03) 46m54.301s Ghostscript 8.70 (2009-07-31) 51m6.334s Ghostscript 9.00 (2010-09-14) 64m7.304s Ghostscript 9.01 (2011-02-07) 53m58.782s Ghostscript 9.02 (2011-03-30) 64m31.972s Ghostscript 9.04 (2011-08-05) 57m7.349s Ghostscript 9.05 (2012-02-08) 53m6.517s Ghostscript 9.06 (2012-08-08) 50m12.135s Ghostscript 9.07 (2013-02-14) 54m6.918s Ghostscript 9.09 (2013-08-21) 73m43.652s Ghostscript 9.10 (2013-08-30) 78m44.951s Ghostscript 9.14 (2014-03-26) 72m46.142s Ghostscript 9.15 (2014-09-22) 58m38.218s Ghostscript 9.16 (2015-03-30) 56m26.753s Ghostscript 9.18 (2015-10-05) 59m40.205s Ghostscript 9.19 (2016-03-23) 60m28.672s Ghostscript 9.20 (2016-09-26) 1m10.467s Ghostscript 9.21 (2017-03-16) 1m9.854s Ghostscript 9.22 (2017-10-04) 1m8.757s Ghostscript 9.27 (2019-04-04) 1m7.372s Ghostscript RELEASE CANDIDATE 1 9.28 (2019-08-15) 1m8.125s Ghostscript RELEASE CANDIDATE 2 9.28 (2019-09-05) 1m8.531s Ghostscript RELEASE CANDIDATE 3 9.28 (2019-09-18) 1m8.385s Ghostscript RELEASE CANDIDATE 4 9.28 (2019-09-30) 1m8.270s Ghostscript 9.50 (2019-10-15) 1m8.737s Ghostscript 9.51 (2020-03-12) 1m13.849s Ghostscript 9.52 (2020-03-19) 1m17.514s Ghostscript 9.53.1 (2020-09-14) 1m17.221s Ghostscript 9.53.3 (2020-10-01) 1m13.181s Ghostscript GIT PRERELEASE 9.54.0 (2020-10-01) 1m7.805s