javaejb-2.xweblogic8.x

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


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!


Solution

  • 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.