activemq-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "James Strachan" <james.strac...@gmail.com>
Subject Re: Locked trying to write to journal
Date Wed, 06 Jun 2007 09:28:29 GMT
any chance you could upgrade to 4.1.1 which has numerous bug fixes and
see if you can reproduce this?

On 6/4/07, Manuel Teira <mteira@tid.es> wrote:
> Hello. I've just detected a lock problem using activemq-core 4.0.2 that
> seems to be related with journal writing logic.
> I was able to get a stack of the running process, where we can see that
> a lot of threads (56 to be precise) are waiting to lock the journal, in
> this way:
>
> "ActiveMQ Transport: tcp:///10.228.32.104:32194" daemon prio=10
> tid=0x0228c5a8 nid=0x1b0e0 waiting for monitor entry
> [0xed97e000..0xed97faa8]
>         at
> org.apache.activeio.journal.active.JournalImpl.write(JournalImpl.java:169)
> *        - waiting to lock <0x2a9f58c0> (a
> org.apache.activeio.journal.active.JournalImpl)*
>         at
> org.apache.activeio.journal.active.JournalImpl.write(JournalImpl.java:157)
>         at
> org.apache.activemq.store.journal.JournalPersistenceAdapter.writeCommand(JournalPersistenceAdapter.java:588)
>         at
> org.apache.activemq.store.journal.JournalMessageStore.addMessage(JournalMessageStore.java:94)
>         at org.apache.activemq.broker.region.Queue.send(Queue.java:253)
>         at
> org.apache.activemq.broker.region.AbstractRegion.send(AbstractRegion.java:225)
>         at
> org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:342)
>         at
> org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:192)
>         at
> org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:113)
>         at
> org.apache.activemq.broker.CompositeDestinationBroker.send(CompositeDestinationBroker.java:97)
>         at
> org.apache.activemq.broker.MutableBrokerFilter.send(MutableBrokerFilter.java:126)
>         at
> org.apache.activemq.broker.AbstractConnection.processMessage(AbstractConnection.java:377)
>         at
> org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:590)
>         at
> org.apache.activemq.broker.AbstractConnection.service(AbstractConnection.java:226)
>         at
> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:62)
>         at
> org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:91)
>         at
> org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:63)
>         at
> org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:122)
>         at
> org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:122)
>         at
> org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:87)
>         at
> org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:127)
>         at java.lang.Thread.run(Unknown Source)
>
>
> Furthermore, some threads have got the lock (4 threads) , but are
> waiting for a java.util.concurrent.CountDownLatch to became zero:
>
> "ActiveMQ Task" daemon prio=10 tid=0x0205e598 nid=0x1b0cb in
> Object.wait() [0xed77f000..0xed77fb28]
>         at java.lang.Object.wait(Native Method)
>         at java.lang.Object.wait(Unknown Source)
> *        at
> edu.emory.mathcs.backport.java.util.concurrent.CountDownLatch.await(CountDownLatch.java:179)*
> *        - locked <0x384ddf68> (a
> edu.emory.mathcs.backport.java.util.concurrent.CountDownLatch)*
>         at
> org.apache.activeio.journal.active.BatchedWrite.waitForForce(BatchedWrite.java:95)
>         at
> org.apache.activeio.journal.active.JournalImpl.write(JournalImpl.java:187)
>         at
> org.apache.activeio.journal.active.JournalImpl.setMark(JournalImpl.java:344)
>         - locked <0x2a9f58c0> (a
> org.apache.activeio.journal.active.JournalImpl)
>         at
> org.apache.activemq.store.journal.JournalPersistenceAdapter.doCheckpoint(JournalPersistenceAdapter.java:395)
>         at
> org.apache.activemq.store.journal.JournalPersistenceAdapter$2.iterate(JournalPersistenceAdapter.java:122)
>         at
> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:110)
>         at
> org.apache.activemq.thread.PooledTaskRunner.access$100(PooledTaskRunner.java:25)
>         at
> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
>         at
> edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
>         at
> edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
>         at java.lang.Thread.run(Unknown Source)
>
> and also some transport threads, in a similar situation:
>
> "ActiveMQ Transport: tcp:///10.228.32.110:50356" daemon prio=10
> tid=0x02098b90 nid=0x1b0ca in Object.wait() [0xf157e000..0xf157fba8]
>         at java.lang.Object.wait(Native Method)
>         at java.lang.Object.wait(Unknown Source)
> *        at
> edu.emory.mathcs.backport.java.util.concurrent.CountDownLatch.await(CountDownLatch.java:179)
>         - locked <0x384ddf68> (a
> edu.emory.mathcs.backport.java.util.concurrent.CountDownLatch)*
>         at
> org.apache.activeio.journal.active.BatchedWrite.waitForForce(BatchedWrite.java:95)
>         at
> org.apache.activeio.journal.active.JournalImpl.write(JournalImpl.java:187)
>         at
> org.apache.activeio.journal.active.JournalImpl.write(JournalImpl.java:157)
>         at
> org.apache.activemq.store.journal.JournalPersistenceAdapter.writeCommand(JournalPersistenceAdapter.java:588)
>         at
> org.apache.activemq.store.journal.JournalMessageStore.addMessage(JournalMessageStore.java:94)
>         at org.apache.activemq.broker.region.Queue.send(Queue.java:253)
>         at
> org.apache.activemq.broker.region.AbstractRegion.send(AbstractRegion.java:225)
>         at
> org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:342)
>         at
> org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:192)
>         at
> org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:113)
>         at
> org.apache.activemq.broker.CompositeDestinationBroker.send(CompositeDestinationBroker.java:97)
>         at
> org.apache.activemq.broker.MutableBrokerFilter.send(MutableBrokerFilter.java:126)
>         at
> org.apache.activemq.broker.AbstractConnection.processMessage(AbstractConnection.java:377)
>         at
> org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:590)
>         at
> org.apache.activemq.broker.AbstractConnection.service(AbstractConnection.java:226)
>         at
> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:62)
>         at
> org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:91)
>         at
> org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:63)
>         at
> org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:122)
>         at
> org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:122)
>         at
> org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:87)
>         at
> org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:127)
>         at java.lang.Thread.run(Unknown Source)
>
>
> After a fast review of the code, it seems that someone should call :
>
> org.apache.activeio.journal.active.BatchedWrite.forced()
>
> or
>
> org.apache.activeio.journal.active.BatchedWrite.writeFailed()
>
> I guess that after the actual write to the journal is performed.
>
>
> As additional information, in the environment where we have the activeMQ
> running, there's a known  problem where servlets acting as JMS clients
> are not closing explicitly its connection, causing exceptions ( I
> suppose that is the reason) like:
>
> Error writing log '[WARNING][2007/06/04.09:28:26.785][ActiveMQ
> Scheduler]Async exception with no exception listener:
> org.apache.activemq.transport.InactivityIOException: Channel was
> inactive for too long.(Channel was inactive for too long.)
> '
> java.io.InterruptedIOException
>         at java.io.FileOutputStream.writeBytes(Native Method)
>         at java.io.FileOutputStream.write(Unknown Source)
>         at sun.nio.cs.StreamEncoder$CharsetSE.writeBytes(Unknown Source)
>         at sun.nio.cs.StreamEncoder$CharsetSE.implFlushBuffer(Unknown
> Source)
>         at sun.nio.cs.StreamEncoder$CharsetSE.implFlush(Unknown Source)
>         at sun.nio.cs.StreamEncoder.flush(Unknown Source)
>         at java.io.OutputStreamWriter.flush(Unknown Source)
>         at java.io.BufferedWriter.flush(Unknown Source)
>         at
> es.tid.planb.core.FileLogWriter$RealFile.put(FileLogWriter.java:140)
>         at es.tid.planb.core.FileLogWriter.put(FileLogWriter.java:241)
>         at es.tid.planb.core.RotFileLogWriter.put(RotFileLogWriter.java:99)
>         at es.tid.planb.core.Logger.write(Logger.java:240)
>         at es.tid.planb.core.Logger.rWarning(Logger.java:291)
>         at es.tid.planb.core.Logger.warning(Logger.java:193)
>         at es.tid.planb.core.PBLogger.warn(PBLogger.java:260)
>         at
> org.apache.activemq.ActiveMQConnection.onAsyncException(ActiveMQConnection.java:1453)
>         at
> org.apache.activemq.ActiveMQConnection.onException(ActiveMQConnection.java:1459)
>         at
> org.apache.activemq.transport.TransportFilter.onException(TransportFilter.java:94)
>         at
> org.apache.activemq.transport.ResponseCorrelator.onException(ResponseCorrelator.java:110)
>         at
> org.apache.activemq.transport.TransportFilter.onException(TransportFilter.java:94)
>         at
> org.apache.activemq.transport.TransportFilter.onException(TransportFilter.java:94)
>         at
> org.apache.activemq.transport.WireFormatNegotiator.onException(WireFormatNegotiator.java:128)
>         at
> org.apache.activemq.transport.InactivityMonitor.onException(InactivityMonitor.java:149)
>         at
> org.apache.activemq.transport.InactivityMonitor.readCheck(InactivityMonitor.java:101)
>         at
> org.apache.activemq.transport.InactivityMonitor.access$000(InactivityMonitor.java:35)
>         at
> org.apache.activemq.transport.InactivityMonitor$1.run(InactivityMonitor.java:51)
>         at
> edu.emory.mathcs.backport.java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:431)
>         at
> edu.emory.mathcs.backport.java.util.concurrent.FutureTask.runAndReset(FutureTask.java:198)
>         at
> edu.emory.mathcs.backport.java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:189)
>         at
> edu.emory.mathcs.backport.java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:213)
>         at
> edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
>         at
> edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
>         at java.lang.Thread.run(Unknown Source)
>
>
> The journal persistence configuration we're using is:
>
>     <persistenceAdapter>
>       <journaledJDBC journalLogFiles="5"
> dataDirectory="/opt/project/run/activemq-data" dataSource="#jdbc-ds">
>       </journaledJDBC>
>     </persistenceAdapter>
>
> Any advice or clue about what could be happening? Is there any situation
> in what calling BatchedWrite.forced() or BatchedWrite.writeFailed()
> could be skipped? Perhaps the inactivity related exceptions I'm
> suffering could be related with this?
>
> My apologizes for the long stack dumps, and thanks a lot for this great
> project. We are suffering the problem in the production environment, so,
> I should be very grateful if you could provide any idea about it.
> If more information is needed, don't hesitate to ask me for it.
>
>
> Regards.
>
>


-- 
James
-------
http://macstrac.blogspot.com/

Mime
View raw message