Bad usage of ClassLoader.loadClass() for Java6 in SerializationHelper$CustomObjectInputStream - deserialization bottleneck for arrays ------------------------------------------------------------------------------------------------------------------------------------- Key: HHH-2990 URL: http://opensource.atlassian.com/projects/hibernate/browse/HHH-2990 Project: Hibernate3 Issue Type: Bug Affects Versions: 3.2.5 Environment: Hibernate 3.2.5, Java 6 Sun (any), any platform (tested Linux x64, Mac x64 (J6dp1)) Reporter: Tom Eicher Sun has "clarified" (others say modified) the API of "ClassLoader.loadClass()" and no longer allows this to be called for arrays, e.g. String[]. ( see: http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6500212 and duplicates ) and states that this has always been very unstable to use/do in the first place. So trying to load an array of something using this method results in ClassNotFoundException. The correct thing to do is call Class.forName(className,false,myClassLoader); instead of myClassLoader.loadClass(className); In SerializationHelper$CustomObjectInputStream.resolveClass() we do ClassLoader loader = Thread.currentThread().getContextClassLoader(); try { resolvedClass = loader.loadClass(className); log.trace("Class resolved through context class loader"); } catch(ClassNotFoundException e) { log.trace("Asking super to resolve"); resolvedClass = super.resolveClass(v); } which results in the deserialization process for a String[] always searching String[] in all the application's jars/wars/etc before really loading it. The bad thing is, loadClass() is synchronized. In our case, we have multiple threads loading database rows containing String[]s, which results in one Thread doing INFO | jvm 1 | 2007/11/30 16:56:44 | java.lang.Thread.State: RUNNABLE INFO | jvm 1 | 2007/11/30 16:56:44 | at java.util.zip.ZipFile.getEntry(Native Method) INFO | jvm 1 | 2007/11/30 16:56:44 | at java.util.zip.ZipFile.getEntry(ZipFile.java:149) INFO | jvm 1 | 2007/11/30 16:56:44 | - locked <0x00002aaab4047c20> (a java.util.jar.JarFile) INFO | jvm 1 | 2007/11/30 16:56:44 | at java.util.jar.JarFile.getEntry(JarFile.java:206) INFO | jvm 1 | 2007/11/30 16:56:44 | at java.util.jar.JarFile.getJarEntry(JarFile.java:189) INFO | jvm 1 | 2007/11/30 16:56:44 | at sun.misc.URLClassPath$JarLoader.getResource(URLClassPath.java:754) INFO | jvm 1 | 2007/11/30 16:56:44 | at sun.misc.URLClassPath.getResource(URLClassPath.java:168) INFO | jvm 1 | 2007/11/30 16:56:44 | at java.net.URLClassLoader$1.run(URLClassLoader.java:192) INFO | jvm 1 | 2007/11/30 16:56:44 | at java.security.AccessController.doPrivileged(Native Method) INFO | jvm 1 | 2007/11/30 16:56:44 | at java.net.URLClassLoader.findClass(URLClassLoader.java:188) INFO | jvm 1 | 2007/11/30 16:56:44 | at java.lang.ClassLoader.loadClass(ClassLoader.java:306) INFO | jvm 1 | 2007/11/30 16:56:44 | - locked <0x00002aaab4025998> (a org.apache.catalina.loader.StandardClassLoader) INFO | jvm 1 | 2007/11/30 16:56:44 | at java.lang.ClassLoader.loadClass(ClassLoader.java:299) INFO | jvm 1 | 2007/11/30 16:56:44 | - locked <0x00002aaab4095a68> (a org.apache.catalina.loader.StandardClassLoader) INFO | jvm 1 | 2007/11/30 16:56:44 | at java.lang.ClassLoader.loadClass(ClassLoader.java:251) INFO | jvm 1 | 2007/11/30 16:56:44 | at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1346) INFO | jvm 1 | 2007/11/30 16:56:44 | at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1205) INFO | jvm 1 | 2007/11/30 16:56:44 | at org.hibernate.util.SerializationHelper$CustomObjectInputStream.resolveClass(SerializationHelper.java:263) INFO | jvm 1 | 2007/11/30 16:56:44 | at java.io.ObjectInputStream.readNonProxyDesc(ObjectInputStream.java:1575) INFO | jvm 1 | 2007/11/30 16:56:44 | at java.io.ObjectInputStream.readClassDesc(ObjectInputStream.java:1496) INFO | jvm 1 | 2007/11/30 16:56:44 | at java.io.ObjectInputStream.readArray(ObjectInputStream.java:1624) INFO | jvm 1 | 2007/11/30 16:56:44 | at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1323) INFO | jvm 1 | 2007/11/30 16:56:44 | at java.io.ObjectInputStream.readObject(ObjectInputStream.java:351) INFO | jvm 1 | 2007/11/30 16:56:44 | at org.hibernate.util.SerializationHelper.deserialize(SerializationHelper.java:210) and all other threads doing nothing INFO | jvm 1 | 2007/11/30 16:56:44 | java.lang.Thread.State: BLOCKED (on object monitor) INFO | jvm 1 | 2007/11/30 16:56:44 | at java.lang.ClassLoader.loadClass(ClassLoader.java:295) INFO | jvm 1 | 2007/11/30 16:56:44 | - waiting to lock <0x00002aaab4095a68> (a org.apache.catalina.loader.StandardClassLoader) INFO | jvm 1 | 2007/11/30 16:56:44 | at java.lang.ClassLoader.loadClass(ClassLoader.java:251) INFO | jvm 1 | 2007/11/30 16:56:44 | at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1346) INFO | jvm 1 | 2007/11/30 16:56:44 | at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1205) INFO | jvm 1 | 2007/11/30 16:56:44 | at org.hibernate.util.SerializationHelper$CustomObjectInputStream.resolveClass(SerializationHelper.java:263) INFO | jvm 1 | 2007/11/30 16:56:44 | at java.io.ObjectInputStream.readNonProxyDesc(ObjectInputStream.java:1575) (rest of stack trace identical to above) This can easily be worked around by setting the compatibility property -Dsun.lang.ClassLoader.allowArraySyntax=true however a) this workaround might not be around for long and b) most people will never find this bottleneck, therefore will not apply the workaround. For our case, we got a 35% performance increase just be setting this property (and not a single loadClass() or ZipFile.getEntry() in any thread dump any more). Cheers, Tom. -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://opensource.atlassian.com/projects/hibernate/secure/Administrators.... - For more information on JIRA, see: http://www.atlassian.com/software/jira