Uploaded image for project: 'JBoss A-MQ'
  1. JBoss A-MQ
  2. ENTMQ-2059

A-MQ: Incorrect logging from KahaDB cleanup task when enableAckCompaction=true

XMLWordPrintable

    • Hide

      Using Karaf shell JMS producer and consumer to reproduce the problem.

      Run an AMQ 6.3 broker with this KahaDB configuration

              <kahaDB
                directory="${data}/kahadb"
                journalMaxFileLength="32mb"
                concurrentStoreAndDispatchQueues="false"
                checksumJournalFiles="false"
                indexCacheSize="100000"
                indexWriteBatchSize="10000"
                preallocationStrategy="os_kernel_copy"
                enableJournalDiskSyncs="false"
                enableAckCompaction="true"
                compactAcksIgnoresStoreGrowth="true"
                ignoreMissingJournalfiles="true"
                compactAcksAfterNoGC="2"
            />

      Configure detailed KahaDB logging:

      # kahaDB Messsage Database appender
log4j.appender.kahadb=org.apache.log4j.RollingFileAppender
log4j.appender.kahadb.file=${karaf.data}/log/kahadb.log
log4j.appender.kahadb.maxFileSize=1024KB
log4j.appender.kahadb.maxBackupIndex=5
log4j.appender.kahadb.append=true
log4j.appender.kahadb.layout=org.apache.log4j.PatternLayout
log4j.appender.kahadb.layout.ConversionPattern=%d [%-15.15t] %-5p %-30.30c{1} - %m%n
log4j.logger.org.apache.activemq.store.kahadb.MessageDatabase=TRACE, kahadb

      Start AMQ and two Karaf shells. Also tail data/log/kahadb.log

      First run 

      activemq:producer --user admin --password admin --destination queue://TEST.1 --messageCount 1 --persistent true

      to send a single msg to queue TEST.1.

      Then in two Karaf shells execute these commands in parallel

      activemq:producer --user admin --password admin --destination queue://TEST.2 --messageCount 30000 --textMessageSize 2048000 --persistent true

activemq:consumer --user admin --password admin --destination queue://TEST.2 --messageCount 30000

      and wait for commands to finish and ack compaction to occur, i.e. to log

      TRACE MessageDatabase  - ACKS forwarded, updates for ack locations: {11=[1, 2]}
TRACE MessageDatabase - ACK File Map following updates: {3=[2, 3], 4=[3, 4], 5=[4, 5], 6=[5, 6], 7=[6, 7], 10=[10], 11=[1, 2]}

      In my test the ack compaction creates file 

      1.7M Jun  6 12:29 db-11.log

      Note: The file size is only 1.7M, not 32M as with usual journal files, indicating this is an ack compacted journal. db-11.log is also the currently latest journal file!

      Then run

       
activemq:consumer --user admin --password admin --destination queue://TEST.1 --messageCount 1

      to consume the only remaining msg and wait for KahaDB clean up task to be run again.
      It should log

      DEBUG MessageDatabase - Cleanup removing the data files: [1, 2, 3, 4, 5, 6, 7, 11]

      where it says it removes journal db-11.log which in fact is not deleted!

      Show
      Using Karaf shell JMS producer and consumer to reproduce the problem. Run an AMQ 6.3 broker with this KahaDB configuration <kahaDB directory= "${data}/kahadb" journalMaxFileLength= "32mb" concurrentStoreAndDispatchQueues= " false " checksumJournalFiles= " false " indexCacheSize= "100000" indexWriteBatchSize= "10000" preallocationStrategy= "os_kernel_copy" enableJournalDiskSyncs= " false " enableAckCompaction= " true " compactAcksIgnoresStoreGrowth= " true " ignoreMissingJournalfiles= " true " compactAcksAfterNoGC= "2" /> Configure detailed KahaDB logging: # kahaDB Messsage Database appender log4j.appender.kahadb=org.apache.log4j.RollingFileAppender log4j.appender.kahadb.file=${karaf.data}/log/kahadb.log log4j.appender.kahadb.maxFileSize=1024KB log4j.appender.kahadb.maxBackupIndex=5 log4j.appender.kahadb.append= true log4j.appender.kahadb.layout=org.apache.log4j.PatternLayout log4j.appender.kahadb.layout.ConversionPattern=%d [%-15.15t] %-5p %-30.30c{1} - %m%n log4j.logger.org.apache.activemq.store.kahadb.MessageDatabase=TRACE, kahadb Start AMQ and two Karaf shells. Also tail data/log/kahadb.log First run activemq:producer --user admin --password admin --destination queue: //TEST.1 --messageCount 1 --persistent true to send a single msg to queue TEST.1. Then in two Karaf shells execute these commands in parallel activemq:producer --user admin --password admin --destination queue: //TEST.2 --messageCount 30000 --textMessageSize 2048000 --persistent true activemq:consumer --user admin --password admin --destination queue: //TEST.2 --messageCount 30000 and wait for commands to finish and ack compaction to occur, i.e. to log TRACE MessageDatabase - ACKS forwarded, updates for ack locations: {11=[1, 2]} TRACE MessageDatabase - ACK File Map following updates: {3=[2, 3], 4=[3, 4], 5=[4, 5], 6=[5, 6], 7=[6, 7], 10=[10], 11=[1, 2]} In my test the ack compaction creates file 1.7M Jun 6 12:29 db-11.log Note: The file size is only 1.7M, not 32M as with usual journal files, indicating this is an ack compacted journal. db-11.log is also the currently latest journal file! Then run activemq:consumer --user admin --password admin --destination queue: //TEST.1 --messageCount 1 to consume the only remaining msg and wait for KahaDB clean up task to be run again. It should log DEBUG MessageDatabase - Cleanup removing the data files: [1, 2, 3, 4, 5, 6, 7, 11] where it says it removes journal db-11.log which in fact is not deleted!

      When KahaDB is configured for enableAckCompaction=true, it moves acks into a new journal file. Such journal file will only contains the compacted acks, it won't be used to hold messages.

      If the actual journal (to which new messages are written to) has a lower number than the journal files that were created during ack compaction, the periodic cleanup task will not delete any journals that are higher than the actual journal file. So multiple journal files may remain active on disk although there is no single unconsumed message on the broker.
      This in itself is okay, however when trace logging for the cleanup task is enabled, it reports differently, namely that it is going to delete these journals, where in fact it is not deleting them.

      E.g. lets take the following example.
      The KahaDB folder on disk consists of 

      [kahadb]$ ls -alh
total 54M
drwxr-xr-x.  2 fuse fuse  128K Feb  1 15:50 .
drwxr-xr-x. 13 fuse fuse  4.0K Nov  4 13:14 ..
-rw-r--r--.  1 fuse fuse   32M Feb  1 16:26 db-65.log
-rw-r--r--.  1 fuse fuse  4.6M Feb  1 15:24 db-66.log
-rw-r--r--.  1 fuse fuse  4.5M Feb  1 15:29 db-67.log
-rw-r--r--.  1 fuse fuse  4.6M Feb  1 15:34 db-68.log
-rw-r--r--.  1 fuse fuse  4.5M Feb  1 15:39 db-69.log
-rw-r--r--.  1 fuse fuse  2.5M Feb  1 16:26 db.data
-rw-r--r--.  1 fuse fuse   32M Feb  1 14:51 db-log.template
-rw-r--r--.  1 fuse fuse 1002K Feb  1 16:26 db.redo
-rw-r--r--.  1 fuse fuse     8 Feb  1 14:51 lock

      and the logging says:

      Last update: 65:26636520, full gc candidates set: [65, 66, 67, 68, 69]
gc candidates after producerSequenceIdTrackerLocation:65, [66, 67, 68, 69]
gc candidates after ackMessageFileMapLocation:65, [66, 67, 68, 69]
...
gc candidates: [66, 67, 68, 69]
    ackMessageFileMap: {65=[65]}
Cleanup removing the data files: [66, 67, 68, 69]

      In this example the actual journal file to which msgs are written is 65. The journal files 66-69 were created during ack compaction and have a higher number than 65.
      So KahaDB won't delete the journals 66-69 until the actual journal file is moved to journal 70, despite that there are no unconsumed messages on the broker.
      However the last log line suggests that it will remove the journals 66-69, but they will not get removed due to rule above.

      We should align the logging output with the logic used to determine which journals to delete.

        1. ENTMQ2059.tar.gz
          33 kB
          Tomas Kratky

              gtully@redhat.com Gary Tully
              rhn-support-tmielke Torsten Mielke
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

                Created:
                Updated:
                Resolved: