Bug 66928

I could not attach the file here due maximum attachment size. Please check the downstream bugreport to download the file. https://bugzilla.redhat.com/show_bug.cgi?id=984235

FWIW they are not in an infinite loop, it just takes *a lot* of time. 

Just to render the first page test-poppler-qt4 is calling GfxICCBaseColorSpace::getRGB 1.6 million times, no wonder it's slow :D

Thomas, do you think you could have a look at why that's happening?

(In reply to comment #2)
> 
> Thomas, do you think you could have a look at why that's happening?

What should be the problem with with Lezione11-ASS.pdf?
I configured actual git master with 
./configure --enable-cms=lcms2
 and called 
./utils/pdftoppm -png -cropbox -r 72 bugzilla/66928.open/Lezione11-ASS.pdf output/lez
rendering the first page only took
real	0m1.466s
the complete PDF took round about 2m 15s, where as page 3 took the most time with round about 19s.

Can I have some more info?

Oh, I see: opening the PDF with okular (also git master) is really annoying, I'll have a deeper look into it.

If I configure poppler with 

./configure --enable-cms=lcms1

it works like a charme even with okular!

Could it be that Your caching of GfxICCBasedColorSpace doesn't work correctly, Albert? The parse routine (and cmsCreateTransform) is called 2640 times (cmsCreateTransform 5280 times) just for the first page!

If you need, I have more files that triggers the problem

(In reply to comment #5)
> Could it be that Your caching of GfxICCBasedColorSpace doesn't work
> correctly, Albert? 

Sorry, Albert, my mistake: had an old callgrind file flying around and kcacheground took it, it was produced prior Your changes ... :-(

I profiled now also page 3, and definitely, the time is wasted in cmsDoTransform. BUT: the call stack is

GfxImageColorMap::getRGB (!!!)
GfxICCBaseColorSpace::getRGB
GfxColorTransform::doTransform
cmsDoTransfrom

called round about 22 million times for page 3, where 256 calls should be sufficient if we cache the results in GfxImageColorMap, but probably we the need to cache GfxImageColorMap, too. But let me first try to cache the RGB results in GfxImageColorMap....

(In reply to comment #6)
> If you need, I have more files that triggers the problem

Not necessary for the moment. If we find a solution for this case and it will not solve it for the other files, please open a new bug.

Created attachment 82478 [details] [review]
cache cms transformed values for images

The patch assumes that the colortransformation from RGB to RGB is somewhat linear, but the result is quite simular (at least in this case), and the perfomance increase is dramatically:

thomas@w7-thomas:~/Entwicklung/xpdfmerge/thread/poppler$ time ./utils/pdftoppm -cropbox -png bugzilla/66928.open/Lezione11-ASS.pdf output/lezval

real	0m20.094s
user	0m19.993s
sys	0m0.052s

Created attachment 83395 [details]
This document is taking more than 32 times more time than Acrobat

The attached document takes more than 32 seconds (usertime) @ 100% for one i5-3570 core (Okular 0.16.5).
Opening the file with Acrobat 9.5.5 takes less than a second.

I see you have found an improvement, Does this work better too ?

Thomas, I've run the regtest and it seems some colorspaces (for example in altona_visual_1v2a_x3.pdf) are not independent regarding r,g,b, that is, you pass
39321 38293 37522
to getRGB, and then
39321 38036 37265
and even if the first of the triplets is the same, the red component in one case is
0.674515
and in the other is
0.670593

Granted is not a big difference, but it is a difference, and maybe in some colorspaces would be even bigger?

What's your opinion on that?

(In reply to comment #11)
> Thomas, I've run the regtest and it seems some colorspaces (for example in
> altona_visual_1v2a_x3.pdf) are not independent regarding r,g,b, that is, you
> pass
> 39321 38293 37522
> to getRGB, and then
> 39321 38036 37265
> and even if the first of the triplets is the same, the red component in one
> case is
> 0.674515
> and in the other is
> 0.670593
> 
> Granted is not a big difference, but it is a difference, and maybe in some
> colorspaces would be even bigger?
> 
> What's your opinion on that?

I expected that behaviour, that's what I meant with "somewhat linear". But I spent just 768 byte for the cache, for an exact cache we need 64 MByte. But after my experiences with the (even if artificial and not RGB but CMYK) profiles of the GWG test PDFs I plan now to make some tests with an exact cache (for RGB -> RGB conversion only) first before thinking about a new option (options we have enough, haven't we?)

Created attachment 83665 [details] [review]
use exact cache for RGB -> RGB color transformations

This new patch uses an exact cache now. It's a little bit slower than the former patch but still much faster than without using a cache.

Hmmm, i don't think creating a 64MB cache is for every GfxICCBasedColorSpace is a good idea, more even when most of it is probably going to be unused, maybe we can use something like an std::set? That should give us an smaller memory footprint.

What do you think?

Created attachment 83706 [details] [review]
cache already transformed values in a map

Better?

(I neary always like Your ideas, Albert :-) )

Created attachment 84136 [details]
Volkwagen Golf prices document

Another document from a different source, that triggers the bug.

the attachment tool does not work with pdf files, then here is another document from another source that triggers the problem
http://it.volkswagen.com/content/medialib/vwd4/it/listini/listino_prezzi/golf-7/_jcr_content/renditions/rendition.file/listino-prezzi-volkswagen-nuova-golf.pdf

(In reply to comment #17)
> the attachment tool does not work with pdf files, then here is another
> document from another source that triggers the problem
> http://it.volkswagen.com/content/medialib/vwd4/it/listini/listino_prezzi/
> golf-7/_jcr_content/renditions/rendition.file/listino-prezzi-volkswagen-
> nuova-golf.pdf

1. The attachment WAS okay, just not marked as PDF, so we don't need that link.
2. It's not helpful that we get one after another PDF with "100% CPU usage". "100% CPU usage" can have several reasons, and if You're not able to apply my bugfix by Your own and look if it solves it, You're probably also not able to decide where the "100% CPU usage" comes from. In this case You should just wait until this bug is closed, wait until the new release is available and then test Your problematic PDF files again, and if there are then still problems, open a new bug because it then WILL have another reason.
3. Last but not least: I've tested every attached PDF of this bug with my bugfix in okular and I can tell that the bugfix solves them all, but I will not continue to look at every new attached PDF until Albert has the time to test my bugfix and agrees with it. All of us are working at poppler in our free time, so sometimes it will take a while until problems are solved.

Thomas, the patch looks good, but before regtesting+committing I went ahead and tried the Cairo backend and it's relly fast without this patch.

I see that the difference is that they call getRGBLine instead of getRBG, and that seems to make lcms much happier.

Before introducing this cache (that can increase the memory usage quite a bit), do you think it makes sense to explore the use of getRBGLine instead of gerRBG? Do you have time to look at that or want me to try to find some time?

(In reply to comment #19)
> Thomas, the patch looks good, but before regtesting+committing I went ahead
> and tried the Cairo backend and it's relly fast without this patch.
> 
> I see that the difference is that they call getRGBLine instead of getRBG,
> and that seems to make lcms much happier.
> 
> Before introducing this cache (that can increase the memory usage quite a
> bit), do you think it makes sense to explore the use of getRBGLine instead
> of gerRBG? Do you have time to look at that or want me to try to find some
> time?

I'll have a look at it, Albert (unfotunately I have to work this weekend, but perhaps I'll find some time during next week). On the other hand: with the patch I don't cache the return values of getRGBLine(), so the usage of it will not increase memory usage dramatically even with my patch. So wouldn't it be a good idea to have it both: have a fast usage of getRGB() but use getRGBLine() where ever it is possible?

If (yet to be seen) using getRGBLine fixes the problem, i just think we should kill getRGB since it's probably never really needed, but let's see if getRGBLine  fixes the issue or not and then discuss how to proceed.

(In reply to comment #21)
> If (yet to be seen) using getRGBLine fixes the problem, i just think we
> should kill getRGB since it's probably never really needed, but let's see if
> getRGBLine  fixes the issue or not and then discuss how to proceed.

Are You sure Albert? We can call getRGBLine in case of images, but nowhere else! I.e. every shading, but I think also a lot of other calls, can call getRGBline with only one value, and in this case, I will not expect any performance increasements. So You can wait until I try to increase speed with the usage of getRGBLine(), but You never van kill getRGB() at all!

Created attachment 84195 [details] [review]
use getRGBLine, getCMYKLine and getDeviceNLine in case of images if they ara available

I finished my qork quicker than expected, so I had some time to look into it already, and here is the patch.
Yes, Albert, You were true (as always): the usage of getRGBLine speed up the rendering in case of images. I think that at least lcms2 does than some caching internally. But to complete it also in the CMYK and DeviceN area, we need for them the correcponding functions, too. So this patch does not only use getRGBLine in SplashOutputDev, but it also implements the other needed functions.

And even if I still think we need the cache i.e. for the getRGB() function, I've removed it from this patch, because we don't need it to solve this bug now. On the other hand I don't mark it as obsolete, it's up to You, Albert, to think once again about it.

I've commited the getRGBLine to 0.24, was going to commit the other get*Line  to master (as it's new code and introduces new api) but it doesn't compile when SPLASH_CMYK is not defined.

Can you have a look?

Also about the other cache for the single getRGB, would you mind opening a new bug and we discuss it there? I'd like to close this one as soon as the get*Line variants have been commited to master since it fixes the slowlyness on this bugs.

I'll so i'll rename the bug so that people don't try to use it as a catch all

Created attachment 84319 [details] [review]
use getCMYKLine and getDeviceNLine in CMYK mode in case of images if they ara available

Here a slightly modified patch for CMYK mode: I go the simplier way, just removed the #ifdef SPLASH_CMYK for SPOT_NCOMPS instead of inserting a lot of #ifdef's in GfxState. One reason for this way was that it was nowhere (in GfxState) used before, even not for getDeviceN() which is also only used when compiled with SPLASH_CMYK. Another reason is that I'm still thinking that we should remove the SPLASH_CMYK directives at all someday.

Regarding the cache for the single getRGB: okay, I'll open a new bug someday. First we should commit this and find a solution for bug 34053. In the meantime I'll try to find (or create) a PDF where the cache will be a really improvement.

Ok, commited.

Thomas can we close this bug now and handle the getRBG cache in the other one you opened?

Created attachment 84644 [details] [review]
resolve copy&paste error

Sorry, Albert! I made a copy&paste error. This solves it!

Albert, are You able to have a look at the patch of comment 27? Without that we get crashes (colorSpace2 is NULL and cannot be used there!!!)

Yes, yes, was sick yesterday afternoon and all i did was release the monthly 0.24.x stable patch we promised and then hit the bed, it's on the queue, don't worry.

Pushed