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:[email protected]
