Performance issues when calling java.beans.Introspector.getBeanInfo after inactivity

Question

I am using a 3rd party library that dynamically creates instances of Java classes and populates those instances with the help of Introspector.getBeanInfo. Certain requests may result in 5 or 6 successive calls to Introspector.getBeanInfo. I have found that when the application is idle for about an hour or so the first call to Introspector.getBeanInfo takes a significantly much longer time to execute (20-60 seconds) vs the subsequent calls (< 100 milliseconds). Calls made within the next few minutes continue to take < 100 milliseconds, but when I wait another hour the first call again takes 20-60 seconds.

In an attempt to re-create the behavior with a simple test application I have found similar behavior when a java application itself is not run for an hour. For example, if I run the following console app it may take 15 milliseconds to complete. If I then wait an hour and re-run the application it takes 20 seconds to complete.

long start = System.currentTimeMillis();
System.out.println("Start");
Introspector.getBeanInfo(MyClass.class, Object.class);
long end = System.currentTimeMillis();
System.out.println("End: " + (end-start));

I originally thought the issue may be related to the fact that the Introspector class attempts to create instances of classes based on standard naming conventions that do not exist in my application (for example, MyClassBeanInfo), and it was taking a long time to scan the jar files in an attempt to find those classes (my java application has a little over 100 referenced jar files), but I called Introspector.getBeanInfo(MyClass.class, Object.class, Introspector.IGNORE_ALL_BEANINFO) using reflection (it is a private method in Sun's JRE which from looking at the code seems to skip the lookup of the BeanInfo classes), and I was still able to reproduce the delay.

I have also searched for information regarding any type of JRE/JVM jar cache, but have yet to find anything that seems to explain this behavior. Anyone have any clue why this behaves the way it does, and if there is anything I can do to fix it?

As a side note I am using JDK 1.6.0_21 on Windows XP. The 3rd party library I am using is BlazeDS. My application is hosted in Tomcat using Spring/BlazeDS integration. I overwrote a number of BlazeDS classes in order to pinpoint exactly where the delay was (which is the call to Introspector.getBeanInfo in the getPropertyDescriptorCacheEntry method of flex.messaging.io.BeanProxy). Also, BlazeDS does cache the BeanInfo, so calls to Introspector.getBeanInfo are only made when Blaze is deserializing an object that is mapped to a Java class that has yet to be processed. So, I do have other ways to work around this issue, but I would really like to know if there is a valid explanation for this behavior.

EDIT: I ran jstack on the process multiple times while reproducing the issue (thanks @Tom) and did confirm that it is related to loading jar files. I dumped the threads 5 times over a 20 second time frame (total time of the delay) and each time produced the following result:

"http-8080-exec-6" daemon prio=6 tid=0x65cae800 nid=0x1a50 runnable [0x67a3d000]
   java.lang.Thread.State: RUNNABLE
    at java.util.zip.ZipFile.open(Native Method)
    at java.util.zip.ZipFile.<init>(Unknown Source)
    at java.util.jar.JarFile.<init>(Unknown Source)
    at java.util.jar.JarFile.<init>(Unknown Source)
    at org.apache.catalina.loader.WebappClassLoader.openJARs(WebappClassLoader.java:2704)
    at org.apache.catalina.loader.WebappClassLoader.findResourceInternal(WebappClassLoader.java:2945)
    - locked <0x1804cc18> (a [Ljava.util.jar.JarFile;)
    at org.apache.catalina.loader.WebappClassLoader.findClassInternal(WebappClassLoader.java:2739)
    at org.apache.catalina.loader.WebappClassLoader.findClass(WebappClassLoader.java:1144)
    at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1639)
    - locked <0x1803dd38> (a org.apache.catalina.loader.WebappClassLoader)
    at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1517)
    at java.beans.Introspector.instantiate(Unknown Source)
    at java.beans.Introspector.findExplicitBeanInfo(Unknown Source)
    - locked <0x434649a0> (a java.lang.Class for java.beans.Introspector)
    at java.beans.Introspector.<init>(Unknown Source)
    at java.beans.Introspector.getBeanInfo(Unknown Source)
    - locked <0x181bed70> (a java.lang.Object)

I can't help but think there is some kind of JRE/JVM jar cache that is expiring after an hour and forcing the jar files to be re-scanned, but I can't find anything online that outlines such behavior.

EDIT: As it turns out the Tomcat WebappClassLoader does cache JAR files and periodically purges that cache. Now to find out if that cache is configurable in anyway...

EDIT: Tomcat closes all JAR files 90 seconds after the last time a jar file was accessed. I overwrote the WebappClassLoader to print out when the jar files were closed. After the jar files were closed I tried to reproduce the delay, but was unable to. So, this tells me that there is either a JRE/JVM jar file cache, or just something inherent in the operating system (or my machine, antivirus, etc) that is causing slow load times after a long delay. Still working on it...

Answer 1

At my employer, we too are heavily relying on dynamically generated classes. With the problems of the Introspector and how it behaves (e.g. relying on ClassLoader behavior) and trying to load many *BeanInfo classes which we do not have, it was a no-go for us and we decided to not use Introspector and reimplement the functionality on our own.

Not sure how much of the BeanInfo you really need, but it may be easier to use reflection and a home-grown property-metadata-information component, which you have better under control. And with easier, I also mean the nerves you will safe once you deploy the app on other application servers, which have their own ClassLoader behaviors and which are even more heavy and unconfigurable than the ones on Tomcat.

BeanInfo and related components are interfaces, so you may even need only to reimplement the Introspector itself and not all your code which uses it.

Answer 2

java.beans.Introspector can be a real problem in OSGi environment where searching for non-existing classes can be particulary expensive. It's especially true in Equinox because of buddy class loading: Eclipse-BuddyPolicy: depenent and Eclipse-BuddyPolicy: global can cause serious performance problems.

java.beans.Introspector is used in few unexpected places

• org.apache.log4j.config.PropertySetter
• org.springframework.beans.CachedIntrospectionResults
• org.hibernate.util.Cloneable#copyListeners

In general, Introspector should be relatively safe in Equinox when Introspector.IGNORE_ALL_BEANINFO flag is specified. It's not, beacause in current Oracle JVM implementation BeanInfo caching isn't used unless Introspector.USE_ALL_BEANINFO is specified. That is, obviously, in direct conflict with the javadocs, so I'd say that this is actually a bug in the Introspector implementation (or documentation).