Monday, August 10, 2015

Debugging deadlocks with Java's ReentrantLock


I recently experience a situation where my program just seemed to "stop". My first instinct was to use the Netbeans "check for deadlock" feature. Unfortunately, when Netbeans told me "no deadlock found". I still thought it was a deadlock. The app created dozens of threads, and the Netbeans debugger has a really crummy bug where the vertical slider repositions the threads viewport every time you pause a thread. This made it very difficult to see what was going on, but after a lot of clicking around I seemed to be able to determine that there was a thread waiting on a ReentrantLock. Every time I un-suspended the thread, it stayed at exactly the same place. Obviously someone was holding the lock. With the debugger, I could see a field inside the ReentrantLock called "exclusiveHolder" (or something like that), and by looking at the char array for the field, I could see the name of the other thread. Indeed this other thread was sitting trying to enter a synchronized method. From the call stack of the first thread I could see that the first thread already had entered the synchronized method. So it was a deadlock. To pin it down with certainty, I added these debug statements before attempting lock() on the lock instance.:

log.warn("attempting increment LOCK: " + lock +" w/ queue len  "+lock.getQueueLength());

 I also added this log4j configuration so that I could see the calling thread.


Fortunately, the toString method of ReentrantLock also prints the current owner of the lock.

# Set root logger level to DEBUG and its only appender to A1.
log4j.rootLogger=WARN, A1

# A1 is set to be a ConsoleAppender.
log4j.appender.A1=org.apache.log4j.ConsoleAppender

# A1 uses PatternLayout.
log4j.appender.A1.layout=org.apache.log4j.PatternLayout
log4j.appender.A1.layout.ConversionPattern=%-4r [%t] [line=%L] [%M] %-5p %c %x - %m%n

The "%t" will show the calling thread.