Skip to content

Instantly share code, notes, and snippets.

@rednaxelafx

rednaxelafx/TraceSystemGCCall.java

Created March 8, 2012 13:15
Show Gist options
  • Star 3 You must be signed in to star a gist
  • Fork 2 You must be signed in to fork a gist
  • Save rednaxelafx/2000950 to your computer and use it in GitHub Desktop.
Save rednaxelafx/2000950 to your computer and use it in GitHub Desktop.
Download ZIP
BTrace script to log System.gc() calls
Raw
a_deadlock.md

Detail logs here: https://gist.github.com/2158975

[sajia@211 temp]$ export JAVA_OPTS='-javaagent:/home/sajia/sdk/btrace/build/btrace-agent.jar=script=TraceSystemGCCall.class,debug=true,scriptOutputFile=/home/sajia/temp/mybtrace.log'
[sajia@211 temp]$ groovysh
btrace DEBUG: debugMode is true
btrace DEBUG: scriptOutputFile is /home/sajia/temp/mybtrace.log
btrace DEBUG: unsafeMode is false
btrace DEBUG: dumpClasses is false
btrace DEBUG: stdout is false
btrace DEBUG: probe descriptor path is .
btrace DEBUG: initial script is TraceSystemGCCall.class
btrace DEBUG: verifying BTrace class
btrace DEBUG: verified 'TraceSystemGCCall' successfully
btrace DEBUG: created class filter
btrace DEBUG: preprocessing BTrace class TraceSystemGCCall
btrace DEBUG: preprocessed BTrace class TraceSystemGCCall
btrace DEBUG: creating BTraceRuntime instance for TraceSystemGCCall
btrace DEBUG: created BTraceRuntime instance for TraceSystemGCCall
btrace DEBUG: removing @OnMethod, @OnProbe methods
btrace DEBUG: removed @OnMethod, @OnProbe methods
btrace DEBUG: sending Okay command
btrace DEBUG: client TraceSystemGCCall: got com.sun.btrace.comm.OkayCommand@22c84d9
btrace DEBUG: about to defineClass TraceSystemGCCall
btrace DEBUG: defineClass succeeded for TraceSystemGCCall
btrace DEBUG: parsed command line arguments
btrace DEBUG: new Client created com.sun.btrace.agent.FileClient@268b819f
btrace DEBUG: skipping transform for BTrace class com/sun/btrace/agent/Main$3
btrace DEBUG: starting agent thread
btrace DEBUG: starting server at 2020
btrace DEBUG: filtering loaded classes
btrace DEBUG: client TraceSystemGCCall: instrumenting java/util/Collections$EmptySet$1
btrace DEBUG: client TraceSystemGCCall: instrumenting java/net/ServerSocket

jstack -l

Found one Java-level deadlock:
=============================
"Thread-1":
  waiting to lock monitor 0x00002aaab40f2678 (object 0x0000000604343e40, a <unknown>),
  which is held by "pool-1-thread-1"
"pool-1-thread-1":
  waiting to lock monitor 0x000000005e7f88e0 (object 0x000000075862d060, a sun.misc.Launcher$AppClassLoader),
  which is held by "Thread-1"

Java stack information for the threads listed above:
===================================================
"Thread-1":
        at com.sun.btrace.agent.Client.instrument(Client.java:373)
        at com.sun.btrace.agent.Client.doTransform(Client.java:195)
        at com.sun.btrace.agent.Client.transform(Client.java:155)
        at sun.instrument.TransformerManager.transform(TransformerManager.java:169)
        at sun.instrument.InstrumentationImpl.transform(InstrumentationImpl.java:365)
        at java.lang.ClassLoader.findBootstrapClass(Native Method)
        at java.lang.ClassLoader.findBootstrapClassOrNull(ClassLoader.java:926)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:297)
        - locked <0x00000007586261b0> (a sun.misc.Launcher$ExtClassLoader)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:295)
        - locked <0x000000075862d060> (a sun.misc.Launcher$AppClassLoader)
        at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:301)
        - locked <0x000000075862d060> (a sun.misc.Launcher$AppClassLoader)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:247)
        at com.sun.btrace.agent.Main.startServer(Main.java:368)
        at com.sun.btrace.agent.Main.access$000(Main.java:65)
        at com.sun.btrace.agent.Main$3.run(Main.java:166)
        at java.lang.Thread.run(Thread.java:662)
"pool-1-thread-1":
        at com.sun.btrace.agent.Client.instrument(Client.java:373)
        at com.sun.btrace.agent.Client.doTransform(Client.java:195)
        at com.sun.btrace.agent.Client.transform(Client.java:155)
        at sun.instrument.TransformerManager.transform(TransformerManager.java:169)
        at sun.instrument.InstrumentationImpl.transform(InstrumentationImpl.java:365)
        at java.util.Collections$EmptySet.iterator(Collections.java:2907)
        at java.lang.Class.initAnnotationsIfNecessary(Class.java:3078)
        - locked <0x00000006040308d8> (a java.lang.Class for java.lang.System)
        at java.lang.Class.getAnnotation(Class.java:3029)
        at com.sun.btrace.runtime.ClassFilter.isCandidate(ClassFilter.java:83)
        at com.sun.btrace.agent.Client.isCandidate(Client.java:315)
        at com.sun.btrace.agent.Main$4.run(Main.java:416)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
        at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
        at java.util.concurrent.FutureTask.run(FutureTask.java:138)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:662)

Found 1 deadlock.
Raw
an_unexpected_error
[sajia@211 temp]$ export JAVA_OPTS='-javaagent:/home/sajia/sdk/btrace/build/btrace-agent.jar=script=TraceSystemGCCall.class,debug=true'
[sajia@211 temp]$ groovysh
btrace DEBUG: debugMode is true
btrace DEBUG: unsafeMode is false
btrace DEBUG: dumpClasses is false
btrace DEBUG: stdout is false
btrace DEBUG: probe descriptor path is .
btrace DEBUG: initial script is TraceSystemGCCall.class
btrace DEBUG: scriptOutputFile not specified. defaulting to TraceSystemGCCall.class.btrace
btrace DEBUG: java.lang.NullPointerException
java.lang.NullPointerException
at com.sun.btrace.agent.TraceOutputWriter$SimpleFileOutput.<init>(TraceOutputWriter.java:46)
at com.sun.btrace.agent.TraceOutputWriter.fileWriter(TraceOutputWriter.java:185)
at com.sun.btrace.agent.Main.loadBTraceScript(Main.java:334)
at com.sun.btrace.agent.Main.parseArgs(Main.java:267)
at com.sun.btrace.agent.Main.main(Main.java:117)
at com.sun.btrace.agent.Main.premain(Main.java:101)
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:597)
at sun.instrument.InstrumentationImpl.loadClassAndStartAgent(InstrumentationImpl.java:323)
at sun.instrument.InstrumentationImpl.loadClassAndCallPremain(InstrumentationImpl.java:338)
btrace DEBUG: parsed command line arguments
btrace DEBUG: starting agent thread
btrace DEBUG: starting server at 2020
btrace DEBUG: waiting for clients
Groovy Shell (1.7.7, JVM: 1.6.0_30)
Type 'help' or '\h' for help.
----------------------------------------------------------------------------------------------------------------------------
groovy:000>
Raw
modified_class_example.bytecode
public static void main(java.lang.String[]) throws java.lang.Exception;
Code:
Stack=1, Locals=1, Args_size=1
0: getstatic #19; //Field java/lang/System.in:Ljava/io/InputStream;
3: invokevirtual #25; //Method java/io/InputStream.read:()I
6: pop
7: invokestatic #28; //Method $btrace$TraceSystemGCCall$onSystemGC:()V
10: invokestatic #31; //Method java/lang/System.gc:()V
13: getstatic #19; //Field java/lang/System.in:Ljava/io/InputStream;
16: invokevirtual #25; //Method java/io/InputStream.read:()I
19: pop
20: getstatic #19; //Field java/lang/System.in:Ljava/io/InputStream;
23: invokevirtual #25; //Method java/io/InputStream.read:()I
26: pop
27: return
LineNumberTable:
line 3: 0
line 4: 7
line 5: 13
line 6: 20
line 7: 27
Exceptions:
throws java.lang.Exception
private static void $btrace$TraceSystemGCCall$onSystemGC();
Code:
Stack=1, Locals=0, Args_size=0
0: getstatic #49; //Field TraceSystemGCCall.runtime:Lcom/sun/btrace/BTraceRuntime;
3: invokestatic #55; //Method com/sun/btrace/BTraceRuntime.enter:(Lcom/sun/btrace/BTraceRuntime;)Z
6: ifne 10
9: return
10: invokestatic #60; //Method com/sun/btrace/BTraceUtils$Threads.jstack:()V
13: invokestatic #63; //Method com/sun/btrace/BTraceRuntime.leave:()V
16: return
17: invokestatic #67; //Method com/sun/btrace/BTraceRuntime.handleException:(Ljava/lang/Throwable;)V
20: return
Exception table:
from to target type
10 17 17 Class java/lang/Throwable
StackMapTable: number_of_entries = 2
frame_type = 10 /* same */
frame_type = 70 /* same_locals_1_stack_item */
stack = [ class java/lang/Throwable ]
RuntimeVisibleAnnotations: length = 0x28
00 01 00 20 00 03 00 21 73 00 22 00 23 73 00 22
00 24 40 00 25 00 03 00 26 65 00 27 00 28 00 21
73 00 29 00 23 73 00 1D
Raw
TraceSystemGCCall.java
import com.sun.btrace.annotations.*;
import static com.sun.btrace.BTraceUtils.*;
@BTrace
public class TraceSystemGCCall {
@OnMethod(
clazz="/.*/",
method="/.*/",
location=@Location(
value=Kind.CALL,
clazz="/java\\.lang\\.(?:System|Runtime)/",
method="gc"
)
)
public static void onSystemGC() {
jstack();
}
}
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment