javajvmclassloaderjstat

Excessive jstat "Class Loader Time"


Our Java-based server application is reporting an unusually high class loader time:

# jstat -class 10625 1000
Loaded  Bytes  Unloaded  Bytes     Time
  4781  9165.6      114   185.2   17769.35
  4781  9165.6      114   185.2   17769.85
  4781  9165.6      114   185.2   17770.36
  4781  9165.6      114   185.2   17771.11
  4781  9165.6      114   185.2   17771.73

This is on a server that had been running ~8 hours. jstat reports it has spent 17,769s (~4h56m!) doing class loading, and about 0.5-0.6 extra seconds every second! We've been tracking a performance issue and this is our best candidate for a culprit. Just to be sure, we checked our other Java services: jstat showed a very low value in the Time column (a few seconds, even after having run for hours)

Our code doesn't do constant class loading, but we can't rule out a misbehaving 3rd party library. We enabled -verbose:gc hoping to diagnose the problem. But once our server loads all of its classes (within a minute or so of heavy traffic) the verbose class log became quiet -- we were half-expecting to see a flurry of activity given the jstat data.

My questions would be:

Would really appreciate any suggestions.


Solution

  • This seems like a real problem. Given that class loading time increases while the number of load classes remains the same, I may conclude that the application tries to load a missing class over and over again, e.g. by Class.forName or ClassLoader.loadClass.

    If a class is missing, JVM will scan through the whole classpath before throwing ClassNotFoundException. This can take really much time if a classpath contains many JARs or even network URLs.

    To diagnose this further I suggest to instrument Class.forName and ClassLoader.loadClass methods or intercept ClassNotFoundExceptions.