Using GDB to debug Java!

GDB is a very powerful debugger which is mainly used to debug C/C++ programs. But as many of the languages such as Java, Python, Perl, PHP, Ruby etc. are implemented in C/C++, so sometimes GDB is even useful in debugging some issues in programs implemented in these languages as well. Today I demonstrate one such use cases with Java programs.

Below is the Java program that calls a native API HelloWorld.  The HelloWorld internally calls printf to print some string to console and also prints some string to a file /tmp/testout.txt

//JniHelloWorld.java
import java.io.File;
import java.io.FileNotFoundException;
import java.io.FileOutputStream;
import java.io.IOException;

public class JniHelloWorld implements Runnable{
	
	private native void HelloWorld();
	private Object lock1 = null;
	private Object lock2 = null;
	private FileOutputStream fos = null;

	public JniHelloWorld() {
		lock1 = new Object();
		lock2 = new Object();
		try {
			fos = new FileOutputStream(new File("/tmp/testout.txt"));
		} catch (FileNotFoundException e) {
			e.printStackTrace();
			System.exit(1);
		}
	}
	
	@Override
	public void run() {
		byte []outbytes = "This will go to /tmp/testout.txt file\n".getBytes();
        while (true) {
            try {
                Thread.sleep(200);
            } catch (InterruptedException e) {
            }
            synchronized (lock1) {
                HelloWorld();
            }
            synchronized (lock2) {
                try {
                    fos.write(outbytes);
                } catch (IOException e) {
                }
            }
        }
	}	
	
	public static void main(String[] args) {
        System.loadLibrary("test");
		JniHelloWorld jnh = new JniHelloWorld();
		int i = 0;
		while (i++ < 20){
			new Thread(jnh).start();
		}
	}
}

Let us compile the Java code. $ javac javac JniHelloWorld.java Generate the JNI header file: $ javah JniHelloWorld Create the C file test.c

#include <stdio.h>
#include "JniHelloWorld.h"

JNIEXPORT void JNICALL Java_JniHelloWorld_HelloWorld
  (JNIEnv *env, jobject o){
              printf("hello from printf\n");  
  }

Now let us create the shared library:
$ gcc -I . -I $JAVA_HOME/include -I $JAVA_HOME/include/linux -fPIC -c test.c
In my machine JAVA_HOME points to /home/geet/sws/jdk1.8.0_20.

Now create the shared library:
$ gcc -shared -o libtest.so test.o

Set LD_LIBRARY_PATH (eg. export LD_LIBRARY_PATH=.) and then run the example Java program.
$ java JniHelloWorld

The process keeps running continuously printing to console and /tmp/testout.txt. If you check the program there is no chance for any dead lock in the code.

We may check the threads of Java thread using the commands in the below example (I am not using Jstack or jconsole, JVisualVM etc. as I want to check even the threads created by the native library). Every Java thread is mapped to a native thread (a posix thread on a Linux machine).

$ jps
4512 JniHelloWorld
4602 Jps

$ ps -fT -p 4512

Output will be something like:
UID PID SPID PPID C STIME TTY TIME CMD
geet 4512 4512 3068 0 08:56 pts/15 00:00:00 java JniHelloWorld
geet 4512 4513 3068 0 08:56 pts/15 00:00:00 java JniHelloWorld
geet 4512 4514 3068 0 08:56 pts/15 00:00:00 java JniHelloWorld
geet 4512 4515 3068 0 08:56 pts/15 00:00:00 java JniHelloWorld
geet 4512 4516 3068 0 08:56 pts/15 00:00:00 java JniHelloWorld
geet 4512 4517 3068 0 08:56 pts/15 00:00:00 java JniHelloWorld
geet 4512 4518 3068 0 08:56 pts/15 00:00:00 java JniHelloWorld
geet 4512 4519 3068 0 08:56 pts/15 00:00:00 java JniHelloWorld
geet 4512 4520 3068 0 08:56 pts/15 00:00:00 java JniHelloWorld
geet 4512 4521 3068 0 08:56 pts/15 00:00:00 java JniHelloWorld
geet 4512 4522 3068 0 08:56 pts/15 00:00:00 java JniHelloWorld
geet 4512 4523 3068 0 08:56 pts/15 00:00:00 java JniHelloWorld
geet 4512 4524 3068 0 08:56 pts/15 00:00:00 java JniHelloWorld
...
...

We may attach gdb to any of the thread to examine what it is doing
Eg. $ sudo gdb -p 4551

Now everything runs fine and no issues. Now let us spawn this Java program from another Java program.

// Spawner.java
import java.io.IOException;

public class Spawner {
	
	public static void main(String[] args) {
		ProcessBuilder pb =
				   new ProcessBuilder("java", "JniHelloWorld");
		Process p;
		try {
			p = pb.start();
			while (p.isAlive()){
				Thread.sleep(200);
			}
		} catch (IOException e) {
		} catch (InterruptedException e ){
		}
	}

}

$javac Spawner.java

Now run the Java process
$java Spawner

We may look at the modification time of /tmp/testout.txt to check if it is being updated continuously. After some time, we will see that the file is not being updated at all, but all the Java processes are running!

$ jps
5602 Spawner
6086 Jps
5622 JniHelloWorld


Definitely something wrong with JniHelloWorld process. Let us take its thread-dump

$jstack 5622

Now we examine the output of jstack.
Most of the threads are blocked,
"Thread-0" #10 prio=5 os_prio=0 tid=0x00007fde040e5000 nid=0x160b waiting for monitor entry [0x00007fdddae06000]
java.lang.Thread.State: BLOCKED (on object monitor)
at JniHelloWorld.run(JniHelloWorld.java:33)
- waiting to lock <0x000000076ce5b140> (a java.lang.Object)
at java.lang.Thread.run(Thread.java:745)


They are waiting for lock 0x000000076ce5b140 which corresponds to lock1.

Let us see who acquired the lock lock1 from output of jstack, I found it be the below thread
"Thread-6" #16 prio=5 os_prio=0 tid=0x00007fde040ef800 nid=0x1611 runnable [0x00007fddda800000]
java.lang.Thread.State: RUNNABLE
at JniHelloWorld.HelloWorld(Native Method)
at JniHelloWorld.run(JniHelloWorld.java:33)
- locked <0x000000076ce5b140> (a java.lang.Object)
at java.lang.Thread.run(Thread.java:745)

It has locked lock1 and stuck at native HelloWorld method, effectively blocking other threads waiting for that lock. It is a special kind of dead lock.

Now we need to check why this thread stuck at native method, Java debugger or tools won't help as we are in the native world ! The value of nid for this thread is 0x1611 (= 5649) which is the light weight process id for this thread. Let us attach gdb to this process and get its backtrace,

$sudo gdb -p 0x1611

The backtrace shows:
(gdb) bt
#0 0x00007fde09d7c3cd in write () at ../sysdeps/unix/syscall-template.S:81
#1 0x00007fde09d09a83 in _IO_new_file_write (f=0x7fde0a050400 <_io_2_1_stdout_>, data=0x7fde0a8b4000, n=4096)
at fileops.c:1261
#2 0x00007fde09d0af5c in new_do_write (to_do=4096,
data=0x7fde0a8b4000 "f\nhello from printf\nhello from printf\nhello from printf\nhello from printf\nhello from printf\nhello from printf\nhello from printf\nhello from printf\nhello from printf\nhello from printf\nhello from printf\n"...,
fp=0x7fde0a050400 <_io_2_1_stdout_>) at fileops.c:538
#3 _IO_new_do_write (fp=0x7fde0a050400 <_io_2_1_stdout_>,
data=0x7fde0a8b4000 "f\nhello from printf\nhello from printf\nhello from printf\nhello from printf\nhello from printf\nhello from printf\nhello from printf\nhello from printf\nhello from printf\nhello from printf\nhello from printf\n"...,
to_do=4096) at fileops.c:511
#4 0x00007fde09d0a121 in _IO_new_file_xsputn (f=0x7fde0a050400 <_io_2_1_stdout_>, data=, n=17)
at fileops.c:1332
#5 0x00007fde09d00957 in _IO_puts (str=0x7fdddae086fd "hello from printf") at ioputs.c:41
#6 0x00007fdddae086f1 in Java_JniHelloWorld_HelloWorld (env=0x7fde040ef9e8, o=0x7fddda8005f0) at test.c:6
#7 0x00007fddf489f8e6 in ?? ()
#8 0x000000076ce5b128 in ?? ()
#9 0x00007fde0935f9ac in InterpreterRuntime::monitorexit(JavaThread*, BasicObjectLock*) ()
from /home/geet/sws/jdk1.8.0_20/jre/lib/amd64/server/libjvm.so
#10 0x00007fddf47a798d in ?? ()
#11 0x00007fddf47a798d in ?? ()
#12 0x000000076ce5b128 in ?? ()
#13 0x0000000000000003 in ?? ()
#14 0x000000076ce5b140 in ?? ()
#15 0x00007fddda800650 in ?? ()
#16 0x00007fddf2410668 in ?? ()
#17 0x00007fddda8006d0 in ?? ()
#18 0x00007fddf2410850 in ?? ()
#19 0x0000000000000000 in ?? ()


Clearly the back trace shows that the thread is stuck at write system call (results from call to printf). Why is it blocked? Because its output buffer is full and nobody is taking out or cleaning the data. When we directly run JniHelloWorld from a terminal, the terminal is continuously clearing and spitting out this data and hence then it doesn't block.

BTW, there are neat ways to consume or redirect output buffers of spwaned processes to avoid such problems. I have used this not-very-neat example mainly to show how we can use GDB to debug Java programs in such situations.