[
https://issues.apache.org/jira/browse/AMQ-4835?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13816194#comment-13816194
]
Jiri Patera commented on AMQ-4835:
----------------------------------
No, there are some larger changes there (as far as I know) and the migration
cannot be done easily in our case. So we will have to stay on the v5.7.0 for
some time and migrate later when the schedule is not so busy.
> 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)
