activemq-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Patrick Monfette (JIRA)" <j...@apache.org>
Subject [jira] Issue Comment Edited: (AMQ-3120) KahaDB error: "Could not locate data file"
Date Thu, 20 Jan 2011 16:23:43 GMT

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

Patrick Monfette edited comment on AMQ-3120 at 1/20/11 11:22 AM:
-----------------------------------------------------------------

Hello,

We're experiencing the very same issue and I'm also running ActiveMQ 5.4.2. We also have a
high quantity of messages, at least 30,000 messages per hours sometimes much more (2x, 3x)
than that. We have a mix of very large (fews megs) and very small (few bytes) messages.

What happens: a kaha db missing log (probably deleted too early by kahadb or something else)
then messages start accumulating and my consumers are unable to dequeue them.

This issue is really major, if not blocker. This is new since we upgraded to 5.4.2, we never
had this problem before with version 5.3.x. I'm unable to reproduce it and it happens randomly,
under heavy load or not.

We're running CentOS 4.6, 32 bits.

I found a temporary work around by adding this parameter to the kahadb config, restarting
the broker, wait until all the queued messages are consumed, then removing the parameter and
restarting the broker again.

{noformat}
<persistenceAdapter>
            <kahaDB directory="${activemq.base}/data/kahadb" ignoreMissingJournalfiles="true"/>
</persistenceAdapter>
{noformat}

When you restart the broker with this configuration you will see this and the normal processing
continues:

{noformat}
INFO   | jvm 1    | 2011/01/20 10:05:20 |  INFO | KahaDB is version 3
INFO   | jvm 1    | 2011/01/20 10:05:20 |  INFO | Recovering from the journal ...
INFO   | jvm 1    | 2011/01/20 10:05:20 |  INFO | Recovery replayed 1 operations from the
journal in 0.045 seconds.
INFO   | jvm 1    | 2011/01/20 10:05:20 |  INFO | Some journal files are missing: [4311]
INFO   | jvm 1    | 2011/01/20 10:05:20 |  INFO | Detected missing/corrupt journal files.
 Dropped 1 messages from the index in 0.028 seconds.
{noformat}

This workaround allows me to at least not lose all the DB like I had to do until today (delete
the kahadb folder and restart).

Here is what starts showing over and over again in the wrapper.log when the issue appears:

{noformat}
INFO   | jvm 1    | 2011/01/20 07:31:00 | ERROR | Looking for key 4311 but not found in fileMap:
{3944=db-3944.log number = 3944 , length = 33760316, 406
7=db-4067.log number = 4067 , length = 33590177, 3947=db-3947.log number = 3947 , length =
33677680, 3948=db-3948.log number = 3948 , length = 33596726, 
4068=db-4068.log number = 4068 , length = 33755827, 4075=db-4075.log number = 4075 , length
= 34048968, 4322=db-4322.log number = 4322 , length = 3004262
2, 4076=db-4076.log number = 4076 , length = 33734622, 4320=db-4320.log number = 4320 , length
= 33622170, 4321=db-4321.log number = 4321 , length = 3360
7934, 3943=db-3943.log number = 3943 , length = 33897766, 3961=db-3961.log number = 3961 ,
length = 33715187, 3960=db-3960.log number = 3960 , length = 3
3634841, 4021=db-4021.log number = 4021 , length = 33584217, 4022=db-4022.log number = 4022
, length = 33569989, 4090=db-4090.log number = 4090 , length 
= 33555654, 3955=db-3955.log number = 3955 , length = 33566643, 4030=db-4030.log number =
4030 , length = 33700887, 4091=db-4091.log number = 4091 , leng
th = 33928309, 4031=db-4031.log number = 4031 , length = 33554494, 3889=db-3889.log number
= 3889 , length = 33664097, 3956=db-3956.log number = 3956 , l
ength = 33621892, 3890=db-3890.log number = 3890 , length = 33590196, 4035=db-4035.log number
= 4035 , length = 33653742, 4034=db-4034.log number = 4034 
, length = 33852330, 3912=db-3912.log number = 3912 , length = 33554464, 3913=db-3913.log
number = 3913 , length = 33587386, 4101=db-4101.log number = 41
01 , length = 34013592, 4039=db-4039.log number = 4039 , length = 34009512, 4100=db-4100.log
number = 4100 , length = 33576394, 4038=db-4038.log number =
 4038 , length = 33564352, 4102=db-4102.log number = 4102 , length = 33630267, 3908=db-3908.log
number = 3908 , length = 33660034, 3909=db-3909.log numbe
r = 3909 , length = 33570972, 4317=db-4317.log number = 4317 , length = 33554634, 4316=db-4316.log
number = 4316 , length = 33554832, 4319=db-4319.log nu
mber = 4319 , length = 33560765, 3929=db-3929.log number = 3929 , length = 33773224, 4318=db-4318.log
number = 4318 , length = 33606627, 3928=db-3928.log
 number = 3928 , length = 33575213, 4313=db-4313.log number = 4313 , length = 33666992, 3935=db-3935.log
number = 3935 , length = 33716752, 4312=db-4312.
log number = 4312 , length = 33554827, 3934=db-3934.log number = 3934 , length = 33584253,
4315=db-4315.log number = 4315 , length = 33633620, 4314=db-43
14.log number = 4314 , length = 33676339}
INFO   | jvm 1    | 2011/01/20 07:31:00 | ERROR | Failed to fill batch
INFO   | jvm 1    | 2011/01/20 07:31:00 | java.io.IOException: Could not locate data file
/usr/share/activemq/data/kahadb/db-4311.log
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.kahadb.journal.Journal.getDataFile(Journal.java:345)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.kahadb.journal.Journal.read(Journal.java:592)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:786)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:956)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$5.execute(KahaDBStore.java:494)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.kahadb.page.Transaction.execute(Transaction.java:728)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:4
85)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:88)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:262)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:110)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1678)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1898)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1425)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at java.lang.Thread.run(Thread.java:619)
INFO   | jvm 1    | 2011/01/20 07:31:00 | ERROR | Failed to fill batch
INFO   | jvm 1    | 2011/01/20 07:31:00 | java.lang.RuntimeException: java.io.IOException:
Could not locate data file /usr/share/activemq/data/kahadb/db-
4311.log
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:265)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:110)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1678)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1898)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1425)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at java.lang.Thread.run(Thread.java:619)
INFO   | jvm 1    | 2011/01/20 07:31:00 | Caused by: java.io.IOException: Could not locate
data file /usr/share/activemq/data/kahadb/db-4311.log
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.kahadb.journal.Journal.getDataFile(Journal.java:345)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.kahadb.journal.Journal.read(Journal.java:592)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:786)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:956)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$5.execute(KahaDBStore.java:494)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.kahadb.page.Transaction.execute(Transaction.java:728)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:4
85)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:88)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:262)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       ... 10 more
INFO   | jvm 1    | 2011/01/20 07:31:00 | ERROR | Failed to page in more queue messages 
INFO   | jvm 1    | 2011/01/20 07:31:00 | java.lang.RuntimeException: java.lang.RuntimeException:
java.io.IOException: Could not locate data file /usr/sh
are/activemq/data/kahadb/db-4311.log
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:113)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1678)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1898)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1425)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at java.lang.Thread.run(Thread.java:619)
INFO   | jvm 1    | 2011/01/20 07:31:00 | Caused by: java.lang.RuntimeException: java.io.IOException:
Could not locate data file /usr/share/activemq/data
/kahadb/db-4311.log
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:265)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:110)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       ... 9 more
INFO   | jvm 1    | 2011/01/20 07:31:00 | Caused by: java.io.IOException: Could not locate
data file /usr/share/activemq/data/kahadb/db-4311.log
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.kahadb.journal.Journal.getDataFile(Journal.java:345)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.kahadb.journal.Journal.read(Journal.java:592)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:786)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:956)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$5.execute(KahaDBStore.java:494)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.kahadb.page.Transaction.execute(Transaction.java:728)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:4
85)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:88)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:262)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       ... 10 more
{noformat}




      was (Author: redvortex):
    Hello,

We're experiencing the very same issue and I'm also running ActiveMQ 5.4.2. We also have a
high quantity of messages, at least 30,000 messages per hours sometimes much more (2x, 3x)
than that. We have a mix of very large (fews megs) and very small (few bytes) messages.

What happens: a kaha db missing log (probably deleted too early by kahadb or something else)
then messages start accumulating and my consumers are unable to dequeue them.

This issue is really major, if not blocker. This is new since we upgraded to 5.4.2, we never
had this problem before with version 5.3.x. I'm unable to reproduce it and it happens randomly,
under heavy load or not.

I found a temporary work around by adding this parameter to the kahadb config, restarting
the broker, wait until all the queued messages are consumed, then removing the parameter and
restarting the broker again.

{noformat}
<persistenceAdapter>
            <kahaDB directory="${activemq.base}/data/kahadb" ignoreMissingJournalfiles="true"/>
</persistenceAdapter>
{noformat}

When you restart the broker with this configuration you will see this and the normal processing
continues:

{noformat}
INFO   | jvm 1    | 2011/01/20 10:05:20 |  INFO | KahaDB is version 3
INFO   | jvm 1    | 2011/01/20 10:05:20 |  INFO | Recovering from the journal ...
INFO   | jvm 1    | 2011/01/20 10:05:20 |  INFO | Recovery replayed 1 operations from the
journal in 0.045 seconds.
INFO   | jvm 1    | 2011/01/20 10:05:20 |  INFO | Some journal files are missing: [4311]
INFO   | jvm 1    | 2011/01/20 10:05:20 |  INFO | Detected missing/corrupt journal files.
 Dropped 1 messages from the index in 0.028 seconds.
{noformat}

This workaround allows me to at least not lose all the DB like I had to do until today (delete
the kahadb folder and restart).

Here is what starts showing over and over again in the wrapper.log when the issue appears:

{noformat}
INFO   | jvm 1    | 2011/01/20 07:31:00 | ERROR | Looking for key 4311 but not found in fileMap:
{3944=db-3944.log number = 3944 , length = 33760316, 406
7=db-4067.log number = 4067 , length = 33590177, 3947=db-3947.log number = 3947 , length =
33677680, 3948=db-3948.log number = 3948 , length = 33596726, 
4068=db-4068.log number = 4068 , length = 33755827, 4075=db-4075.log number = 4075 , length
= 34048968, 4322=db-4322.log number = 4322 , length = 3004262
2, 4076=db-4076.log number = 4076 , length = 33734622, 4320=db-4320.log number = 4320 , length
= 33622170, 4321=db-4321.log number = 4321 , length = 3360
7934, 3943=db-3943.log number = 3943 , length = 33897766, 3961=db-3961.log number = 3961 ,
length = 33715187, 3960=db-3960.log number = 3960 , length = 3
3634841, 4021=db-4021.log number = 4021 , length = 33584217, 4022=db-4022.log number = 4022
, length = 33569989, 4090=db-4090.log number = 4090 , length 
= 33555654, 3955=db-3955.log number = 3955 , length = 33566643, 4030=db-4030.log number =
4030 , length = 33700887, 4091=db-4091.log number = 4091 , leng
th = 33928309, 4031=db-4031.log number = 4031 , length = 33554494, 3889=db-3889.log number
= 3889 , length = 33664097, 3956=db-3956.log number = 3956 , l
ength = 33621892, 3890=db-3890.log number = 3890 , length = 33590196, 4035=db-4035.log number
= 4035 , length = 33653742, 4034=db-4034.log number = 4034 
, length = 33852330, 3912=db-3912.log number = 3912 , length = 33554464, 3913=db-3913.log
number = 3913 , length = 33587386, 4101=db-4101.log number = 41
01 , length = 34013592, 4039=db-4039.log number = 4039 , length = 34009512, 4100=db-4100.log
number = 4100 , length = 33576394, 4038=db-4038.log number =
 4038 , length = 33564352, 4102=db-4102.log number = 4102 , length = 33630267, 3908=db-3908.log
number = 3908 , length = 33660034, 3909=db-3909.log numbe
r = 3909 , length = 33570972, 4317=db-4317.log number = 4317 , length = 33554634, 4316=db-4316.log
number = 4316 , length = 33554832, 4319=db-4319.log nu
mber = 4319 , length = 33560765, 3929=db-3929.log number = 3929 , length = 33773224, 4318=db-4318.log
number = 4318 , length = 33606627, 3928=db-3928.log
 number = 3928 , length = 33575213, 4313=db-4313.log number = 4313 , length = 33666992, 3935=db-3935.log
number = 3935 , length = 33716752, 4312=db-4312.
log number = 4312 , length = 33554827, 3934=db-3934.log number = 3934 , length = 33584253,
4315=db-4315.log number = 4315 , length = 33633620, 4314=db-43
14.log number = 4314 , length = 33676339}
INFO   | jvm 1    | 2011/01/20 07:31:00 | ERROR | Failed to fill batch
INFO   | jvm 1    | 2011/01/20 07:31:00 | java.io.IOException: Could not locate data file
/usr/share/activemq/data/kahadb/db-4311.log
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.kahadb.journal.Journal.getDataFile(Journal.java:345)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.kahadb.journal.Journal.read(Journal.java:592)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:786)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:956)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$5.execute(KahaDBStore.java:494)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.kahadb.page.Transaction.execute(Transaction.java:728)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:4
85)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:88)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:262)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:110)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1678)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1898)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1425)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at java.lang.Thread.run(Thread.java:619)
INFO   | jvm 1    | 2011/01/20 07:31:00 | ERROR | Failed to fill batch
INFO   | jvm 1    | 2011/01/20 07:31:00 | java.lang.RuntimeException: java.io.IOException:
Could not locate data file /usr/share/activemq/data/kahadb/db-
4311.log
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:265)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:110)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1678)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1898)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1425)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at java.lang.Thread.run(Thread.java:619)
INFO   | jvm 1    | 2011/01/20 07:31:00 | Caused by: java.io.IOException: Could not locate
data file /usr/share/activemq/data/kahadb/db-4311.log
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.kahadb.journal.Journal.getDataFile(Journal.java:345)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.kahadb.journal.Journal.read(Journal.java:592)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:786)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:956)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$5.execute(KahaDBStore.java:494)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.kahadb.page.Transaction.execute(Transaction.java:728)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:4
85)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:88)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:262)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       ... 10 more
INFO   | jvm 1    | 2011/01/20 07:31:00 | ERROR | Failed to page in more queue messages 
INFO   | jvm 1    | 2011/01/20 07:31:00 | java.lang.RuntimeException: java.lang.RuntimeException:
java.io.IOException: Could not locate data file /usr/sh
are/activemq/data/kahadb/db-4311.log
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:113)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1678)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1898)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1425)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at java.lang.Thread.run(Thread.java:619)
INFO   | jvm 1    | 2011/01/20 07:31:00 | Caused by: java.lang.RuntimeException: java.io.IOException:
Could not locate data file /usr/share/activemq/data
/kahadb/db-4311.log
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:265)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:110)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       ... 9 more
INFO   | jvm 1    | 2011/01/20 07:31:00 | Caused by: java.io.IOException: Could not locate
data file /usr/share/activemq/data/kahadb/db-4311.log
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.kahadb.journal.Journal.getDataFile(Journal.java:345)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.kahadb.journal.Journal.read(Journal.java:592)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:786)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:956)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$5.execute(KahaDBStore.java:494)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.kahadb.page.Transaction.execute(Transaction.java:728)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:4
85)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:88)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:262)
INFO   | jvm 1    | 2011/01/20 07:31:00 |       ... 10 more
{noformat}



  
> KahaDB error: "Could not locate data file"
> ------------------------------------------
>
>                 Key: AMQ-3120
>                 URL: https://issues.apache.org/jira/browse/AMQ-3120
>             Project: ActiveMQ
>          Issue Type: Bug
>          Components: Broker
>    Affects Versions: 5.4.2
>         Environment: linux: CentOS 5.5
> happens on both dual- and quad-cpu boxes, 4gb ram
> java version "1.6.0_21"
> Java(TM) SE Runtime Environment (build 1.6.0_21-b06)
> Java HotSpot(TM) 64-Bit Server VM (build 17.0-b16, mixed mode)
>            Reporter: Dan Checkoway
>
> I'm using an embedded broker (version 5.4.2) with persistence enabled.  We're pumping
hundreds of millions of messages per day through this thing.  Every once in a while, all of
a sudden the KahaDB directory starts growing uncontrollably, and these errors start spewing
out in the log over and over...
> --------------------------
> ERROR; Jan 5, 2011 16:37:57 PM; tid:BrokerService[localhost] Task; AbstractStoreCursor
- Failed to fill batch
> java.lang.RuntimeException: java.io.IOException: Could not locate data file /usr/local/embedded/activemq-data/localhost/KahaDB/db-28098.log
>         at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:265)
>         at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.hasNext(AbstractStoreCursor.java:148)
>         at org.apache.activemq.broker.region.cursors.StoreQueueCursor.hasNext(StoreQueueCursor.java:131)
>         at org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1679)
>         at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1898)
>         at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1425)
>         at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)
>         at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
>         at java.lang.Thread.run(Thread.java:619)
> Caused by: java.io.IOException: Could not locate data file /usr/local/embedded/activemq-data/localhost/KahaDB/db-28098.log
>         at org.apache.kahadb.journal.Journal.getDataFile(Journal.java:345)
>         at org.apache.kahadb.journal.Journal.read(Journal.java:592)
>         at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:786)
>         at org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:956)
>         at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$5.execute(KahaDBStore.java:494)
>         at org.apache.kahadb.page.Transaction.execute(Transaction.java:728)
>         at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:485)
>         at org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:88)
>         at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
>         at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:262)
>         ... 10 more
> ERROR; Jan 5, 2011 16:37:57 PM; tid:BrokerService[localhost] Task; Queue - Failed to
page in more queue messages
> java.lang.RuntimeException: java.lang.RuntimeException: java.io.IOException: Could not
locate data file /usr/local/embedded/activemq-data/localhost/KahaDB/db-28098.log
>         at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.hasNext(AbstractStoreCursor.java:151)
>         at org.apache.activemq.broker.region.cursors.StoreQueueCursor.hasNext(StoreQueueCursor.java:131)
>         at org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1679)
>         at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1898)
>         at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1425)
>         at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)
>         at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
>         at java.lang.Thread.run(Thread.java:619)
> Caused by: java.lang.RuntimeException: java.io.IOException: Could not locate data file
/usr/local/embedded/activemq-data/localhost/KahaDB/db-28098.log
>         at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:265)
>         at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.hasNext(AbstractStoreCursor.java:148)
>         ... 9 more
> Caused by: java.io.IOException: Could not locate data file /usr/local/embedded/activemq-data/localhost/KahaDB/db-28098.log
>         at org.apache.kahadb.journal.Journal.getDataFile(Journal.java:345)
>         at org.apache.kahadb.journal.Journal.read(Journal.java:592)
>         at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:786)
>         at org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:956)
>         at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$5.execute(KahaDBStore.java:494)
>         at org.apache.kahadb.page.Transaction.execute(Transaction.java:728)
>         at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:485)
>         at org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:88)
>         at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
>         at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:262)
>         ... 10 more
> --------------------------
> It doesn't happen consistently, but it has happened numerous times.  The only way to
"fix" it is to kill the app, blow away the KahaDB data directory, and restart (ugh).
> Unfortunately this issue is not reproduceable.
> Here's the embedded broker config, fwiw:
> --------------------------
>   <broker xmlns="http://activemq.apache.org/schema/core"
>           id="embeddedActivemqBroker"
>           useJmx="false"
>           persistent="true"
>           dataDirectory="/usr/local/embedded/activemq-data"
>           schedulerSupport="false"
>           advisorySupport="false"
>           enableStatistics="true">
>     <destinationPolicy>
>       <policyMap>
>         <policyEntries>
>           <policyEntry queue=">" producerFlowControl="false" memoryLimit="20mb"/>
>         </policyEntries>
>       </policyMap>
>     </destinationPolicy>
>   </broker>
> -------------------------- 

-- 
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.


Mime
View raw message