Qpid
  1. Qpid
  2. QPID-4515

Java Broker: improve logging, especially for diagnosis of transactional messaging performance

    Details

    • Type: Improvement Improvement
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: 0.20
    • Fix Version/s: 0.21
    • Component/s: Java Broker
    • Labels:
      None

      Description

      I've recently been involved in a number of support issues where we were diagnosing performance problems.

      We were trying to find out at which point in the message flow a delay was occurring, and identified a number of areas where debug logging should be added or improved to facilitate this.

      We particularly want to track:

      1. The points when frames are received and sent by the broker, including in AMQP 0-8/0-9/0-9-1 environments.
      2. How long BDB commits are taking.
      3. How long post-commit actions are taking

        Activity

        Hide
        Philip Harvey added a comment - - edited

        Committed changes. Some examples of the new logging for an AMQP 0-9-1 session are pasted below. Please can you review.

        Note that frame receipt/dispatch is now logged using the same "RECV" and "SEND" keywords as for AMQP 0-10 sessions, for the sake of consistency.

        2012-12-20 09:54:29,994 DEBUG [IoReceiver - /127.0.0.1:44157] (AMQProtocolEngine.java:312) - RECV: Frame channelId: 1, bodyFrame: [TxCommitBodyImpl: ]
        ...
        ...
        2012-12-20 09:54:29,997 DEBUG [IoReceiver - /127.0.0.1:44157] (AMQProtocolEngine.java:350) - Frame handled in 3 ms. Frame: Frame channelId: 1, bodyFrame: [Tx
        CommitBodyImpl: ]
        2012-12-20 09:54:29,997 DEBUG [IoReceiver - /127.0.0.1:44157] (AMQChannel.java:1588) - sync() called on channel 1(479724676)
        2012-12-20 09:54:30,211 DEBUG [Commit-Thread-test] (CommitThreadWrapper.java:227) - flushLog completed in 214 ms
        2012-12-20 09:54:30,212 DEBUG [IoReceiver - /127.0.0.1:44157] (CommitThreadWrapper.java:149) - waitForCompletion returning after 215 ms for transaction <Tran
        saction id="23">
        2012-12-20 09:54:30,212 DEBUG [IoReceiver - /127.0.0.1:44157] (LocalTransaction.java:389) - Beginning 2 post transaction actions
        2012-12-20 09:54:30,214 DEBUG [IoReceiver - /127.0.0.1:44157] (LocalTransaction.java:399) - Completed post transaction actions
        2012-12-20 09:54:30,214 DEBUG [IoReceiver - /127.0.0.1:44157] (AMQProtocolEngine.java:558) - SEND: Frame channelId: 1, bodyFrame: [TxCommitOkBodyImpl: ]
        ...
        ...
        2012-12-20 10:05:25,936 DEBUG [pool-3-thread-4] (AMQProtocolEngine.java:558) - SEND: [CompositeAMQBodyBlock methodBody=[EncodedDeliveryBody underlyingBody: [
        BasicDeliverBodyImpl: consumerTag=1, deliveryTag=1, redelivered=false, exchange=amq.direct, routingKey=queue1]], headerBody=ContentHeaderBody{classId=60, wei
        ght=0, bodySize=40, properties=reply-to = null,propertyFlags = 47568,ApplicationID = null,ClusterID = null,UserId = guest,JMSMessageID = ID:527719f8-383f-36e
        6-a4b1-6f68adb27d25,JMSCorrelationID = null,JMSDeliveryMode = 2,JMSExpiration = 0,JMSPriority = 4,JMSTimestamp = 1355997256727,JMSType = null}, contentBody=o
        rg.apache.qpid.server.output.ProtocolOutputConverterImpl$MessageContentSourceBody@9ffdf86, channel=1]
        
        Show
        Philip Harvey added a comment - - edited Committed changes. Some examples of the new logging for an AMQP 0-9-1 session are pasted below. Please can you review. Note that frame receipt/dispatch is now logged using the same "RECV" and "SEND" keywords as for AMQP 0-10 sessions, for the sake of consistency. 2012-12-20 09:54:29,994 DEBUG [IoReceiver - /127.0.0.1:44157] (AMQProtocolEngine.java:312) - RECV: Frame channelId: 1, bodyFrame: [TxCommitBodyImpl: ] ... ... 2012-12-20 09:54:29,997 DEBUG [IoReceiver - /127.0.0.1:44157] (AMQProtocolEngine.java:350) - Frame handled in 3 ms. Frame: Frame channelId: 1, bodyFrame: [Tx CommitBodyImpl: ] 2012-12-20 09:54:29,997 DEBUG [IoReceiver - /127.0.0.1:44157] (AMQChannel.java:1588) - sync() called on channel 1(479724676) 2012-12-20 09:54:30,211 DEBUG [Commit-Thread-test] (CommitThreadWrapper.java:227) - flushLog completed in 214 ms 2012-12-20 09:54:30,212 DEBUG [IoReceiver - /127.0.0.1:44157] (CommitThreadWrapper.java:149) - waitForCompletion returning after 215 ms for transaction <Tran saction id="23"> 2012-12-20 09:54:30,212 DEBUG [IoReceiver - /127.0.0.1:44157] (LocalTransaction.java:389) - Beginning 2 post transaction actions 2012-12-20 09:54:30,214 DEBUG [IoReceiver - /127.0.0.1:44157] (LocalTransaction.java:399) - Completed post transaction actions 2012-12-20 09:54:30,214 DEBUG [IoReceiver - /127.0.0.1:44157] (AMQProtocolEngine.java:558) - SEND: Frame channelId: 1, bodyFrame: [TxCommitOkBodyImpl: ] ... ... 2012-12-20 10:05:25,936 DEBUG [pool-3-thread-4] (AMQProtocolEngine.java:558) - SEND: [CompositeAMQBodyBlock methodBody=[EncodedDeliveryBody underlyingBody: [ BasicDeliverBodyImpl: consumerTag=1, deliveryTag=1, redelivered=false, exchange=amq.direct, routingKey=queue1]], headerBody=ContentHeaderBody{classId=60, wei ght=0, bodySize=40, properties=reply-to = null,propertyFlags = 47568,ApplicationID = null,ClusterID = null,UserId = guest,JMSMessageID = ID:527719f8-383f-36e 6-a4b1-6f68adb27d25,JMSCorrelationID = null,JMSDeliveryMode = 2,JMSExpiration = 0,JMSPriority = 4,JMSTimestamp = 1355997256727,JMSType = null}, contentBody=o rg.apache.qpid.server.output.ProtocolOutputConverterImpl$MessageContentSourceBody@9ffdf86, channel=1]
        Hide
        Keith Wall added a comment -

        Patch review, no comments from me.

        Show
        Keith Wall added a comment - Patch review, no comments from me.

          People

          • Assignee:
            Keith Wall
            Reporter:
            Philip Harvey
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development