Monday, May 02, 2011

JDB - Debugging Concurrency issues in Java

Typically debugging concurrency issues using debugger is very difficult as it manifests only when multiple requests are processed concurrently. Also in a debugger tracking multiple threads is further difficult.
JDB is a free command line tool for Java. Please refer to my previous post for details about JDB ( http://rejeev.blogspot.com/2011/04/jdb-command-line-debugger-for-java.html ). We can debug concurrency issues much easily using JDB.
Typically concurrency issues are due to updation (or updaton and read) of a shared variable from two threads. Typically the challenge will be to identify which thread update the variable at which code segment. We can use JDB to identify that.

  • run the application with debug enabled

  • attach JDB to the application.

  • set 'watch' on the variable at the suspect variable.

  • set a 'monitor where all' to print the stack trace whenever the variable is accessed.

  • 'run' the application.

  • 'run' each time the application pauses at modification of the watch point.


Now whenever the application is modifying the variable, thread dump shall be printed. From the thread dump we will be able to identify which thread modifies the variable and at code segment.

Let us see an example now


Given below is a very simple example where a variable is shared between two threads and by the time, the thread 'main' prints out the value of the shared variable, the value has been modified by the other thread.
As this program is only few lines of code it is very trivial to go through the code and understand that the second thread is updating the variable at code Main2 (line:11). In a real application the shared variable may be updated from too many places with too many code paths to that. Eventhough you know that some thread updates the shared variable, it is very difficult to identify which thread updates from which code. JDB will help us to identify that.

Let us see how do we identify that



public class Main2 extends Thread {
public static int count;
public static void main(String[] args) throws Exception {
new Main2().start();
count = 5;
Thread.sleep(10);
System.out.println("value: " + count);
}
public void run(){
try{ Thread.sleep(5); }catch(Exception e){}
count = 10;
}
}

Now compile the code

javac -g Main2.java

Now run the program with debug enabled

java -cp . -Xdebug -Xrunjdwp:transport=dt_socket,server=y,address=8000,suspend=y Main2
Listening for transport dt_socket at address: 8000

Now attach the debugger

jdb -sourcepath . -attach 8000
Set uncaught java.lang.Throwable
Set deferred uncaught java.lang.Throwable
Initializing jdb ...

VM Started: No frames on the current call stack
main[1]

Now set 'watch' on the shared variable count. This means whenever the variable 'count' is modified, program will stop execution (as if there is a break point).

watch Main2.count

Now set 'monitor where all'. This means that whenever the program stops (due to a breakpoint or watch) 'where all' command (thread dump) shall be executed.

monitor where all

Now let us start execution by giving the command 'run'. We will get the first thread dump when the varible count is modified first time.

run
> Set deferred watch modification of Main2.count

Field (Main2.count) is 0, will be 5: "thread=main", Main2.main(), line=5 bci=11

Signal Dispatcher:
Finalizer:
[1] java.lang.Object.wait (native method)
[2] java.lang.ref.ReferenceQueue.remove (ReferenceQueue.java:118)
[3] java.lang.ref.ReferenceQueue.remove (ReferenceQueue.java:134)
[4] java.lang.ref.Finalizer$FinalizerThread.run (Finalizer.java:159)
Reference Handler:
[1] java.lang.Object.wait (native method)
[2] java.lang.Object.wait (Object.java:485)
[3] java.lang.ref.Reference$ReferenceHandler.run (Reference.java:116)
main:
[1] Main2.main (Main2.java:5)
Thread-2:
[1] Main2.run (Main2.java:10)
main[1]

'main[1]' as the command prompt indicates that current thread is 'main[1]'. First line of the thread 'main[1]' is Main2.java:5. That means the current line of code is at Main2.java:5.
run 'list' to see the current see the code at line number Main2.java:5

list
1 public class Main2 extends Thread {
2 public static int count;
3 public static void main(String[] args) throws Exception {
4 new Main2().start();
5 => count = 5;
6 Thread.sleep(10);
7 System.out.println("value: " + count);
8 }
9 public void run(){
10 try{ Thread.sleep(5); }catch(Exception e){}

Now resume execution again from there using 'run'. Now we get the thread dump again when the variable 'count' is modified.

run
Field (Main2.count) is 5, will be 10: "thread=Thread-2", Main2.run(), line=11 bci=12
11 count = 10;

Signal Dispatcher:
Finalizer:
[1] java.lang.Object.wait (native method)
[2] java.lang.ref.ReferenceQueue.remove (ReferenceQueue.java:118)
[3] java.lang.ref.ReferenceQueue.remove (ReferenceQueue.java:134)
[4] java.lang.ref.Finalizer$FinalizerThread.run (Finalizer.java:159)
Reference Handler:
[1] java.lang.Object.wait (native method)
[2] java.lang.Object.wait (Object.java:485)
[3] java.lang.ref.Reference$ReferenceHandler.run (Reference.java:116)
main:
[1] java.lang.Thread.sleep (native method)
[2] Main2.main (Main2.java:6)
Thread-2:
[1] Main2.run (Main2.java:11)
Thread-2[1]

Now current thread of execution is Thread-2 and current line of code is Main2.java:11.
To see the line of code at Main2.java:11

list
7 System.out.println("value: " + count);
8 }
9 public void run(){
10 try{ Thread.sleep(5); }catch(Exception e){}
11 => count = 10;
12 }
13 }

This time 'count' is modified by the second thread. From this it can identified that 'Thread 2' is modifying the variable 'count' at Main2(line:11). Also the code path to this operation also can be infered from the thread dump.
Hence the culprit here is 'Thread-2' and code segment 'Main2.java:11' and the execution path as explained in the stack of Thread-2 in the thread dump.

1 comment:

Thomas Krieger said...

Hi,

I implemented a tool called http://vmlens.com which can detect if a memory field was changed by two or more threads without synchronization. It uses java instrumentation.

Regards
Thomas