[
https://issues.apache.org/jira/browse/AMQ-4835?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13816071#comment-13816071
]
Timothy Bish commented on AMQ-4835:
-----------------------------------
Have you tested on the latest release v5.9.0 ?
> JournalPersistenceAdapter: Persistence Adaptor Task iterates "forever"
> ----------------------------------------------------------------------
>
> Key: AMQ-4835
> URL: https://issues.apache.org/jira/browse/AMQ-4835
> Project: ActiveMQ
> Issue Type: Bug
> Components: Message Store
> Affects Versions: 5.7.0
> Environment: JDK 1.6.0_45
> Reporter: Jiri Patera
>
> This erroneous behavior happens after a simple asynchronous message
> send/receive test has passed and is about to exit. It happens only in case
> the Journal usage is enabled.
> The test shutdown process than takes about 5-10 minutes to complete. The test
> result is then "passed", so no exception occurs during it.
> The thread waits here:
> {code}
> org.apache.activemq.thread.PooledTaskRunner.shutdown(long):101
> {code}
> And will be notified when all the 1000 for-cycle iterations pass here:
> {code}
> org.apache.activemq.thread.PooledTaskRunner.runTask():128
> {code}
> And a log:
> {code}
> 13.10.15 12:04:36:951 DEBUG [main] [PooledConnectionFactory ] Stopping
> the PooledConnectionFactory, number of connections in cache: 0
> 13.10.15 12:04:36:952 DEBUG [ActiveMQ VMTransport:
> vm://JmsEngineActivemqBroker#1-1] [ManagementContext ]
> Unregistering MBean
> org.apache.activemq:BrokerName=JmsEngineActivemqBroker,Type=Producer,destinationType=Dynamic,clientId=ID_localhost-51012-1381831459465-2_1,producerId=ID_localhost-51012-1381831459465-3_1_1_1
> 13.10.15 12:04:36:955 DEBUG [ActiveMQ VMTransport:
> vm://JmsEngineActivemqBroker#1-1] [ManagementContext ]
> Unregistering MBean
> org.apache.activemq:BrokerName=JmsEngineActivemqBroker,Type=Producer,destinationType=Dynamic,clientId=ID_localhost-51012-1381831459465-2_1,producerId=ID_localhost-51012-1381831459465-3_1_3_1
> 13.10.15 12:04:36:955 DEBUG [ActiveMQ VMTransport:
> vm://JmsEngineActivemqBroker#1-1] [ManagementContext ]
> Unregistering MBean
> org.apache.activemq:BrokerName=JmsEngineActivemqBroker,Type=Subscription,persistentMode=Non-Durable,destinationType=Topic,destinationName=ActiveMQ.Advisory.TempQueue_ActiveMQ.Advisory.TempTopic,clientId=ID_localhost-51012-1381831459465-2_1,consumerId=ID_localhost-51012-1381831459465-3_1_-1_1
> 13.10.15 12:04:36:955 DEBUG [ActiveMQ VMTransport:
> vm://JmsEngineActivemqBroker#1-1] [AbstractRegion ]
> JmsEngineActivemqBroker removing consumer:
> ID:localhost-51012-1381831459465-3:1:-1:1 for destination:
> ActiveMQ.Advisory.TempQueue,ActiveMQ.Advisory.TempTopic
> 13.10.15 12:04:36:956 DEBUG [ActiveMQ VMTransport:
> vm://JmsEngineActivemqBroker#1-1] [TransportConnection ] remove
> connection id: ID:localhost-51012-1381831459465-3:1
> 13.10.15 12:04:36:963 DEBUG [ActiveMQ BrokerService[JmsEngineActivemqBroker]
> Task-1] [TransportConnection ] Stopping connection:
> vm://JmsEngineActivemqBroker#0
> 13.10.15 12:04:36:964 DEBUG [ActiveMQ BrokerService[JmsEngineActivemqBroker]
> Task-1] [ThreadPoolUtils ] Forcing shutdown of ExecutorService:
> java.util.concurrent.ThreadPoolExecutor@22f62eba
> 13.10.15 12:04:36:964 DEBUG [ActiveMQ BrokerService[JmsEngineActivemqBroker]
> Task-1] [TransportConnection ] Stopped transport:
> vm://JmsEngineActivemqBroker#0
> 13.10.15 12:04:36:964 DEBUG [ActiveMQ BrokerService[JmsEngineActivemqBroker]
> Task-1] [TransportConnection ] Connection Stopped:
> vm://JmsEngineActivemqBroker#0
> 13.10.15 12:04:36:965 DEBUG [main] [ThreadPoolUtils ] Shutdown
> of ExecutorService: java.util.concurrent.ThreadPoolExecutor@30721965 is
> shutdown: true and terminated: false took: 0.000 seconds.
> 13.10.15 12:04:36:965 DEBUG [main] [ThreadPoolUtils ] Shutdown
> of ExecutorService: java.util.concurrent.ThreadPoolExecutor@d0cc53e is
> shutdown: true and terminated: true took: 0.000 seconds.
> 13.10.15 12:04:36:965 DEBUG [main] [ThreadPoolUtils ] Forcing
> shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@24d37b87
> 13.10.15 12:04:36:965 DEBUG [main] [VMTransportFactory ] Shutting
> down VM connectors for broker: JmsEngineActivemqBroker
> 13.10.15 12:04:36:965 INFO [main] [TransportConnector ] Connector
> vm://JmsEngineActivemqBroker Stopped
> 13.10.15 12:04:36:966 INFO [main] [BrokerService ] Apache
> ActiveMQ 5.7.0 (JmsEngineActivemqBroker,
> ID:localhost-51012-1381831459465-0:1) is shutting down
> 13.10.15 12:04:38:002 INFO [main] [TransportConnector ] Connector
> tcp://localhost:0 Stopped
> 13.10.15 12:04:38:021 DEBUG [main] [ManagementContext ]
> Unregistering MBean
> org.apache.activemq:BrokerName=JmsEngineActivemqBroker,Type=Topic,Destination=ActiveMQ.Advisory.Connection
> 13.10.15 12:04:38:022 DEBUG [main] [ManagementContext ]
> Unregistering MBean
> org.apache.activemq:BrokerName=JmsEngineActivemqBroker,Type=Queue,Destination=requestQueue
> 13.10.15 12:04:38:022 DEBUG [main] [ManagementContext ]
> Unregistering MBean
> org.apache.activemq:BrokerName=JmsEngineActivemqBroker,Type=Topic,Destination=ActiveMQ.Advisory.Queue
> 13.10.15 12:04:38:023 DEBUG [main] [ManagementContext ]
> Unregistering MBean
> org.apache.activemq:BrokerName=JmsEngineActivemqBroker,Type=Topic,Destination=ActiveMQ.Advisory.Consumer.Queue.requestQueue
> 13.10.15 12:04:38:023 DEBUG [main] [ManagementContext ]
> Unregistering MBean
> org.apache.activemq:BrokerName=JmsEngineActivemqBroker,Type=Queue,Destination=replyQueue
> 13.10.15 12:04:38:024 DEBUG [main] [ManagementContext ]
> Unregistering MBean
> org.apache.activemq:BrokerName=JmsEngineActivemqBroker,Type=Topic,Destination=ActiveMQ.Advisory.Consumer.Queue.replyQueue
> 13.10.15 12:04:38:025 INFO [main] [PListStore ]
> PListStore:[/.../jms-engine-activemq/target/jms-engine-activemq-data-custom/broker/JmsEngineActivemqBroker/tmp_storage]
> stopped
> 13.10.15 12:04:38:025 DEBUG [main] [JournalPersistenceAdapter ] Waking
> for checkpoint to complete.
> 13.10.15 12:04:38:855 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Marking journal at: 0:3122
> 13.10.15 12:04:38:855 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint done.
> 13.10.15 12:04:38:855 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint started.
> 13.10.15 12:04:40:593 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Marking journal at: 0:3122
> 13.10.15 12:04:40:593 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint done.
> 13.10.15 12:04:40:593 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint started.
> 13.10.15 12:04:42:693 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Marking journal at: 0:3122
> 13.10.15 12:04:42:694 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint done.
> 13.10.15 12:04:42:694 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint started.
> 13.10.15 12:04:44:622 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Marking journal at: 0:3122
> 13.10.15 12:04:44:622 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint done.
> 13.10.15 12:04:44:622 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint started.
> 13.10.15 12:04:46:468 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Marking journal at: 0:3122
> 13.10.15 12:04:46:469 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint done.
> 13.10.15 12:04:46:469 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint started.
> 13.10.15 12:04:48:244 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Marking journal at: 0:3122
> 13.10.15 12:04:48:244 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint done.
> 13.10.15 12:04:48:244 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint started.
> 13.10.15 12:04:50:027 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Marking journal at: 0:3122
> 13.10.15 12:04:50:027 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint done.
> 13.10.15 12:04:50:027 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint started.
> 13.10.15 12:04:51:900 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Marking journal at: 0:3122
> 13.10.15 12:04:51:900 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint done.
> 13.10.15 12:04:51:900 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint started.
> 13.10.15 12:04:54:010 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Marking journal at: 0:3122
> 13.10.15 12:04:54:010 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint done.
> 13.10.15 12:04:54:011 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint started.
> 13.10.15 12:04:55:991 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Marking journal at: 0:3122
> 13.10.15 12:04:55:991 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint done.
> 13.10.15 12:04:55:991 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint started.
> 13.10.15 12:04:57:926 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Marking journal at: 0:3122
> 13.10.15 12:04:57:926 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint done.
> 13.10.15 12:04:57:927 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint started.
> 13.10.15 12:04:59:680 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Marking journal at: 0:3122
> 13.10.15 12:04:59:681 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint done.
> 13.10.15 12:04:59:681 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint started.
> 13.10.15 12:05:01:958 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Marking journal at: 0:3122
> 13.10.15 12:05:01:959 DEBUG [Persistence Adaptor Task-1]
> [JournalPersistenceAdapter ] Checkpoint done.
> .
> .
> .
> {code}
> This iterating makes the ActiveMQ to finish with success after a couple of
> minutes (after the 1000 iterations or sometimes sooner if the DB operations
> are fast enough to get their elapsed time under the 500 ms). So it does not
> really block the applicacion "forever".
> The task.iterate() method should return the {{false}} value, but the call to
> the following method sets the {{JournalPersistenceAdapter.fullCheckPoint}}
> always to {{true}}. The reason seems to be connected with a time delay which
> is considerably larger when using a remote DB server in contrast with a local
> one.
> The following method sets the {{JournalPersistenceAdapter.fullCheckPoint}} to
> {{true}}:
> {code}
> org.apache.activemq.store.journal.JournalPersistenceAdapter.checkpoint(boolean,
> boolean):352
> {code}
> There is a hard-coded constant in the ActiveMQ code:
> {code}
> org.apache.activeio.journal.active.JournalImpl.OVERFLOW_RENOTIFICATION_DELAY
> = 500;
> {code}
> When a set of persistence operations takes longer than 500 ms (which in our
> use-case with a remote DB server does, but with a local DB does not), the
> boolean flag {{JournalPersistenceAdapter.fullCheckPoint}} is set to {{true}}
> and the for-cycle goes to the next iteration (out of 1000).
> The 1000 iterations is a default value for the {{TaskRunnerFactory}} set in
> the
> {{org.apache.activemq.broker.BrokerService.getPersistenceTaskRunnerFactory()}}
> getter method. Altering this {{TaskRunnerFactory.maxIterationsPerRun}} value
> to some lower number when creating the {{BrokerService}} instance can be
> considered a workaround (but I am not sure if it does not break something
> else?)
> The problem can be simulated by placing a {{sleep(500)}} to the right place
> in the code to make sure the persistence operations always take longer than
> 500 ms:
> {code}
> private void rolloverCheck() throws IOException {
> // See if we need to issue an overflow notification.
> if (eventListener != null && file.isPastHalfActive()
> && overflowNotificationTime + OVERFLOW_RENOTIFICATION_DELAY <
> System.currentTimeMillis() && !doingNotification ) {
> doingNotification = true;
> try {
> // We need to send an overflow notification to free up
> // some logFiles.
> Location safeSpot =
> file.getFirstRecordLocationOfSecondActiveLogFile();
> eventListener.overflowNotification(safeSpot);
> overflowNotificationTime = System.currentTimeMillis();
> try {
> Thread.sleep(500);
> } catch (InterruptedException e1) {
> e1.printStackTrace();
> }
> } finally {
> doingNotification = false;
> }
> }
> ...
> {code}
> What is strange is that if the sleep is placed in the beginning of the method
> body (or setting the {{JournalImpl.OVERFLOW_RENOTIFICATION_DELAY}} to some
> really low value), a NPE occurs:
> {code}
> Caused by: java.io.IOException: Write failed: java.lang.NullPointerException
> at
> org.apache.activeio.journal.active.JournalImpl.write(JournalImpl.java:197)
> at
> org.apache.activeio.journal.active.JournalImpl.write(JournalImpl.java:158)
> at
> org.apache.activemq.store.journal.JournalPersistenceAdapter.deleteAllMessages(JournalPersistenceAdapter.java:679)
> at
> org.apache.activemq.broker.BrokerService.deleteAllMessages(BrokerService.java:1500)
> at
> org.apache.activemq.broker.BrokerService.doStartPersistenceAdapter(BrokerService.java:621)
> at
> org.apache.activemq.broker.BrokerService.startPersistenceAdapter(BrokerService.java:612)
> at
> org.apache.activemq.broker.BrokerService.start(BrokerService.java:577)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at
> org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1544)
> at
> org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1485)
> at
> org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1417)
> ... 52 more
> Caused by: java.lang.NullPointerException
> at
> org.apache.activemq.store.journal.JournalPersistenceAdapter.checkpoint(JournalPersistenceAdapter.java:356)
> at
> org.apache.activemq.store.journal.JournalPersistenceAdapter.overflowNotification(JournalPersistenceAdapter.java:333)
> at
> org.apache.activeio.journal.active.JournalImpl.rolloverCheck(JournalImpl.java:284)
> at
> org.apache.activeio.journal.active.JournalImpl.write(JournalImpl.java:184)
> ... 65 more
> {code}
--
This message was sent by Atlassian JIRA
(v6.1#6144)
