You are viewing a plain text version of this content. The canonical link for it is here.
Posted to fop-dev@xmlgraphics.apache.org by Ognjen Blagojevic <og...@gmail.com> on 2011/03/11 12:54:03 UTC

20x slowdown in PNG processing when switching from JDK 1.6.0_17 to 1.6.0_18

Hi,

(This seems to be JDK issue, but I would like to pinpoint it together 
with Apache FOP/xmlgraphics developers, since it has significant impact 
on performance.)

I'm using Apache FOP 1.0 to generate a large number of PDF documents 
(each having 8 A4 pages). Those documents contain PNG images. One 
particular image is sized 2035x1875 pixels. This image uses "sRGB 
IEC61966-2.1" color profile. FOP generates PDF in about 2 seconds.

But, when I switched from JDK 1.6.0_17 to JDK 1.6.0_18 (or latest JDK 
1.6.0_24), I noticed that PDF generation takes around 40 seconds. 
Slowdown is noticable on both CentOS Linux 5.5, and Windows XP. If I 
remove color profile from PNG, the performance is back to normal ~2s.

Profiler reveals that single method call

 
org.apache.xmlgraphics.ps.ImageEncodingHelper.encodeRenderedImageAsRGB(RenderedImage 
image, OutputStream out)

takes ~2s when using 1.6.0_17, and ~40s when using JDK 1.6.0_18. This 
method in turn calls several transformations for every pixel (~2M times):

     for (int y = 0; y < h; y++) {
         int idx = -1;
         for (int x = 0; x < w; x++) {
             int rgb = colorModel.getRGB(raster.getDataElements(x, y, 
data)); // (*)
             buf[++idx] = (byte)(rgb >> 16);
             buf[++idx] = (byte)(rgb >> 8);
             buf[++idx] = (byte)(rgb);
         }
         out.write(buf);
     }

Now, it seems that marked line (*) calls JDK methods responsible for 
this slowdown.

I'm stuck here. I'm having hard time profiling JDK methods. I tried to 
make several thread dumps during execution, and it is always the same 
native method being executed:

java.lang.Thread.State: RUNNABLE
   at sun.awt.color.CMM.cmmColorConvert(Native Method)
   at sun.awt.color.ICC_Transform.colorConvert(ICC_Transform.java:862)
   - locked <0x2983f388> (a sun.awt.color.ICC_Transform)
   at java.awt.color.ICC_ColorSpace.toRGB(ICC_ColorSpace.java:160)
   (...)

Ironically, in JDK 1.6.0_18 release notes [1], the only issue related to 
PNG is: "Faster processing of PNG images. (Refer to 6549882.)", which 
is, again, hidden bug for security reasons.

Having said all this, my proposal is:

1. if someone can help me to track bug further (remember, 1.6.0_17 was 
working just fine) we could file the bug report to Oracle, or
2. we could just add the info in FOP/xmlgraphics docs that color profile 
in PNG images introduces significant slowdown on JDK 1.6.0_18+.

What do you think?


[1] http://www.oracle.com/technetwork/java/javase/6u18-142093.html

Re: 20x slowdown in PNG processing when switching from JDK 1.6.0_17 to 1.6.0_18

Posted by Jeremias Maerki <de...@jeremias-maerki.ch>.
A color profiles how pixel data is supposed to be interpreted. XSL-FO
and SVG, by default, work in the sRGB color space which is a
standardized RGB color profile. If you don't have a color profile, you
don't know exactly what the color will look like on screen or paper when,
for example, you have a color rgb(123,166,45). This is being referred to
as an uncalibrated color. OTOH, if you know that this RGB color is in
the sRGB color space, the appearance of that color is closely defined
and is therefore called calibrated

You can read more about color management here:
http://en.wikipedia.org/wiki/Color_management

Yes, you can get color output without a color profile resulting in
uncalibrated (i.e. not necessarily correct colors). But you're using
PNGRenderer and since Java internally works with sRGB and PNG does, too,
you'll get calibrated sRGB colors.

On 18.03.2011 14:10:16 Eric Douglas wrote:
> What is this color profile?  Can I get color output without it?  I am
> using the PNGRenderer, currently running JDK 6u17 about to install u24
> today. 
> 
> -----Original Message-----
> From: Ognjen Blagojevic [mailto:ognjen.d.blagojevic@gmail.com] 
> Sent: Friday, March 18, 2011 4:21 AM
> To: fop-dev@xmlgraphics.apache.org
> Subject: Re: 20x slowdown in PNG processing when switching from JDK
> 1.6.0_17 to 1.6.0_18
> 
> On 11.3.2011 12:54, Ognjen Blagojevic wrote:
> > Having said all this, my proposal is:
> >
> > 1. if someone can help me to track bug further (remember, 1.6.0_17 was
> 
> > working just fine) we could file the bug report to Oracle, or 2. we 
> > could just add the info in FOP/xmlgraphics docs that color profile in 
> > PNG images introduces significant slowdown on JDK 1.6.0_18+.
> 
> Ok, since it seems that it is too hard to track this down, I suggest we
> add to PNG Graphics page [1] something like:
> 
> "Note: PNG images with color profile are on certain JDKs (most notably
> Oracle JDK 6u18+) processed as much as 20 times slower than same images
> without color profile. This slowdown is introduced by JDK image
> manipulation classes."
> 
> Thoughts?
> 
> -Ognjen
> 
> [1] http://xmlgraphics.apache.org/fop/1.0/graphics.html#png




Jeremias Maerki


RE: 20x slowdown in PNG processing when switching from JDK 1.6.0_17 to 1.6.0_18

Posted by Eric Douglas <ed...@blockhouse.com>.
What is this color profile?  Can I get color output without it?  I am
using the PNGRenderer, currently running JDK 6u17 about to install u24
today. 

-----Original Message-----
From: Ognjen Blagojevic [mailto:ognjen.d.blagojevic@gmail.com] 
Sent: Friday, March 18, 2011 4:21 AM
To: fop-dev@xmlgraphics.apache.org
Subject: Re: 20x slowdown in PNG processing when switching from JDK
1.6.0_17 to 1.6.0_18

On 11.3.2011 12:54, Ognjen Blagojevic wrote:
> Having said all this, my proposal is:
>
> 1. if someone can help me to track bug further (remember, 1.6.0_17 was

> working just fine) we could file the bug report to Oracle, or 2. we 
> could just add the info in FOP/xmlgraphics docs that color profile in 
> PNG images introduces significant slowdown on JDK 1.6.0_18+.

Ok, since it seems that it is too hard to track this down, I suggest we
add to PNG Graphics page [1] something like:

"Note: PNG images with color profile are on certain JDKs (most notably
Oracle JDK 6u18+) processed as much as 20 times slower than same images
without color profile. This slowdown is introduced by JDK image
manipulation classes."

Thoughts?

-Ognjen

[1] http://xmlgraphics.apache.org/fop/1.0/graphics.html#png

Re: 20x slowdown in PNG processing when switching from JDK 1.6.0_17 to 1.6.0_18

Posted by "Peter B. West" <li...@pbw.id.au>.
Ognjen,

You may well have it, depending on where you got your Java installation. I see you're on windows, so it's probably already included. With linux, I used to have to install it myself, but I've been using OS X for a while now, so I don't know about  either Windows or linux any more.

The others will tell you if it's necessary.

Peter West

"Why do you seek the living among the dead? He is not here, but is risen."

On 04/05/2011, at 11:24 PM, Ognjen Blagojevic wrote:

> Hi Peter,
> 
> I didn't install anything other than regular JDK for Linux.
> 
> Do you mean "JAI library" or "JAI Image I/O tools"? They are both mentioned in FOP docs [1], but from what I understand neither is necessary for PNG image manipulation:
> 
> "(BMP, TIFF) Requires the presence of JAI Image I/O Tools (or an equivalent Image I/O compatible codec) in the classpath. JAI Image I/O Tools also adds support for JPEG 2000, WBMP, RAW and PNM. Other Image I/O codecs may provide support for additional formats.".
> 
> Do I need to install it, anyway?
> 
> Regards,
> Ognjen
> 
> [1] http://xmlgraphics.apache.org/fop/1.0/graphics.html#support-overview


Re: 20x slowdown in PNG processing when switching from JDK 1.6.0_17 to 1.6.0_18

Posted by Ognjen Blagojevic <og...@gmail.com>.
Hi Peter,

I didn't install anything other than regular JDK for Linux.

Do you mean "JAI library" or "JAI Image I/O tools"? They are both 
mentioned in FOP docs [1], but from what I understand neither is 
necessary for PNG image manipulation:

"(BMP, TIFF) Requires the presence of JAI Image I/O Tools (or an 
equivalent Image I/O compatible codec) in the classpath. JAI Image I/O 
Tools also adds support for JPEG 2000, WBMP, RAW and PNM. Other Image 
I/O codecs may provide support for additional formats.".

Do I need to install it, anyway?

Regards,
Ognjen

[1] http://xmlgraphics.apache.org/fop/1.0/graphics.html#support-overview




On 4.5.2011 14:08, Peter B. West wrote:
> I suppose you have JAI installed in both 6u17 and 6u18/24?
>
> Peter West
>
> "Why do you seek the living among the dead? He is not here, but is risen."
>
> On 04/05/2011, at 8:17 PM, Ognjen Blagojevic wrote:
>
>> Hi,
>>
>> To keep issue alive, I reported a bug:
>>
>>   https://issues.apache.org/bugzilla/show_bug.cgi?id=51149
>>
>> Regards,
>> Ognjen
>
>


Re: 20x slowdown in PNG processing when switching from JDK 1.6.0_17 to 1.6.0_18

Posted by "Peter B. West" <li...@pbw.id.au>.
I suppose you have JAI installed in both 6u17 and 6u18/24?

Peter West

"Why do you seek the living among the dead? He is not here, but is risen."

On 04/05/2011, at 8:17 PM, Ognjen Blagojevic wrote:

> Hi,
> 
> To keep issue alive, I reported a bug:
> 
>  https://issues.apache.org/bugzilla/show_bug.cgi?id=51149
> 
> Regards,
> Ognjen


Re: 20x slowdown in PNG processing when switching from JDK 1.6.0_17 to 1.6.0_18

Posted by Ognjen Blagojevic <og...@gmail.com>.
Hi,

To keep issue alive, I reported a bug:

   https://issues.apache.org/bugzilla/show_bug.cgi?id=51149

Regards,
Ognjen


On 19.3.2011 12:30, Ognjen Blagojevic wrote:
> Jeremias,
>
> For this particular image, with Java 6u17 I get:
>
> [DEBUG] New ImageAdapter created for key:
> (snip)/image-with-color-profile.png
> [DEBUG] Image returns ICC profile: sRGB IEC61966-2.1, default sRGB=false
>
> Image processing is fast, program execution time is 7s.
>
>
> However, with JDK 6u24, I get
>
> [DEBUG] New ImageAdapter created for key:
> (snip)/image-with-color-profile.png
> [DEBUG] Image returns ICC profile: sRGB IEC61966-2.1, default sRGB=true
>
> Image processing is slow, program execution time is 52s.
>
>
> This seems to be contrary to what is expected?
>
> Here is PNG attached (if the list accepts it).
>
> -Ognjen
>
>
> On 18.3.2011 16:32, Jeremias Maerki wrote:
>> Ognjen,
>> sorry for the late answer. Could you please set the following log level
>> to FINE/DEBUG: org.apache.fop.render.pdf.AbstractImageAdapter
>>
>> If you get the line "Image returns ICC profile: sRGB, default sRGB=true",
>> your PNG is a normal sRGB bitmap. This will (normally) allow FOP to dump
>> the bitmap data efficiently to the output file.
>>
>> In your case, the encoded color model seems to differ from the original
>> one which is why the ImageEncodingHelper (from XML Graphics Commons)
>> falls back to encoding sRGB data which has to go through color
>> management. And that's what's making the process very slow. Every pixel
>> is converted to sRGB by the color profile associated with the
>> BufferedImage that has been built from the PNG file.
>>
>> But...I cannot reproduce your problem. With all PNGs I've tested I get
>> optimized encoding (Sun Java 6.0_24). Could you please send me your PNG?
>> Maybe there's something peculiar about it.
>>
>> On 18.03.2011 09:20:34 Ognjen Blagojevic wrote:
>>> On 11.3.2011 12:54, Ognjen Blagojevic wrote:
>>>> Having said all this, my proposal is:
>>>>
>>>> 1. if someone can help me to track bug further (remember, 1.6.0_17 was
>>>> working just fine) we could file the bug report to Oracle, or
>>>> 2. we could just add the info in FOP/xmlgraphics docs that color
>>>> profile
>>>> in PNG images introduces significant slowdown on JDK 1.6.0_18+.
>>>
>>> Ok, since it seems that it is too hard to track this down, I suggest we
>>> add to PNG Graphics page [1] something like:
>>>
>>> "Note: PNG images with color profile are on certain JDKs (most notably
>>> Oracle JDK 6u18+) processed as much as 20 times slower than same images
>>> without color profile. This slowdown is introduced by JDK image
>>> manipulation classes."
>>>
>>> Thoughts?
>>>
>>> -Ognjen
>>>
>>> [1] http://xmlgraphics.apache.org/fop/1.0/graphics.html#png
>>
>>
>>
>>
>> Jeremias Maerki
>>
>>
>


Re: 20x slowdown in PNG processing when switching from JDK 1.6.0_17 to 1.6.0_18

Posted by Ognjen Blagojevic <og...@gmail.com>.
Jeremias,

For this particular image, with Java 6u17 I get:

[DEBUG] New ImageAdapter created for key: 
(snip)/image-with-color-profile.png
[DEBUG] Image returns ICC profile: sRGB IEC61966-2.1, default sRGB=false

Image processing is fast, program execution time is 7s.


However, with JDK 6u24, I get

[DEBUG] New ImageAdapter created for key: 
(snip)/image-with-color-profile.png
[DEBUG] Image returns ICC profile: sRGB IEC61966-2.1, default sRGB=true

Image processing is slow, program execution time is 52s.


This seems to be contrary to what is expected?

Here is PNG attached (if the list accepts it).

-Ognjen


On 18.3.2011 16:32, Jeremias Maerki wrote:
> Ognjen,
> sorry for the late answer. Could you please set the following log level
> to FINE/DEBUG: org.apache.fop.render.pdf.AbstractImageAdapter
>
> If you get the line "Image returns ICC profile: sRGB, default sRGB=true",
> your PNG is a normal sRGB bitmap. This will (normally) allow FOP to dump
> the bitmap data efficiently to the output file.
>
> In your case, the encoded color model seems to differ from the original
> one which is why the ImageEncodingHelper (from XML Graphics Commons)
> falls back to encoding sRGB data which has to go through color
> management. And that's what's making the process very slow. Every pixel
> is converted to sRGB by the color profile associated with the
> BufferedImage that has been built from the PNG file.
>
> But...I cannot reproduce your problem. With all PNGs I've tested I get
> optimized encoding (Sun Java 6.0_24). Could you please send me your PNG?
> Maybe there's something peculiar about it.
>
> On 18.03.2011 09:20:34 Ognjen Blagojevic wrote:
>> On 11.3.2011 12:54, Ognjen Blagojevic wrote:
>>> Having said all this, my proposal is:
>>>
>>> 1. if someone can help me to track bug further (remember, 1.6.0_17 was
>>> working just fine) we could file the bug report to Oracle, or
>>> 2. we could just add the info in FOP/xmlgraphics docs that color profile
>>> in PNG images introduces significant slowdown on JDK 1.6.0_18+.
>>
>> Ok, since it seems that it is too hard to track this down, I suggest we
>> add to PNG Graphics page [1] something like:
>>
>> "Note: PNG images with color profile are on certain JDKs (most notably
>> Oracle JDK 6u18+) processed as much as 20 times slower than same images
>> without color profile. This slowdown is introduced by JDK image
>> manipulation classes."
>>
>> Thoughts?
>>
>> -Ognjen
>>
>> [1] http://xmlgraphics.apache.org/fop/1.0/graphics.html#png
>
>
>
>
> Jeremias Maerki
>
>


Re: 20x slowdown in PNG processing when switching from JDK 1.6.0_17 to 1.6.0_18

Posted by Jeremias Maerki <de...@jeremias-maerki.ch>.
Ognjen,
sorry for the late answer. Could you please set the following log level
to FINE/DEBUG: org.apache.fop.render.pdf.AbstractImageAdapter

If you get the line "Image returns ICC profile: sRGB, default sRGB=true",
your PNG is a normal sRGB bitmap. This will (normally) allow FOP to dump
the bitmap data efficiently to the output file.

In your case, the encoded color model seems to differ from the original
one which is why the ImageEncodingHelper (from XML Graphics Commons)
falls back to encoding sRGB data which has to go through color
management. And that's what's making the process very slow. Every pixel
is converted to sRGB by the color profile associated with the
BufferedImage that has been built from the PNG file.

But...I cannot reproduce your problem. With all PNGs I've tested I get
optimized encoding (Sun Java 6.0_24). Could you please send me your PNG?
Maybe there's something peculiar about it.

On 18.03.2011 09:20:34 Ognjen Blagojevic wrote:
> On 11.3.2011 12:54, Ognjen Blagojevic wrote:
> > Having said all this, my proposal is:
> >
> > 1. if someone can help me to track bug further (remember, 1.6.0_17 was
> > working just fine) we could file the bug report to Oracle, or
> > 2. we could just add the info in FOP/xmlgraphics docs that color profile
> > in PNG images introduces significant slowdown on JDK 1.6.0_18+.
> 
> Ok, since it seems that it is too hard to track this down, I suggest we 
> add to PNG Graphics page [1] something like:
> 
> "Note: PNG images with color profile are on certain JDKs (most notably 
> Oracle JDK 6u18+) processed as much as 20 times slower than same images 
> without color profile. This slowdown is introduced by JDK image 
> manipulation classes."
> 
> Thoughts?
> 
> -Ognjen
> 
> [1] http://xmlgraphics.apache.org/fop/1.0/graphics.html#png




Jeremias Maerki


Re: 20x slowdown in PNG processing when switching from JDK 1.6.0_17 to 1.6.0_18

Posted by Ognjen Blagojevic <og...@gmail.com>.
On 11.3.2011 12:54, Ognjen Blagojevic wrote:
> Having said all this, my proposal is:
>
> 1. if someone can help me to track bug further (remember, 1.6.0_17 was
> working just fine) we could file the bug report to Oracle, or
> 2. we could just add the info in FOP/xmlgraphics docs that color profile
> in PNG images introduces significant slowdown on JDK 1.6.0_18+.

Ok, since it seems that it is too hard to track this down, I suggest we 
add to PNG Graphics page [1] something like:

"Note: PNG images with color profile are on certain JDKs (most notably 
Oracle JDK 6u18+) processed as much as 20 times slower than same images 
without color profile. This slowdown is introduced by JDK image 
manipulation classes."

Thoughts?

-Ognjen

[1] http://xmlgraphics.apache.org/fop/1.0/graphics.html#png