-
Bug
-
Resolution: Done
-
Major
-
JBoss A-MQ 6.2.1
-
None
Upon startup with a large kahadb / index, we are seeing extended startup times (> 10 minutes), with no logging present in the activemq-related threads (BrokerService, ActiveMqServiceFactory, MessageDatabase) for several to many minutes between the "Using Persistence Adapter:" statement and the "KahaDB is version" statement. Looking at thread dumps, we see a long-running thread that appears to be in journal reading operations. It does not appear to be blocked - just busy (99% cpu):
"AMQ-1-thread-1" #101 prio=5 os_prio=0 tid=0x00007ee4fc010800 nid=0x5d0 runnable [0x00007ee4988d6000] java.lang.Thread.State: RUNNABLE at java.io.RandomAccessFile.readBytes(Native Method) at java.io.RandomAccessFile.read(RandomAccessFile.java:377) at java.io.RandomAccessFile.readFully(RandomAccessFile.java:436) at java.io.RandomAccessFile.readFully(RandomAccessFile.java:416) at org.apache.activemq.util.RecoverableRandomAccessFile.readFully(RecoverableRandomAccessFile.java:75) at org.apache.activemq.store.kahadb.disk.journal.DataFileAccessor.readFully(DataFileAccessor.java:97) at org.apache.activemq.store.kahadb.disk.journal.Journal.checkBatchRecord(Journal.java:393) at org.apache.activemq.store.kahadb.disk.journal.Journal.recoveryCheck(Journal.java:325) at org.apache.activemq.store.kahadb.disk.journal.Journal.start(Journal.java:199) - locked <0x00007f28188dbfd8> (a org.apache.activemq.store.kahadb.disk.journal.Journal) at org.apache.activemq.store.kahadb.MessageDatabase.open(MessageDatabase.java:378) at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:418) at org.apache.activemq.store.kahadb.MessageDatabase.doStart(MessageDatabase.java:262) at org.apache.activemq.store.kahadb.KahaDBStore.doStart(KahaDBStore.java:205) at org.apache.activemq.util.ServiceSupport.start(ServiceSupport.java:55) at org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.doStart(KahaDBPersistenceAdapter.java:223) at org.apache.activemq.util.ServiceSupport.start(ServiceSupport.java:55) at org.apache.activemq.broker.BrokerService.doStartPersistenceAdapter(BrokerService.java:657) at org.apache.activemq.broker.BrokerService.startPersistenceAdapter(BrokerService.java:641) at org.apache.activemq.broker.BrokerService.start(BrokerService.java:606) at io.fabric8.mq.fabric.ActiveMQServiceFactory$ClusteredConfiguration.doStart(ActiveMQServiceFactory.java:506) at io.fabric8.mq.fabric.ActiveMQServiceFactory$ClusteredConfiguration.access$400(ActiveMQServiceFactory.java:318) at io.fabric8.mq.fabric.ActiveMQServiceFactory$ClusteredConfiguration$1.run(ActiveMQServiceFactory.java:449) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) Locked ownable synchronizers: - <0x00007f2818099798> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync) - <0x00007f28380d0310> (a java.util.concurrent.ThreadPoolExecutor$Worker) and later: "AMQ-1-thread-1" #101 prio=5 os_prio=0 tid=0x00007ee4fc010800 nid=0x5d0 runnable [0x00007ee4988d6000] java.lang.Thread.State: RUNNABLE at java.io.RandomAccessFile.readBytes(Native Method) at java.io.RandomAccessFile.read(RandomAccessFile.java:377) at java.io.RandomAccessFile.readFully(RandomAccessFile.java:436) at java.io.RandomAccessFile.readFully(RandomAccessFile.java:416) at org.apache.activemq.util.RecoverableRandomAccessFile.readFully(RecoverableRandomAccessFile.java:75) at org.apache.activemq.store.kahadb.disk.journal.DataFileAccessor.readFully(DataFileAccessor.java:97) at org.apache.activemq.store.kahadb.disk.journal.Journal.checkBatchRecord(Journal.java:393) at org.apache.activemq.store.kahadb.disk.journal.Journal.recoveryCheck(Journal.java:325) at org.apache.activemq.store.kahadb.disk.journal.Journal.start(Journal.java:199) - locked <0x00007f2528539798> (a org.apache.activemq.store.kahadb.disk.journal.Journal) at org.apache.activemq.store.kahadb.MessageDatabase.open(MessageDatabase.java:378) at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:418) at org.apache.activemq.store.kahadb.MessageDatabase.doStart(MessageDatabase.java:262) at org.apache.activemq.store.kahadb.KahaDBStore.doStart(KahaDBStore.java:205) at org.apache.activemq.util.ServiceSupport.start(ServiceSupport.java:55) at org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.doStart(KahaDBPersistenceAdapter.java:223) at org.apache.activemq.util.ServiceSupport.start(ServiceSupport.java:55) at org.apache.activemq.broker.BrokerService.doStartPersistenceAdapter(BrokerService.java:657) at org.apache.activemq.broker.BrokerService.startPersistenceAdapter(BrokerService.java:641) at org.apache.activemq.broker.BrokerService.start(BrokerService.java:606) at io.fabric8.mq.fabric.ActiveMQServiceFactory$ClusteredConfiguration.doStart(ActiveMQServiceFactory.java:506) at io.fabric8.mq.fabric.ActiveMQServiceFactory$ClusteredConfiguration.access$400(ActiveMQServiceFactory.java:318) at io.fabric8.mq.fabric.ActiveMQServiceFactory$ClusteredConfiguration$1.run(ActiveMQServiceFactory.java:449) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) Locked ownable synchronizers: - <0x00007f25265105f0> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync) - <0x00007f252853b6a0> (a java.util.concurrent.ThreadPoolExecutor$Worker)
Integrity checks are enabled in the adapter:
<persistenceAdapter> <kahaDB directory="${karaf.data}/amq/kahadb" cleanupInterval="120000" archiveDataLogs="false" directoryArchive="${karaf.data}/amq/archive/kahadb" concurrentStoreAndDispatchQueues="false" journalMaxFileLength="50 mb" useLock="true" enableJournalDiskSyncs="true" indexCacheSize="102400" checksumJournalFiles="true" checkForCorruptJournalFiles="true" lockKeepAlivePeriod="5000"> <locker> <shared-file-locker lockAcquireSleepInterval="5000" /> </locker> </kahaDB> </persistenceAdapter>
In the cases where this is observed, the kahadb store does not seem inordinately large (in the 10s of GB to low 100s of GB), but the index seems large (100s of mb to several GB). The index seems to grow rapidly when many small messages are pushed through the broker.
