Thursday, 25 October 2012

Investigating Deadlocks – Part 3: Analysing the Thread Dump

In my previous two blogs in this series, part 1 and part 2, I’ve demonstrated how to create a piece of bad code that deadlocks and then used this code to show three ways of taking a thread dump. In this blog I’m going to analyze the thread dump to figure out what when wrong.

The discussion below refers to both the Account and DeadlockDemo classes from part 1 of this series, which contains full code listings.

The first thing that that I need is a thread dump from the DeadlockDemo application, so as they used to say on Blue Peter “here’s one I prepared earlier”.

2012-10-16 13:37:03
Full thread dump Java HotSpot(TM) 64-Bit Server VM (20.10-b01-428 mixed mode):

"DestroyJavaVM" prio=5 tid=7f9712001000 nid=0x110247000 waiting on condition [00000000]
   java.lang.Thread.State: RUNNABLE

"Thread-21" prio=5 tid=7f9712944000 nid=0x118d76000 waiting for monitor entry [118d75000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:86)
 - waiting to lock <7f3366f58> (a threads.deadlock.Account)
 - locked <7f3366ee0> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)

"Thread-20" prio=5 tid=7f971216c000 nid=0x118c73000 waiting for monitor entry [118c72000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:86)
 - waiting to lock <7f3366e98> (a threads.deadlock.Account)
 - locked <7f3366f58> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)

"Thread-19" prio=5 tid=7f9712943800 nid=0x118b70000 waiting for monitor entry [118b6f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:81)
 - waiting to lock <7f3366f40> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)

"Thread-18" prio=5 tid=7f9712942800 nid=0x118a6d000 waiting for monitor entry [118a6c000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:81)
 - waiting to lock <7f3366f40> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)

"Thread-17" prio=5 tid=7f9712942000 nid=0x11896a000 waiting for monitor entry [118969000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:81)
 - waiting to lock <7f3366ec8> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)

"Thread-16" prio=5 tid=7f9712941000 nid=0x118867000 waiting for monitor entry [118866000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:81)
 - waiting to lock <7f3366ec8> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)

"Thread-15" prio=5 tid=7f9712940800 nid=0x118764000 waiting for monitor entry [118763000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:81)
 - waiting to lock <7f3366ef8> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)

"Thread-14" prio=5 tid=7f971293f800 nid=0x118661000 waiting for monitor entry [118660000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:81)
 - waiting to lock <7f3366f28> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)

"Thread-13" prio=5 tid=7f97129ae000 nid=0x11855e000 waiting for monitor entry [11855d000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:81)
 - waiting to lock <7f3366eb0> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)

"Thread-12" prio=5 tid=7f97129ad000 nid=0x11845b000 waiting for monitor entry [11845a000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:81)
 - waiting to lock <7f3366f40> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)

"Thread-11" prio=5 tid=7f97129ac800 nid=0x118358000 waiting for monitor entry [118357000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:86)
 - waiting to lock <7f3366f58> (a threads.deadlock.Account)
 - locked <7f3366eb0> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)

"Thread-10" prio=5 tid=7f97129ab800 nid=0x118255000 waiting for monitor entry [118254000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:81)
 - waiting to lock <7f3366eb0> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)

"Thread-9" prio=5 tid=7f97129ab000 nid=0x118152000 waiting for monitor entry [118151000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:86)
 - waiting to lock <7f3366e98> (a threads.deadlock.Account)
 - locked <7f3366ec8> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)

"Thread-8" prio=5 tid=7f97129aa000 nid=0x11804f000 waiting for monitor entry [11804e000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:86)
 - waiting to lock <7f3366eb0> (a threads.deadlock.Account)
 - locked <7f3366f28> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)

"Thread-7" prio=5 tid=7f97129a9800 nid=0x117f4c000 waiting for monitor entry [117f4b000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:86)
 - waiting to lock <7f3366eb0> (a threads.deadlock.Account)
 - locked <7f3366e80> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)

"Thread-6" prio=5 tid=7f97129a8800 nid=0x117e49000 waiting for monitor entry [117e48000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:81)
 - waiting to lock <7f3366e80> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)

"Thread-5" prio=5 tid=7f97128a1800 nid=0x117d46000 waiting for monitor entry [117d45000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:81)
 - waiting to lock <7f3366f28> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)

"Thread-4" prio=5 tid=7f97121af800 nid=0x117c43000 waiting for monitor entry [117c42000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:86)
 - waiting to lock <7f3366e80> (a threads.deadlock.Account)
 - locked <7f3366e98> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)

"Thread-3" prio=5 tid=7f97121ae800 nid=0x117b40000 waiting for monitor entry [117b3f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:86)
 - waiting to lock <7f3366e80> (a threads.deadlock.Account)
 - locked <7f3366ef8> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)

"Thread-2" prio=5 tid=7f971224a000 nid=0x117a3d000 waiting for monitor entry [117a3c000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:86)
 - waiting to lock <7f3366eb0> (a threads.deadlock.Account)
 - locked <7f3366f40> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)

"RMI TCP Accept-0" daemon prio=5 tid=7f97128fd800 nid=0x117837000 runnable [117836000]
   java.lang.Thread.State: RUNNABLE
 at java.net.PlainSocketImpl.socketAccept(Native Method)
 at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:408)
 - locked <7f32ee740> (a java.net.SocksSocketImpl)
 at java.net.ServerSocket.implAccept(ServerSocket.java:462)
 at java.net.ServerSocket.accept(ServerSocket.java:430)
 at sun.management.jmxremote.LocalRMIServerSocketFactory$1.accept(LocalRMIServerSocketFactory.java:34)
 at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(TCPTransport.java:369)
 at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(TCPTransport.java:341)
 at java.lang.Thread.run(Thread.java:680)

"Poller SunPKCS11-Darwin" daemon prio=1 tid=7f97128fd000 nid=0x117734000 waiting on condition [117733000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
 at java.lang.Thread.sleep(Native Method)
 at sun.security.pkcs11.SunPKCS11$TokenPoller.run(SunPKCS11.java:692)
 at java.lang.Thread.run(Thread.java:680)

"Low Memory Detector" daemon prio=5 tid=7f971209e000 nid=0x1173ec000 runnable [00000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" daemon prio=9 tid=7f971209d000 nid=0x1172e9000 waiting on condition [00000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" daemon prio=9 tid=7f971209c800 nid=0x1171e6000 waiting on condition [00000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=9 tid=7f971209b800 nid=0x1170e3000 waiting on condition [00000000]
   java.lang.Thread.State: RUNNABLE

"Surrogate Locker Thread (Concurrent GC)" daemon prio=5 tid=7f971209a800 nid=0x116fe0000 waiting on condition [00000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=8 tid=7f971209a000 nid=0x116d1c000 in Object.wait() [116d1b000]
   java.lang.Thread.State: WAITING (on object monitor)
 at java.lang.Object.wait(Native Method)
 - waiting on <7f3001300> (a java.lang.ref.ReferenceQueue$Lock)
 at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
 - locked <7f3001300> (a java.lang.ref.ReferenceQueue$Lock)
 at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
 at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=7f9712099000 nid=0x116c19000 in Object.wait() [116c18000]
   java.lang.Thread.State: WAITING (on object monitor)
 at java.lang.Object.wait(Native Method)
 - waiting on <7f30011d8> (a java.lang.ref.Reference$Lock)
 at java.lang.Object.wait(Object.java:485)
 at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
 - locked <7f30011d8> (a java.lang.ref.Reference$Lock)

"VM Thread" prio=9 tid=7f9712096800 nid=0x116b16000 runnable 

"Gang worker#0 (Parallel GC Threads)" prio=9 tid=7f9712002800 nid=0x1135c7000 runnable 

"Gang worker#1 (Parallel GC Threads)" prio=9 tid=7f9712003000 nid=0x1136ca000 runnable 

"Concurrent Mark-Sweep GC Thread" prio=9 tid=7f971204d800 nid=0x116790000 runnable 
"VM Periodic Task Thread" prio=10 tid=7f97122d4000 nid=0x11793a000 waiting on condition 

"Exception Catcher Thread" prio=10 tid=7f9712001800 nid=0x1103ef000 runnable 
JNI global references: 1037


Found one Java-level deadlock:
=============================
"Thread-21":
  waiting to lock monitor 7f97118bd560 (object 7f3366f58, a threads.deadlock.Account),
  which is held by "Thread-20"
"Thread-20":
  waiting to lock monitor 7f97118bc108 (object 7f3366e98, a threads.deadlock.Account),
  which is held by "Thread-4"
"Thread-4":
  waiting to lock monitor 7f9711834360 (object 7f3366e80, a threads.deadlock.Account),
  which is held by "Thread-7"
"Thread-7":
  waiting to lock monitor 7f97118b9708 (object 7f3366eb0, a threads.deadlock.Account),
  which is held by "Thread-11"
"Thread-11":
  waiting to lock monitor 7f97118bd560 (object 7f3366f58, a threads.deadlock.Account),
  which is held by "Thread-20"

Java stack information for the threads listed above:
===================================================
"Thread-21":
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:86)
 - waiting to lock <7f3366f58> (a threads.deadlock.Account)
 - locked <7f3366ee0> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)
"Thread-20":
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:86)
 - waiting to lock <7f3366e98> (a threads.deadlock.Account)
 - locked <7f3366f58> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)
"Thread-4":
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:86)
 - waiting to lock <7f3366e80> (a threads.deadlock.Account)
 - locked <7f3366e98> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)
"Thread-7":
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:86)
 - waiting to lock <7f3366eb0> (a threads.deadlock.Account)
 - locked <7f3366e80> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)
"Thread-11":
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:86)
 - waiting to lock <7f3366f58> (a threads.deadlock.Account)
 - locked <7f3366eb0> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)

Found 1 deadlock.

Heap
 par new generation   total 19136K, used 11590K [7f3000000, 7f44c0000, 7f44c0000)
  eden space 17024K,  68% used [7f3000000, 7f3b51ac0, 7f40a0000)
  from space 2112K,   0% used [7f40a0000, 7f40a0000, 7f42b0000)
  to   space 2112K,   0% used [7f42b0000, 7f42b0000, 7f44c0000)
 concurrent mark-sweep generation total 63872K, used 0K [7f44c0000, 7f8320000, 7fae00000)
 concurrent-mark-sweep perm gen total 21248K, used 8268K [7fae00000, 7fc2c0000, 800000000)

Scanning quickly through, you can see that this thread dump is divided into four parts. These are:
  1. A complete list of all the applcation’s threads
  2. A list of deadlocked threads
  3. A small stack trace of deadlocked threads
  4. The application’s heap summary

The Thread List


The thread list in point one above is a list of all the application’s threads and their current status. From this you can see that an application consists of a whole bunch of threads, which you can roughly divide in to two. Firstly there are the background threads. These are the ones that every application has, which get on with all the dirty jobs that we, as application programmers, don’t usually need to worry about. These have names such as: "DestroyJavaVM", Low Memory Detector, Finalizer, Exception Catcher Thread and Concurrent Mark-Sweep GC Thread. Secondly, there are the threads that you or I may create as part of our code. These usually have names that consist of the word Thread followed by a number. For example: Thread-3, Thread-6 and Thread-20.

"Thread-20" prio=5 tid=7f971216c000 nid=0x118c73000 waiting for monitor entry [118c72000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:82)
 - waiting to lock <7f3366e98> (a threads.deadlock.Account)
 - locked <7f3366f58> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:58)

Looking at the information given on Thread-20 in more detail you can see that this can be broken down into several parts. These are:

Thread-20 The thread’s name as described above.
prio=5 The thread's priority. A number from 1 to 10, where 1 is the lowest and 10 is the highest priority.
tid=7f971216c000 The thread id. A unique number that’s returned by a Thread.getId() call.
nid=0x118c73000 The native thread id. This maps to a platform dependent thread id.
waiting for monitor entry [118c72000]
java.lang.Thread.State: BLOCKED (on object monitor)
This is the status of the thread; in this case it’s BLOCKED. Also included is a stack trace outlining where the thread is blocked.

Note that a thread can also be marked as a daemon. For example:
"RMI TCP Accept-0" daemon prio=5 tid=7f97128fd800 nid=0x117837000 runnable [117836000]
   java.lang.Thread.State: RUNNABLE
Daemon threads are background task threads such as the RMI TCP Accept-0 thread listed above. A daemon thread is a thread that does not prevent the JVM from exiting. The JVM will exit, or close down, when only daemon threads remain.

However, the thread list doesn't really help in tracing the cause of a deadlock, so moving swiftly along...


The Deadlock Thread List


This section of the thread dump contains a list of all threads that are involved in the deadlock.

Found one Java-level deadlock:
=============================
"Thread-21":
  waiting to lock monitor 7f97118bd560 (object 7f3366f58, a threads.deadlock.Account),
  which is held by "Thread-20"
"Thread-20":
  waiting to lock monitor 7f97118bc108 (object 7f3366e98, a threads.deadlock.Account),
  which is held by "Thread-4"
"Thread-4":
  waiting to lock monitor 7f9711834360 (object 7f3366e80, a threads.deadlock.Account),
  which is held by "Thread-7"
"Thread-7":
  waiting to lock monitor 7f97118b9708 (object 7f3366eb0, a threads.deadlock.Account),
  which is held by "Thread-11"
"Thread-11":
  waiting to lock monitor 7f97118bd560 (object 7f3366f58, a threads.deadlock.Account),
  which is held by "Thread-20"

From the segment above, you can see that there are five threads all blocking on instances the threads.deadlock.Account class

Leaving aside the monitor ids and Account instances, you can see that "Thread-21" is waiting for "Thread-20", which is waiting for "Thread-4", which in turn is waiting for "Thread-7". "Thread-7" is waiting for "Thread-11", which is waiting for "Thread-20": a deadlock loop as shown in the diagram below:


The Deadlock Stack Traces


The final piece of the puzzle is the list of deadlocked thread stack traces as shown below:

Java stack information for the threads listed above:
===================================================
"Thread-21":
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:86)
 - waiting to lock <7f3366f58> (a threads.deadlock.Account)
 - locked <7f3366ee0> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)
"Thread-20":
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:86)
 - waiting to lock <7f3366e98> (a threads.deadlock.Account)
 - locked <7f3366f58> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)
"Thread-4":
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:86)
 - waiting to lock <7f3366e80> (a threads.deadlock.Account)
 - locked <7f3366e98> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)
"Thread-7":
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:86)
 - waiting to lock <7f3366eb0> (a threads.deadlock.Account)
 - locked <7f3366e80> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)
"Thread-11":
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:86)
 - waiting to lock <7f3366f58> (a threads.deadlock.Account)
 - locked <7f3366eb0> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)

From the previous section, we know that Thread-20 is waiting, via a circuitous route, for Thread-11 and Thread-11 is waiting for Thread-20. This is our deadlock.

The next step is to tie this deadlock up to lines of code using the thread stack trace above and I’ve simplified this in the diagram below.


In the above diagram I've removed the 7f3366 prefix from the object ids for clarity; hence, object 7f3366f58 is now f58. From this diagram, you can see that object f58 is locked by Thread-20 on line 59 and is waiting for a lock on object e98 on line 86. Following the arrows down, you can see that Thread-7 is waiting for a lock on eb0 on line 86, which in turn is locked by Thread-11 on line 59. Thread-11 is waiting for a lock on f58 on line 86, which, looping back up, is locked on line 58 by Thread-20

So, where are these lines of code? The following shows line 59:


...and this is line 86:


Everyone gets surprises sometimes and the stack trace above surprised me. I was expecting the locks to be on lines 85 and 86; however, they were on 59 and 86. Since line 59 doesn’t contain a synchronized keyword, I’m guessing that the compiler has done some optimisation on the transfer(...) method’s first synchronized keyword.

The conclusion that can be drawn from this is that the code, which randomly picks two Account objects from a list, is locking them in the wrong order on lines 59 and 86. So what’s the fix? More on that next time; however, there’s one final point to note, which is that the make up of a deadlock may not be the same every time you generate a thread dump on a program. After running the DeadlockDemo program again and using kill -3 PID to get hold of another thread dump, I obtained these results:

Found one Java-level deadlock:
=============================
"Thread-20":
  waiting to lock monitor 7fdc7c802508 (object 7f311a530, a threads.deadlock.Account),
  which is held by "Thread-3"
"Thread-3":
  waiting to lock monitor 7fdc7a83d008 (object 7f311a518, a threads.deadlock.Account),
  which is held by "Thread-11"
"Thread-11":
  waiting to lock monitor 7fdc7c802508 (object 7f311a530, a threads.deadlock.Account),
  which is held by "Thread-3"

Java stack information for the threads listed above:
===================================================
"Thread-20":
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:86)
 - waiting to lock <7f311a530> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)
"Thread-3":
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:87)
 - waiting to lock <7f311a518> (a threads.deadlock.Account)
 - locked <7f311a530> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)
"Thread-11":
 at threads.deadlock.DeadlockDemo$BadTransferOperation.transfer(DeadlockDemo.java:87)
 - waiting to lock <7f311a530> (a threads.deadlock.Account)
 - locked <7f311a518> (a threads.deadlock.Account)
 at threads.deadlock.DeadlockDemo$BadTransferOperation.run(DeadlockDemo.java:59)

Found 1 deadlock.

In this thread dump a smaller number of threads are involved in the deadlock, but if you analyze it you can draw the same conclusions as my first example.

Next time: fixing the code...


For more information see the other blogs in this series.

All source code for this an other blogs in the series are available on Github at git://github.com/roghughe/captaindebug.git



No comments: