Classloader Loader Event Tracing

Classloader Event Tracing

If you are seeing classloader closed errors from time to time, then one really useful utility OC4J has is the ability to log the various events related to different aspects of the classloading mechanism.

So for example, lets say you are seeing errors occasionally containing this type of message: "This loader has been closed and should not be in use."

Then what you can do to help trace why this is occurring is to enable log tracing for the various loader events.

In the error message above, it should also explicitly provide the name of the loader that was being used, of the form appname.modulename[.module]:major.minor. For example myapp.webmodule.root:0.0

To observe classloading events relating to this specific loader, you configure OC4J to start as follows:

>java -Dclass.load.trace=loader:myapp.webmodule.* -Dclass.load.trace.level=all -jar oc4j.jar


That setup configures OC4J to output all the loader related classloading events, at the log level of ALL, where the loader name matches the pattern "myapp.webmodule.*".

In the output, you'll see entries such as:

ClassLoader created: myapp.webmodule.root:0.0.0 (instance 1cba87)
ClassLoader committed: myapp.webmodule.root:0.0.0 (instance 1cba87)
...
ClassLoader closing: myapp.webmodule..jsp13471351:0.0.0 (instance 14441b6)
...

That shows you where the loaders are being operated on, and confirms (one way or another) that the loader is actually being closed -- this may correlate with other actions you have performs -- say a redeployment operation.

Now to help further understand why/where the loader event occured, you can add an extra event filter. The "stack" event filter adds the associated stacktrace that caused the loader event to occur to the output -- thus for the loader closed events, you can trace back and identify the source of the loader close.

To add the stack event filter to the classloader tracing, simply concatentate it to the class.load.trace property:
>java -Dclass.load.trace=stack+loader:myapp.webmodule.* -Dclass.load.trace.level=all -jar oc4j.jar

That then causes a stacktrace to be appended to each event that is logged:

ClassLoader closing: myapp.webmodule:0.0.0 (instance 18aea9e)
at oracle.classloader.util.ClassLoadTracing$LoaderListener.loaderClosing(ClassLoadTracing.java:738)
at oracle.classloader.EventDispatcher.loaderClosing(EventDispatcher.java:232)
at oracle.classloader.PolicyClassLoader.close(PolicyClassLoader.java:1056)
at oracle.classloader.PolicyClassLoader.close(PolicyClassLoader.java:1041)
at com.evermind.server.http.HttpApplication.destroy(HttpApplication.java:5860)
at com.evermind.server.http.HttpApplication.stopCleanUp(HttpApplication.java:8437)
at com.evermind.server.http.HttpApplication.componentStop(HttpApplication.java:8383)
at com.evermind.server.Application.doStop(Application.java:2092)
at com.evermind.server.Application.stop(Application.java:2019)
at oracle.oc4j.admin.management.mbeans.J2EEStateManageableObjectBase.stop(J2EEStateManageableObjectBase.java:275)
at oracle.oc4j.admin.management.mbeans.J2EEApplication.stop(J2EEApplication.java:1542)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at sun.reflect.misc.Trampoline.invoke(MethodUtil.java:36)
at sun.reflect.GeneratedMethodAccessor17.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at sun.reflect.misc.MethodUtil.invoke(MethodUtil.java:239)
at javax.management.modelmbean.RequiredModelMBean.invokeMethod(RequiredModelMBean.java:1071)
at javax.management.modelmbean.RequiredModelMBean.invoke(RequiredModelMBean.java:953)
at oracle.oc4j.admin.jmx.server.mbeans.model.DefaultModelMBeanImpl.invoke(DefaultModelMBeanImpl.java:700)
at com.sun.jmx.mbeanserver.DynamicMetaDataImpl.invoke(DynamicMetaDataImpl.java:213)
at com.sun.jmx.mbeanserver.MetaDataImpl.invoke(MetaDataImpl.java:220)
at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:815)
at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:784)
at oracle.oc4j.admin.jmx.server.state.ApplicationStateFilterMBeanServer.invoke(ApplicationStateFilterMBeanServer.java:572)
at oracle.oc4j.admin.jmx.shared.UserMBeanServer.invoke(UserMBeanServer.java:634)
at oracle.oc4j.admin.jmx.server.state.LocalizationFilterMBeanServer.invoke(LocalizationFilterMBeanServer.java:579)
at oracle.sysman.ias.studio.jmx.spi.JMXConnectorImpl.invoke(JMXConnectorImpl.java:389)
at oracle.sysman.ias.studio.oc4j.JMXAppAdminBean.stopApp(JMXAppAdminBean.java:276)
at oracle.sysman.ias.studio.oc4j.AppHelper.doStopAppOp(AppHelper.java:776)
at oracle.sysman.ias.studio.oc4j.AppHelper.access$600(AppHelper.java:116)
at oracle.sysman.ias.studio.oc4j.AppHelper$AppControlProcessingBean.appControlOperation(AppHelper.java:1628)
at oracle.sysman.ias.studio.oc4j.AppHelper$AppControlProcessingBean.doWork(AppHelper.java:1642)
at oracle.sysman.ias.studio.util.ProcessingBean$ProcessingThread.run(ProcessingBean.java:273)
at com.evermind.util.ReleasableResourcePooledExecutor$MyWorker.run(ReleasableResourcePooledExecutor.java:298)
at java.lang.Thread.run(Thread.java:595)


Looking at the stacktrace for the loader closing event, you can reasonably surmise that the event was caused by the application being "stopped" from ascontrol (sysman).

Now that's a contrived example, I agree! But I hope it serves in some small way to demonstrate how you can use the classloader tracing mechanism to get a handle on the different events that happen to loaders and why they have occurred.