activemq-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Manuel Teira <mte...@tid.es>
Subject Re: Locked trying to write to journal
Date Wed, 06 Jun 2007 16:02:14 GMT
James Strachan escribió:
> any chance you could upgrade to 4.1.1 which has numerous bug fixes and
> see if you can reproduce this?
I don't think so. The problem is that I was not able to reproduce the 
problem other than in the production environment. Unfortunately, 
changing the production version without knowing what is exactly 
happening is not a choice.

Is there any corrected bug for 4.1.1 that could be related with this 
problem?

Thanks a lot.


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


Mime
View raw message