The Many Faces of Traces

Most Java developers are familiar with jstack but if you're running on Linux, you might want to familiarise yourself with pstack too. This is especially useful if you are executing native code.

Let's create some native code we can call via JNI (see my last post if you want to compile it yourself):

#include <stdlib.h>
#include <stdio.h>
#include <jni.h>
#include "com_henryp_jni_MyJni.h"
#include <execinfo.h>
#include <signal.h>
#include <unistd.h>

JNIEXPORT jstring JNICALL Java_com_henryp_jni_MyJni_munge
  (JNIEnv* env, jobject obj, jstring str) {
        void *array[20];
        size_t size;
        jstring ret = 0;
        char* msg = "this is a test";

        printf("Java_com_henryp_jni_MyJni_munge called!\n");
        ret = (*env)->NewStringUTF(env, msg);

        printf("Hit return...\n");
        getchar();

        // get void*'s for all entries on the stack
        size = backtrace(array, 20);
        // print out all the frames to stderr
        backtrace_symbols_fd(array, size, STDERR_FILENO);

        return ret;
}

Here, we enter the C code, wait for a key press and print to stderr the non-Java stack trace by calling backtrace. This outputs:

[phenry@localhost MyTest]$ java -Djava.library.path=/mnt/hgfs/Shared/Code/JNI/MyJni/Debug -cp target/classes/ com.henryp.jni.MyJni

Java_com_henryp_jni_MyJni_munge called!

Hit return...

/mnt/hgfs/Shared/Code/JNI/MyJni/Debug/libMyJni.so(Java_com_henryp_jni_MyJni_munge+0x61)[0x1b7569]

[0xb560a84d]

[0xb560345a]

[0xb56003d9]

/usr/java/jdk1.7.0_07/jre/lib/i386/client/libjvm.so(+0x27dd65)[0x885d65]

/usr/java/jdk1.7.0_07/jre/lib/i386/client/libjvm.so(+0x3a27d9)[0x9aa7d9]

/usr/java/jdk1.7.0_07/jre/lib/i386/client/libjvm.so(+0x27cb7f)[0x884b7f]

/usr/java/jdk1.7.0_07/jre/lib/i386/client/libjvm.so(+0x29062a)[0x89862a]

/usr/java/jdk1.7.0_07/jre/lib/i386/client/libjvm.so(+0x29ae9b)[0x8a2e9b]

/usr/java/jdk1.7.0_07/bin/../jre/lib/i386/jli/libjli.so(+0x3384)[0x116384]

/lib/libpthread.so.0[0x468a4a2e]

/lib/libc.so.6(clone+0x5e)[0x467ea81e]

this is a test

If we allow the thread to tarry a little a little in this native method and run jstack we see our thread is runnable in the Java world even though it is blocking in the real world.

"main" prio=10 tid=0xb7705800 nid=0x3d46 runnable [0xb78a8000]

   java.lang.Thread.State: RUNNABLE

at com.henryp.jni.MyJni.munge(Native Method)

at com.henryp.jni.MyJni.main(MyJni.java:22)

This is consistent with what RUNNABLE means in the Java world, name that it is "in the runnable state is executing in the Java virtual machine but it may be waiting for other resources from the operating system such as processor."

Where pstack is handy is that we don't need to write our own C code to examine the stack when it enters native code. We can take the Java thread's ID (0x3d46) and call pstack on it so:

[phenry@localhost My_AsmLocks]$ printf "%d\n" 0x3d46

15686

[phenry@localhost My_AsmLocks]$ pstack 15686

Thread 1 (process 15686):

#0  0x00ec0424 in __kernel_vsyscall ()

#1  0x467da6db in read () from /lib/libc.so.6

#2  0x4682cbeb in _IO_old_file_underflow () from /lib/libc.so.6

#3  0x4677ed99 in _IO_default_uflow_internal () from /lib/libc.so.6

#4  0x4677ebaf in __uflow () from /lib/libc.so.6

#5  0x46779294 in getchar () from /lib/libc.so.6

#6  0x00a8f58f in myhandler () from /mnt/hgfs/Shared/Code/JNI/MyJni/Debug/libMyJni.so

#7  0x00a8f627 in Java_com_henryp_jni_MyJni_munge () from /mnt/hgfs/Shared/Code/JNI/MyJni/Debug/libMyJni.so

#8  0xb570a84d in ?? ()

#9  0xb570345a in ?? ()

#10 0xb57003d9 in ?? ()

#11 0x0038dd65 in JavaCalls::call_helper(JavaValue*, methodHandle*, JavaCallArguments*, Thread*) () from /usr/java/jdk1.7.0_07/jre/lib/i386/client/libjvm.so

#12 0x004b27d9 in os::os_exception_wrapper(void (*)(JavaValue*, methodHandle*, JavaCallArguments*, Thread*), JavaValue*, methodHandle*, JavaCallArguments*, Thread*) () from /usr/java/jdk1.7.0_07/jre/lib/i386/client/libjvm.so

#13 0x0038cb7f in JavaCalls::call(JavaValue*, methodHandle, JavaCallArguments*, Thread*) () from /usr/java/jdk1.7.0_07/jre/lib/i386/client/libjvm.so

#14 0x003a062a in jni_invoke_static(JNIEnv_*, JavaValue*, _jobject*, JNICallType, _jmethodID*, JNI_ArgumentPusher*, Thread*) () from /usr/java/jdk1.7.0_07/jre/lib/i386/client/libjvm.so

#15 0x003aae9b in jni_CallStaticVoidMethod () from /usr/java/jdk1.7.0_07/jre/lib/i386/client/libjvm.so

#16 0x00bc9384 in JavaMain () from /usr/java/jdk1.7.0_07/bin/../jre/lib/i386/jli/libjli.so

#17 0x468a4a2e in start_thread () from /lib/libpthread.so.0

#18 0x467ea81e in clone () from /lib/libc.so.6

giving us much the same result.

Addendum

When using jstack, you might have noticed the last line looks something like:

JNI global references: 114

This refers to how many global references still exist that were created in the JNI code [1]. By global I don't mean that were created with methods like this:

    for (i = 0 ; i < 10 ; i++) {
        ret = (*env)->NewStringUTF(env, msg);
    }

This makes no difference to the count. But, replace the line with this [2]:

        jclass cls1 = (*env)->GetObjectClass(env, obj);
        cls = (*env)->NewGlobalRef(env, cls1);

and you quickly see the count rise:

$ watch "jstack `jps | grep MyJni | perl -pe s/\ .*//g` | grep JNI"

This check may be why JNI has a reputation for being slow (but that's perhaps only compared to the optimised code that JIT creates).

[1] Oracle JNI Spec.

[2] Local and Global References.