Bug 692959

Summary: Many pages of attached PDF render very slowly, especially with images
Product: Ghostscript Reporter: Till Kamppeter <till.kamppeter>
Component: PDF InterpreterAssignee: 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 8476 [details]
Ausgabe1.pdf

Hi, on

https://bugs.launchpad.net/ubuntu/+source/ghostscript/+bug/668800

comment #36 a user has attached a PDF file (also attached to this bug) and complained that it renders too slowly for him and with the hl1250 output device even leads to errors.

The file has 46 pages, so the slowness can be caused by certain graphical elements on some pages. So I ran the following command line to measure the rendering times of every single page:

p=1; while echo; echo PAGE $p; time gs -dFirstPage=$p -dLastPage=$p -dBATCH -dNOPAUSE -dQUIT -sDEVICE=cups -r600 -sOutputFile=out.raster ~/Ausgabe1.pdf; do p=$(($p + 1)); done 2>&1 | tee log.txt

Note that the loop is infinite, as Ghostscript does not error out when one requests a non-existing page.

log.txt is also attached.

Looking into the original file one sees that the pages which render to slowly contain bitmap images, especially screenshots of some Windows programs, but the slow rendering does not happen for images of scanned hand-written formulas, so it seems to depend on the internal structure of the images, generated by the different applications (scan software, Windows screenshot, ...).

I am using Ghostscript 9.05 as shipped with Ubuntu Precise 12.04 (current state, I hope I can ship one with this problem fixed). The same problem occurs also with Ghostscript 9.04 on Ubuntu Oneiric 11.10.
Comment 1 Till Kamppeter 2012-03-31 21:04:13 UTC
Created attachment 8477 [details]
log.txt
Comment 2 Till Kamppeter 2012-03-31 21:21:49 UTC
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.
Comment 3 Ray Johnston 2012-03-31 21:31:43 UTC
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.
Comment 4 Till Kamppeter 2012-03-31 22:27:18 UTC
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?
Comment 5 Ray Johnston 2012-04-01 01:01:41 UTC
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...
Comment 6 Till Kamppeter 2012-04-01 07:34:31 UTC
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.
Comment 7 Chris Liddell (chrisl) 2012-04-03 15:02:43 UTC
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?
Comment 8 Till Kamppeter 2012-04-03 17:03:26 UTC
Also reported to Cairo:

https://bugs.freedesktop.org/show_bug.cgi?id=48260
Comment 9 Adrian Johnson 2012-04-07 11:56:14 UTC
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.
Comment 10 Chris Liddell (chrisl) 2012-04-07 12:45:42 UTC
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.
Comment 11 Adrian Johnson 2012-04-07 13:56:50 UTC
(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?
Comment 12 Chris Liddell (chrisl) 2012-04-10 09:48:30 UTC
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.
Comment 13 Adrian Johnson 2012-04-10 11:45:51 UTC
(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.
Comment 14 Chris Liddell (chrisl) 2012-04-10 11:59:18 UTC
(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.
Comment 15 Ray Johnston 2012-04-10 17:06:05 UTC
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.)
Comment 16 Ray Johnston 2020-12-07 17:05:46 UTC
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.