Mailing-List: contact users-help@qpid.apache.org; run by ezmlm
Precedence: bulk
Reply-To: users@qpid.apache.org
Received-SPF: pass (nike.apache.org: domain of aik@fnal.gov designates
 216.82.250.19 as permitted sender)
Message-Id: <A34DDD5B-4553-4DDD-91C3-BED59C695DC1@fnal.gov>
From: Alex Kulyavtsev <aik@fnal.gov>
To: users@qpid.apache.org
Content-Type: text/plain; charset=US-ASCII; format=flowed; delsp=yes
Content-Transfer-Encoding: 7bit
Mime-Version: 1.0 (Apple Message framework v936)
Subject: timer woken up tens of ms late
Date: Tue, 6 Sep 2011 12:21:21 -0500
Cc: Alex Kulyavtsev <aik@fnal.gov>

We have qpid c++ broker log full of messages like follows. Is it  
something we shall worry about?
Log reports some tasks are 50 to 80 ms late and reports are few times  
a minute.

2011-09-06 11:54:01 warning ManagementAgent::periodicProcessing timer  
callback overran by 2ms [taking 286000ns]
2011-09-06 11:54:02 warning JournalInactive:dur-queue timer woken up  
83ms late, overrunning by 66ms [taking 14000ns]
2011-09-06 11:54:02 warning JournalInactive:policy_engine timer woken  
up 67ms late
2011-09-06 11:54:03 warning JournalInactive:migrator timer callback  
overran by 4ms [taking 14000ns]
2011-09-06 11:54:03 warning JournalInactive:example.RequestQueue timer  
woken up 80ms late, overrunning by 73ms [taking 6000ns]
2011-09-06 11:54:03 warning JournalInactive:pe_test timer woken up  
73ms late, overrunning by 58ms [taking 4000ns]
2011-09-06 11:54:03 warning JournalInactive:migrator_reply timer woken  
up 58ms late
2011-09-06 11:54:04 warning JournalInactive:M1 timer woken up 65ms  
late, overrunning by 44ms [taking 21000ns]
2011-09-06 11:54:05 warning JournalInactive:migrator timer callback  
overran by 9ms [taking 12000ns]
2011-09-06 11:54:05 warning JournalInactive:md_replies timer callback  
overran by 3ms [taking 5000ns]

The amqp message traffic is light, but this node is busy running other  
servers:

top - 11:55:49 up 21 days, 10 min,  2 users,  load average: 5.54,  
6.77, 6.10
Tasks: 206 total,   3 running, 200 sleeping,   0 stopped,   3 zombie
Cpu0  :  7.3%us, 43.7%sy,  0.3%ni, 48.3%id,  0.3%wa,  0.0%hi,   
0.0%si,  0.0%st
Cpu1  :  5.0%us, 37.4%sy,  0.0%ni, 55.6%id,  1.7%wa,  0.0%hi,   
0.3%si,  0.0%st
Cpu2  :  4.3%us, 55.0%sy,  0.0%ni, 39.7%id,  1.0%wa,  0.0%hi,   
0.0%si,  0.0%st
Cpu3  :  5.6%us, 54.5%sy,  0.0%ni, 37.9%id,  2.0%wa,  0.0%hi,   
0.0%si,  0.0%st

This is qpid 0.8 running on Scientific Linux 5.3  (RHEL 5 custom  
rebuild), kernel 2.6.18-238.5.1.el5  x86_64

On the different idle node running qpid 0.12 most reported delays are  
2 ms (cutoff threshold) and less frequent.
Log is similar on idle node running qpid 0.8 broker.

2011-09-03 00:43:39 warning ManagementAgent::periodicProcessing task  
overran 1 times by 2ms (taking 719000ns) on average.
2011-09-03 00:44:19 warning JournalInactive:migrator task late and  
overran 1 times: late 2ms, overran 2ms (taking 8000ns) on average.
2011-09-03 00:47:02 warning JournalInactive:migrator task late and  
overran 1 times: late 2ms, overran 2ms (taking 4000ns) on average.
2011-09-03 00:52:10 warning JournalInactive:migration_dispatcher task  
late and overran 1 times: late 2ms, overran 2ms (taking 4000ns) on  
average.
2011-09-03 00:52:52 warning JournalInactive:migration_dispatcher task  
late and overran 1 times: late 2ms, overran 2ms (taking 4000ns) on  
average.
2011-09-03 00:54:44 warning JournalInactive:migration_dispatcher task  
late and overran 1 times: late 2ms, overran 2ms (taking 3000ns) on  
average.
2011-09-03 00:54:52 warning JournalInactive:migrator task late and  
overran 1 times: late 2ms, overran 2ms (taking 4000ns) on average.
2011-09-03 00:55:52 warning JournalInactive:migrator task late and  
overran 1 times: late 2ms, overran 2ms (taking 4000ns) on average.
2011-09-03 00:57:18 warning JournalInactive:migration_dispatcher task  
late and overran 1 times: late 2ms, overran 2ms (taking 7000ns) on  
average.
2011-09-03 01:06:17 warning JournalInactive:migrator task late and  
overran 1 times: late 2ms, overran 2ms (taking 4000ns) on average.
2011-09-03 01:10:25 warning JournalInactive:migration_dispatcher task  
late and overran 1 times: late 2ms, overran 2ms (taking 4000ns) on  
average.
2011-09-03 01:11:33 warning JournalInactive:migrator task late and  
overran 1 times: late 2ms, overran 2ms (taking 7000ns) on average.
2011-09-03 01:16:33 warning JournalInactive:migration_dispatcher task  
late and overran 1 times: late 2ms, overran 2ms (taking 4000ns) on  
average.
2011-09-03 01:16:50 warning JournalInactive:migrator task late and  
overran 1 times: late 2ms, overran 2ms (taking 3000ns) on average.
2011-09-03 01:19:24 warning JournalInactive:migration_dispatcher task  
late and overran 1 times: late 2ms, overran 2ms (taking 4000ns) on  
average.
2011-09-03 01:21:58 warning JournalInactive:migration_dispatcher task  
late and overran 1 times: late 2ms, overran 2ms (taking 7000ns) on  
average.

The other strange thing, log reports "taking 4000ns" which is 4  
microseconds, and reported overrun or delay is of the order of  
milliseconds.

Isn't is expected to have tasks to woke up later than requested in  
sleep for non-realtime kernel? Also note, this is not MRG kernel  
optimized to minimize  delays.

Shall we worry about this type of warnings in the log? Is there way to  
suppress these messages and/or increase threshold for "late"  reports?

Thanks in advance, Alex.


---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project:      http://qpid.apache.org
Use/Interact: mailto:users-subscribe@qpid.apache.org