3
votes

I have a problem with ActiveMQ Artemis version 2.10.0 which is running on a docker. That's exactly a threading problem (logs below). At some point in the logs, I see this entry:

Component org.apache.activemq.artemis.core.io.buffer.TimedBuffer is expired on path 0

After that there is a entry which announced broker process will be killed:

AMQ224079: The process for the virtual machine will be killed, as component org.apache.activemq.artemis.core.io.buffer.TimedBuffer@51b01960 is not responsive

Later, there are a series of entries with thread process id, since id=2, to thread id 200 (i.e. to the value which is set variable thread-pool-max-size =200 scheduled-thread-pool-max-size= 20 as described in the docs).

On the Artemis website I found that the broker can be turned off if it is in an unstable state.

Why that happen?

Logs:

 WARN  [org.apache.activemq.artemis.utils.critical.CriticalMeasure] Component org.apache.activemq.artemis.core.io.buffer.TimedBuffer is expired on path 0
 ERROR [org.apache.activemq.artemis.core.server] AMQ224079: The process for the virtual machine will be killed, as component org.apache.activemq.artemis.core.io.buffer.TimedBuffer@51b01960 is not responsive
 WARN  [org.apache.activemq.artemis.core.server] AMQ222199: Thread dump: *******************************************************************************
Complete Thread dump
"Reference Handler" Id=2 RUNNABLE
        at [email protected]/java.lang.ref.Reference.waitForReferencePendingList(Native Method)
        at [email protected]/java.lang.ref.Reference.processPendingReferences(Reference.java:241)
        at [email protected]/java.lang.ref.Reference$ReferenceHandler.run(Reference.java:213)


"Finalizer" Id=3 WAITING on java.lang.ref.ReferenceQueue$Lock@1d3b0b50
        at [email protected]/java.lang.Object.wait(Native Method)
        -  waiting on java.lang.ref.ReferenceQueue$Lock@1d3b0b50
        at [email protected]/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:155)
        at [email protected]/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:176)
        at [email protected]/java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:170)


"Signal Dispatcher" Id=4 RUNNABLE


"Common-Cleaner" Id=18 TIMED_WAITING on java.lang.ref.ReferenceQueue$Lock@a9de548
        at [email protected]/java.lang.Object.wait(Native Method)
        -  waiting on java.lang.ref.ReferenceQueue$Lock@a9de548
        at [email protected]/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:155)
        at [email protected]/jdk.internal.ref.CleanerImpl.run(CleanerImpl.java:148)
        at [email protected]/java.lang.Thread.run(Thread.java:834)
        at [email protected]/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:134)


"oneagentsubpathsender 1.189.238.20200508-120527" Id=20 RUNNABLE (in native)


"oneagentperiodiceventsmanaged" Id=21 RUNNABLE (in native)


"oneagentautosensor" Id=22 RUNNABLE


"oneagentperiodicurls" Id=23 RUNNABLE (in native)


"oneagentperiodicrequests" Id=24 RUNNABLE (in native)


"ActiveMQ Artemis Server Shutdown Timer" Id=27 TIMED_WAITING on java.util.TaskQueue@3cc6ec06
        at [email protected]/java.lang.Object.wait(Native Method)
        -  waiting on java.util.TaskQueue@3cc6ec06
        at [email protected]/java.util.TimerThread.mainLoop(Timer.java:553)
        at [email protected]/java.util.TimerThread.run(Timer.java:506)

"Thread-0 (-scheduled-threads)" Id=29 RUNNABLE
        at [email protected]/sun.management.ThreadImpl.dumpThreads0(Native Method)
        at [email protected]/sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:502)
        at [email protected]/sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:490)
        at org.apache.activemq.artemis.utils.ThreadDumpUtil.threadDump(ThreadDumpUtil.java:47)
        at org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl.threadDump(ActiveMQServerImpl.java:1022)
        at org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl.lambda$initializeCriticalAnalyzer$0(ActiveMQServerImpl.java:678)
        at org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$$Lambda$127/0x00000001002df840.run(Unknown Source)
        at org.apache.activemq.artemis.utils.critical.CriticalAnalyzerImpl.fireAction(CriticalAnalyzerImpl.java:155)
        at org.apache.activemq.artemis.utils.critical.CriticalAnalyzerImpl.check(CriticalAnalyzerImpl.java:140)
        at org.apache.activemq.artemis.utils.critical.CriticalAnalyzerImpl$1.run(CriticalAnalyzerImpl.java:53)
        at org.apache.activemq.artemis.core.server.ActiveMQScheduledComponent$2.run(ActiveMQScheduledComponent.java:284)
        at org.apache.activemq.artemis.core.server.ActiveMQScheduledComponent$3.run(ActiveMQScheduledComponent.java:294)
        at [email protected]/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at [email protected]/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
        at [email protected]/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
        at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at org.apache.activemq.artemis.utils.ActiveMQThreadFactory$1.run(ActiveMQThreadFactory.java:118)

        Number of locked synchronizers = 1
        - java.util.concurrent.ThreadPoolExecutor$Worker@1b58ff9e


"Thread-0 (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$6@466cf502)" Id=35 TIMED_WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@350d7400
        at [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
        -  waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@350d7400
        at [email protected]/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
        at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123)
        at [email protected]/java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:458)
        at org.apache.activemq.artemis.utils.ActiveMQThreadPoolExecutor$ThreadPoolQueue.poll(ActiveMQThreadPoolExecutor.java:112)
        at org.apache.activemq.artemis.utils.ActiveMQThreadPoolExecutor$ThreadPoolQueue.poll(ActiveMQThreadPoolExecutor.java:45)
        at [email protected]/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053)
        at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
        at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at org.apache.activemq.artemis.utils.ActiveMQThreadFactory$1.run(ActiveMQThreadFactory.java:118)



"Thread-0 (activemq-netty-threads)" Id=112 WAITING on java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync@50ab59d6
        at [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
        -  waiting on java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync@50ab59d6
        at [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
        at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:885)
        at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:917)
        at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1240)
        at [email protected]/java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:959)
        at org.apache.activemq.artemis.core.paging.impl.PagingStoreImpl.page(PagingStoreImpl.java:835)
        at org.apache.activemq.artemis.core.persistence.impl.journal.AbstractJournalStorageManager.addToPage(AbstractJournalStorageManager.java:2074)
        at org.apache.activemq.artemis.core.postoffice.impl.PostOfficeImpl.processRoute(PostOfficeImpl.java:1308)
        at org.apache.activemq.artemis.core.postoffice.impl.PostOfficeImpl.route(PostOfficeImpl.java:1003)
        at org.apache.activemq.artemis.core.postoffice.impl.PostOfficeImpl.route(PostOfficeImpl.java:894)
        at org.apache.activemq.artemis.core.server.impl.ServerSessionImpl.doSend(ServerSessionImpl.java:2073)
        -  locked org.apache.activemq.artemis.core.server.impl.ServerSessionImpl@7805129
        at org.apache.activemq.artemis.core.server.impl.ServerSessionImpl.send(ServerSessionImpl.java:1712)
        -  locked org.apache.activemq.artemis.core.server.impl.ServerSessionImpl@7805129
        at org.apache.activemq.artemis.core.server.impl.ServerSessionImpl.send(ServerSessionImpl.java:1651)
        -  locked org.apache.activemq.artemis.core.server.impl.ServerSessionImpl@7805129
        at org.apache.activemq.artemis.core.server.impl.ServerSessionImpl.send(ServerSessionImpl.java:1643)
        at org.apache.activemq.artemis.core.protocol.openwire.amq.AMQSession.lambda$sendShouldBlockProducer$0(AMQSession.java:453)
        at org.apache.activemq.artemis.core.protocol.openwire.amq.AMQSession$$Lambda$274/0x0000000100597840.run(Unknown Source)
        at org.apache.activemq.artemis.core.paging.impl.PagingStoreImpl.checkMemory(PagingStoreImpl.java:728)
        at org.apache.activemq.artemis.core.protocol.openwire.amq.AMQSession.sendShouldBlockProducer(AMQSession.java:504)
        at org.apache.activemq.artemis.core.protocol.openwire.amq.AMQSession.send(AMQSession.java:415)
        at org.apache.activemq.artemis.core.protocol.openwire.OpenWireConnection$CommandProcessor.processMessage(OpenWireConnection.java:1570)
        at org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:768)
        at org.apache.activemq.artemis.core.protocol.openwire.OpenWireConnection.bufferReceived(OpenWireConnection.java:293)
        at org.apache.activemq.artemis.core.remoting.server.impl.RemotingServiceImpl$DelegatingBufferHandler.bufferReceived(RemotingServiceImpl.java:654)
        at org.apache.activemq.artemis.core.remoting.impl.netty.ActiveMQChannelHandler.channelRead(ActiveMQChannelHandler.java:73)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:337)
        at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:323)
        at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:297)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:337)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1408)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345)
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:930)
        at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:796)
        at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:427)
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:328)
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905)
        at org.apache.activemq.artemis.utils.ActiveMQThreadFactory$1.run(ActiveMQThreadFactory.java:118)


"Thread-29 (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$6@466cf502)" Id=200 TIMED_WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@350d7400
        at [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
        -  waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@350d7400
        at [email protected]/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
        at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123)
        at [email protected]/java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:458)
        at org.apache.activemq.artemis.utils.ActiveMQThreadPoolExecutor$ThreadPoolQueue.poll(ActiveMQThreadPoolExecutor.java:112)
        at org.apache.activemq.artemis.utils.ActiveMQThreadPoolExecutor$ThreadPoolQueue.poll(ActiveMQThreadPoolExecutor.java:45)
        at [email protected]/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053)
        at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
        at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at org.apache.activemq.artemis.utils.ActiveMQThreadFactory$1.run(ActiveMQThreadFactory.java:118)


"Scheduler-143999341" Id=202 WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@2a25f629
        at [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
        -  waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@2a25f629
        at [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
        at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081)
        at [email protected]/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1170)
        at [email protected]/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)
        at [email protected]/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1054)
        at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
        at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at [email protected]/java.lang.Thread.run(Thread.java:834)


"Thread-1 (activemq-netty-threads)" Id=2344 RUNNABLE (in native)
        at io.netty.channel.epoll.Native.epollWait0(Native Method)
        at io.netty.channel.epoll.Native.epollWait(Native.java:114)
        at io.netty.channel.epoll.EpollEventLoop.epollWait(EpollEventLoop.java:251)
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:276)
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905)
        at org.apache.activemq.artemis.utils.ActiveMQThreadFactory$1.run(ActiveMQThreadFactory.java:118)

1
Why that happen ?avalus

1 Answers

5
votes

This issue, as far as I can tell doesn't really have anything to do with threading. The issue is, as the error message indicates, that the "TimedBuffer is expired on path 0" or in other words "TimedBuffer@51b01960 is not responsive." The "TimedBuffer" is the component which is responsible for flushing data to disk, and it's taking too long to flush data so the broker's "critical analyzer" shuts the broker down and emits a thread dump for debugging purposes.

The "critical analyzer" is a service within the broker which monitors important tasks and if those tasks take too long to complete then the critical analyzer will take action. The default broker.xml contains this configuration for the critical analyzer:

<critical-analyzer>true</critical-analyzer>
<critical-analyzer-timeout>120000</critical-analyzer-timeout>
<critical-analyzer-check-period>60000</critical-analyzer-check-period>
<critical-analyzer-policy>HALT</critical-analyzer-policy>

Therefore, every 60 seconds the critical analyzer will check various components and if any of them have stalled for 120 seconds (i.e. 2 minutes) then it will stop the broker. You will need to restart the broker manually or, depending on your platform, if the broker is acting as a "service" then it could be automatically restarted. You can read more about the critical analyzer in the documentation.