In the last blog, I confirmed that the high system CPU usage was related to the Java class loader having to go to the file system to search repeatedly for classes that were never found. To identify the code that was trying to use a class that was never found, I suggested that we use the following Java startup option: -Xtrace:trigger=method{java/lang/ClassLoader.loadClass,jstacktrace},print=mt. This is actually a very verbose class loader trace option which will produce a dump of method call stack, but for class loading activities. Listing 1 shows a small portion of an example trace:
17:38:50.661 0x301baa00 mt.23 * < java/lang/ClassLoader.loadClass(Ljava/lang/String;Z)Ljava/lang/Class; compiled method, exception thrown
17:38:50.662 0x301baa00 mt.1 > java/lang/ClassLoader.loadClass(Ljava/lang/String;)Ljava/lang/Class; compiled method, this = 0xf007dee8
17:38:50.662 0x301baa00 j9trc_aux.0 - jstacktrace:
17:38:50.662 0x301baa00 j9trc_aux.1 - [1] java.lang.ClassLoader.loadClass (ClassLoader.java:853) (Compiled Code)
17:38:50.662 0x301baa00 j9trc_aux.1 - [2] java.lang.ClassLoader.defineClassImpl (Native Method)
17:38:50.662 0x301baa00 j9trc_aux.1 - [3] java.lang.ClassLoader.defineClass (ClassLoader.java:379) (Compiled Code)
17:38:50.662 0x301baa00 j9trc_aux.1 - [4] java.security.SecureClassLoader.defineClass (SecureClassLoader.java:154) (Compiled Code)
17:38:50.662 0x301baa00 j9trc_aux.1 - [5] java.net.URLClassLoader.defineClass (URLClassLoader.java:730) (Compiled Code)
17:38:50.662 0x301baa00 j9trc_aux.1 - [6] java.net.URLClassLoader.access$400 (URLClassLoader.java:96)
17:38:50.662 0x301baa00 j9trc_aux.1 - [7] java.net.URLClassLoader$ClassFinder.run (URLClassLoader.java:1187) (Compiled Code)
17:38:50.662 0x301baa00 j9trc_aux.1 - [8] java.security.AccessController.doPrivileged (AccessController.java:739)
17:38:50.662 0x301baa00 j9trc_aux.1 - [9] java.net.URLClassLoader.findClass (URLClassLoader.java:605) (Compiled Code)
17:38:50.662 0x301baa00 j9trc_aux.1 - [10] java.lang.ClassLoader.loadClassHelper (ClassLoader.java:925) (Compiled Code)
17:38:50.662 0x301baa00 j9trc_aux.1 - [11] java.lang.ClassLoader.loadClass (ClassLoader.java:870) (Compiled Code)
17:38:50.662 0x301baa00 j9trc_aux.1 - [12] sun.misc.Launcher$AppClassLoader.loadClass (Launcher.java:343) (Compiled Code)
17:38:50.662 0x301baa00 j9trc_aux.1 - [13] java.lang.ClassLoader.loadClass (ClassLoader.java:853) (Compiled Code)
17:38:50.662 0x301baa00 j9trc_aux.1 - [14] package.SimplePersistenceDelegate.register (SimplePersistenceDelegate.java:49)
Listing1: Example class loader trace
Note that I did not include the whole jstacktrace section. I only included the key portion. A couple of things to note in Listing 1 are:
- There is an exception thrown as shown at the top of the listing
- It appears that the code register() method is engaging the class loader to load a class.
The problem with this listing is that it does not show anything conclusive; I don’t know what class the code is trying to load and I don’t know what the exception is.
To get closer to the code that is triggering the class not found problem even though this is not reported as mentioned in the last log, I thought the following trace option that is specified as a JVM startup parameter would be useful:
-Xdump:java:events=throw+systhrow,filter=java/lang/ClassNotFoundException,msg_filter=*PersistenceDelegate*,request=exclusive+preempt
What this trace option does is:
If the class that the code is trying to load matches the pattern “PersistenceDelegate” and the class is not found, then generate a thread dump (Java core) where the current thread identifies the call stack that is triggering the class loader to load the class. The reason I selected "PersistenceDelegate" for the class pattern was that the classes that were never found match this pattern. Indeed, the trace option was very helpful as I finally was able to identify the product code that is causing a very high system CPU usage by engaging the class loader to repeatedly look for classes that are never found in the filesystem.
The top of the thread dump shows Listing 1:
1TISIGINFO Dump Event "throw" (00000010) Detail "java/lang/ClassNotFoundException" "package.SimplePersistenceDelegate" received
Listing 1: Top of the thread dump
Now, I searched for “current thread” to find the thread that involved the ClassNotFoundException and I found what is listed in Listing 2:
3XMTHREADINFO3 Java callstack:
4XESTACKTRACE at java/net/URLClassLoader.findClass(URLClassLoader.java:610(Compiled Code))
4XESTACKTRACE at java/lang/ClassLoader.loadClassHelper(ClassLoader.java:925(Compiled Code))
5XESTACKTRACE (entered lock: java/lang/ClassLoader$ClassNameBasedLock@0x00000000F0B614A8, entry count: 1)
4XESTACKTRACE at java/lang/ClassLoader.loadClass(ClassLoader.java:870(Compiled Code))
4XESTACKTRACE at java/lang/ClassLoader.loadClassHelper(ClassLoader.java:914(Compiled Code))
5XESTACKTRACE (entered lock: java/lang/ClassLoader$ClassNameBasedLock@0x00000000F0B61460, entry count: 1)
4XESTACKTRACE at java/lang/ClassLoader.loadClass(ClassLoader.java:870(Compiled Code))
4XESTACKTRACE at sun/misc/Launcher$AppClassLoader.loadClass(Launcher.java:343)
4XESTACKTRACE at java/lang/ClassLoader.loadClass(ClassLoader.java:853)
4XESTACKTRACE at java/lang/ClassLoader.defineClassImpl(Native Method)
4XESTACKTRACE at java/lang/ClassLoader.defineClass(ClassLoader.java:379(Compiled Code))
4XESTACKTRACE at java/security/SecureClassLoader.defineClass(SecureClassLoader.java:154)
4XESTACKTRACE at java/net/URLClassLoader.defineClass(URLClassLoader.java:730(Compiled Code))
4XESTACKTRACE at java/net/URLClassLoader.access$400(URLClassLoader.java:96)
4XESTACKTRACE at java/net/URLClassLoader$ClassFinder.run(URLClassLoader.java:1187(Compiled Code))
4XESTACKTRACE at java/security/AccessController.doPrivileged(AccessController.java:739)
4XESTACKTRACE at java/net/URLClassLoader.findClass(URLClassLoader.java:605(Compiled Code))
4XESTACKTRACE at java/lang/ClassLoader.loadClassHelper(ClassLoader.java:925(Compiled Code))
5XESTACKTRACE (entered lock: java/lang/ClassLoader$ClassNameBasedLock@0x00000000F0B460B0, entry count: 1)
4XESTACKTRACE at java/lang/ClassLoader.loadClass(ClassLoader.java:870(Compiled Code))
4XESTACKTRACE at sun/misc/Launcher$AppClassLoader.loadClass(Launcher.java:343)
4XESTACKTRACE at java/lang/ClassLoader.loadClass(ClassLoader.java:853)
4XESTACKTRACE at product-package/product-class.method(product-class.java:139)
Listing 2: Current thread
Now, I have the product code and the exact line that is trying to implicitly load the SimplePersistenceDelegate class that is never found.
In the next blog, I will talk about the options to resolve the high system CPU usage resulting from the classes that are never found.