activemq-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "raghav rao (Commented) (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (AMQ-2891) ActiveMQ takes longer to start with KahaDb and more than 10000 messages
Date Fri, 09 Dec 2011 20:38:53 GMT

    [ https://issues.apache.org/jira/browse/AMQ-2891?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13166537#comment-13166537
] 

raghav rao commented on AMQ-2891:
---------------------------------

@Gary

The issue where Broker is starting slowly even after shutting it down cleanly is still there..

It takes 117 seconds to restart the broker with KahaDB size on disk = 14GB with 1 million
records.
Subsequent starts after clean shutdown also take the same amount of time.

When i stop the broker i am calling broker.stop();

Thoughts??

Log statements
--------------
[2011-12-09 12:18:43.372]  DEBUG: binding to broker: stitcher1-UDCServer
[2011-12-09 12:18:43.461]   INFO: PListStore:/home/rrao/myudc/stitcher1-UDCServer/tmp_storage
started
[2011-12-09 12:18:43.572]  DEBUG: Probably not using JRE 1.4: mx4j.tools.naming.NamingService
[2011-12-09 12:18:43.574]  DEBUG: Starting JMXConnectorServer...
[2011-12-09 12:18:43.694]   INFO: Using Persistence Adapter: KahaDBPersistenceAdapter[/home/rrao/myudc/stitcher1-UDCServer/KahaDB]
[2011-12-09 12:18:43.700]   INFO: JMX consoles can connect to service:jmx:rmi:///jndi/rmi://localhost:1099/jmxrmi
[2011-12-09 12:20:34.390]   INFO: KahaDB is version 3
[2011-12-09 12:20:34.391]  DEBUG: loading
[2011-12-09 12:20:34.400]  DEBUG: loading
[2011-12-09 12:20:34.400]  DEBUG: loading
[2011-12-09 12:20:34.400]  DEBUG: loading
[2011-12-09 12:20:34.409]  DEBUG: loading
[2011-12-09 12:20:34.409]  DEBUG: loading
[2011-12-09 12:20:34.464]   INFO: Recovering from the journal ...
[2011-12-09 12:20:34.464]   INFO: Recovery replayed 1 operations from the journal in 0.055
seconds.
[2011-12-09 12:20:36.905]   INFO: ActiveMQ null JMS Message Broker (stitcher1-UDCServer) is
starting
[2011-12-09 12:20:36.905]   INFO: For help or more information please see: http://activemq.apache.org/
[2011-12-09 12:20:37.076]  DEBUG: stitcher1-UDCServer adding destination: queue://queue-AVIR
[2011-12-09 12:20:40.731]  DEBUG: Checkpoint started.
[2011-12-09 12:20:40.752]  DEBUG: Checkpoint done.
[2011-12-09 12:20:40.794]  DEBUG: queue-AVIR toPageIn: 200, Inflight: 0, pagedInMessages.size
0, enqueueCount: 0, dequeueCount: 0
[2011-12-09 12:20:40.800]  DEBUG: Publishing: vm://stitcher1-UDCServer for broker transport
URI: vm://stitcher1-UDCServer?marshal=false&broker.persistent=true
[2011-12-09 12:20:40.800]  DEBUG: stitcher1-UDCServer adding destination: topic://ActiveMQ.Advisory.Queue
[2011-12-09 12:20:40.811]  DEBUG: queue-AVIR toPageIn: 200, Inflight: 0, pagedInMessages.size
0, enqueueCount: 0, dequeueCount: 0
[2011-12-09 12:20:40.814]   INFO: Connector vm://stitcher1-UDCServer?marshal=false&broker.persistent=true
Started
[2011-12-09 12:20:40.830]   INFO: ActiveMQ JMS Message Broker (stitcher1-UDCServer, ID:stitcher1-38687-1323462036935-0:1)
started
[2011-12-09 12:20:40.940]  DEBUG: Setting up new connection id: ID:stitcher1-38687-1323462036935-2:1,
address: vm://stitcher1-UDCServer?marshal=false&broker.persistent=true#0
[2011-12-09 12:20:40.941]  DEBUG: stitcher1-UDCServer adding destination: topic://ActiveMQ.Advisory.Connection
[2011-12-09 12:20:40.949]  DEBUG: stitcher1-UDCServer adding consumer: ID:stitcher1-38687-1323462036935-2:1:-1:1
for destination: ActiveMQ.Advisory.TempQueue,ActiveMQ.Advisory.TempTopic
[2011-12-09 12:20:41.080]  DEBUG: Setting up new connection id: ID:stitcher1-38687-1323462036935-2:2,
address: vm://stitcher1-UDCServer?marshal=false&broker.persistent=true#2
[2011-12-09 12:20:41.082]  DEBUG: stitcher1-UDCServer adding consumer: ID:stitcher1-38687-1323462036935-2:2:-1:1
for destination: ActiveMQ.Advisory.TempQueue,ActiveMQ.Advisory.TempTopic
[2011-12-09 12:20:41.088]  DEBUG: stitcher1-UDCServer adding consumer: ID:stitcher1-38687-1323462036935-2:2:1:1
for destination: queue://queue-AVIR
[2011-12-09 12:20:41.095]  DEBUG: queue://queue-AVIR add sub: QueueSubscription: consumer=ID:stitcher1-38687-1323462036935-2:2:1:1,
destinations=0, dispatched=0, delivered=0, pending=0, dequeues: 0, dispatched: 0, inflight:
0
[2011-12-09 12:20:41.095]  DEBUG: stitcher1-UDCServer adding destination: topic://ActiveMQ.Advisory.Consumer.Queue.queue-AVIR
[2011-12-09 12:20:41.096]  DEBUG: queue-AVIR toPageIn: 200, Inflight: 0, pagedInMessages.size
0, enqueueCount: 0, dequeueCount: 0
[2011-12-09 12:20:41.101]   INFO: started dispatcher [AVIR-1] (com.activevideo.udc.server.dispatcher.DispatcherManager.start:832)
[2011-12-09 12:20:41.157]  DEBUG: Main:memory:queue://queue-AVIR:memory: usage change from:
0% of available memory, to: 1% of available memory
[2011-12-09 12:20:41.158]  DEBUG: Main:memory: usage change from: 0% of available memory,
to: 1% of available memory
[2011-12-09 12:20:41.169]  DEBUG: Main:memory:queue://queue-AVIR:memory: usage change from:
1% of available memory, to: 2% of available memory
[2011-12-09 12:20:41.169]  DEBUG: Main:memory: usage change from: 1% of available memory,
to: 2% of available memory
[2011-12-09 12:20:41.184]  DEBUG: Main:memory:queue://queue-AVIR:memory: usage change from:
2% of available memory, to: 3% of available memory
[2011-12-09 12:20:41.184]  DEBUG: Main:memory: usage change from: 2% of available memory,
to: 3% of available memory
[2011-12-09 12:20:41.199]  DEBUG: Main:memory:queue://queue-AVIR:memory: usage change from:
3% of available memory, to: 4% of available memory
[2011-12-09 12:20:41.199]  DEBUG: Main:memory: usage change from: 3% of available memory,
to: 4% of available memory
[2011-12-09 12:20:41.213]  DEBUG: Main:memory:queue://queue-AVIR:memory: usage change from:
4% of available memory, to: 5% of available memory
[2011-12-09 12:20:41.213]  DEBUG: Main:memory: usage change from: 4% of available memory,
to: 5% of available memory

                
> ActiveMQ takes longer to start with KahaDb and more than 10000 messages
> -----------------------------------------------------------------------
>
>                 Key: AMQ-2891
>                 URL: https://issues.apache.org/jira/browse/AMQ-2891
>             Project: ActiveMQ
>          Issue Type: Bug
>          Components: Broker
>    Affects Versions: 5.4.0
>         Environment: Windows XP
>            Reporter: Dinny Mathew
>            Assignee: Gary Tully
>
> ActiveMQ takes around five minutes to start with KahaDb with more than 10000 messages.
All messages are persistent queue. 
> With 500,000 persistent messsages, ittook around 20 minutes to start.
> See the five minutes time difference between lines:
> 2010-08-31 12:55:19,286 | INFO | PListStore:C:\ActiveMQ\apache-activemq-5.4.0\bin\win32\..\..\data\localhost\tmp_storage
initialized | org.apache.activemq.store.kahadb.plist.PListStore | WrapperSimpleAppMain
> 2010-08-31 13:03:56,983 | INFO | Listening for connections at: nio://S90356004630988:61616
| org.apache.activemq.transport.TransportServerThreadSupport | WrapperSimpleAppMain
> From activemq.log with 100,000 messages
> 2010-08-31 12:55:10,436 | INFO | JMX consoles can connect to service:jmx:rmi:///jndi/rmi://localhost:1099/jmxrmi
| org.apache.activemq.broker.jmx.ManagementContext | JMX connector
> 2010-08-31 12:55:11,294 | INFO | KahaDB is version 2 | org.apache.activemq.store.kahadb.MessageDatabase
| WrapperSimpleAppMain
> 2010-08-31 12:55:11,435 | INFO | Recovering from the journal ... | org.apache.activemq.store.kahadb.MessageDatabase
| WrapperSimpleAppMain
> 2010-08-31 12:55:11,435 | INFO | Recovery replayed 1 operations from the journal in 0.063
seconds. | org.apache.activemq.store.kahadb.MessageDatabase | WrapperSimpleAppMain
> 2010-08-31 12:55:12,090 | INFO | ActiveMQ 5.4.0 JMS Message Broker (localhost) is starting
| org.apache.activemq.broker.BrokerService | WrapperSimpleAppMain
> 2010-08-31 12:55:12,090 | INFO | For help or more information please see: http://activemq.apache.org/
| org.apache.activemq.broker.BrokerService | WrapperSimpleAppMain
> 2010-08-31 12:55:12,278 | INFO | Scheduler using directory: activemq-data\scheduler |
org.apache.activemq.broker.scheduler.SchedulerBroker | WrapperSimpleAppMain
> 2010-08-31 12:55:19,286 | INFO | PListStore:C:\ActiveMQ\apache-activemq-5.4.0\bin\win32\..\..\data\localhost\tmp_storage
initialized | org.apache.activemq.store.kahadb.plist.PListStore | WrapperSimpleAppMain
> 2010-08-31 13:03:56,983 | INFO | Listening for connections at: nio://S90356004630988:61616
| org.apache.activemq.transport.TransportServerThreadSupport | WrapperSimpleAppMain
> 2010-08-31 13:03:56,999 | INFO | Connector nio Started | org.apache.activemq.broker.TransportConnector
| WrapperSimpleAppMain
> 2010-08-31 13:03:57,045 | INFO | ActiveMQ JMS Message Broker (localhost, ID:S90356004630988-3777-1283273712137-0:0)
started | org.apache.activemq.broker.BrokerService | WrapperSimpleAppMain
> 2010-08-31 13:03:57,639 | INFO | Logging to org.slf4j.impl.JCLLoggerAdapter(org.eclipse.jetty.util.log)
via org.eclipse.jetty.util.log.Slf4jLog | org.eclipse.jetty.util.log | WrapperSimpleAppMain
> 2010-08-31 13:03:57,639 | INFO | jetty-7.0.1.v20091125 | org.eclipse.jetty.util.log |
WrapperSimpleAppMain
> 2010-08-31 13:03:58,451 | INFO | ActiveMQ WebConsole initialized. | org.apache.activemq.web.WebConsoleStarter
| WrapperSimpleAppMain
> 2010-08-31 13:03:58,857 | INFO | Initializing Spring FrameworkServlet 'dispatcher' |
/admin | WrapperSimpleAppMain
> 2010-08-31 13:03:59,341 | INFO | ActiveMQ Console at http://0.0.0.0:8161/admin | org.eclipse.jetty.util.log
| WrapperSimpleAppMain
> 2010-08-31 13:04:00,091 | INFO | Initializing Spring root WebApplicationContext | /camel
| WrapperSimpleAppMain
> 2010-08-31 13:04:02,668 | INFO | Connector vm://localhost Started | org.apache.activemq.broker.TransportConnector
| WrapperSimpleAppMain
> 2010-08-31 13:04:04,526 | INFO | Camel Console at http://0.0.0.0:8161/camel | org.eclipse.jetty.util.log
| WrapperSimpleAppMain
> 2010-08-31 13:04:04,589 | INFO | ActiveMQ Web Demos at http://0.0.0.0:8161/demo | org.eclipse.jetty.util.log
| WrapperSimpleAppMain
> 2010-08-31 13:04:04,651 | INFO | RESTful file access application at http://0.0.0.0:8161/fileserver
| org.eclipse.jetty.util.log | WrapperSimpleAppMain
> 2010-08-31 13:04:04,698 | INFO | Started SelectChannelConnector@0.0.0.0:8161 | org.eclipse.jetty.util.log
| WrapperSimpleAppMain
> 2
> With 500,000 messages, AMQ took 20 minutes to start.
> 2010-08-31 15:24:31,178 | INFO  | JMX consoles can connect to service:jmx:rmi:///jndi/rmi://localhost:1099/jmxrmi
| org.apache.activemq.broker.jmx.ManagementContext | JMX connector
> 2010-08-31 15:24:31,975 | INFO  | KahaDB is version 2 | org.apache.activemq.store.kahadb.MessageDatabase
| WrapperSimpleAppMain
> 2010-08-31 15:24:32,194 | INFO  | Recovering from the journal ... | org.apache.activemq.store.kahadb.MessageDatabase
| WrapperSimpleAppMain
> 2010-08-31 15:24:32,194 | INFO  | Recovery replayed 1 operations from the journal in
0.047 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | WrapperSimpleAppMain
> 2010-08-31 15:24:35,365 | INFO  | ActiveMQ 5.4.0 JMS Message Broker (localhost) is starting
| org.apache.activemq.broker.BrokerService | WrapperSimpleAppMain
> 2010-08-31 15:24:35,365 | INFO  | For help or more information please see: http://activemq.apache.org/
| org.apache.activemq.broker.BrokerService | WrapperSimpleAppMain
> 2010-08-31 15:24:35,552 | INFO  | Scheduler using directory: activemq-data\scheduler
| org.apache.activemq.broker.scheduler.SchedulerBroker | WrapperSimpleAppMain
> 2010-08-31 15:24:48,034 | INFO  | PListStore:C:\ActiveMQ\apache-activemq-5.4.0\bin\win32\..\..\data\localhost\tmp_storage
initialized | org.apache.activemq.store.kahadb.plist.PListStore | WrapperSimpleAppMain
> 2010-08-31 15:45:09,767 | INFO  | Listening for connections at: nio://S90356004630988:61616
| org.apache.activemq.transport.TransportServerThreadSupport | WrapperSimpleAppMain
> 2010-08-31 15:45:09,767 | INFO  | Connector nio Started | org.apache.activemq.broker.TransportConnector
| WrapperSimpleAppMain
> 2010-08-31 15:45:09,876 | INFO  | ActiveMQ JMS Message Broker (localhost, ID:S90356004630988-3029-1283282675427-0:0)
started | org.apache.activemq.broker.BrokerService | WrapperSimpleAppMain
> 2010-08-31 15:45:10,923 | INFO  | Logging to org.slf4j.impl.JCLLoggerAdapter(org.eclipse.jetty.util.log)
via org.eclipse.jetty.util.log.Slf4jLog | org.eclipse.jetty.util.log | WrapperSimpleAppMain
> 2010-08-31 15:45:10,923 | INFO  | jetty-7.0.1.v20091125 | org.eclipse.jetty.util.log
| WrapperSimpleAppMain
> 2010-08-31 15:45:10,970 | INFO  | Slow KahaDB access: cleanup took 1047 | org.apache.activemq.store.kahadb.MessageDatabase
| ActiveMQ Journal Checkpoint Worker
> 2010-08-31 15:45:11,829 | INFO  | ActiveMQ WebConsole initialized. | org.apache.activemq.web.WebConsoleStarter
| WrapperSimpleAppMain
> 2010-08-31 15:45:12,235 | INFO  | Initializing Spring FrameworkServlet 'dispatcher' |
/admin | WrapperSimpleAppMain
> 2010-08-31 15:45:12,719 | INFO  | ActiveMQ Console at http://0.0.0.0:8161/admin | org.eclipse.jetty.util.log
| WrapperSimpleAppMain
> 2010-08-31 15:45:13,422 | INFO  | Initializing Spring root WebApplicationContext | /camel
| WrapperSimpleAppMain
> 2010-08-31 15:45:16,390 | INFO  | Connector vm://localhost Started | org.apache.activemq.broker.TransportConnector
| WrapperSimpleAppMain
> 2010-08-31 15:45:18,468 | INFO  | Camel Console at http://0.0.0.0:8161/camel | org.eclipse.jetty.util.log
| WrapperSimpleAppMain
> 2010-08-31 15:45:18,561 | INFO  | ActiveMQ Web Demos at http://0.0.0.0:8161/demo | org.eclipse.jetty.util.log
| WrapperSimpleAppMain
> 2010-08-31 15:45:18,624 | INFO  | RESTful file access application at http://0.0.0.0:8161/fileserver
| org.eclipse.jetty.util.log | WrapperSimpleAppMain
> 2010-08-31 15:45:18,686 | INFO  | Started SelectChannelConnector@0.0.0.0:8161 | org.eclipse.jetty.util.log
| WrapperSimpleAppMain
> Here is the config:
>     <broker xmlns="http://activemq.apache.org/schema/core" brokerName="localhost"
dataDirectory="${activemq.base}/data" persistent="true" systemExitOnShutdown="true" useShutdownHook="false"
advisorySupport="false" useJmx="true">
>  
>         <!--
> 			For better performances use VM cursor and small memory limit.
> 			For more information, see:
>             
>             http://activemq.apache.org/message-cursors.html
>             
>             Also, if your producer is "hanging", it's probably due to producer flow control.
>             For more information, see:
>             http://activemq.apache.org/producer-flow-control.html
>         -->
>               
>         <destinationPolicy>
>             <policyMap>
>               <policyEntries>
>                 <policyEntry topic=">" producerFlowControl="false" optimizedDispatch="true"
memoryLimit="128mb">
>                   <pendingSubscriberPolicy>
>                     <fileCursor />
>                   </pendingSubscriberPolicy>
>                 </policyEntry>
>                 <policyEntry queue=">" producerFlowControl="false" optimizedDispatch="true"
memoryLimit="128mb">
>                   <!-- Use VM cursor for better latency
>                        For more information, see:
>                        
>                        http://activemq.apache.org/message-cursors.html
>                    -->    
>                   <pendingQueuePolicy>
>                     <fileQueueCursor/>
>                   </pendingQueuePolicy>
>                   
>                 </policyEntry>
>               </policyEntries>
>             </policyMap>
>         </destinationPolicy> 
>  
>         
>         <!-- 
>             The managementContext is used to configure how ActiveMQ is exposed in 
>             JMX. By default, ActiveMQ uses the MBean server that is started by 
>             the JVM. For more information, see: 
>             
>             http://activemq.apache.org/jmx.html 
>         -->
>         <managementContext>
>             <managementContext createConnector="true"/>
>         </managementContext>
>         <!-- 
>             Configure message persistence for the broker. The default persistence
>             mechanism is the KahaDB store (identified by the kahaDB tag). 
>             For more information, see: 
>             
>             http://activemq.apache.org/persistence.html 
>         -->
>         <persistenceAdapter>
>             <kahaDB directory="${activemq.base}/data/kahadb" enableIndexWriteAsync="true"
journalMaxFileLength="64mb"  indexWriteBatchSize="10000" indexCacheSize="10000"/>
>         </persistenceAdapter>
>         
>         
>           <!--
>             The systemUsage controls the maximum amount of space the broker will 
>             use before slowing down producers. For more information, see:
>             
>             http://activemq.apache.org/producer-flow-control.html
>              
>         <systemUsage>
>             <systemUsage>
>                 <memoryUsage>
>                     <memoryUsage limit="600 mb"/>
>                 </memoryUsage>
>                 <storeUsage>
>                     <storeUsage limit="10 gb"/>
>                 </storeUsage>
>                 <tempUsage>
>                     <tempUsage limit="1 gb"/>
>                 </tempUsage>
>             </systemUsage>
>         </systemUsage>
> 		-->
> 		  
>         <!-- 
>             The transport connectors expose ActiveMQ over a given protocol to
>             clients and other brokers. For more information, see: 
>             
>             http://activemq.apache.org/configuring-transports.html 
>         -->
>         <transportConnectors>
>             <transportConnector name="nio" uri="nio://0.0.0.0:61616"/>
>         </transportConnectors>
>     </broker>

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira

        

Mime
View raw message