activemq-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Jiri Patera (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (AMQ-4835) JournalPersistenceAdapter: Persistence Adaptor Task iterates "forever"
Date Thu, 07 Nov 2013 18:13:18 GMT

    [ 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)

Mime
View raw message