[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

Re: [xmlblaster] locking bug



Hi Marcel,

nice approach!
Please report what you find out,

I got the problem! It's a deadlock between two ReentrantLocks. I just captured the following log messages:

2008-10-28 12:32:27,413 ERROR [XmlBlaster.DispatchWorkerPool.nova-226] (DebugReentrantLock.java:46) - trylock failed, locked by
        at java.lang.Object.wait(Native Method)
        at java.lang.Object.wait(Object.java:485)
        at EDU.oswego.cs.dl.util.concurrent.ReentrantLock.acquire(ReentrantLock.java:40)
        at org.xmlBlaster.util.ReentrantLock.lock(ReentrantLock.java:23)
        at org.xmlBlaster.engine.TopicHandler.forwardToDestinations(TopicHandler.java:844)
        at org.xmlBlaster.engine.TopicHandler.publish(TopicHandler.java:728)
        at org.xmlBlaster.engine.RequestBroker.publish(RequestBroker.java:1679)
        at org.xmlBlaster.engine.RequestBroker.publish(RequestBroker.java:1405)
        at org.xmlBlaster.engine.RequestBroker.publish(RequestBroker.java:1393)
        at org.xmlBlaster.engine.XmlBlasterImpl.publish(XmlBlasterImpl.java:180)
        at org.xmlBlaster.engine.XmlBlasterImpl.publishArr(XmlBlasterImpl.java:219)
        at org.xmlBlaster.engine.XmlBlasterImpl.publishOneway(XmlBlasterImpl.java:233)
        at org.xmlBlaster.util.protocol.RequestReplyExecutor.receiveReply(RequestReplyExecutor.java:441)
        at org.xmlBlaster.protocol.socket.HandleClient.handleMessage(HandleClient.java:194)
        at org.xmlBlaster.protocol.socket.HandleClient$1.run(HandleClient.java:369)
        at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:665)
        at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:690)
        at java.lang.Thread.run(Thread.java:619)
2008-10-28 12:32:27,413 ERROR [XmlBlaster.DispatchWorkerPool.nova-226] (DebugReentrantLock.java:49) - lock() called
        at org.xmlBlaster.debug.DebugReentrantLock.tryLock(DebugReentrantLock.java:40)
        at org.xmlBlaster.engine.TopicAccessor$TopicContainer.lock(TopicAccessor.java:416)
        at org.xmlBlaster.engine.TopicAccessor.findOrCreate(TopicAccessor.java:187)
        at org.xmlBlaster.engine.RequestBroker.publish(RequestBroker.java:1677)
        at org.xmlBlaster.engine.RequestBroker.publish(RequestBroker.java:1405)
        at org.xmlBlaster.engine.RequestBroker.publish(RequestBroker.java:1393)
        at org.xmlBlaster.engine.XmlBlasterImpl.publish(XmlBlasterImpl.java:180)
        at org.xmlBlaster.engine.XmlBlasterImpl.publishArr(XmlBlasterImpl.java:219)
        at org.xmlBlaster.engine.XmlBlasterImpl.publishOneway(XmlBlasterImpl.java:233)
        at org.xmlBlaster.util.protocol.RequestReplyExecutor.receiveReply(RequestReplyExecutor.java:441)
        at org.xmlBlaster.protocol.socket.HandleClient.handleMessage(HandleClient.java:194)
        at org.xmlBlaster.protocol.socket.HandleClient$1.run(HandleClient.java:369)
        at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:665)
        at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:690)
        at java.lang.Thread.run(Thread.java:619)
2008-10-28 12:32:27,414 ERROR [XmlBlaster.DispatchWorkerPool.nova-226] (DebugReentrantLock.java:51) - failed to lock()
        at org.xmlBlaster.debug.DebugReentrantLock.tryLock(DebugReentrantLock.java:51)
        at org.xmlBlaster.engine.TopicAccessor$TopicContainer.lock(TopicAccessor.java:416)
        at org.xmlBlaster.engine.TopicAccessor.access(TopicAccessor.java:93)
        at org.xmlBlaster.engine.MsgUnitWrapper.toDestroyed(MsgUnitWrapper.java:595)
        at org.xmlBlaster.engine.MsgUnitWrapper.incrementReferenceCounter(MsgUnitWrapper.java:279)
        at org.xmlBlaster.engine.queuemsg.ReferenceEntry.incrementReferenceCounter(ReferenceEntry.java:191)
        at org.xmlBlaster.engine.queuemsg.ReferenceEntry.removed(ReferenceEntry.java:230)
        at org.xmlBlaster.util.queue.ram.RamQueuePlugin.removeRandom(RamQueuePlugin.java:543)
        at org.xmlBlaster.util.dispatch.DispatchManager.removeFromQueue(DispatchManager.java:519)
        at org.xmlBlaster.util.dispatch.DispatchWorker.run(DispatchWorker.java:123)
        at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:732)
        at java.lang.Thread.run(Thread.java:619)

Explanation:
The first stacktrace is the current state of the thread which was the last to successfully acquire the lock. The second stacktrace is from the same thread as the first, but it reflects the state when the last locking was successfully acquired. The third stacktrace is the stack of the thread which timed out while trying to acquire the lock.

To conclude, the deadlock is between two instances of the following locks:
1) org.xmlBlaster.engine.SessionInfo.lock
2) org.xmlBlaster.authentication.TopicAccessor.TopicContainer.lock

I'm trying to decipher the exact cause and if it can be circumvented, but I think it's better if you looked into it since this may require more in-depth knowledge of the inner workings of the server.

Hoping to hear from you soon!

regards,
Balázs Póka