One of the
most common technique used while debugging a problem in Java is to add debug
statements (System.out.println) into the suspected code or dump the stack
trace using the Thread.currentThread().dumpStack()
API. This helps to print the parameter
values, know the code path that lead to the suspected method. However, this has the drawback that the code
needs to be re-compiled, updated to the relevant JAR file and tested.
A more efficient approach to do the same is to use to tracing facility that comes with IBM JDKs. IBM JDK provides the –Xtrace option to trace the Java or native methods and it also allows the user to dump the stacktrace of any Java method.
The “jstacktrace” option allows the user to walk the Java stack of the current thread. This option is available since IBM Java 6 SR5. In this blog, I would like to give syntax details and a couple of examples on how the “jstacktrace” option can be used to dump the stacktrace of any Java method or a JNI method.
- Use the below option to print the Java stack trace to the console when java/nio/ByteBuffer.allocateDirect() method is called:
-Xtrace:print=mt,trigger=method{java/nio/ByteBuffer.allocateDirect,jstacktrace}
11:30:14.560 0x2a5c00 j9trc_aux.0 - jstacktrace:
11:30:14.560 0x2a5c00 j9trc_aux.1 - [1] sun.misc.Unsafe.allocateMemory (Native Method)
11:30:14.561 0x2a5c00 j9trc_aux.1 - [2] java.nio.DirectByteBuffer.<init> (DirectByteBuffer.java:102)
11:30:14.561 0x2a5c00 j9trc_aux.1 - [3] java.nio.ByteBuffer.allocateDirect (ByteBuffer.java:288)
11:30:14.561 0x2a5c00 j9trc_aux.1 - [4] sun.io.CharToByteSingleByte.createCopy (CharToByteSingleByte.java:557)
11:30:14.561 0x2a5c00 j9trc_aux.1 - [5] sun.io.CharToByteCp1252.<clinit> (CharToByteCp1252.java:221)
11:30:14.561 0x2a5c00 j9trc_aux.1 - [6] java.lang.J9VMInternals.initializeImpl (Native Method)
11:30:14.561 0x2a5c00 j9trc_aux.1 - [7] java.lang.J9VMInternals.initialize (J9VMInternals.java:200)
11:30:14.561 0x2a5c00 j9trc_aux.1 - [8] java.lang.Class.forNameImpl (Native Method)
11:30:14.562 0x2a5c00 j9trc_aux.1 - [9] java.lang.Class.forName (Class.java:141)
11:30:14.562 0x2a5c00 j9trc_aux.1 - [10] sun.io.Converters.getConverterClass (Converters.java:298)
11:30:14.562 0x2a5c00 j9trc_aux.1 - [11] sun.io.Converters.newConverter (Converters.java:334)
11:30:14.562 0x2a5c00 j9trc_aux.1 - [12] sun.io.CharToByteConverter.getConverter (CharToByteConverter.java:86)
11:30:14.562 0x2a5c00 j9trc_aux.1 - [13] java.lang.StringCoding.makeEncoder (StringCoding.java:179)
11:30:14.562 0x2a5c00 j9trc_aux.1 - [14] java.lang.StringCoding$EncoderCache$1.run (StringCoding.java:244)
11:30:14.562 0x2a5c00 j9trc_aux.1 - [15] java.security.AccessController.doPrivileged (AccessController.java:277)
11:30:14.563 0x2a5c00 j9trc_aux.1 - [16] java.lang.StringCoding$EncoderCache.getEncoder (StringCoding.java:241)
11:30:14.563 0x2a5c00 j9trc_aux.1 - [17] java.lang.StringCoding.getEncoder (StringCoding.java:434)
11:30:14.563 0x2a5c00 j9trc_aux.1 - [18] java.lang.StringCoding.encode (StringCoding.java:576)
11:30:14.563 0x2a5c00 j9trc_aux.1 - [19] java.lang.StringCoding.encode (StringCoding.java:641)
11:30:14.563 0x2a5c00 j9trc_aux.1 - [20] java.lang.System.<clinit> (System.java:106)
11:30:14.563 0x2a5c00 j9trc_aux.1 - [21] java.lang.J9VMInternals.initializeImpl (Native Method)
11:30:14.563 0x2a5c00 j9trc_aux.1 - [22] java.lang.J9VMInternals.initialize (J9VMInternals.java:200)
11:30:14.564 0x2a5c00 j9trc_aux.1 - [23] java.lang.ClassLoader.initializeClassLoaders (ClassLoader.java:74)
11:30:14.564 0x2a5c00 j9trc_aux.1 - [24] java.lang.Thread.initialize (Thread.java:325)
11:30:14.564 0x2a5c00 j9trc_aux.1 - [25] java.lang.Thread.<init> (Thread.java:124)
- Use the below option to write the Java stack trace to a file when java/nio/ByteBuffer.allocateDirect() method is called:
-Xtrace:maximal=mt,output=trc.out,trigger=method{java/nio/ByteBuffer.allocateDirect,jstacktrace}
Display the Java Stack Trace for JNI Methods
- Use the below option to print the Java stack trace to the console when tracepoint id of Unsafe.allocateMemory is called:
-Xtrace:print="j9jcl.62",trigger="tpnid{j9jcl.62,jstacktrace}"
Note: j9jcl.62 is the tracepoint for the JNI method Unsafe.allocateMemory
Sample Output:
15:01:24.995*0x247600 j9jcl.62 > sun_misc_Unsafe_allocateMemory(8)
15:01:24.997 0x247600 j9trc_aux.0 - jstacktrace:
15:01:24.997 0x247600 j9trc_aux.1 - [1] sun.misc.Unsafe.allocateMemory (Native Method)
15:01:24.997 0x247600 j9trc_aux.1 - [2] java.nio.Bits.byteOrder (Bits.java:556)
15:01:24.997 0x247600 j9trc_aux.1 - [3] java.nio.ByteBuffer.<init> (ByteBuffer.java:1361)
15:01:24.997 0x247600 j9trc_aux.1 - [4] java.nio.ByteBuffer.<init> (ByteBuffer.java:267)
15:01:24.997 0x247600 j9trc_aux.1 - [5] java.nio.MappedByteBuffer.<init> (MappedByteBuffer.java:72)
15:01:24.998 0x247600 j9trc_aux.1 - [6] java.nio.DirectByteBuffer.<init> (DirectByteBuffer.java:97)
15:01:24.998 0x247600 j9trc_aux.1 - [7] java.nio.ByteBuffer.allocateDirect (ByteBuffer.java:288)
15:01:24.998 0x247600 j9trc_aux.1 - [8] sun.io.CharToByteSingleByte.createCopy (CharToByteSingleByte.java:557)
15:01:24.998 0x247600 j9trc_aux.1 - [9] sun.io.CharToByteCp1252.<clinit> (CharToByteCp1252.java:221)
15:01:24.998 0x247600 j9trc_aux.1 - [10] java.lang.J9VMInternals.initializeImpl (Native Method)
15:01:24.998 0x247600 j9trc_aux.1 - [11] java.lang.J9VMInternals.initialize (J9VMInternals.java:200)
15:01:24.998 0x247600 j9trc_aux.1 - [12] java.lang.Class.forNameImpl (Native Method)
15:01:24.998 0x247600 j9trc_aux.1 - [13] java.lang.Class.forName (Class.java:141)
15:01:24.998 0x247600 j9trc_aux.1 - [14] sun.io.Converters.getConverterClass (Converters.java:298)
15:01:24.999 0x247600 j9trc_aux.1 - [15] sun.io.Converters.newConverter (Converters.java:334)
15:01:24.999 0x247600 j9trc_aux.1 - [16] sun.io.CharToByteConverter.getConverter (CharToByteConverter.java:86)
15:01:24.999 0x247600 j9trc_aux.1 - [17] java.lang.StringCoding.makeEncoder (StringCoding.java:179)
15:01:24.999 0x247600 j9trc_aux.1 - [18] java.lang.StringCoding$EncoderCache$1.run (StringCoding.java:244)
15:01:25.000 0x247600 j9trc_aux.1 - [19] java.security.AccessController.doPrivileged (AccessController.java:277)
15:01:25.000 0x247600 j9trc_aux.1 - [20] java.lang.StringCoding$EncoderCache.getEncoder (StringCoding.java:241)
15:01:25.001 0x247600 j9trc_aux.1 - [21] java.lang.StringCoding.getEncoder (StringCoding.java:434)
15:01:25.001 0x247600 j9trc_aux.1 - [22] java.lang.StringCoding.encode (StringCoding.java:576)
15:01:25.001 0x247600 j9trc_aux.1 - [23] java.lang.StringCoding.encode (StringCoding.java:641)
15:01:25.001 0x247600 j9trc_aux.1 - [24] java.lang.System.<clinit> (System.java:106)
15:01:25.001 0x247600 j9trc_aux.1 - [25] java.lang.J9VMInternals.initializeImpl (Native Method)
15:01:25.001 0x247600 j9trc_aux.1 - [26] java.lang.J9VMInternals.initialize (J9VMInternals.java:200)
15:01:25.001
0x247600 j9trc_aux.1 - [27]
java.lang.ClassLoader.initializeClassLoaders (ClassLoader.java:74)
15:01:25.001 0x247600 j9trc_aux.1 - [28] java.lang.Thread.initialize (Thread.java:325)
15:01:25.001 0x247600 j9trc_aux.1 - [29] java.lang.Thread.<init> (Thread.java:124)
Control the number of stack frames displayed
The
“stackdepth” option can be used to limit the number of stack frames displayed
along with the jstacktrace trigger option. By default, all the stack frames are
displayed.
- Use the below option to print only 5 frames of the Java stack trace to the console when java/nio/ByteBuffer.allocateDirect() method is called:
-Xtrace:print=mt,trigger=method{java/nio/ByteBuffer.allocateDirect,jstacktrace},stackdepth=5
15:00:20.707*0x627800 mt.3 > java/nio/ByteBuffer.allocateDirect(I)Ljava/nio/ByteBuffer; Bytecode static method
15:00:20.707 0x627800 mt.19 - Static method arguments: ((int)65536)
15:00:20.711 0x627800 j9trc_aux.0 - jstacktrace:
15:00:20.711 0x627800 j9trc_aux.1 - [1] java.nio.ByteBuffer.allocateDirect (ByteBuffer.java:288)
15:00:20.711 0x627800 j9trc_aux.1 - [2] sun.io.CharToByteSingleByte.createCopy (CharToByteSingleByte.java:557)
15:00:20.711 0x627800 j9trc_aux.1 - [3] sun.io.CharToByteCp1252.<clinit> (CharToByteCp1252.java:221)
15:00:20.712 0x627800 j9trc_aux.1 - [4] java.lang.J9VMInternals.initializeImpl (Native Method)
15:00:20.712 0x627800 j9trc_aux.1 - [5] java.lang.J9VMInternals.initialize (J9VMInternals.java:200)
15:00:20.719 0x627800 mt.9 < java/nio/ByteBuffer.allocateDirect(I)Ljava/nio/ByteBuffer; Bytecode static method