activemq-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Roelof Naude (JIRA)" <j...@apache.org>
Subject [jira] Commented: (AMQ-2962) Hanging at startup
Date Fri, 15 Oct 2010 13:38:41 GMT

    [ https://issues.apache.org/activemq/browse/AMQ-2962?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=62612#action_62612
] 

Roelof Naude commented on AMQ-2962:
-----------------------------------

i've found something of interest. the write lock hangs are due to the read lock being taken.
i also added LOG.debug statement before each lock and after each unlock in KahaDBStore.java
as well as those places in MessageDatabase.java as indicated in the attached thread dumps.

2010-10-15 15:27:16,082 INFO  [org.apache.activemq.store.kahadb.MessageDatabase] KahaDB is
version 2
2010-10-15 15:27:16,172 INFO  [org.apache.activemq.store.kahadb.MessageDatabase] Recovering
from the journal ...
2010-10-15 15:27:16,180 DEBUG [org.apache.activemq.store.kahadb.MessageDatabase] process remove
- lock[java.util.concurrent.locks.ReentrantReadWriteLock@30de3c87[Write locks = 2, Read locks
= 0]]
2010-10-15 15:27:16,183 DEBUG [org.apache.activemq.store.kahadb.MessageDatabase] process remove
- unlock[java.util.concurrent.locks.ReentrantReadWriteLock@30de3c87[Write locks = 2, Read
locks = 0]]
2010-10-15 15:27:16,183 INFO  [org.apache.activemq.store.kahadb.MessageDatabase] Recovery
replayed 3 operations from the journal in 0.081 seconds.
2010-10-15 15:27:16,198 INFO  [org.apache.activemq.broker.BrokerService] ActiveMQ 5.4.1 JMS
Message Broker (localhost) is starting
2010-10-15 15:27:16,200 INFO  [org.apache.activemq.broker.BrokerService] For help or more
information please see: http://activemq.apache.org/
2010-10-15 15:27:16,358 DEBUG [org.apache.activemq.store.kahadb.KahaDBStore] getDestinations
- lock[java.util.concurrent.locks.ReentrantReadWriteLock@30de3c87[Write locks = 0, Read locks
= 0]]
2010-10-15 15:27:16,360 DEBUG [org.apache.activemq.store.kahadb.KahaDBStore] getDestinations
- unlock[java.util.concurrent.locks.ReentrantReadWriteLock@30de3c87[Write locks = 0, Read
locks = 0]]
2010-10-15 15:27:16,362 DEBUG [org.apache.activemq.broker.region.AbstractRegion] localhost
adding destination: queue://Consumer.superuser.VirtualTopic.ALARM
2010-10-15 15:27:16,394 DEBUG [org.apache.activemq.store.kahadb.KahaDBStore] getMessageCount
- lock[java.util.concurrent.locks.ReentrantReadWriteLock@30de3c87[Write locks = 0, Read locks
= 0]]
2010-10-15 15:27:16,395 DEBUG [org.apache.activemq.store.kahadb.KahaDBStore] getMessageCount
- unlock[java.util.concurrent.locks.ReentrantReadWriteLock@30de3c87[Write locks = 0, Read
locks = 0]]
2010-10-15 15:27:16,395 DEBUG [org.apache.activemq.store.kahadb.KahaDBStore] recover - lock[java.util.concurrent.locks.ReentrantReadWriteLock@30de3c87[Write
locks = 0, Read locks = 0]]
2010-10-15 15:27:16,421 DEBUG [org.apache.activemq.broker.region.Queue] message expired: Message
ID:segfault-43426-1287148162735-2:8:1:1:1 dropped=false acked=false locked=false
2010-10-15 15:27:16,421 DEBUG [org.apache.activemq.broker.region.RegionBroker] Message expired
Message ID:segfault-43426-1287148162735-2:8:1:1:1 dropped=false acked=false locked=false
2010-10-15 15:27:16,425 DEBUG [org.apache.activemq.broker.region.AbstractRegion] localhost
adding destination: topic://ActiveMQ.Advisory.MessageDLQd.Topic.VirtualTopic.ALARM
2010-10-15 15:27:16,448 DEBUG [org.apache.activemq.broker.region.AbstractRegion] localhost
adding destination: topic://ActiveMQ.Advisory.Expired.Topic.VirtualTopic.ALARM
2010-10-15 15:27:16,464 DEBUG [org.apache.activemq.store.kahadb.MessageDatabase] process remove
- lock[java.util.concurrent.locks.ReentrantReadWriteLock@30de3c87[Write locks = 0, Read locks
= 1]]

take note of:
1. recover - lock (no unlock is printed)
2. MessageDatabase] process remove

(1) takes a read lock in KahaDBStore::recover. when (2) MessageDatabase::process (final KahaRemoveMessageCommand)
comes along it blocks. ditto for MessageDatabase::checkpointCleanup

i guess the next step would be to figure out why KahaDBStore::recover is not releasing the
lock?

> Hanging at startup
> ------------------
>
>                 Key: AMQ-2962
>                 URL: https://issues.apache.org/activemq/browse/AMQ-2962
>             Project: ActiveMQ
>          Issue Type: Bug
>          Components: Message Store
>    Affects Versions: 5.4.1
>         Environment: Fedora Core 12
>            Reporter: Roelof Naude
>            Priority: Minor
>         Attachments: amq.ra.threads.txt, debug_traces_hanging.log, debug_traces_startup.log,
thread_dump_during_hang.txt
>
>
> Noticed today the activemq was hanging during startup. Investigation revealed that it
is tied to expiration of messages at startup. The only way to recover from this was to kill
-9 the VM and delete the kahadb message store.
> Further testing was done whereby message expiry time was set to longer period. AMQ started
up just fine. Another test was performed whereby:
> 1. subscribe for messages
> 2. send a few messages
> 3. disconnect consumer
> 4. send more messages (1 or 2 will do)
> 5. shutdown AMQ
> 6. wait for a time period exceeded the expiration time of the messages
> 7. start AMQ. at this time it should be hanging
> Logs and thread dumps attached.

-- 
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