users@jaxb.java.net

investigated --- Re: xjc 20040405 uses 1.4 API

From: Kohsuke Kawaguchi <Kohsuke.Kawaguchi_at_Sun.COM>
Date: Wed, 21 Apr 2004 17:07:59 -0700

I was able to reproduce the problem. Indeed it happens sometime with JDK
1.3.

What's strange is that right before OutOfMemoryError, the memory usage
is just around 7MB and nowhere near the VM limit. So initially I thought
maybe someone is doing something stupid like:

    new byte[x];

where x is incredibly large by mistake.

Then I noticed that if I use Windows task manager to monitor the memory
usage, it grows constantly up to around 54MB before it crashes. This
doesn't agree with what -verbose:gc is showing.

So I then used JVMStat (http://developers.sun.com/dev/coolstuff/jvmstat/),
unfortunately this one only works with JDK 1.4, but even with JDK 1.4, I
found that it does seem like leaking memory (attached.) At this point I
decided to work with JDK 1.4 exclusively.

Next I used -Xrunhprof to get the basic profilng. It actually generated
a huge file, so I only shows the top #20 memory use:

SITES BEGIN (ordered by live bytes) Wed Apr 21 16:24:50 2004
          percent live alloc'ed stack class
 rank self accum bytes objs bytes objs trace name
    1 13.89% 13.89% 2260072 16685 2260072 16685 3236 [B
    2 7.37% 21.25% 1198856 23189 1198856 23189 3236 [S
    3 5.87% 27.12% 955824 24316 986600 25233 3236 java.lang.Object
    4 5.74% 32.87% 934360 16685 934360 16685 3236 java.lang.Class
    5 2.53% 35.40% 412256 212 17192688 9894 4126 [C
    6 1.88% 37.27% 305376 5849 1294096 20471 218 [C
    7 1.77% 39.04% 287280 1890 567248 4819 1601 [C
    8 1.68% 40.72% 273632 5787 273632 5787 3236 [I
    9 1.39% 42.11% 226544 3867 1729168 39226 1666 [C
   10 1.31% 43.42% 213200 13 26453200 1613 3505 [C
   11 1.27% 44.69% 206448 391 10368864 19638 107 [B
   12 1.21% 45.90% 196800 12 6445200 393 4485 [C
   13 1.16% 47.06% 188784 23 6287328 766 4484 [B
   14 1.14% 48.20% 184888 4581 184888 4581 96688 [C
   15 1.01% 49.20% 164000 10 164000 10 96675 [C
   16 0.90% 50.10% 146104 93 6077328 4132 4128 [C
   17 0.89% 50.99% 144480 1806 144480 1806 1762 java.util.HashMap$Entry
   18 0.88% 51.87% 142648 582 146064 631 1 [C
   19 0.81% 52.68% 132168 5507 295728 12322 171 java.lang.String
   20 0.79% 53.46% 127992 671 127992 671 506 [B

The worst 4 come from the stack trace 3236, which is as follows:

TRACE 3236:
        java.lang.ClassLoader.defineClass0(ClassLoader.java:Native method)
        java.lang.ClassLoader.defineClass(ClassLoader.java:537)
        org.apache.tools.ant.loader.AntClassLoader2.defineClassFromData(AntClassLoader2.java:77)
        org.apache.tools.ant.AntClassLoader.getClassFromStream(AntClassLoader.java:1074)

So I started suspecting that maybe class loading is an issue.

I re-run visualgc, and noticed that the # of classes loaded is around
18500, and this number grows constantly throughout the whole build. I
took this to mean that new classes are constantly being loaded, which
doesn't sound right given that the build is just running XJC with
different schemas (IOW, you would expect that a lot of classes to be
loaded initially, then after the 1st compilation it should finish
loading most of the classes.)


Then I rerun Ant with -verbose:class, and found out that the same class
(like com.sun.tools.xjc.ConsoleErrorReporter) is loaded 14 times. The
build scripts compile 1 dummy schema + 13 schemas so this seems to imply
that somehow a fresh set of XJC classes is loaded every time one
invokes the XJC task, which seems like a terrible waste.

Now that I start to suspect Ant for memory leak, I searched Apache
BugZilla for some information. And I found this:

   http://nagoya.apache.org/bugzilla/show_bug.cgi?id=8689

In particular see the comment "Mike Aizatsky 2004-03-31 09:42", which
says he doesn't see the clean up to AntClassLoader.

Unless the class loader is freed, no classes loaded from it can be freed.
So this seems to explain why XJC classes are loaded so many times. So
this bug seems to explain everything.

I'll leave it up to you to apply the suggested patch locally and see if
the problem goes away. Meanwhile, this seems like a restriction of Ant,
so I'm afraid there's nothing we can do about this.


This concludes my little journey. Let me know how you think.

regards,
--
Kohsuke Kawaguchi
Sun Microsystems                   kohsuke.kawaguchi_at_sun.com
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe_at_jaxb.dev.java.net
For additional commands, e-mail: users-help_at_jaxb.dev.java.net