Steps To Quickly Catch Lock Contention

A trick often used by the authors to get a quick sense of where lock contention is occurring in a Java application is to capture several thread dumps using the JDK’s jstack command. This approach works well when operating in more of a monitoring role where the objective is to quickly capture some data rather than spending time to set up and configure a profiler where a more detailed analysis can be done.

The following jstack output is from an application that has a set of reader threads and writer threads that share a single queue. Work is placed on the queue by writer threads, and reader threads pull work from the queue.

Only the relevant stack traces are included to illustrate the usefulness of using jstack to rapidly find contended locks. In the jstack output the thread, Read Thread-33, has successfully acquired the shared queue lock, which is identified as a Queue object at address 0x22e88b10. This is highlighted in the output in bold as locked <0x22e88b10> (a Queue).

All the other thread stack traces shown are waiting to lock the same lock held by the thread, Read Thread-33. This is highlighted in the other stack traces in bold as waiting to lock <0x22e88b10> (a Queue).

”Read Thread-33” prio=6 tid=0x02b1d400 nid=0x5c0 runnable
[0x0424f000..0x0424fd94]
java.lang.Thread.State: RUNNABLE
at Queue.dequeue(Queue.java:69)
- locked <0x22e88b10> (a Queue)
at ReadThread.getWorkItemFromQueue(ReadThread.java:32)
at ReadThread.run(ReadThread.java:23)
”Writer Thread-29” prio=6 tid=0x02b13c00 nid=0x3cc waiting for monitor
entry [0x03f7f000..0x03f7fd94]
java.lang.Thread.State: BLOCKED (on object monitor)
at Queue.enqueue(Queue.java:31)
- waiting to lock <0x22e88b10> (a Queue)
at WriteThread.putWorkItemOnQueue(WriteThread.java:54)
at WriteThread.run(WriteThread.java:47)
”Writer Thread-26” prio=6 tid=0x02b0d400 nid=0x194 waiting for monitor
entry [0x03d9f000..0x03d9fc94]
java.lang.Thread.State: BLOCKED (on object monitor)
at Queue.enqueue(Queue.java:31)
- waiting to lock <0x22e88b10> (a Queue)
at WriteThread.putWorkItemOnQueue(WriteThread.java:54)
at WriteThread.run(WriteThread.java:47)
”Read Thread-23” prio=6 tid=0x02b08000 nid=0xbf0 waiting for monitor entry
[0x03c0f000..0x03c0fb14]
java.lang.Thread.State: BLOCKED (on object monitor)
at Queue.dequeue(Queue.java:55)
- waiting to lock <0x22e88b10> (a Queue)
at ReadThread.getWorkItemFromQueue(ReadThread.java:32)
at ReadThread.run(ReadThread.java:23)
”Writer Thread-24” prio=6 tid=0x02b09000 nid=0xef8 waiting for monitor
entry [0x03c5f000..0x03c5fa94]
java.lang.Thread.State: BLOCKED (on object monitor)
at Queue.enqueue(Queue.java:31)
- waiting to lock <0x22e88b10> (a Queue)
at WriteThread.putWorkItemOnQueue(WriteThread.java:54)
at WriteThread.run(WriteThread.java:47)
”Writer Thread-20” prio=6 tid=0x02b00400 nid=0x19c waiting for monitor
entry [0x039df000..0x039dfa14]
java.lang.Thread.State: BLOCKED (on object monitor)
at Queue.enqueue(Queue.java:31)
- waiting to lock <0x22e88b10> (a Queue)
at WriteThread.putWorkItemOnQueue(WriteThread.java:54)
at WriteThread.run(WriteThread.java:47)
”Read Thread-13” prio=6 tid=0x02af2400 nid=0x9ac waiting for monitor entry
[0x035cf000..0x035cfd14]
java.lang.Thread.State: BLOCKED (on object monitor) at Queue.dequeue(Queue.java:55)

- waiting to lock <0x22e88b10> (a Queue)
at ReadThread.getWorkItemFromQueue(ReadThread.java:32)
at ReadThread.run(ReadThread.java:23)
”Read Thread-96” prio=6 tid=0x047c4400 nid=0xaa4 waiting for monitor
entry [0x06baf000..0x06bafa94]
java.lang.Thread.State: BLOCKED (on object monitor)
at Queue.dequeue(Queue.java:55)
- waiting to lock <0x22e88b10> (a Queue)
at ReadThread.getWorkItemFromQueue(ReadThread.java:32)
at ReadThread.run(ReadThread.java:23)

It is important to note the lock addresses, the hex number surrounded by < and >, are the same address. This is how locks are uniquely identified in jstack output. If lock addresses in the stack traces are different, they represent different locks. In other words, thread stack traces that have different lock addresses are threads that are not contending on the same lock.

The key to finding contended locks in jstack output is searching for the same lock address across multiple stack traces and finding threads that are waiting to acquire the same lock address. Observing multiple thread stack traces trying to lock the same lock address is an indication the application is experiencing lock contention. If capturing multiple jstack outputs yields similar results of observing lock contention on the same lock, it is stronger evidence of a highly contended lock in the application.

Also notice that the stack trace provides the source code location of the contended lock. Being able to find the location in the source code of a highly contended lock in a Java application has historically been a difficult task. Using jstack in the manner described here can help significantly in tracking down contended locks in applications.

In case of any ©Copyright or missing credits issue please check CopyRights page for faster resolutions.