Bug 690107

Summary: Too many 'task overran' warnings in qpid broker logs
Product: Red Hat Enterprise MRG Reporter: Siddhesh Poyarekar <spoyarek>
Component: qpid-cppAssignee: Justin Ross <jross>
Status: CLOSED ERRATA QA Contact: Zdenek Kraus <zkraus>
Severity: medium Docs Contact:
Priority: medium    
Version: 1.3CC: jneedle, matt, mcressma, mnewsome, rdassen, rrajaram, zkraus
Target Milestone: 2.0.10   
Target Release: ---   
Hardware: Unspecified   
OS: Linux   
Whiteboard:
Fixed In Version: qpid-cpp-0.10-7.el6_1 Doc Type: Bug Fix
Doc Text:
Under heavy load, the broker generated a large number of timer late/overrun warning messages. Though the messages themselves were usually inoffensive, the time to log them individually caused long (up to several seconds) delays and inflated log files. With this update, logging output for these messages has been restricted to the "--log-enabled=info" option, thus preventing this bug.
 Story Points: ---
Clone Of: Environment:
Last Closed: 2011-10-24 11:43:28 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Bug Depends On:    
Bug Blocks: 742040, 744036, 745231    

Description Siddhesh Poyarekar 2011-03-23 11:20:49 UTC 
Description of problem:

bug 629756 describes the problem of too many 'task overran' warnings coming up during high load. This has been fixed by accumulating the warnings and showing them as averages in 5 second intervals. But this is also not quiet enough, since for consistent high loads, it means that the logs will have this message every 5 seconds.

There needs to be a way to either completely disable these 'task overran' warnings or a configurable delay (with a default of 5 seconds) with which these messages should be printed.

Version-Release number of selected component (if applicable):
qpid-cpp-server-0.7.946106-28.el5

How reproducible:
Consistently, under heavy load.

Steps to Reproduce:
1. qpid-perftest --durable yes --count 10000 --qt 40 -s
2. watch qpidd log for late/overrun warnings
  
Actual results:

A message every 5 seconds:

2011-02-25 11:54:01 warning  task overran 2 times by 2ms (taking 3000ns) on average.
2011-02-25 11:54:17 warning  task overran 1 times by 2ms (taking 2000ns) on average.
2011-02-25 11:54:23 warning  task overran 15 times by 2ms (taking 2533ns) on average.
2011-02-25 11:54:36 warning  task overran 10 times by 2ms (taking 2500ns) on average.
2011-02-25 11:54:41 warning  task overran 37 times by 2ms (taking 2270ns) on average.
2011-02-25 11:54:52 warning  task overran 442 times by 2ms (taking 2556ns) on average.
2011-02-25 11:54:58 warning  task overran 7 times by 2ms (taking 2857ns) on average.

Expected results:

Much less or no messages, based on user preference.
Comment 1 Matthew Farrellee 2011-04-28 15:49:31 UTC 
# rpm -q qpid-cpp-server
qpid-cpp-server-0.10-1.el5
# wc -l /var/log/messages
78878 /var/log/messages
# grep qpidd /var/log/messages | wc -l
78812
# grep qpidd /var/log/messages | grep overran | wc -l
74834
Comment 4 Zdenek Kraus 2011-10-06 12:17:56 UTC 
for qpid-cpp-0.10-9.el5 & qpid-cpp-0.10-4.el6_1.1
'task overran' is moved from default setting for --log-enable into '--log-enable=info+'.

Are there another parameters for changing behaviour of 'task overran' logging, that need to test?
Comment 6 Zdenek Kraus 2011-10-07 13:42:41 UTC 
'task overran' logging output moved to --log-enabled=info

tested on
 RHEL5.7 i386, x86_64
 RHEL6.1 i386, x86_64

moving to VERIFIED
Comment 7 Tomas Capek 2011-10-17 14:07:14 UTC 
    Technical note added. If any revisions are required, please edit the "Technical Notes" field
    accordingly. All revisions will be proofread by the Engineering Content Services team.
    
    New Contents:
Under heavy load, the broker generated a large number of timer late/overrun warning messages. Though the messages themselves were usually inoffensive, the time to log them individually caused long (up to several seconds) delays and inflated log files. With this update, logging output for these messages has been restricted to the "--log-enabled=info" option, thus preventing this bug.
Comment 8 errata-xmlrpc 2011-10-24 11:43:28 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHBA-2011-1399.html