Details

    • Type: Improvement Improvement
    • Status: Resolved
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: 0.14
    • Fix Version/s: 0.17
    • Component/s: Java Client
    • Labels:
      None

      Description

      Kevin Conner provided a patch to improve our logging.
      For the most part it reduces noise by downgrading most log messages from info to debug.
      It also adds a if(logger.isDebugEnabled()) to save on any unnecessary (and potentially expensive) string concatenations.

      1. logging.patch
        20 kB
        Rajith Attapattu
      2. logging.patch
        20 kB
        Kevin Conner

        Activity

        Hide
        Rajith Attapattu added a comment -

        Patch applied to trunk.

        Show
        Rajith Attapattu added a comment - Patch applied to trunk.
        Hide
        Rajith Attapattu added a comment -

        Yes Weston also confirmed the same.
        Just wanted to confirm the test was doing this as opposed to multiple producers being created under the hood due to a bug in our JCA code.

        Show
        Rajith Attapattu added a comment - Yes Weston also confirmed the same. Just wanted to confirm the test was doing this as opposed to multiple producers being created under the hood due to a bug in our JCA code.
        Hide
        Kevin Conner added a comment -

        There were 10000 (plus a few) producers created by the test.

        Show
        Kevin Conner added a comment - There were 10000 (plus a few) producers created by the test.
        Hide
        Rajith Attapattu added a comment -

        "The only one which really showed up, related to performance, was
        MessageProducer org.apache.qpid.client.BasicMessageProducer_0_10@658eeb10 using publish mode : ASYNC_PUBLISH_ALL

        For example one of the performance tests had over 10000 entries in our log files."

        This log message is *only* printed when we create a producer instance.
        So I wonder why there are so many producers being created in the perf test ?

        Perhaps this could be pointing to something in our JCA implementation. Perhaps worthwhile investigating.

        Show
        Rajith Attapattu added a comment - "The only one which really showed up, related to performance, was MessageProducer org.apache.qpid.client.BasicMessageProducer_0_10@658eeb10 using publish mode : ASYNC_PUBLISH_ALL For example one of the performance tests had over 10000 entries in our log files." This log message is * only * printed when we create a producer instance. So I wonder why there are so many producers being created in the perf test ? Perhaps this could be pointing to something in our JCA implementation. Perhaps worthwhile investigating.
        Hide
        Rajith Attapattu added a comment -

        I will mark the flow control message at INFO before committing the patch.
        As Rob mentioned, at some point we need to make a pass at our logging to get rid of all the junk and adjust levels properly.

        Show
        Rajith Attapattu added a comment - I will mark the flow control message at INFO before committing the patch. As Rob mentioned, at some point we need to make a pass at our logging to get rid of all the junk and adjust levels properly.
        Hide
        Kevin Conner added a comment -

        The only one which really showed up, related to performance, was
        MessageProducer org.apache.qpid.client.BasicMessageProducer_0_10@658eeb10 using publish mode : ASYNC_PUBLISH_ALL

        For example one of the performance tests had over 10000 entries in our log files.

        It was while dealing with this that I took a quick look at the others, trying to rationalise them.

        As for the flow control messages I have no real opinion other than I do not believe they should be at WARN. Please change as you see fit.

        Show
        Kevin Conner added a comment - The only one which really showed up, related to performance, was MessageProducer org.apache.qpid.client.BasicMessageProducer_0_10@658eeb10 using publish mode : ASYNC_PUBLISH_ALL For example one of the performance tests had over 10000 entries in our log files. It was while dealing with this that I took a quick look at the others, trying to rationalise them. As for the flow control messages I have no real opinion other than I do not believe they should be at WARN. Please change as you see fit.
        Hide
        Rob Godfrey added a comment -

        Agree that the highlighted messages should be more than debug (though I would probably buy info rather than warn for the first one if we get rid of all the junk that was at info level).

        The rest of the changes I am comfortable with though I don't think any of these really adversely affect performance (certainly they've never shown up on any of the profiling I've done).

        Show
        Rob Godfrey added a comment - Agree that the highlighted messages should be more than debug (though I would probably buy info rather than warn for the first one if we get rid of all the junk that was at info level). The rest of the changes I am comfortable with though I don't think any of these really adversely affect performance (certainly they've never shown up on any of the profiling I've done).
        Hide
        Rob Godfrey added a comment -

        As an aside, if these are patches from someone else, should he not be the one attaching them to a JIRA with the necessary copyright assignment?

        Show
        Rob Godfrey added a comment - As an aside, if these are patches from someone else, should he not be the one attaching them to a JIRA with the necessary copyright assignment?
        Hide
        Rajith Attapattu added a comment -

        LOL, I realized I got the affects and fixed versions mixed up

        Thanks for the review and raising questions.

        These were originally marked as WARN so I assume they are meant to happen fairly infrequently.
        Usually monitoring folks would like to see these kinds of messages. So I wouldn't argue about it's importance.

        However Kevin may have seen this message quite frequently in the logs to downgrade this, or perhaps a mistake.
        I'll ping him and see what prompted him to push this to debug.

        Rajith

        Show
        Rajith Attapattu added a comment - LOL, I realized I got the affects and fixed versions mixed up Thanks for the review and raising questions. These were originally marked as WARN so I assume they are meant to happen fairly infrequently. Usually monitoring folks would like to see these kinds of messages. So I wouldn't argue about it's importance. However Kevin may have seen this message quite frequently in the logs to downgrade this, or perhaps a mistake. I'll ping him and see what prompted him to push this to debug. Rajith
        Hide
        Robbie Gemmell added a comment -

        Its a bit late to fix 0.14

        I'm not too interested in most of the changes, but I'm not sure I agree these are debug:

        @@ -3194,7 +3194,10 @@ public abstract class AMQSession<C extends BasicMessageConsumer, P extends Basic
             public void setFlowControl(final boolean active)
             {
                 _flowControl.setFlowControl(active);
        -        _logger.warn("Broker enforced flow control " + (active ? "no longer in effect" : "has been enforced"));
        +        if (_logger.isDebugEnabled())
        +        {
        +        	_logger.debug("Broker enforced flow control " + (active ? "no longer in effect" : "has been enforced"));
        +        }
             }
         
             public void checkFlowControl() throws InterruptedException, JMSException
        @@ -3208,7 +3211,10 @@ public abstract class AMQSession<C extends BasicMessageConsumer, P extends Basic
                     {
         
                         _flowControl.wait(_flowControlWaitPeriod);
        -                _logger.warn("Message send delayed by " + (System.currentTimeMillis() + _flowControlWaitFailure - expiryTime)/1000 + "s due to broker enforced flow control");
        +                if (_logger.isDebugEnabled())
        +                {
        +                    _logger.debug("Message send delayed by " + (System.currentTimeMillis() + _flowControlWaitFailure - expiryTime)/1000 + "s due to broker enforced flow control");
        +                }
                     }
                     if(!_flowControl.getFlowControl())
                     {
        
        Show
        Robbie Gemmell added a comment - Its a bit late to fix 0.14 I'm not too interested in most of the changes, but I'm not sure I agree these are debug: @@ -3194,7 +3194,10 @@ public abstract class AMQSession<C extends BasicMessageConsumer, P extends Basic public void setFlowControl(final boolean active) { _flowControl.setFlowControl(active); - _logger.warn("Broker enforced flow control " + (active ? "no longer in effect" : "has been enforced")); + if (_logger.isDebugEnabled()) + { + _logger.debug("Broker enforced flow control " + (active ? "no longer in effect" : "has been enforced")); + } } public void checkFlowControl() throws InterruptedException, JMSException @@ -3208,7 +3211,10 @@ public abstract class AMQSession<C extends BasicMessageConsumer, P extends Basic { _flowControl.wait(_flowControlWaitPeriod); - _logger.warn("Message send delayed by " + (System.currentTimeMillis() + _flowControlWaitFailure - expiryTime)/1000 + "s due to broker enforced flow control"); + if (_logger.isDebugEnabled()) + { + _logger.debug("Message send delayed by " + (System.currentTimeMillis() + _flowControlWaitFailure - expiryTime)/1000 + "s due to broker enforced flow control"); + } } if(!_flowControl.getFlowControl()) {
        Hide
        Rajith Attapattu added a comment -

        Attaching patch by Kevin Conner.

        Show
        Rajith Attapattu added a comment - Attaching patch by Kevin Conner.

          People

          • Assignee:
            Rajith Attapattu
            Reporter:
            Rajith Attapattu
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development