Uploaded image for project: 'FUSE Message Broker'
  1. FUSE Message Broker
  2. MB-558

JMS clients stalled in case of many messages on a different queue.

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Major
    • Resolution: Done
    • Affects Version/s: 5.0.0.27-fuse, 5.3.0.4-fuse
    • Fix Version/s: 5.3.0.5-fuse
    • Component/s: broker
    • Labels:
      None

      Description

      Consider the following scenario: a queue Q has 2 million messages that are all persistet into the JDBC db. Another producer/consumer pair connects to a different queue X but does not get to produce/consume any messages.

      Because of having two million msgs on one queue, the periodically run clean up task takes ages to complete (for me >20 mins) but locks the entire database during that time as it runs an SQL delete statement:

      DEBUG DefaultJDBCAdapter - Executing SQL: DELETE FROM ACTIVEMQ_MSGS WHERE ( EXPIRATION<>0 AND EXPIRATION<?)
      OR ID <= ( SELECT min(ACTIVEMQ_ACKS.LAST_ACKED_ID) FROM ACTIVEMQ_ACKS WHERE 
      ACTIVEMQ_ACKS.CONTAINER=ACTIVEMQ_MSGS.CONTAINER)
      

      During that time no other message (no matter for what queue) can be processed.
      Also, the cleanup task is scheduled to run every 2-3 mins, so once it has completed to run over the 2 million messages (>20 mins) it is already late on schedule, hence it gets kicked off again straight away, not leaving much processing time for other threads to insert msgs into the db. So the threads managing the other queues starve and might perhaps never get the processing time to process their messages.

      In order to diagnose this further I suggest to enable this logging:

      log4j.logger.org.apache.activemq.store.jdbc=DEBUG
      

      This should show the above SQL statement being executed for a long time and being called repeatedly as soon as it has finished.
      Also, I suggest to attach jconsole to the broker and take a stack trace of the thread that manages the queue X and has a producer/consumer pair attached. It should be waiting almost forever in the following stack trace:

      Name: QueueThread:queue://JMSLoadTest.queue.0
        State: RUNNABLE
        Total blocked: 1  Total waited: 0
      
        Stack trace: 
        java.net.SocketInputStream.socketRead0(Native Method)
        java.net.SocketInputStream.read(SocketInputStream.java:129)
        com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:113)
        com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160)
        com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188)
        com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2428)
        com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2882)
        com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2871)
        com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3414)
        com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1936)
        com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2060)
        com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2542)
        com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1734)
        com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1876)
        org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:91)
        org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:91)
        org.apache.activemq.store.jdbc.adapter.DefaultJDBCAdapter.doRecoverNextMessages(DefaultJDBCAdapter.java:709)
        org.apache.activemq.store.jdbc.JDBCMessageStore.recoverNextMessages(JDBCMessageStore.java:230)
        org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:83)
        org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:75)
        org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:210)
        org.apache.activemq.broker.region.cursors.AbstractStoreCursor.hasNext(AbstractStoreCursor.java:119)
        org.apache.activemq.broker.region.cursors.StoreQueueCursor.hasNext(StoreQueueCursor.java:131)
        org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1243)
        org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1378)
        org.apache.activemq.broker.region.Queue.iterate(Queue.java:1086)
        org.apache.activemq.thread.DeterministicTaskRunner.runTask(DeterministicTaskRunner.java:84)
        org.apache.activemq.thread.DeterministicTaskRunner$1.run(DeterministicTaskRunner.java:41)
        java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
        java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
        java.lang.Thread.run(Thread.java:595)
      

        Gliffy Diagrams

          Attachments

            Activity

              People

              • Assignee:
                garytully Gary Tully
                Reporter:
                mielket Torsten Mielke
              • Votes:
                0 Vote for this issue
                Watchers:
                3 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: