Cannot profile Tomcat with Mustag and YourKit EAP

[tomdz]

Hi,

I wanted to try out the new features of the EAP (newest build, downloaded today) with the current Mustang (b68). So I started to profile a web app which has a memory leak (the known classloader problem where the WebappClassLoader is not GC'd because of strong references). The problem is that Tomcat (both 5.5.12 and 5.5.15) crash before I get any useful profile data. The reason why I'm posting this here rather than in the Tomcat mailing lists is that without the profiling agent, Tomcat works just fine on Mustang, but not with YourKit enabled.
I get a hs_err log file which contains this:


#
# An unexpected error has been detected by Java Runtime Environment:
#
# EXCEPTION_ACCESS_VIOLATION (0xc0000005) at pc=0x6d883e5c, pid=3476, tid=332
#
# Java VM: Java HotSpot(TM) Client VM (1.6.0-rc-b68 mixed mode)
# Problematic frame:
# V [jvm.dll+0x113e5c]
#
# If you would like to submit a bug report, please visit:
# http://java.sun.com/webapps/bugreport/crash.jsp
#

--------------- T H R E A D ---------------

Current thread (0x0b5e8c00): JavaThread "http-8080-Processor25" daemon [_thread_in_vm, id=332]

siginfo: ExceptionCode=0xc0000005, reading address 0x00000004

Registers:
EAX=0x06b67e68, EBX=0x00000000, ECX=0x0c4beba0, EDX=0x00034188
ESP=0x0c4beb58, EBP=0x0b5e8c00, ESI=0x00038010, EDI=0x00000000
EIP=0x6d883e5c, EFLAGS=0x00010246

Top of Stack: (sp=0x0c4beb58)
0x0c4beb58: 00000000 00038010 00000000 6d8875fb
0x0c4beb68: 0b5e8c00 00000000 00000000 0b5e8c00
0x0c4beb78: 0c4bec58 00000000 00000000 00000002
0x0c4beb88: 0b5e8c00 0b5e93a0 0b5e93c0 0b5e9414
0x0c4beb98: 0b5e97b4 0c4bf028 6d8cee41 0b5e9404
0x0c4beba8: 0b5e9408 0b5e93f8 0b5e8c01 0b5e9400
0x0c4bebb8: 0000000e 0b5e93fc 00000001 0b5e8c00
0x0c4bebc8: 0b5e8c00 0b5e8c00 0c4bec58 0b5e8ce4

Instructions: (pc=0x6d883e5c)
0x6d883e4c: cc cc cc cc a1 08 25 98 6d 53 56 57 8b 7c 24 14
0x6d883e5c: 8b 5f 04 3b d8 8b f1 75 18 57 e8 15 68 fa ff 83


Stack: [0x0c470000,0x0c4c0000), sp=0x0c4beb58, free space=314k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V [jvm.dll+0x113e5c]

Java frames: (J=compiled Java code, j=interpreted, Vv=VM code)
j sun.reflect.NativeMethodAccessorImpl.invoke0(Ljava/lang/reflect/Method;Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;+0
j sun.reflect.NativeMethodAccessorImpl.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;+95
j sun.reflect.DelegatingMethodAccessorImpl.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;+14
j java.lang.reflect.Method.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;+119
j java.io.ObjectStreamClass.invokeWriteObject(Ljava/lang/Object;Ljava/io/ObjectOutputStream;)V+32
j java.io.ObjectOutputStream.writeSerialData(Ljava/lang/Object;Ljava/io/ObjectStreamClass;)V+128
j java.io.ObjectOutputStream.writeOrdinaryObject(Ljava/lang/Object;Ljava/io/ObjectStreamClass;Z)V+145
j java.io.ObjectOutputStream.writeObject0(Ljava/lang/Object;Z)V+578
j java.io.ObjectOutputStream.defaultWriteFields(Ljava/lang/Object;Ljava/io/ObjectStreamClass;)V+209
j java.io.ObjectOutputStream.writeSerialData(Ljava/lang/Object;Ljava/io/ObjectStreamClass;)V+208
j java.io.ObjectOutputStream.writeOrdinaryObject(Ljava/lang/Object;Ljava/io/ObjectStreamClass;Z)V+145
j java.io.ObjectOutputStream.writeObject0(Ljava/lang/Object;Z)V+578
j java.io.ObjectOutputStream.writeObject(Ljava/lang/Object;)V+32
j java.util.ArrayList.writeObject(Ljava/io/ObjectOutputStream;)V+43
v ~StubRoutines::call_stub
j sun.reflect.NativeMethodAccessorImpl.invoke0(Ljava/lang/reflect/Method;Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;+0
j sun.reflect.NativeMethodAccessorImpl.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;+95
j sun.reflect.DelegatingMethodAccessorImpl.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;+14
j java.lang.reflect.Method.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;+119
j java.io.ObjectStreamClass.invokeWriteObject(Ljava/lang/Object;Ljava/io/ObjectOutputStream;)V+32
j java.io.ObjectOutputStream.writeSerialData(Ljava/lang/Object;Ljava/io/ObjectStreamClass;)V+128
j java.io.ObjectOutputStream.writeOrdinaryObject(Ljava/lang/Object;Ljava/io/ObjectStreamClass;Z)V+145
j java.io.ObjectOutputStream.writeObject0(Ljava/lang/Object;Z)V+578
j java.io.ObjectOutputStream.writeObject(Ljava/lang/Object;)V+32
j org.apache.commons.lang.SerializationUtils.serialize(Ljava/io/Serializable;Ljava/io/OutputStream;)V+35
j org.apache.commons.lang.SerializationUtils.serialize(Ljava/io/Serializable;)[B+21
j org.apache.commons.lang.SerializationUtils.clone(Ljava/io/Serializable;)Ljava/lang/Object;+9
j org.apache.ojb.broker.metadata.ConnectionRepository.getAllDescriptor()Ljava/util/List;+22
j org.apache.ojb.broker.metadata.MetadataManager.buildDefaultKey()Lorg/apache/ojb/broker/PBKey;+12
j org.apache.ojb.broker.metadata.MetadataManager.getDefaultPBKey()Lorg/apache/ojb/broker/PBKey;+17
j org.apache.ojb.broker.core.PersistenceBrokerFactoryBaseImpl.getDefaultKey()Lorg/apache/ojb/broker/PBKey;+11
j org.apache.ojb.broker.core.PersistenceBrokerFactoryBaseImpl.defaultPersistenceBroker()Lorg/apache/ojb/broker/PersistenceBrokerInternal;+9
j org.apache.ojb.broker.PersistenceBrokerFactory.defaultPersistenceBroker()Lorg/apache/ojb/broker/PersistenceBroker;+11
j org.mfftest.InitAction.getDocSets()Ljava/util/Collection;+8
j org.mfftest.InitAction.doInit(Ljavax/servlet/ServletContext;)V+9
j org.apache.jsp.index_jsp._jspService(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)V+119
j org.apache.jasper.runtime.HttpJspBase.service(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)V+11
j javax.servlet.http.HttpServlet.service(Ljavax/servlet/ServletRequest;Ljavax/servlet/ServletResponse;)V+38
j org.apache.jasper.servlet.JspServletWrapper.service(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;Z)V+202
j org.apache.jasper.servlet.JspServlet.serviceJspFile(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;Ljava/lang/String;Ljava/lang/Throwable;Z)V+145
j org.apache.jasper.servlet.JspServlet.service(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)V+443
j javax.servlet.http.HttpServlet.service(Ljavax/servlet/ServletRequest;Ljavax/servlet/ServletResponse;)V+38
j org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Ljavax/servlet/ServletRequest;Ljavax/servlet/ServletResponse;)V+378
j org.apache.catalina.core.ApplicationFilterChain.doFilter(Ljavax/servlet/ServletRequest;Ljavax/servlet/ServletResponse;)V+109
j org.apache.catalina.core.StandardWrapperValve.invoke(Lorg/apache/catalina/connector/Request;Lorg/apache/catalina/connector/Response;)V+678
j org.apache.catalina.core.StandardContextValve.invoke(Lorg/apache/catalina/connector/Request;Lorg/apache/catalina/connector/Response;)V+317
j org.apache.catalina.core.StandardHostValve.invoke(Lorg/apache/catalina/connector/Request;Lorg/apache/catalina/connector/Response;)V+80
j org.apache.catalina.valves.ErrorReportValve.invoke(Lorg/apache/catalina/connector/Request;Lorg/apache/catalina/connector/Response;)V+14
j org.apache.catalina.core.StandardEngineValve.invoke(Lorg/apache/catalina/connector/Request;Lorg/apache/catalina/connector/Response;)V+58
j org.apache.catalina.connector.CoyoteAdapter.service(Lorg/apache/coyote/Request;Lorg/apache/coyote/Response;)V+149
j org.apache.coyote.http11.Http11Processor.process(Ljava/io/InputStream;Ljava/io/OutputStream;)V+574
j org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Lorg/apache/tomcat/util/net/TcpConnection;[Ljava/lang/Object;)V+121
j org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(Ljava/net/Socket;Lorg/apache/tomcat/util/net/TcpConnection;[Ljava/lang/Object;)V+53
j org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt([Ljava/lang/Object;)V+110
j org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run()V+175
j java.lang.Thread.run()V+19
v ~StubRoutines::call_stub

--------------- P R O C E S S ---------------

Java Threads: ( => current thread )
0x0b1af400 JavaThread "TP-Monitor" daemon [_thread_blocked, id=3884]
0x0b5d1400 JavaThread "TP-Processor4" daemon [_thread_in_native, id=2124]
0x0b1ba800 JavaThread "TP-Processor3" daemon [_thread_blocked, id=628]
0x0b607400 JavaThread "TP-Processor2" daemon [_thread_blocked, id=1516]
0x0b5c5400 JavaThread "TP-Processor1" daemon [_thread_blocked, id=1636]
0x0b5e9c00 JavaThread "http-8080-Monitor" [_thread_blocked, id=3892]
=>0x0b5e8c00 JavaThread "http-8080-Processor25" daemon [_thread_in_vm, id=332]
0x0b5e7c00 JavaThread "http-8080-Processor24" daemon [_thread_in_native, id=3640]
0x0b5e7000 JavaThread "http-8080-Processor23" daemon [_thread_blocked, id=3740]
0x0b0a5800 JavaThread "http-8080-Processor22" daemon [_thread_blocked, id=2548]
0x0b0a4800 JavaThread "http-8080-Processor21" daemon [_thread_blocked, id=2504]
0x0b0a3800 JavaThread "http-8080-Processor20" daemon [_thread_blocked, id=3624]
0x0b0a2800 JavaThread "http-8080-Processor19" daemon [_thread_blocked, id=4028]
0x0b0a1800 JavaThread "http-8080-Processor18" daemon [_thread_blocked, id=3136]
0x0b0a0c00 JavaThread "http-8080-Processor17" daemon [_thread_blocked, id=1704]
0x0b09fc00 JavaThread "http-8080-Processor16" daemon [_thread_blocked, id=708]
0x0b787400 JavaThread "http-8080-Processor15" daemon [_thread_blocked, id=2792]
0x0b786400 JavaThread "http-8080-Processor14" daemon [_thread_blocked, id=3020]
0x0b785400 JavaThread "http-8080-Processor13" daemon [_thread_blocked, id=2712]
0x0b784800 JavaThread "http-8080-Processor12" daemon [_thread_blocked, id=3700]
0x0b783800 JavaThread "http-8080-Processor11" daemon [_thread_blocked, id=3664]
0x0b782800 JavaThread "http-8080-Processor10" daemon [_thread_blocked, id=2432]
0x0b781c00 JavaThread "http-8080-Processor9" daemon [_thread_blocked, id=2800]
0x0b71c400 JavaThread "http-8080-Processor8" daemon [_thread_blocked, id=2808]
0x0b71b400 JavaThread "http-8080-Processor7" daemon [_thread_blocked, id=2828]
0x0b71a400 JavaThread "http-8080-Processor6" daemon [_thread_blocked, id=3636]
0x0b719c00 JavaThread "http-8080-Processor5" daemon [_thread_blocked, id=2804]
0x0b134c00 JavaThread "http-8080-Processor4" daemon [_thread_blocked, id=1232]
0x0b134400 JavaThread "http-8080-Processor3" daemon [_thread_blocked, id=3336]
0x0b1cd800 JavaThread "http-8080-Processor2" daemon [_thread_blocked, id=1188]
0x0b1cd400 JavaThread "http-8080-Processor1" daemon [_thread_blocked, id=1328]
0x0b099c00 JavaThread "ContainerBackgroundProcessor[StandardEngine[Catalina]]" daemon [_thread_blocked, id=3860]
0x0b033c00 JavaThread "Low Memory Detector" daemon [_thread_blocked, id=3384]
0x0afee800 JavaThread "CompilerThread0" daemon [_thread_blocked, id=3360]
0x0b02e800 JavaThread "YJPAgent-CPUSampler" daemon [_thread_blocked, id=3416]
0x0aff2000 JavaThread "YJPAgent-RequestListener" daemon [_thread_in_native, id=3368]
0x0affb800 JavaThread "YJPAgent-Telemetry" daemon [_thread_blocked, id=2212]
0x0afe7400 JavaThread "Attach Listener" daemon [_thread_blocked, id=656]
0x0afe6400 JavaThread "Signal Dispatcher" daemon [_thread_blocked, id=4084]
0x0ace6000 JavaThread "Finalizer" daemon [_thread_blocked, id=3792]
0x0ace1800 JavaThread "Reference Handler" daemon [_thread_blocked, id=1248]
0x00039c00 JavaThread "main" [_thread_in_native, id=3908]

Other Threads:
0x0acddc00 VMThread [id=2272]
0x0b03ec00 WatcherThread [id=2216]

VM state:not at safepoint (normal execution)

VM Mutex/Monitor currently owned by a thread: None

Heap
def new generation total 960K, used 101K [0x02b50000, 0x02c50000, 0x03030000)
eden space 896K, 4% used [0x02b50000, 0x02b59768, 0x02c30000)
from space 64K, 99% used [0x02c30000, 0x02c3fff8, 0x02c40000)
to space 64K, 0% used [0x02c40000, 0x02c40000, 0x02c50000)
tenured generation total 7888K, used 5054K [0x03030000, 0x037e4000, 0x06b50000)
the space 7888K, 64% used [0x03030000, 0x0351fb38, 0x0351fc00, 0x037e4000)
compacting perm gen total 12288K, used 11358K [0x06b50000, 0x07750000, 0x0ab50000)
the space 12288K, 92% used [0x06b50000, 0x076679d0, 0x07667a00, 0x07750000)
No shared spaces configured.

Dynamic libraries:
0x00400000 - 0x00411000 E:\development\jdk1.6.0_b68\bin\java.exe
0x7c910000 - 0x7c9c7000 C:\WINDOWS\system32\ntdll.dll
0x7c800000 - 0x7c906000 C:\WINDOWS\system32\kernel32.dll
0x6d010000 - 0x6d01a000 E:\development\jdk1.6.0_b68\bin\jli.dll
0x7c340000 - 0x7c396000 E:\development\jdk1.6.0_b68\bin\MSVCR71.dll
0x77da0000 - 0x77e4a000 C:\WINDOWS\system32\ADVAPI32.dll
0x77e50000 - 0x77ee1000 C:\WINDOWS\system32\RPCRT4.dll
0x6d770000 - 0x6d9aa000 E:\development\jdk1.6.0_b68\jre\bin\client\jvm.dll
0x77d10000 - 0x77da0000 C:\WINDOWS\system32\USER32.dll
0x77ef0000 - 0x77f37000 C:\WINDOWS\system32\GDI32.dll
0x76af0000 - 0x76b1e000 C:\WINDOWS\system32\WINMM.dll
0x6d2f0000 - 0x6d2f8000 E:\development\jdk1.6.0_b68\jre\bin\hpi.dll
0x76bb0000 - 0x76bbb000 C:\WINDOWS\system32\PSAPI.DLL
0x10000000 - 0x10083000 E:\Programme\yjp51eap\bin\win32\yjpagent.dll
0x71a10000 - 0x71a27000 C:\WINDOWS\system32\WS2_32.dll
0x77be0000 - 0x77c38000 C:\WINDOWS\system32\msvcrt.dll
0x71a00000 - 0x71a08000 C:\WINDOWS\system32\WS2HELP.dll
0x6d720000 - 0x6d72c000 E:\development\jdk1.6.0_b68\jre\bin\verify.dll
0x6d380000 - 0x6d39f000 E:\development\jdk1.6.0_b68\jre\bin\java.dll
0x6d760000 - 0x6d76f000 E:\development\jdk1.6.0_b68\jre\bin\zip.dll
0x6d520000 - 0x6d533000 E:\development\jdk1.6.0_b68\jre\bin\net.dll
0x719b0000 - 0x719f0000 C:\WINDOWS\system32\mswsock.dll
0x66710000 - 0x66769000 C:\WINDOWS\system32\hnetcfg.dll
0x719f0000 - 0x719f8000 C:\WINDOWS\System32\wshtcpip.dll
0x6d510000 - 0x6d519000 E:\development\jdk1.6.0_b68\jre\bin\management.dll

VM Arguments:
jvm_args: -agentlib:yjpagent=sessionname=Tomcat -Xrunyjpagent:sessionname=Tomcat -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djava.util.logging.config.file=E:\development\apache-tomcat-5.5.15\conf\logging.properties -Djava.endorsed.dirs=E:\development\apache-tomcat-5.5.15\common\endorsed -Dcatalina.base=E:\development\apache-tomcat-5.5.15 -Dcatalina.home=E:\development\apache-tomcat-5.5.15 -Djava.io.tmpdir=E:\development\apache-tomcat-5.5.15\temp
java_command: org.apache.catalina.startup.Bootstrap start
Launcher Type: SUN_STANDARD

Environment Variables:
JAVA_HOME=E:\development\jdk1.6.0_b68
JRE_HOME=E:\development\jdk1.6.0_b68
JAVA_TOOL_OPTIONS=-agentlib:yjpagent=sessionname=Tomcat
CLASSPATH=E:\development\jdk1.6.0_b68\lib\tools.jar;E:\development\apache-tomcat-5.5.15\bin\bootstrap.jar
PATH=E:\Programme\yjp51eap\bin\win32;e:\development\ruby\bin;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\Programme\ATI Technologies\ATI Control Panel;E:\development\apache-ant-1.6.5\bin;E:\development\jdk1.6.0_b68\bin;E:\development\apache-forrest-0.7\bin;e:\Programme\GTK\2.0\bin;e:\programme
USERNAME=tomdz
OS=Windows_NT
PROCESSOR_IDENTIFIER=x86 Family 6 Model 13 Stepping 6, GenuineIntel



--------------- S Y S T E M ---------------

OS: Windows XP Build 2600 Service Pack 2

CPU:total 1 family 6, cmov, cx8, fxsr, mmx, sse, sse2

Memory: 4k page, physical 2096112k(1481904k free), swap 2467220k(2057984k free)

vm_info: Java HotSpot(TM) Client VM (1.6.0-rc-b68) for windows-x86, built on Jan 19 2006 00:46:23 by "java_re" with unknown MS VC++:1310


Any idea ?

Tom

[tomdz]

Ups, sorry, wrong forum.

[Vladimir Kondratyev]

What version of profiler are you using?

[tomdz]

As I wrote, newest build (5.1 build 802 EAP).

[Anton Katilin]

Hi,

We didn't manage to reproduce it here.

Actually, there's no profiler agent code in the problematic stack. It seems that the JVM either crashed itself, or the crash was somehow indirectly caused by the presense of the profiler.

Is this crash always reproducible for you?

Is this crash reproducible with the profiler agent running Tomcat with Java 5?

Could you please provide more detail on what you were doing before you got this crash.

Best regards,
Anton

[tomdz]

The usage scenario is as follows: a simple webapp access a MySql database, retrieves some values and prints them (just a few lines of code). The webapp does not use shared libraries, e.g. all libs (incl. JDBC driver) are in WEB-INF/lib.
Running this webapp without the profiler works without any problems in Tomcat 5.5.12 and 5.5.15, with Java 5, and Mustang b68.
Profiling with build 802 likewise works without problems when using Java 5. But when profiling (more precisely, object allocation recording) is on, the webapp crashes at an indeterministic point. Sometimes at startup, sometimes when the webapp is reloaded using Tomcat's manager (I'm trying to analyze a memory leak at the WebappClassLoader, and hoped, Java 6 gives me more info). Nonetheless, Tomcat always crashes, I havn't yet been able to reload the webapp.
I can send you the webapp via email if that helps.

[Anton Katilin]

We have managed to reproduce this crash witn b68 (works fine with Java 5)

We're investigating the problem now...

[tomdz]

Thanks !

[Anton Katilin]

We have found that most likely this is a problem of Mustang.

Even simplest "java -version" crashes the same way when is launched with allocation recording on Mustang b68.

We've reported this issue to Sun JVM engineers and are waiting for their response.

Meanwhile I'd recommeded to use Java 5 to do the profiling.

[tomdz]

Mhm, a pity, because I thought I get more info when running in Mustang. Problem is that the WebappClassLoader is not GC'd and YourKit/Java 5 does not give me enough info to determine the problem lies (e.g. which class still references the WebappClassLoader). Using Java 6 was noted in some other forum thread, but unfortunately it does not seem to work right now ...

Tom

[Anton Katilin]

This problem appeared exactly in b68.

Mustang b67 works fine:

http://download.java.net/jdk6/archive/b ... n_2006.csp

[Anton Katilin]

This JVM bug will be fixed in b71.

[tomdz]

Thanks for the link, b67 works nicely.