[jdom-interest] Using NanoXML and JDOM

[Dennis Sosnoski]

Jason Hunter wrote:

> Dennis Sosnoski wrote:
> >
> > My tests measured memory usage before and after building the document copies,
> > but always after running through the code to make sure the class loading was
> > done. I go through some pains to encourage garbage collection before measuring
> > usage, to make sure I'm only measuring the memory that's actually used for the
> > documents in a stable system.
> >
> >   - Dennis
>
> Are you sure that's accurate?  In my OptimizeIt experience taking memory
> marks before and after builds will often include the objects used during
> the parse, and even when you call System.gc() your JVM likely does not
> remove those objects.  It's only when you use a little *more* memory and
> threaten to run out that the system really does a GC.  I found with that
> testing model that consuming more memory can actually give the
> impression of using less.
>
> -jh-

I'm not sure about *anything* when it comes to Hot Spot JVMs, but at least on Linux
it appears that the chance of a garbage collection is pretty good if you first call
System.gc() and then wait for a significant amount of time. This is not coincidental
- Hot Spot is supposed to make use of idle time to clean up memory so it doesn't
have to steal cycles when the JVM is busy doing productive work.

In the original test runs I waited for 1 second each time before checking the memory
usage. I just made a change that I thought I'd put in previously but apparently had
missed, to loop for 1 second with calls to System.gc() each followed by waits of .1
second. It changed a couple of the document size figures, but by less than 5 percent
each.

Below is a sample of my summary output for the documents, first for JDOM and then
for dom4j. I'm parsing 10 copies of each document, measuring usage only for the last
9 to avoid any parser overhead or such (interning of names, etc.). The first
document, init.xml, is a throw-away - I use it to make sure everything is loaded and
executed, but do not include it in the test results.

The test sequence actually builds all 10 copies of the document first, then walks
each copy, and finally nulls out the reference to the array of documents (as well as
all objects created and used during the tests).

The most important thing to notice in the results are that the tests generally show
very little change in memory usage (the "Chg mem" value) from the beginning of the
test to the end. "Init mem" is the memory in use at the start of the test, "End mem"
that in use at the end of the tests. The fact that these figures are usually about
the same leads me to believe that garbage collection is taking place as intended.

One other interesting point in the JDOM results is that the "Walked sz" figure is
non-zero (more than 20% of the document size in some cases, in fact). I didn't bring
this up in my article (didn't get around to investigating it so I knew what was
going on), but it looks like JDOM has significant memory overhead involved in
walking the tree. Is something going on to change the memory structure of the
document when I cycle through the children of an element?

  - Dennis

Java version 1.3.1
Java HotSpot(TM) Client VM
1.3.1-b24
Sun Microsystems Inc.
Running JDOM with 10 passes on file init.xml:
 Init mem=1767464 End mem=1790976 Chg mem=23512  First sz=46824  Avg sz=23208
 Walked sz=2240

Running JDOM with 10 passes on file much_ado.xml:
 Init mem=1791016 End mem=1791016 Chg mem=0      First sz=1235408 Avg sz=1256957
 Walked sz=264712

Running JDOM with 10 passes on file periodic.xml:
 Init mem=1791056 End mem=1791056 Chg mem=0      First sz=619984 Avg sz=619880
 Walked sz=53816

Running JDOM with 10 passes on file soap1.xml:
 Init mem=1791096 End mem=1791808 Chg mem=712    First sz=2280   Avg sz=1464
 Walked sz=280

Running JDOM with 10 passes on file soap2.xml:
 Init mem=1791848 End mem=1792976 Chg mem=1128   First sz=1073712 Avg sz=1096206
 Walked sz=224168

Running JDOM with 10 passes on file nt.xml:
 Init mem=1793016 End mem=1793016 Chg mem=0      First sz=3921504 Avg sz=3953972
 Walked sz=485656

Running JDOM with 10 passes on file xml.xml:
 Init mem=1793056 End mem=1859776 Chg mem=66720  First sz=826336 Avg sz=759512
 Walked sz=76776


Java version 1.3.1
Java HotSpot(TM) Client VM
1.3.1-b24
Sun Microsystems Inc.
Running dom4j with 10 passes on file init.xml:
 Init mem=1773216 End mem=1780656 Chg mem=7440   First sz=62216  Avg sz=18568
 Walked sz=0

Running dom4j with 10 passes on file much_ado.xml:
 Init mem=1780696 End mem=1781648 Chg mem=952    First sz=994872 Avg sz=957616
 Walked sz=0

Running dom4j with 10 passes on file periodic.xml:
 Init mem=1781688 End mem=1783304 Chg mem=1616   First sz=482816 Avg sz=444800
 Walked sz=0

Running dom4j with 10 passes on file soap1.xml:
 Init mem=1783344 End mem=1784568 Chg mem=1224   First sz=39400  Avg sz=1328
 Walked sz=0

Running dom4j with 10 passes on file soap2.xml:
 Init mem=1784608 End mem=1786752 Chg mem=2144   First sz=779072 Avg sz=739648
 Walked sz=0

Running dom4j with 10 passes on file nt.xml:
 Init mem=1786792 End mem=1787632 Chg mem=840    First sz=3182328 Avg sz=3182550
 Walked sz=0

Running dom4j with 10 passes on file xml.xml:
 Init mem=1787672 End mem=1793256 Chg mem=5584   First sz=687880 Avg sz=642344
 Walked sz=0