Axiom is heavy-weight and slow

• Key: AXIS2-533
• Type: Bug
• Status: Resolved
• Resolution: Fixed
• Priority: Major
• Assignee: Eran Chinthaka
• Reporter: Dennis Sosnoski
• Component/s: om
• Affects Version/s: 0.95
• Fix Version/s: 1.1

Description

In performance tests comparing Axiom with JDOM, dom4j, and Xerces DOM document models Axiom was consistently both slower and bulkier than the other OMs when the tree was expanded. Axiom delivered good performance for the initial "parse" operation only by virtue of not building the tree. Here are some time comparison figures for Axiom vs. dom4j on a fairly large SOAP response (from the MS interop suite):

Running Axiom with 10 passes on file docs/xmlformatter.xml (274920 bytes):
 Build mn=563 Build av=5110 Walk mn=33360 Walk av=60885 Build-Walk mn=33923
 Build-Walk av=65995 Write mn=31774 Write av=52782 Mod mn=5 Mod av=6

Running dom4j with 10 passes on file docs/xmlformatter.xml (274920 bytes):
 Build mn=24816 Build av=28843 Walk mn=2839 Walk av=3055 Build-Walk mn=27655
 Build-Walk av=31898 Write mn=18866 Write av=19369 Mod mn=5 Mod av=6

The most interesting figures here are the Build-Walk time (sum of microseconds for the initial parse operation plus walking the document tree, which forces Axiom expansion) and the Write time. The average times are especially bad by comparison with dom4j, which I'd suspect is caused by a lot of temporary object creation. The write times may be at least partially caused by the XMLStreamWriter API, since only Axiom uses this approach for output. Here are memory comparisons:

Running Axiom memory test with 4 passes on file docs/xmlformatter.xml (274920 bytes):
 Init mem=451872 Chg mem=928 First sz=15192 Avg sz=15261 Walked sz=2071960
 Avg+Walked sz=2087221

Running dom4j memory test with 4 passes on file docs/xmlformatter.xml (274920 bytes):
 Init mem=829968 Chg mem=3120 First sz=1031760 Avg sz=971976 Walked sz=0
 Avg+Walked sz=971976

The interesting figures here are the Avg+Walked sz values, which give the total bytes of memory in use after parsing and walking the document representation.

Here are the same time and memory test results for a collection of smaller SOAP documents:

Running Axiom with 10 passes on directory docs/soaps (30 files totaling 19407 bytes):
 Build mn=13610 Build av=16897 Walk mn=2332 Walk av=10523 Build-Walk mn=15942
 Build-Walk av=27420 Write mn=16079 Write av=22565 Mod mn=9 Mod av=9

Running dom4j with 10 passes on directory docs/soaps (30 files totaling 19407 bytes):
 Build mn=7507 Build av=12354 Walk mn=121 Walk av=134 Build-Walk mn=7628
 Build-Walk av=12488 Write mn=4226 Write av=5012 Mod mn=10 Mod av=10

Running Axiom memory test with 4 passes on directory docs/soaps (30 files totaling 19407 bytes):
 Init mem=456104 Chg mem=1640 First sz=451960 Avg sz=449760 Walked sz=103520
 Avg+Walked sz=553280

Running dom4j memory test with 4 passes on directory docs/soaps (30 files totaling 19407 bytes):
 Init mem=836392 Chg mem=7944 First sz=103824 Avg sz=33768 Walked sz=0
 Avg+Walked sz=33768

Note the huge memory usage in this case. It appears that Axiom has a high per-document memory overhead, perhaps caused by holding on to the XMLStreamReader (which suggests the references to the reader should be cleared as the tree is constructed, so that once the tree is complete the reader can be garbage collected).

Comments

[Dennis Sosnoski]

Benchmark source code and libraries, with Eclipse project files and try.sh to run tests. JDOM v1.0, dom4j v1.6.1, Axiom as of yesterday, Xerces 2.7.0

[Davanum Srinivas]

Dennis,

I took the liberty of adding the zip to our svn. is this ok?

https://svn.apache.org/repos/asf/webservices/axis2/trunk/archive/java/scratch/dennis

thanks,
dims

[Dennis Sosnoski]

Absolutely, dims - I checked the box on the form to say I was licensing it for ASF use. Let me know if there's anything you'd like to try out - the test code is a little convoluted because it's based on a general framework.

[Davanum Srinivas]

Dennis,

Latest numbers as of Revision: 391559 of AXIOM. Please review it and post your analysis.

thanks,
dims

=======================================================================================================
C:\perf2>java -Xms512M -Xmx512M -cp bin;lib/jaxp.jar;lib/Piccolo.jar;lib/jdom.jar com.sosnoski.xmlbench.XMLBench -sb -u com.bluecast.xml.Piccolo jdom docs/init.xml docs/xmlformatter.xml docs/soaps
Running JDOM with 10 passes on file docs/init.xml (3604 bytes):
  Document has 51 elements, 82 attributes with 1215 characters of data, and 65 content text segments with 380 characters of text
  Original text size was 3604, output text size was 3441
 Build mn=315 Build av=350 Walk mn=9 Walk av=10 Build-Walk mn=324
 Build-Walk av=360 Write mn=285 Write av=341 Mod mn=34 Mod av=37
 Elems=51 Conts=65 Attrs=82 Text ch=380 Attr ch=1215

Running JDOM with 10 passes on file docs/xmlformatter.xml (274920 bytes):
  Document has 5009 elements, 1 attributes with 1 characters of data, and 10017 content text segments with 92468 characters of text
  Original text size was 274920, output text size was 274962
 Build mn=35574 Build av=36323 Walk mn=2076 Walk av=2335 Build-Walk mn=37650
 Build-Walk av=38658 Write mn=20559 Write av=25960 Mod mn=11401 Mod av=12021
 Elems=5009 Conts=10017 Attrs=1 Text ch=92468 Attr ch=1

Running JDOM with 10 passes on directory docs/soaps (30 files totaling 19407 bytes):
  Document has 211 elements, 162 attributes with 2431 characters of data, and 72 content text segments with 452 characters of text
  Original text size was 19407, output text size was 19521
 Build mn=2558 Build av=2761 Walk mn=59 Walk av=92 Build-Walk mn=2617
 Build-Walk av=2853 Write mn=2194 Write av=2466 Mod mn=173 Mod av=183
 Elems=211 Conts=72 Attrs=162 Text ch=452 Attr ch=2431


C:\perf2>java -Xms512M -Xmx512M -cp bin;lib/jaxp.jar;lib/Piccolo.jar;lib/dom4j.jar com.sosnoski.xmlbench.XMLBench -sb -u com.bluecast.xml.Piccolo dom4j docs/init.xml docs/xmlformatter.xml docs/soaps
Running dom4j with 10 passes on file docs/init.xml (3604 bytes):
  Document has 51 elements, 82 attributes with 1215 characters of data, and 65 content text segments with 380 characters of text
  Original text size was 3604, output text size was 3329
 Build mn=272 Build av=282 Walk mn=14 Walk av=14 Build-Walk mn=286
 Build-Walk av=296 Write mn=222 Write av=235 Mod mn=2 Mod av=2
 Elems=51 Conts=65 Attrs=82 Text ch=380 Attr ch=1215

Running dom4j with 10 passes on file docs/xmlformatter.xml (274920 bytes):
  Document has 5009 elements, 1 attributes with 1 characters of data, and 10020 content text segments with 92468 characters of text
  Original text size was 274920, output text size was 268945
 Build mn=16978 Build av=17621 Walk mn=1243 Walk av=1325 Build-Walk mn=18221
 Build-Walk av=18946 Write mn=13542 Write av=13807 Mod mn=2 Mod av=2
 Elems=5009 Conts=10020 Attrs=1 Text ch=92468 Attr ch=1

Running dom4j with 10 passes on directory docs/soaps (30 files totaling 19407 bytes):
  Document has 211 elements, 162 attributes with 2431 characters of data, and 72 content text segments with 452 characters of text
  Original text size was 19407, output text size was 19450
 Build mn=1920 Build av=2007 Walk mn=36 Walk av=40 Build-Walk mn=1956
 Build-Walk av=2047 Write mn=1605 Write av=2050 Mod mn=2 Mod av=2
 Elems=211 Conts=72 Attrs=162 Text ch=452 Attr ch=2431


C:\perf2>#java -Xms512M -Xmx512M -cp bin;lib/dom4j.jar;lib/stax-api-1.0.jar;lib/wstx-asl-2.9.2.jar com.sosnoski.xmlbench.XMLBench -sb dom4jstax docs/init.xml docs/xmlformatter.xml docs/soaps
'#java' is not recognized as an internal or external command,
operable program or batch file.

C:\perf2>java -Xms512M -Xmx512M -cp bin;lib/xmlParserAPIs.jar;lib/xercesImpl.jar com.sosnoski.xmlbench.XMLBench -sb xerces2 docs/init.xml docs/xmlformatter.xml docs/soaps
Running Xerces2 DOM with 10 passes on file docs/init.xml (3604 bytes):
  Document has 51 elements, 84 attributes with 1269 characters of data, and 65 content text segments with 380 characters of text
  Original text size was 3604, output text size was 3263
 Build mn=324 Build av=371 Walk mn=18 Walk av=29 Build-Walk mn=342
 Build-Walk av=400 Write mn=146 Write av=151 Mod mn=30 Mod av=31
 Elems=51 Conts=65 Attrs=84 Text ch=380 Attr ch=1269

Running Xerces2 DOM with 10 passes on file docs/xmlformatter.xml (274920 bytes):
  Document has 5009 elements, 1006 attributes with 104150 characters of data, and 10017 content text segments with 92468 characters of text
  Original text size was 274920, output text size was 268945
 Build mn=18587 Build av=19010 Walk mn=1245 Walk av=1540 Build-Walk mn=19832
 Build-Walk av=20550 Write mn=11740 Write av=12023 Mod mn=11705 Mod av=12224
 Elems=5009 Conts=10017 Attrs=1006 Text ch=92468 Attr ch=104150

Running Xerces2 DOM with 10 passes on directory docs/soaps (30 files totaling 19407 bytes):
  Document has 211 elements, 314 attributes with 7660 characters of data, and 72 content text segments with 452 characters of text
  Original text size was 19407, output text size was 19416
 Build mn=2062 Build av=2406 Walk mn=67 Walk av=80 Build-Walk mn=2129
 Build-Walk av=2486 Write mn=1343 Write av=1598 Mod mn=152 Mod av=166
 Elems=211 Conts=72 Attrs=314 Text ch=452 Attr ch=7660


C:\perf2>java -Xms512M -Xmx512M -cp bin;lib/axiom-api-SNAPSHOT.jar;lib/axiom-impl-SNAPSHOT.jar;lib/stax-api-1.0.jar;lib/wstx-asl-2.9.2.jar com.sosnoski.xmlbench.XMLBench -sb axiom docs/init.xml docs/xmlformatter.xml docs/soaps
Running Axiom with 10 passes on file docs/init.xml (3604 bytes):
  Document has 51 elements, 82 attributes with 1215 characters of data, and 65 content text segments with 380 characters of text
  Original text size was 3604, output text size was 3296
 Build mn=15 Build av=18 Walk mn=263 Walk av=345 Build-Walk mn=278
 Build-Walk av=363 Write mn=199 Write av=204 Mod mn=2 Mod av=2
 Elems=51 Conts=65 Attrs=82 Text ch=380 Attr ch=1215

Running Axiom with 10 passes on file docs/xmlformatter.xml (274920 bytes):
  Document has 5009 elements, 1 attributes with 1 characters of data, and 10017 content text segments with 92468 characters of text
  Original text size was 274920, output text size was 269112
 Build mn=15 Build av=18 Walk mn=20616 Walk av=20918 Build-Walk mn=20631
 Build-Walk av=20936 Write mn=11870 Write av=12265 Mod mn=2 Mod av=2
 Elems=5009 Conts=10017 Attrs=1 Text ch=92468 Attr ch=1

Running Axiom with 10 passes on directory docs/soaps (30 files totaling 19407 bytes):
  Document has 211 elements, 162 attributes with 2431 characters of data, and 72 content text segments with 452 characters of text
  Original text size was 19407, output text size was 19401
 Build mn=472 Build av=689 Walk mn=1305 Walk av=1464 Build-Walk mn=1777
 Build-Walk av=2153 Write mn=1857 Write av=2020 Mod mn=2 Mod av=6
 Elems=211 Conts=72 Attrs=162 Text ch=452 Attr ch=2431


C:\perf2>java -Xms512M -Xmx512M -cp bin;lib/jaxp.jar;lib/Piccolo.jar;lib/jdom.jar com.sosnoski.xmlbench.XMLBench -sbmp4n -u com.bluecast.xml.Piccolo jdom docs/init.xml docs/xmlformatter.xml docs/soaps
Running JDOM memory test with 4 passes on file docs/init.xml (3604 bytes):
 Init mem=516080 Chg mem=533440 First sz=699912 Avg sz=-9362 Walked sz=-19786
 Avg+Walked sz=-29148

Running JDOM memory test with 4 passes on file docs/xmlformatter.xml (274920 bytes):
 Init mem=1043856 Chg mem=6208 First sz=6226136 Avg sz=6157720 Walked sz=-7737482
 Avg+Walked sz=-1579762

Running JDOM memory test with 4 passes on directory docs/soaps (30 files totaling 19407 bytes):
 Init mem=1051584 Chg mem=6816 First sz=293472 Avg sz=5250 Walked sz=-61114
 Avg+Walked sz=-55864


C:\perf2>java -Xms512M -Xmx512M -cp bin;lib/jaxp.jar;lib/Piccolo.jar;lib/dom4j.jar com.sosnoski.xmlbench.XMLBench -sbmp4n -u com.bluecast.xml.Piccolo dom4j docs/init.xml docs/xmlformatter.xml docs/soaps
Running dom4j memory test with 4 passes on file docs/init.xml (3604 bytes):
 Init mem=516088 Chg mem=532896 First sz=689672 Avg sz=-14400 Walked sz=-15917
 Avg+Walked sz=-30317

Running dom4j memory test with 4 passes on file docs/xmlformatter.xml (274920 bytes):
 Init mem=1041792 Chg mem=7456 First sz=1168744 Avg sz=1105570 Walked sz=-1140602
 Avg+Walked sz=-35032

Running dom4j memory test with 4 passes on directory docs/soaps (30 files totaling 19407 bytes):
 Init mem=1050600 Chg mem=13352 First sz=178104 Avg sz=13938 Walked sz=-36648
 Avg+Walked sz=-22710


C:\perf2>#java -Xms512M -Xmx512M -cp bin;lib/dom4j.jar;lib/stax-api-1.0.jar;lib/wstx-asl-2.9.2.jar com.sosnoski.xmlbench.XMLBench -sbmp4n dom4jstax docs/init.xml docs/xmlformatter.xml docs/soaps
'#java' is not recognized as an internal or external command,
operable program or batch file.

C:\perf2>java -Xms512M -Xmx512M -cp bin;lib/xmlParserAPIs.jar;lib/xercesImpl.jar com.sosnoski.xmlbench.XMLBench -sbmp4n xerces2 docs/init.xml docs/xmlformatter.xml docs/soaps
Running Xerces2 DOM memory test with 4 passes on file docs/init.xml (3604 bytes):
 Init mem=515544 Chg mem=230664 First sz=395952 Avg sz=-23165 Walked sz=-29778
 Avg+Walked sz=-52943

Running Xerces2 DOM memory test with 4 passes on file docs/xmlformatter.xml (274920 bytes):
 Init mem=728392 Chg mem=1776 First sz=1682736 Avg sz=1620933 Walked sz=-2173432
 Avg+Walked sz=-552499

Running Xerces2 DOM memory test with 4 passes on directory docs/soaps (30 files totaling 19407 bytes):
 Init mem=733720 Chg mem=16608 First sz=117096 Avg sz=99232 Walked sz=-127496
 Avg+Walked sz=-28264


C:\perf2>java -Xms512M -Xmx512M -cp bin;lib/axiom-api-SNAPSHOT.jar;lib/axiom-impl-SNAPSHOT.jar;lib/stax-api-1.0.jar;lib/wstx-asl-2.9.2.jar com.sosnoski.xmlbench.XMLBench -sbmp4n axiom docs/init.xml docs/xmlformatter.xml docs/soaps
Running Axiom memory test with 4 passes on file docs/init.xml (3604 bytes):
 Init mem=576560 Chg mem=71856 First sz=182432 Avg sz=-20794 Walked sz=-16064
 Avg+Walked sz=-36858

Running Axiom memory test with 4 passes on file docs/xmlformatter.xml (274920 bytes):
 Init mem=648608 Chg mem=1168 First sz=15504 Avg sz=14728 Walked sz=-17381
 Avg+Walked sz=-2653

Running Axiom memory test with 4 passes on directory docs/soaps (30 files totaling 19407 bytes):
 Init mem=653320 Chg mem=4672 First sz=452496 Avg sz=463392 Walked sz=-612666
 Avg+Walked sz=-149274

=======================================================================================================

[Davanum Srinivas]

Dennis,

Please see the charts here:
http://people.apache.org/~dims/perf/

Make sure you see all the 3 sheets (tab strip at bottom of the page)

thanks,
dims

[Davanum Srinivas]

Excel sheet with charts. Please feel free to modify and post new charts.

[Dennis Sosnoski]

The performance gains in the latest version look very good, but these are still using the JRocket JVM. I suggest dropping the memory size to something like 16M when using JRocket - I haven't tried it, but suspect that'll give a more realistic test. I'll try updating my Axiom installation and see how it does with Sun's 1.5 JVM later today.

It's probably best to just drop the init.xml document from the spreadsheet and charts, by the way, since the point of that one is only to "warm up" the JVM with the framework code. Also, I didn't implement the modify ("mod mn" and "mod av") test for Axiom (hence the great time on these!), since I was mainly interested in the basic construction and serialization time. If anybody wants to implement these the code for the other frameworks can be used as examples.

[Davanum Srinivas]

Yes, please try whatever combinations and post the results. *PLEASE* update the code in the SVN, so that all of us are on the same page and the results are reproducible.
http://svn.apache.org/repos/asf/webservices/axis2/trunk/archive/java/scratch/dennis/

thanks,
dims

[Dennis Sosnoski]

The speed performance also looks very good in my Sun 1.5 JVM tests, with Axiom now about on a par with dom4j (revision 392635). Size is still just as much of an issue as before, though, with the expanded Axiom tree taking up about 80% more memory than dom4j for the large SOAP (about 50% more than JDOM, and 35% more than Xerces2) and many times the memory of any of the other models for the collection of smaller SOAPs.

I'm attaching both Oo2 and Excel spreadsheets with charts for these (no guarantees on the Excel ones, since they were generated as exports from Oo2). I'm also attaching a modified test.sh which generates CSV summary lines suitable for pasting into spreadsheets and also references the commons-logging and log4j jars now needed by Axiom. Those jars also need to be copied into the lib directory for testing Axiom.

[Dennis Sosnoski]

Oo2 spreadsheet for sizes with originally-tested Axiom.

[Dennis Sosnoski]

Oo2 spreadsheets for test results.

[Dennis Sosnoski]

Excel spreadsheets for test results (exported by Oo2).

[Dennis Sosnoski]

Excel spreadsheet for sizes with originally-tested Axiom (exported from Oo2).

[Dennis Sosnoski]

Test shell script modified for spreadsheet-friendly output and additional jars for Axiom.

[Deepal Jayasinghe]

dont we in the good position to resolve this issue

[Dennis Sosnoski]

Still heavy, no longer slow. ;-)

I think we should close this: its impossible for one implementation to optimize both time and space .. that's the classic CS tradeoff!!!!!

I'd like to (over time, not for 1.0 ;-)) resurrect the table impl of Axiom. The table impl is the one that trades off speed for space. The LLOM impl does the opposite. Once we have both working nicely we can have a fight over which one to make default .. or probably compromise by having a property in axis2.xml to set the default impl so that the user can pick it based on their predominant scenarios: big or small.

[Davanum Srinivas]

I'd like to spend a bit more time on this before we close it for good. +1 to table impl. I have my eye on that pesky factory in each node for example.

-- dims

[Dan Diephouse]

My comments on Dim's blog posting:

What XML driver are you using with the other DOM implementations? Have
you tried using woodstox as the driver with all of them? Woodstox is
30+% faster than the standard sax driver, so I don't know that the above
is a fair comparison.

Also, have you looked at XOM? It is the fastest DOM that I know of.

[Davanum Srinivas]

And my reply :)

The suite was developed by Dennis, the code is here:
http://svn.apache.org/repos/asf/webservices/axis2/archive/java/scratch/dennis/

Details on the tests are here:
http://issues.apache.org/jira/browse/AXIS2-533

No, i just ran the tests that he provided. He did not have a driver for XOM.

[Dennis Sosnoski]

I agree with Dan's comment on the parsers. I hadn't heard that XOM was so fast, but can add that to the comparison without much difficulty. Is there a StAX builder for XOM that you can recommend, Dan? I did find this one in a search: http://dsd.lbl.gov/nux/ but I gather that uses its own version of XOM.

Likewise on the other document models. dom4j has some StAX support - but only the lame event layer version, which is automatically going to be slow. I'm not willing to write my own code to build the trees from XMLStreamReader, but if you can point me at stable code for this purpose I'll gladly switch to using it.

[Eran Chinthaka]

I don't think this stand still with Dims' perf results.

[Dennis Sosnoski]

My own tests show Axiom document build performance good, though output is relatively slow and the size for an expanded document is about twice that of most other document models. I've got an article that covers Axiom (including performance comparisons) that I'd hoped would be published on devWorks by now, but is caught in a backlog. I'll update my tests for Axiom 1.1 and post at least a summary of results on this Jira.

[Davanum Srinivas]

Dennis,

Please create a new JIRA issue when you update the tests.

thanks,
dims