Unchecked Logging in Xerces Churns Memory on Older ClassLoader Implementations
Sunday, February 17th, 2008While profiling a transaction in an application at work, I found this trace to be interesting:
Trace 6 | total: 275,780 | total: 276,320
identical: 45 | average: 6,128 | average: 6,140
percent: 0.32% | percent: 1.41% | percent: 1.41%
--------------------+--------------------------+--------------------------
com/ibm/jvm/ExtendedSystem,resizeArray
java/lang/StringBuffer,expandCapacity
java/lang/StringBuffer,append
com/ibm/ws/classloader/CompoundClassLoader,toString
java/lang/String,valueOf
java/lang/StringBuffer,append
org/apache/xerces/util/ObjectFactory,newInstance
Some code in the Xerces jar looks to be leveraging the toString() method on the ClassLoader implementation, which in WAS 5.1 is creating a StringBuffer full of class names. Looking at the newInstance() method in the Xerces ObjectFactory class reveals the code that invokes the CompoundClassLoader.toString():
debugPrintln("created new instance of " + class1 + " using ClassLoader: " + classloader);
The debug doesn’t check for any debug flag before doing the expensive String concatenation that results in our expensive CompoundClassLoader.toString() call. So every time we use this factory to get a new instance of a class, we’re generating a new StringBuffer of all the classes loaded by the application.
Further problems arise when one goes to actually look at the debugPrintln() method’s implementation.
/** Set to true for debugging */ private static final boolean DEBUG = false; /** Prints a message to standard error if debugging is enabled. */ private static void debugPrintln(String msg) { if (DEBUG) { System.err.println("JAXP: " + msg); } } // debugPrintln(String)
There’s no way to ever set DEBUG to true at runtime, so this is purely for the Xerces developers. This class concatenates Strings all over the ObjectFactory class to send them to a method that depends on a hard-coded class variables to operate. This is not a good practice.
For the one transaction in this application, there are 13 stack traces that report this issue (@ a 100 byte threshold) for a total of 829,920 bytes. A significant waste of memory in my estimation. Note that your mileage may very as this number is directly related to the number of classes loaded and the frequency of newInstance() calls in your application.
I checked the following version of Xerces and they all have the same unchecked debug code:
- Xerxes-2.4.0.jar
- Xerxes-2.5.0.jar
- Xerxes-2.6.0.jar



