activemq-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From immilev <i.mi...@gmail.com>
Subject Re: [jira] Updated: (AMQ-2512) "Failed to page in more queue messages"
Date Sat, 02 Jan 2010 21:37:27 GMT

"> Following exception occurs quite often at the moment when cursor percent
usage is over 100% and suddenly drops down below 100%..."

The same exception is thrown by ActiveMQ 5.3.0 using the KahaDB store for
persistent queues. The MaxPageSize is set to 20,000. In this case, it occurs
when the count of messages to be paged in gets up to 37K.  Both
CursorPercentUsage and MemoryPercentUsage in our case is around 10-15%, so
it does not seem related to cursor percent usage near 100%

2010-01-02 20:57:49,440 | DEBUG | outputQueue toPageIn: 2, Inflight: 17,
pagedInMessages.size 38738 | org.apache.activemq.broker.region
.Queue | QueueThread:queue://outputQueue
2010-01-02 20:57:49,440 | ERROR | Failed to page in more queue messages  |
org.apache.activemq.broker.region.Queue | QueueThread:queue://outputQueue
java.lang.NullPointerException
        at org.apache.kahadb.index.BTreeIndex.loadNode(BTreeIndex.java:260)
        at
org.apache.kahadb.index.BTreeNode$BTreeIterator.findNextPage(BTreeNode.java:103)
        at
org.apache.kahadb.index.BTreeNode$BTreeIterator.hasNext(BTreeNode.java:120)
        at
org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$2.execute(KahaDBStore.java:194)
        at
org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$2.execute(KahaDBStore.java:190)
        at org.apache.kahadb.page.Transaction.execute(Transaction.java:751)
        at
org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.getMessageCount(KahaDBStore.java:189)
        at
org.apache.activemq.broker.region.cursors.QueueStorePrefetch.getStoreSize(QueueStorePrefetch.java:63)
        at
org.apache.activemq.broker.region.cursors.AbstractStoreCursor.remove(AbstractStoreCursor.java:185)
        at
org.apache.activemq.broker.region.cursors.StoreQueueCursor.remove(StoreQueueCursor.java:141)
        at org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1367)
        at
org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1503)
        at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1178)
        at
org.apache.activemq.thread.DeterministicTaskRunner.runTask(DeterministicTaskRunner.java:84)
        at
org.apache.activemq.thread.DeterministicTaskRunner$1.run(DeterministicTaskRunner.java:41)
        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)

Cheers!

Ivaylo


JIRA jira@apache.org wrote:
> 
> 
>      [
> https://issues.apache.org/activemq/browse/AMQ-2512?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
> ]
> 
> Dariusz Szablinski updated AMQ-2512:
> ------------------------------------
> 
>     Attachment: jconsole.jpg
> 
>> "Failed to page in more queue messages"
>> ---------------------------------------
>>
>>                 Key: AMQ-2512
>>                 URL: https://issues.apache.org/activemq/browse/AMQ-2512
>>             Project: ActiveMQ
>>          Issue Type: Bug
>>    Affects Versions: 5.3.1
>>            Reporter: Dariusz Szablinski
>>             Fix For: 5.3.1, 5.4.0
>>
>>         Attachments: jconsole.jpg
>>
>>
>> Following exception occurs quite often at the moment when cursor percent
>> usage is over 100% and suddenly drops down below 100%:
>> 2009-11-25 21:16:00,287 | INFO  | Slow KahaDB access: cleanup took 547 |
>> org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal
>> Checkpoint Worker
>> 2009-11-25 21:16:27,832 | INFO  | Slow KahaDB access: Journal append
>> took: 0 ms, Index update took 891 ms |
>> org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Transport:
>> tcp:///192.168.1.4:57697
>> 2009-11-25 21:16:30,324 | INFO  | Slow KahaDB access: Journal append
>> took: 0 ms, Index update took 1172 ms |
>> org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Transport:
>> tcp:///192.168.1.4:57697
>> 2009-11-25 21:16:31,283 | ERROR | Failed to page in more queue messages 
>> | org.apache.activemq.broker.region.Queue | Queue:dee.q
>> java.lang.NullPointerException
>> 	at org.apache.kahadb.index.BTreeIndex.loadNode(BTreeIndex.java:260)
>> 	at
>> org.apache.kahadb.index.BTreeNode$BTreeIterator.findNextPage(BTreeNode.java:103)
>> 	at
>> org.apache.kahadb.index.BTreeNode$BTreeIterator.hasNext(BTreeNode.java:120)
>> 	at
>> org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$2.execute(KahaDBStore.java:194)
>> 	at
>> org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$2.execute(KahaDBStore.java:190)
>> 	at org.apache.kahadb.page.Transaction.execute(Transaction.java:751)
>> 	at
>> org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.getMessageCount(KahaDBStore.java:189)
>> 	at
>> org.apache.activemq.broker.region.cursors.QueueStorePrefetch.getStoreSize(QueueStorePrefetch.java:63)
>> 	at
>> org.apache.activemq.broker.region.cursors.AbstractStoreCursor.remove(AbstractStoreCursor.java:189)
>> 	at
>> org.apache.activemq.broker.region.cursors.StoreQueueCursor.remove(StoreQueueCursor.java:141)
>> 	at org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1370)
>> 	at
>> org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1505)
>> 	at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1176)
>> 	at
>> org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:98)
>> 	at
>> org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:36)
>> Additional side effect is that broker stops dispatching messages out of
>> the queue (see queue size and consumer count on screenshot from jconsole)
>> Sometimes this exception is also followed by:
>> 2009-11-25 20:45:00,783 | WARN  | Async error occurred:
>> java.lang.ClassCastException: java.lang.String cannot be cast to
>> org.apache.kahadb.journal.Location |
>> org.apache.activemq.broker.TransportConnection.Service | ActiveMQ
>> Transport: tcp:///192.168.1.4:57516
>> java.lang.ClassCastException: java.lang.String cannot be cast to
>> org.apache.kahadb.journal.Location
>> 	at org.apache.kahadb.journal.Location.compareTo(Location.java:29)
>> 	at java.util.Arrays.binarySearch0(Arrays.java:2001)
>> 	at java.util.Arrays.binarySearch(Arrays.java:1943)
>> 	at org.apache.kahadb.index.BTreeNode.remove(BTreeNode.java:234)
>> 	at org.apache.kahadb.index.BTreeNode.remove(BTreeNode.java:240)
>> 	at org.apache.kahadb.index.BTreeNode.remove(BTreeNode.java:240)
>> 	at org.apache.kahadb.index.BTreeIndex.remove(BTreeIndex.java:194)
>> 	at
>> org.apache.activemq.store.kahadb.MessageDatabase.updateIndex(MessageDatabase.java:873)
>> 	at
>> org.apache.activemq.store.kahadb.MessageDatabase.access$700(MessageDatabase.java:82)
>> 	at
>> org.apache.activemq.store.kahadb.MessageDatabase$13.execute(MessageDatabase.java:757)
>> 	at org.apache.kahadb.page.Transaction.execute(Transaction.java:728)
>> 	at
>> org.apache.activemq.store.kahadb.MessageDatabase.process(MessageDatabase.java:755)
>> 	at
>> org.apache.activemq.store.kahadb.MessageDatabase$11.visit(MessageDatabase.java:700)
>> 	at
>> org.apache.activemq.store.kahadb.data.KahaRemoveMessageCommand.visit(KahaRemoveMessageCommand.java:220)
>> 	at
>> org.apache.activemq.store.kahadb.MessageDatabase.process(MessageDatabase.java:692)
>> 	at
>> org.apache.activemq.store.kahadb.MessageDatabase.store(MessageDatabase.java:644)
>> 	at
>> org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.removeMessage(KahaDBStore.java:153)
>> 	at org.apache.activemq.broker.region.Queue.acknowledge(Queue.java:602)
>> 	at
>> org.apache.activemq.broker.region.Queue.removeMessage(Queue.java:1235)
>> 	at
>> org.apache.activemq.broker.region.QueueSubscription.acknowledge(QueueSubscription.java:60)
>> 	at
>> org.apache.activemq.broker.region.PrefetchSubscription.acknowledge(PrefetchSubscription.java:250)
>> 	at
>> org.apache.activemq.broker.region.AbstractRegion.acknowledge(AbstractRegion.java:369)
>> 	at
>> org.apache.activemq.broker.region.RegionBroker.acknowledge(RegionBroker.java:470)
>> 	at
>> org.apache.activemq.broker.TransactionBroker.acknowledge(TransactionBroker.java:194)
>> 	at
>> org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:74)
>> 	at
>> org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:74)
>> 	at
>> org.apache.activemq.broker.MutableBrokerFilter.acknowledge(MutableBrokerFilter.java:85)
>> 	at
>> org.apache.activemq.broker.TransportConnection.processMessageAck(TransportConnection.java:449)
>> 	at org.apache.activemq.command.MessageAck.visit(MessageAck.java:205)
>> 	at
>> org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:297)
>> 	at
>> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:175)
>> 	at
>> org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:68)
>> 	at
>> org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)
>> 	at
>> org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:210)
>> 	at
>> org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:84)
>> 	at
>> org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:203)
>> 	at
>> org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:185)
>> 	at java.lang.Thread.run(Thread.java:619)
>> I'm using latest 5.3.1-SNAPSHOT
> 
> -- 
> This message is automatically generated by JIRA.
> -
> You can reply to this email to add a comment to the issue online.
> 
> 
> 

-- 
View this message in context: http://old.nabble.com/-jira--Created%3A-%28AMQ-2512%29-%22Failed-to-page-in-more-queue-messages%22-tp26519757p26996701.html
Sent from the ActiveMQ - Dev mailing list archive at Nabble.com.


Mime
View raw message