What does "Lock released while waiting:" mean in a Java thread dump?

Question

In this thread dump:

INFO   | jvm 3    | 2011/06/08 13:36:12 | "ExecuteThread: '38' for queue: 'default'" id=55 idx=0x78 tid=5316 prio=5 alive, in native, waiting, daemon
INFO   | jvm 3    | 2011/06/08 13:36:12 |     -- Waiting for notification on: weblogic/ejb20/locks/ExclusiveLockManager$LockWaiter@0x25EF8828[fat lock]
INFO   | jvm 3    | 2011/06/08 13:36:12 |     at jrockit/vm/Threads.waitForSignal(J)Z(Native Method)
INFO   | jvm 3    | 2011/06/08 13:36:12 |     at java/lang/Object.wait(J)V(Native Method)[optimized]
INFO   | jvm 3    | 2011/06/08 13:36:12 |     at weblogic/ejb20/locks/ExclusiveLockManager$LockBucket.lock(Ljava/lang/Object;Ljava/lang/Object;I)Z(ExclusiveLockManager.java:504)[optimized]
INFO   | jvm 3    | 2011/06/08 13:36:12 |     ^-- Lock released while waiting: weblogic/ejb20/locks/ExclusiveLockManager$LockWaiter@0x25EF8828[fat lock]
INFO   | jvm 3    | 2011/06/08 13:36:12 |     at weblogic/ejb20/locks/ExclusiveLockManager.lock(Ljava/lang/Object;Ljava/lang/Object;I)Z(ExclusiveLockManager.java:261)[optimized]
INFO   | jvm 3    | 2011/06/08 13:36:12 |     at weblogic/ejb20/manager/ExclusiveEntityManager.acquireLock(Ljava/lang/Object;Ljavax/transaction/Transaction;I)Z(ExclusiveEntityManager.java:210)[inlined]
INFO   | jvm 3    | 2011/06/08 13:36:12 |     at weblogic/ejb20/manager/ExclusiveEntityManager.getReadyBean(Ljava/lang/Object;Ljavax/transaction/Transaction;I)Ljavax/ejb/EntityBean;(ExclusiveEntityManager.java:267)[inlined]
INFO   | jvm 3    | 2011/06/08 13:36:12 |     at weblogic/ejb20/manager/ExclusiveEntityManager.preInvoke(Lweblogic/ejb20/internal/InvocationWrapper;)Ljavax/ejb/EnterpriseBean;(ExclusiveEntityManager.java:242)[optimized]
INFO   | jvm 3    | 2011/06/08 13:36:12 |     at weblogic/ejb20/internal/BaseEJBObject.preInvoke(Lweblogic/ejb20/internal/InvocationWrapper;Lweblogic/security/service/ContextHandler;)Lweblogic/ejb20/internal/InvocationWrapper;(BaseEJBObject.java:152)[inlined]
INFO   | jvm 3    | 2011/06/08 13:36:12 |     at weblogic/ejb20/internal/EntityEJBObject.preInvoke(Lweblogic/ejb20/internal/MethodDescriptor;Lweblogic/security/service/ContextHandler;)Lweblogic/ejb20/internal/InvocationWrapper;(EntityEJBObject.java:104)[inlined]
INFO   | jvm 3    | 2011/06/08 13:36:12 |     at foob/ejb/commodity/ejb_Commodity_etfd4i_EOImpl.getData()Lfoob/ejb/commodity/db/CommodityData;(ejb_Commodity_etfd4i_EOImpl.java:701)[optimized]
INFO   | jvm 3    | 2011/06/08 13:36:12 |     at foob/ejb/item/OurItem.loadCommodityData()V(OurItem.java:172)[optimized]
INFO   | jvm 3    | 2011/06/08 13:36:12 |     ^-- Holding lock: java/lang/Class@0x067EA070[fat lock]
INFO   | jvm 3    | 2011/06/08 13:36:12 |     at foob/ejb/item/OurItem.getCommodityData()Lfoob/ejb/commodity/db/CommodityData;(OurItem.java:251)
INFO   | jvm 3    | 2011/06/08 13:36:12 |     at foob/ejb/item/OurItem.getTheControlGid()Ljava/lang/String;(OurItem.java:259)
INFO   | jvm 3    | 2011/06/08 13:36:12 |     at foob/business/shipment/OurThing.getTheControlGid(Lfoob/util/jdbc/OurConnection;)Ljava/lang/String;(OurThing.java:379)

What does the line

Lock released while waiting: weblogic/ejb20/locks/ExclusiveLockManager$LockWaiter@0x25EF8828

mean? We had 8 other threads blocked waiting for java/lang/Class@0x067EA070 to be released, which this thread is holding, but I don't understand what this thread was blocking on, nor what it means that that the lock was released. I would have thought that a thread dump is a stop-the-world type of event, and therefor the line in question wouldn't refer to the lock being released while the thread dump was happening...

Also, does where it appear have any significance (i.e. the line above it and below it)?

Obviously I'm not a Java expect, so I hope this isn't too stupid of a question. Thanks for the help!

"A thread dump is a stop-the-world type of event". No, it isn't. It is merely a dump of the stack frames of all the threads executing at a point in the JVM. It may be generated at the point of a stop-the-world type of event like a JVM crash. **Edit**: You can get a thread dump by sending SIGBREAK to a JVM process. — Vineet Reynolds, Jun 15 '11 at 14:14
Vineet - by "stop-the-world" I meant that all execution in the JVM pauses, the thread dump is taken, then all execution resumes. Some GCs behave this way. — Joe Casadonte, Jun 15 '11 at 14:22
Ok, you're right in that sense. I interpreted it in a different way. — Vineet Reynolds, Jun 15 '11 at 14:28

Vineet Reynolds · Accepted Answer · 2011-06-15T14:52:08.537

From the Oracle JRockit JDK Tools Guide,

The semantics for waiting (for notification) for an object in Java is somewhat complex. First, to enter a synchronized block, you must take the lock for the object, and then you call wait() on that object. In the wait method, the lock is released before the thread goes to sleep waiting for a notification. When the thread receives a notification, wait() re-takes the lock before returning. If a thread has taken a lock, and is waiting for notification about that lock, the line in the stack trace that describes when the lock was taken is not shown as (Holding lock); it is shown as (Lock released while waiting.)

In other words, it means that the said thread has an object that acquired a lock earlier, and then at a later point released it, when it invoked object.wait(). The pattern of code similar to the behavior is:

synchronized(lock) //acquires the lock
{
   ...
   do some work
   ...
   object.wait(); //releases the lock, and waits for a notification
}

Update

On looking at the stack trace, it appears that you are using Entity EJB Beans, and given the manner in which such implementations operate, locks are usually acquired on the entity EJBs. This would actually depend on the concurrency strategy used for managing concurrent transactions that have to access the database. I would suspect that the number of beans is either too low, or there is only one bean to lock on.

That's a much better page than the one I found: http://download.oracle.com/docs/cd/E13188_01/jrockit/docs50/userguide/apstkdmp.html -- thanks! — Joe Casadonte, Jun 15 '11 at 14:46
@Joe, take a look at my update. It is more specific to your stack trace. — Vineet Reynolds, Jun 15 '11 at 14:52

score 1 · Answer 2 · answered Jun 15 '11 at 14:22

Search for "Lock released" on this page and that provides a fairly good explanation of what is happening within the logic of waiting on the object.

http://download.oracle.com/docs/cd/E13188_01/jrockit/docs142/userguide/apstkdmp.html

It appears that this message represents when the original wait() call that gets notify()ed recaptures the object's lock.

For future reference, I found this by just doing a google search on "Lock released while waiting" and this was the first page that showed up...hopefully you already did a search on the net and just weren't satisfied with what you found, in which case I'm sorry if this doesn't help.

Yeah, I googled around for about half an hour before I posted, but I didn't find this. Usually I have mad googling skills, but they must have deserted me today -- thanks! — Joe Casadonte, Jun 15 '11 at 14:41

score 0 · Answer 3 · answered Jun 15 '11 at 14:22

0

It most likely relates to the entry two lines above:

at java/lang/Object.wait(J)V(Native Method)[optimized]

wait() will release the currently held lock (the lock held by the surrounding synchronized block) and wait for a notify() signal.

answered Jun 15 '11 at 14:22

pap

27,064
6
41
46

What does "Lock released while waiting:" mean in a Java thread dump?

3 Answers3