| Summary: | Many pages of attached PDF render very slowly, especially with images | ||
|---|---|---|---|
| Product: | Ghostscript | Reporter: | Till Kamppeter <till.kamppeter> |
| Component: | PDF Interpreter | Assignee: | Ray Johnston <ray.johnston> |
| Status: | RESOLVED FIXED | ||
| Severity: | major | CC: | ajohnson, chris.liddell, jackie.rosen |
| Priority: | P4 | ||
| Version: | 9.05 | ||
| Hardware: | PC | ||
| OS: | Linux | ||
| Customer: | Word Size: | --- | |
| Attachments: |
Ausgabe1.pdf
log.txt log2.txt test case |
||
|
Description
Till Kamppeter
2012-03-31 21:03:08 UTC
Created attachment 8477 [details]
log.txt
Created attachment 8478 [details]
log2.txt
I have also tried with the "hl1250" output device but I had no problems with errors. The rendering slownesses seem to be the same.
Command line used:
p=1; while echo; echo PAGE $p; time gs -dFirstPage=$p -dLastPage=$p -dBATCH -dNOPAUSE -dQUIT -sDEVICE=hl1250 -r600 -sOutputFile=out.prn ~/Ausgabe1.pdf; do p=$(($p + 1)); done 2>&1 | tee log2.txt
log2.txt attached.
First, please document the 'even leads to errors'. Until it is established that there are errors from the processing, I am changing the severity to "enhancement". The original user mentions several VERY different system configurations: 1) Pentium 3 500 MHz with 312Mb RAM (a VERY old, slow and small system), 2) Q6600 (Core 2) Duo machine with 4GB (only about 5 years old, but decent) but does not quantify the timings observed. Note that the gs option -Z: prints out the Outputpage start and end times, so is generally useful if 'wall clock' timing is adequate (this time is the same as the "time" command "real" time, not the CPU "user" time). You can determine if the time increase is during parsing of the PDF and writing of the clist (display list) or during rendering, or shared. If the time increase is mostly during parsing, then the image decompression may be a contributor. Also examination of the -dPDFDEBUG output for the slow pages may provide some insight. Some systems output images as a whole mess of single line images rather than as a single image. Ghostscript 9.00 and later performs color management based on ICC profiles, which is more correct, but slower than what 8.xx used. The -dUseFastColor option uses color conversion that is more similar to 8.xx in the colors produced and in the speed of conversion. Lastly profiling of the slow pages will point to the area of slowness. Note that the system of the original poster of the Ubuntu bug (Oliver) is not relevant for the poster of the attached file (Stefan D.), I can reproduce the problem on a recent laptop, as you can see in my measurements in my attached log files. The errors the user complains about when he uses the "hl1250" output device, I cannot reproduce. Adding "-dPDFDEBUG" does not solve the problem for me. The rendering times do not change significantl. If I run with "-Z:" I get something like: % Outputpage start time = 31.0733, memory allocated = 5924824, used = 5290237 INFO: Processing page 9... % Outputpage end time = 36.9526, memory allocated = 6489976, used = 5619949 Page 9 % Outputpage start time = 37.4091, memory allocated = 5806548, used = 5138879 INFO: Processing page 10... % Outputpage end time = 44.6249, memory allocated = 6472620, used = 5440775 Page 10 % Outputpage start time = 44.8508, memory allocated = 6078160, used = 5794645 INFO: Processing page 11... % Outputpage end time = 66.7253, memory allocated = 6885520, used = 6021717 Page 11 % Outputpage start time = 66.7674, memory allocated = 5205192, used = 4804162 INFO: Processing page 12... % Outputpage end time = 66.7849, memory allocated = 5205192, used = 4804162 Page 12 For all pages with slow rendering time there quickly appears "% Outputpage start time ..." then it takes its time and after that the lines "INFO: Processing page ...", "% Outputpage end time ...", and "Page ..." appear in a quick sequence, so most of the time of the processing of the page happens between "% Outputpage start time ..." and "INFO: Processing page ...". If I add "-Z: -dPDFDEBUG", the page takes its time always right after "% Outputpage start time ..." appears, all other output is coming out in a very quick sequence. What does it mean? Is the problem parsing speed or rendering speed? Running on my core i5 2.4 GHz laptop I get the following set of parse and render times: parse: 0.116 render: 0.003 parse: 0.101 render: 0.003 parse: 0.37 render: 2.535 parse: 0.067 render: 0.004 parse: 0.184 render: 5.389 parse: 0.15 render: 3.471 parse: 0.089 render: 1.962 parse: 0.239 render: 3.739 parse: 0.131 render: 3.696 parse: 0.102 render: 22.56 parse: 0.027 render: 0.002 parse: 0.73 render: 53.23 parse: 0.071 render: 0.001 parse: 0.125 render: 2.488 parse: 0.075 render: 0.002 parse: 0.173 render: 0.003 parse: 0.263 render: 106.7 parse: 0.062 render: 75.03 parse: 0.964 render: 35.31 parse: 0.325 render: 63.08 parse: 0.072 render: 0.003 parse: 0.469 render: 33.55 parse: 0.809 render: 13.03 parse: 0.08 render: 153.82 parse: 0.485 render: 109.1 parse: 0.281 render: 0.003 parse: 0.559 render: 69.95 parse: 0.582 render: 100.4 parse: 0.341 render: 105.3 parse: 0.365 render: 5.757 parse: 0.512 render: 54.10 parse: 0.82 render: 0 parse: 0.07 render: 0 parse: 0.07 render: 0 parse: 0.22 render: 4.19 parse: 0.44 render: 36.51 parse: 0.21 render: 6.78 parse: 0.36 render: 6.54 parse: 0.37 render: 45.04 parse: 0.59 render: 29.77 parse: 0.59 render: 38.84 parse: 0.18 render: 3.05 parse: 0.3 render: 31.01 parse: 0.75 render: 39.99 parse: 0.44 render: 64.99 parse: 0.23 render: 30.29 Final time: 1376.16 Note these were run on a 'release' (not 'debug') build with: time bin/gswin32c -Z: -r600 -sDEVICE=pbmraw -o nul: Bug692959.pdf (i.e. default parameters for clist, band height, etc.) The 'time' command showed: real 22m56.342s user 0m0.000s sys 0m0.015s but the '0m.000s' user time may be due to a bug in the msys shell. In any case, I can confirm that some pages are slow and that the entire slowdown is with the render time (all of the parse times are < 1 second). The 'Task Manager' showed my CPU time at 25% the entire time, so that tells me that the CPU was the bottleneck (as expected with -o nul:) Running with -dNumRenderingThreads=4 (appropriate for a core i5) shows near 100% cpu time and shows: parse: 0.099 render: 0.003 parse: 0.086 render: 0.004 parse: 0.313 render: 1.385 parse: 0.054 render: 0.003 parse: 0.159 render: 2.604 parse: 0.128 render: 1.788 parse: 0.094 render: 0.982 parse: 0.194 render: 1.7 parse: 0.109 render: 1.807 parse: 0.085 render: 9.655 parse: 0.023 render: 0.003 parse: 0.627 render: 27.412 parse: 0.075 render: 0.003 parse: 0.098 render: 1.617 parse: 0.086 render: 0.004 parse: 0.205 render: 0.004 parse: 0.296 render: 81.864 parse: 0.087 render: 67.028 parse: 1.239 render: 30.649 parse: 0.554 render: 52.587 parse: 0.106 render: 0.003 parse: 0.81 render: 27.848 parse: 1.389 render: 10.852 parse: 0.106 render: 122.911 parse: 0.786 render: 85.708 parse: 0.403 render: 0.002 parse: 0.921 render: 55.596 parse: 0.937 render: 77.673 parse: 0.523 render: 81.173 parse: 0.484 render: 4.599 parse: 0.821 render: 42.358 parse: 1.343 render: 0.002 parse: 0.117 render: 0.003 parse: 0.108 render: 0.002 parse: 0.333 render: 3.264 parse: 0.68 render: 27.983 parse: 0.338 render: 5.111 parse: 0.541 render: 5.137 parse: 0.666 render: 34.177 parse: 0.914 render: 24.11 parse: 0.909 render: 30.186 parse: 0.299 render: 2.553 parse: 0.41 render: 24.25 parse: 1.209 render: 30.807 parse: 0.697 render: 51.547 parse: 0.35 render: 23.62 Final time: 1073.49 real 17m53.688s user 0m0.015s sys 0m0.031s Why this file is so slow on some pages probably (as Till suggessted) has to do with transparency. Running gswin32c -- toolbin/pdf_info.ps Bug692959.pdf gives: c:/Artifex/bugs/bug-gs/Bug692959.pdf has 46 pages Creator: cairo 1.10.2 (http://cairographics.org) Producer: cairo 1.10.2 (http://cairographics.org) Page 1 MediaBox: [0 0 595.275574 841.889771] Page 2 MediaBox: [0 0 595.275574 841.889771] Page 3 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 4 MediaBox: [0 0 595.275574 841.889771] Page 5 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 6 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 7 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 8 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 9 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 10 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 11 MediaBox: [0 0 595.275574 841.889771] Page 12 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 13 MediaBox: [0 0 595.275574 841.889771] Page 14 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 15 MediaBox: [0 0 595.275574 841.889771] Page 16 MediaBox: [0 0 595.275574 841.889771] Page 17 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 18 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 19 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 20 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 21 MediaBox: [0 0 595.275574 841.889771] Page 22 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 23 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 24 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 25 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 26 MediaBox: [0 0 595.275574 841.889771] Page 27 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 28 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 29 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 30 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 31 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 32 MediaBox: [0 0 595.275574 841.889771] Page 33 MediaBox: [0 0 595.275574 841.889771] Page 34 MediaBox: [0 0 595.275574 841.889771] Page 35 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 36 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 37 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 38 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 39 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 40 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 41 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 42 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 43 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 44 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 45 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features Page 46 MediaBox: [0 0 595.275574 841.889771] Page uses transparency features No system fonts are needed. Note that the Creator -- "Cairo" is notorious for generating VERY bad PDF's that render inefficiently. One of the Cairo deficiencies is that they don't properly establish the BoundingBox for regions needing transparency, instead defaulting to the entire page. Running this file on a debug build with -Z: may give some insight. Since it takes so long to run, I'll post any information later... Yes, it must be transparency, with -dNOTRANSPARENCY the whole file renders in 90 seconds for me, but I cannot apply this option in our print work flow as many files will come out incorrectly then. Till, Have you (or has anyone) reported the poorly calculated bounding boxes, and the totally pointless transparency stuff that comes of the Cairo PDF generation code to Cairo themselves? Also reported to Cairo: https://bugs.freedesktop.org/show_bug.cgi?id=48260 Created attachment 8510 [details] test case The bounding box problem has been fixed in cairo 1.12. I did some testing with the test case in https://bugs.launchpad.net/ubuntu/+source/ghostscript/+bug/968785 comment 4. ie printing this page from firefox: http://www.mindtools.com/pages/article/newPPM_94.htm. This command line used in the bug report is: gs -q -dNOPAUSE -dBATCH -dSAFER -sDEVICE=ps2write -dLanguageLevel=3 -dCompressFonts=false -dNoT3CCITT -dEncodeMonoImages=false -dEncodeColorImages=false -sOUTPUTFILE=out.ps test.pdf The attached test case is one page that has been extracted from the firefox pdf output using pdftk. It takes 11 seconds to run the above command. The text in the PS output has been rasterized. The pdf contains some text and a couple of small images with smasks. If I remove the smask from the images then gs takes less than a second to run and the text is not rasterized. What is the issue with this pdf? There are no page sized bounding boxes or pointless transparency in this pdf. The size of the bounding box is only part of the problem. The file contains SMask objects (for no readily apparent reason - removing the SMasks doesn't seem to change the output). In general, we check for "meaninful" transparency, and if we don't find any, then we skip the blending code, but realistically, we can't check the entire content of an SMask (we might end up having pre-process the entire page). So, those SMask objects mean we *have* to go through the motions of flattening *all* the PDF transparency constructs to display in an opaque imaging model (PDF supports transparency, Postscript doesn't), and the only really reliable way to do that is to render to an image. Note also that ps2write, being a Postscript Level 2 device, does not support CIDFonts (the -dLanguageLevel=3 setting is spurious and has no effect), which are used in the PDF file, so even without the transparency problems, the text will be converted into Type 3 Postscript fonts. Still boils down to needless transparency in in PDF. With the SMask objects in place, the PDF file from the above Ubuntu bug takes 1m35s to convert through ps2write, and results in a PS file that is 13Mb in size. Removing the SMask objects, it takes 2.8 seconds, and results in a 2.8Mb PS file. And I can't see any visible differences in the printed output. The PDF file tells us we have to do transparency blending, so we do. That's hardly Ghostscript's fault..... Note that page 12 of Ausgabe1.pdf takes Acrobat more than 1 minute to render at 600 dpi. (In reply to comment #10) > The size of the bounding box is only part of the problem. The file contains > SMask objects (for no readily apparent reason - removing the SMasks doesn't > seem to change the output). Without the smasks the light gray bars are black. > In general, we check for "meaninful" transparency, and if we don't find any, > then we skip the blending code, but realistically, we can't check the entire > content of an SMask (we might end up having pre-process the entire page). Cairo already checks for "meaningful" transparency in image smasks and avoids emitting the smask if the image is opaque. In this case the transparency was requested by the application supplying an RGBA image, the transparency was "meaningful", so cairo had to included the smask. > So, those SMask objects mean we *have* to go through the motions of flattening > *all* the PDF transparency constructs to display in an opaque imaging model > (PDF supports transparency, Postscript doesn't), and the only really reliable > way to do that is to render to an image. I'm not understanding the problem here. The smask is part of the image so only the image needs to be flattened. The rest of the content is opaque. What exactly is gs doing different when there is an image with an smask? In investigating another issue, it turns out that poppler also renders the entire page to an image - it just does so at a lower resolution than we do. Ghostscript's ps2write defaults to 720dpi whilst pstops defaults to 300dpi. If I set Ghostscript's resolution also 300dpi, the time and file size for the Postscript output is much closer between GS and pstops. I guess we need to establish what resolution the poppler based cups raster filter was using, too. (In reply to comment #12) > I guess we need to establish what resolution the poppler based cups raster > filter was using, too. pdftops defaults to 300dpi. Prior to version 0.18 (released Sep 2011) it was not possible to change the resolution. Cairo PS output will only rasterize the regions containing transparency. Running "pdftocairo -ps -r 600 test.pdf out.ps" takes about 70ms and produces a 104KB PS file that prints as fast as my printer can print it. Is there any reason why ghostscript can't rasterize only the transparent regions? When printing the ghostscript PS output from test.pdf, my printer takes about 30 seconds to process the job before it starts printing and the text comes out in rich black. (In reply to comment #13) > (In reply to comment #12) > > I guess we need to establish what resolution the poppler based cups raster > > filter was using, too. > > pdftops defaults to 300dpi. Prior to version 0.18 (released Sep 2011) it was > not possible to change the resolution. > > Cairo PS output will only rasterize the regions containing transparency. > Running "pdftocairo -ps -r 600 test.pdf out.ps" takes about 70ms and produces a > 104KB PS file that prints as fast as my printer can print it. I don't have access to pdftocairo, but pdftops takes ~1 second, and produces a 1.1Mb file, which is the entire page group in a rasterized image. Ghostscript using ps2write takes ~1.5 seconds, and results in a 510k PS file, which is also the entire page group in a rasterized image. > Is there any reason why ghostscript can't rasterize only the transparent > regions? When printing the ghostscript PS output from test.pdf, my printer > takes about 30 seconds to process the job before it starts printing and the > text comes out in rich black. Yes, there is a reason why Ghostscript can't do that. In order for text to be in K only, the ps2write device would need to work in the CMYK color space and then the ICC profile would for 'text' would need to map black to K (as opposed to the default output ICC profile). Refer to doc/Use.htm#ICC_color_parameters for the -sTextICCProfile=filename and -sTextIntent=intent (0-3) BTW, the reason that the entire page is rendered as an image is that the PDF transparency model requires any transparent region to be 'blended' on top of any graphics on the page. Since we don't do full analysis of the PDF to determine what paints where, we have to render graphics to the page level transparency buffers just in case some later transparency group (that may have a BBox that is a subset of the page) must be blended onto some marks already made on the page level. Trying to allow the printer PS RIP to render parts of the page outside the area where the transparency is actually used (as with an image with SMask) might work in simple cases, but rendering detail differences would make it impossible to have objects that cross "into" the area that is pre-rendered have the correct appearance (no glitches at the boundary, color matches, etc.) This bug somehow shifted from 1-bit raster output for the hl1250 to ps2write. In any case, with current Ghostscript (9.53.3) release build, the ORIGINAL test case (46 page Ausgabe1.pdf), this takes 151 seconds. If I add some parameters to make more use of memory, then it speeds up to 42 seconds. I added: -dMaxBitmap=1g which is enough to let it render completely in RAM (as most software does since they don't have a banding/clist mode). The ps2write testing of the second file is so fast it isn't worth dealing with, and I'm not sure how that got wrapped up in this bug. Closing (seems fast enough, particularly with the increased RAM usage). It may be that we've made some performance improvements since this was opened. |