xmlgraphics-fop-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Puppala, Kumar (LNG-CON)" <kumar.pupp...@lexisnexis.com>
Subject RE: Fop 0.20.5 vs Fop Trunk Performace
Date Tue, 12 Feb 2008 20:10:13 GMT
Hi Andreas/Jeremias,

  Thanks for the quick responses. Provided below are my responses to
your questions.

 

 

Thanks!!

 

-----Original Message-----
From: Andreas Delmelle [mailto:andreas.delmelle@telenet.be] 
Sent: Tuesday, February 12, 2008 2:22 PM
To: fop-users@xmlgraphics.apache.org
Subject: Re: Fop 0.20.5 vs Fop Trunk Performace

 

On Feb 12, 2008, at 17:06, Puppala, Kumar (LNG-CON) wrote:

 

Hi Kumar

> We are currently using FOP 0.20.5 on our production boxes and  

> intend to use the latest FOP at some point this year. As such, we  

> are trying to gauge performance improvements between the two.  

> However, I am finding that the new FOP is taking more time to  

> render than the old one. The options used to run the FOP (both old  

> and new) are as shown below:

> 

Just to be sure: which revision of the trunk are you trying out?

 

 --> I obtained the latest from the trunk on Jan 22nd. Information
pertaining to the fopTrunk as seen in the status.xml file is:

"status.xml 614201 2008-01-22 14:02:27Z jeremias"

 

As Jeremias already pointed out, make sure that at least the  

FopFactory is instantiated only once (that was the whole point of its  

inception: to save time on reloading resources that can be shared  

between multiple runs).

 --> Yes, I am instantiating FopFactory just once. Initially I was not
doing that but I changed my code to instantiate it just once. The
results provided are with the change.

 

Apart from that, focusing purely on FOP Trunk, if you know how to  

narrow it down to specific methods/calls that cause the increase in  

processing time that would help us a lot.

 --> I do have the complete Heap report. Some of the classes having
maximum instances are as shown below:

463132 instances <http://dvc7632:7172/instances/0xb4d0a270>  of class
org.apache.fop.traits.MinOptMax <http://dvc7632:7172/class/0xb4d0a270>  
441537 instances <http://dvc7632:7172/instances/0xb4d139a8>  of class
org.apache.fop.layoutmgr.NonLeafPosition
<http://dvc7632:7172/class/0xb4d139a8>  
386229 instances <http://dvc7632:7172/instances/0xb4bd3f50>  of class
org.apache.fop.fo.properties.CondLengthProperty
<http://dvc7632:7172/class/0xb4bd3f50>  
362166 instances <http://dvc7632:7172/instances/0xb4d33020>  of class
org.apache.fop.layoutmgr.LeafPosition
<http://dvc7632:7172/class/0xb4d33020>  
216985 instances <http://dvc7632:7172/instances/0xb4bd6648>  of class
org.apache.fop.fo.properties.SpaceProperty
<http://dvc7632:7172/class/0xb4bd6648>  
181359 instances <http://dvc7632:7172/instances/0xb4cf9dd0>  of class
org.apache.fop.layoutmgr.KnuthGlue
<http://dvc7632:7172/class/0xb4cf9dd0>  
164198 instances <http://dvc7632:7172/instances/0xb4d69638>  of class
org.apache.fop.layoutmgr.inline.TextLayoutManager$AreaInfo
<http://dvc7632:7172/class/0xb4d69638>  
140706 instances <http://dvc7632:7172/instances/0xb4d17690>  of class
org.apache.fop.layoutmgr.KnuthPenalty
<http://dvc7632:7172/class/0xb4d17690>  
107113 instances <http://dvc7632:7172/instances/0xb4c62c38>  of class
org.apache.fop.fo.properties.CommonBorderPaddingBackground
<http://dvc7632:7172/class/0xb4c62c38>  
107113 instances <http://dvc7632:7172/instances/0xb4c64700>  of class
[Lorg.apache.fop.fo.properties.CommonBorderPaddingBackground$BorderInfo;
<http://dvc7632:7172/class/0xb4c64700>  
104453 instances <http://dvc7632:7172/instances/0xb4d69f18>  of class
org.apache.fop.layoutmgr.inline.KnuthInlineBox
<http://dvc7632:7172/class/0xb4d69f18>  
91823 instances <http://dvc7632:7172/instances/0xb4c64c78>  of class
[Lorg.apache.fop.fo.properties.CondLengthProperty;
<http://dvc7632:7172/class/0xb4c64c78>  
84488 instances <http://dvc7632:7172/instances/0xb4cc3ac8>  of class
org.apache.fop.layoutmgr.LMiter <http://dvc7632:7172/class/0xb4cc3ac8>  
78913 instances <http://dvc7632:7172/instances/0xb4d7acb0>  of class
org.apache.fop.area.inline.WordArea
<http://dvc7632:7172/class/0xb4d7acb0>  
73825 instances <http://dvc7632:7172/instances/0xb4c91138>  of class
org.apache.fop.fo.flow.table.BorderSpecification
<http://dvc7632:7172/class/0xb4c91138>  
70532 instances <http://dvc7632:7172/instances/0xb4c79380>  of class
org.apache.fop.datatypes.LengthBase
<http://dvc7632:7172/class/0xb4c79380>  
70532 instances <http://dvc7632:7172/instances/0xb4bdea20>  of class
org.apache.fop.fo.properties.PercentLength
<http://dvc7632:7172/class/0xb4bdea20>  
69942 instances <http://dvc7632:7172/instances/0xb4c7bbd8>  of class
org.apache.fop.fo.FObj$FObjIterator
<http://dvc7632:7172/class/0xb4c7bbd8>  
67494 instances <http://dvc7632:7172/instances/0xb4c92670>  of class
org.apache.fop.fo.flow.table.ConditionalBorder
<http://dvc7632:7172/class/0xb4c92670>  
63321 instances <http://dvc7632:7172/instances/0xb4d24378>  of class
org.apache.fop.traits.SpaceVal <http://dvc7632:7172/class/0xb4d24378>  
62513 instances <http://dvc7632:7172/instances/0xb4d7a598>  of class
org.apache.fop.area.inline.SpaceArea
<http://dvc7632:7172/class/0xb4d7a598>  
60204 instances <http://dvc7632:7172/instances/0xb4c712e0>  of class
[Lorg.apache.fop.fo.FONode; <http://dvc7632:7172/class/0xb4c712e0>  
50599 instances <http://dvc7632:7172/instances/0xb4d2c5a8>  of class
[Lorg.apache.fop.traits.MinOptMax;
<http://dvc7632:7172/class/0xb4d2c5a8> 

 

I am not sure if this is something expected. I can provide the complete
jmap dump (its 341 MB).

 

Small question: Did you, by any chance, also try different JVM  

versions? Different platform?

> /usr/local/jvta/jre1.6.0_02/bin/java -Djava.endorsed.dirs=/usr/ 

> local/java/pkgs/jmx1.0.1 -server -Xms128m -Xmx1024m - 

> XX:MaxPermSize=128m -verbose:gc -XX:+PrintGCDetails -XX: 

> +PrintGCTimeStamps -DJMX_1_2=true -D -Sqds_fop_dev5_001 -javaagent:/ 

> opt/wily/Agent.jar -Dcom.wily.introscope.agentProfile=/l-n/app/ 

> sysman/wily/default/Agent_tier1.profile - 

> Dcom.wily.introscope.agentName=FOP -Dpid=11403  

> com.lxnx.ols.qds.fop.gen.server.FOPServer

> 

 --> No. I can try on jre1.6.0_04. Since we are running the current FOP
on Solaris platform, we are performing our tests on Solaris.

 

Do you know which XML parser / XSLT processor gets used at runtime?  

Not necessarily to shift the blame, but if you can check whether  

substituting one of those helps, that would again be very helpful.

 --> We do not use an XSLT processor. We generate the FO file using an
in-house application and feed it to the FOP Server. Since I am using the
default handler, I think it's using SAX Parser behind the scenes.

 

> <snip />

> 

> Here are my findings after running:

> 

> 1)       After server startup, the initial transactions are not  

> that far apart from those obtained using old FOP. However, as time  

> progresses, I do see the time for the same transactions increases.  

> After about 15 such iterations, the processing time almost doubles.

> 

 

So, (again focusing on FOP Trunk) this would mean that the processing  

time increases with the number of runs, or do I interpret this wrong?

 --> Yes, the processing time increases with the number of runs.

 

In local tests I ran here, with two concurrent threads and a shared  

FopFactory instance, the processing time remains quite stable for me  

(test run on Apple JVM 1.5 using a  document that generates two page- 

sequences (=2+69 pages; the larger page-sequence contains forced  

breaks for each page))

 --> My tests are much more diverse. Each iteration contains about 120
testcases. Each testcase targets a specific feature that we use. Hence
each such iteration covers most of the features like tables, cells,
images, big documents, rowspanning, columnSpanning, dual column layout
etc... In total I would say I am generating about 3000 pages per
iteration. When comparing the results, I am comparing them after each
such iteration for about 15 times and I am seeing a gradual increase in
processing times.

 

> 2)       I do see a lot of garbage collection happening in the new  

> FOP. The collection times are also very high. I am hereby attaching  

> the garbage collection stats for both the old and new FOP for about  

> the same number of transactions (refer to newFop_SL.stdout.txt and  

> oldFop_SL_stdout.txt). Also a thread dump for the server running  

> new FOP is provided (threadDump_newFop.txt).

> 

> 3)       After using jmap and jhat to analyze the heap, I do see a  

> lot of objects consuming lot of memory in the new FOP. I am hereby  

> providing a spreadsheet containing Heap histograms for both the old  

> and new FOP for the same load (refer to HeapObjects.xls). Also, the  

> jmap output for the server using old and new FOP is provided (refer  

> to oldFopMap.txt and newFopMap.txt)

> 

> 4)       Documents containing lots of Images are rendered amazingly  

> fast (about 85% improvement).

> 

 

That last bit is certainly good to know.

The high ratio of GC is also to be expected, since both during  

parsing and layout, a lot of short-lived objects are created. FOP  

0.20.5 simply offered the JVM less opportunity to clean up any mess.

 

Come to think of it: are your images stored on a local disk, or is  

there any network traffic involved that might explain the increasing  

lag...?

--> The images are stored on local disk. However, I do see better
results for testcases containing Images and hence I do not believe that
there are any network traffic issues involved.

 

 

HTH!

 

Cheers

 

Andreas

 

---------------------------------------------------------------------

To unsubscribe, e-mail: fop-users-unsubscribe@xmlgraphics.apache.org

For additional commands, e-mail: fop-users-help@xmlgraphics.apache.org

 


Mime
View raw message