Details

    • Type: Bug
    • Status: Resolved
    • Priority: Major
    • Resolution: Done
    • Affects Version/s: JBoss A-MQ 6.2.1
    • Fix Version/s: JBoss A-MQ 6.3.x
    • Component/s: broker, kahadb
    • Labels:
      None
    • Steps to Reproduce:
      Hide

      (Reproducer in progress - Seems to occur with large quantities of small messages over a short period)

      Show
      (Reproducer in progress - Seems to occur with large quantities of small messages over a short period)

      Description

      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.

        Gliffy Diagrams

          Attachments

            Activity

              People

              • Assignee:
                garytully Gary Tully
                Reporter:
                hawkinsds Duane Hawkins
              • Votes:
                0 Vote for this issue
                Watchers:
                10 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: