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

classic Classic list List threaded Threaded
10 messages Options
Reply | Threaded
Open this post in threaded view
|

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

Ognjen Blagojevic-5
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
Reply | Threaded
Open this post in threaded view
|

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

Ognjen Blagojevic-5
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
Reply | Threaded
Open this post in threaded view
|

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

Eric Douglas
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:[hidden email]]
Sent: Friday, March 18, 2011 4:21 AM
To: [hidden email]
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
Reply | Threaded
Open this post in threaded view
|

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

Jeremias Maerki-2
In reply to this post by Ognjen Blagojevic-5
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

Reply | Threaded
Open this post in threaded view
|

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

Jeremias Maerki-2
In reply to this post by Eric Douglas
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:[hidden email]]
> Sent: Friday, March 18, 2011 4:21 AM
> To: [hidden email]
> 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

Reply | Threaded
Open this post in threaded view
|

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

Ognjen Blagojevic-5
In reply to this post by Jeremias Maerki-2
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
>
>


image-with-color-profile.png (274K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

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

Ognjen Blagojevic-5
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
>>
>>
>

Reply | Threaded
Open this post in threaded view
|

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

Peter B. West
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

Reply | Threaded
Open this post in threaded view
|

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

Ognjen Blagojevic-5
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
>
>

Reply | Threaded
Open this post in threaded view
|

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

Peter B. West
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