You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@qpid.apache.org by Gordon Sim <gs...@redhat.com> on 2009/08/12 13:25:29 UTC
Timer woken up late?
The output from make check-long is now showing lots of warnings of the
following form:
soak-1: 2009-08-12 06:40:56 warning Timer woken up 3ms late
Is this a serious issue? If so what do we need to do to prevent it
happening? If not, is warning the appropriate logging level?
---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project: http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org
Re: Timer woken up late?
Posted by Matthew Gillen <me...@mattgillen.net>.
On 08/12/2009 10:19 AM, Andrew Stitcher wrote:
> On Wed, 2009-08-12 at 08:56 -0400, Alan Conway wrote:
>> On 08/12/2009 07:25 AM, Gordon Sim wrote:
>>> The output from make check-long is now showing lots of warnings of the
>>> following form:
>>>
>>> soak-1: 2009-08-12 06:40:56 warning Timer woken up 3ms late
>>>
>>> Is this a serious issue? If so what do we need to do to prevent it
>>> happening? If not, is warning the appropriate logging level?
>>>
>>>
>> I've also been seeing a lot of those messages since sometime last week. As it
>> stands its not a useful message at any log level so I'd be inclined to remove it
>> or else build in some fudge factor so it only reports if the Timer is
>> significantly late. Hard to guess what's a good value for "significant".
>
> I think that these messages are less important than the overrun
> messages, but useful in retrospect - to understand that a timing delay
> isn't the result of anything happening in qpidd, but caused by the
> machine being so busy (for whatever reason) that the kernel couldn't
> wake the timer thread up in time.
>
> If you are seeing lots and lots of these messages it almost certainly
> means that the io threads (or I guess another process entirely) are
> monopolising the cpus to the extent that the timing thread can't be
> restarted, and this is perhaps important in itself.
It's not necessarily related to CPU load. It has more to do with the
real-time properties of your OS. For example, I've done measurements on
several linux systems and found that the Java Thread.sleep() operation will
consistently wake up in X+2ms or X+3ms (where X is number of milliseconds you
passed to sleep()), even on a machine that was 99% idle. (using the POSIX/C
nanosleep function also awakens up to 3+ ms late on an unloaded machine,
although not consistently).
So there's a lower bound on the accuracy of sleep() that is potentially
platform dependent. A warning message might be useful if the Timer overslept
for an amount of time that is "high" for the platform. Perhaps a timer
calibration routine at startup time could print the threshold above which
future warning messages will be issued?
Matt
---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project: http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org
Re: Timer woken up late?
Posted by Alan Conway <ac...@redhat.com>.
On 08/12/2009 10:19 AM, Andrew Stitcher wrote:
> On Wed, 2009-08-12 at 08:56 -0400, Alan Conway wrote:
>> On 08/12/2009 07:25 AM, Gordon Sim wrote:
>>> The output from make check-long is now showing lots of warnings of the
>>> following form:
>>>
>>> soak-1: 2009-08-12 06:40:56 warning Timer woken up 3ms late
>>>
>>> Is this a serious issue? If so what do we need to do to prevent it
>>> happening? If not, is warning the appropriate logging level?
>>>
>>>
>> I've also been seeing a lot of those messages since sometime last week. As it
>> stands its not a useful message at any log level so I'd be inclined to remove it
>> or else build in some fudge factor so it only reports if the Timer is
>> significantly late. Hard to guess what's a good value for "significant".
>
> I think that these messages are less important than the overrun
> messages, but useful in retrospect - to understand that a timing delay
> isn't the result of anything happening in qpidd, but caused by the
> machine being so busy (for whatever reason) that the kernel couldn't
> wake the timer thread up in time.
>
> If you are seeing lots and lots of these messages it almost certainly
> means that the io threads (or I guess another process entirely) are
> monopolising the cpus to the extent that the timing thread can't be
> restarted, and this is perhaps important in itself.
>
> Currently the notion of significant is 1ms for active Timer tasks and
> 500ms for cancelled timer tasks. The significance of a delay will
> strongly depend on what time dependent tasks are going on so it's
> difficult to know currently the heartbeat related tasks are the most
> time sensitive and they fail after delays of about 0.5 * the heartbeat
> interval.
>
> As it currently stands we could probably increase the limit to 50ms and
> not miss really significant delays.
>
> Thoughts?
>
That works for me. What I've been seeing is a constant stream of mostly 1ms,
occasionally 2ms misses, about every second or so a clustered broker on mrg32.
---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project: http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org
Re: Timer woken up late?
Posted by Andrew Stitcher <as...@redhat.com>.
On Wed, 2009-08-12 at 08:56 -0400, Alan Conway wrote:
> On 08/12/2009 07:25 AM, Gordon Sim wrote:
> > The output from make check-long is now showing lots of warnings of the
> > following form:
> >
> > soak-1: 2009-08-12 06:40:56 warning Timer woken up 3ms late
> >
> > Is this a serious issue? If so what do we need to do to prevent it
> > happening? If not, is warning the appropriate logging level?
> >
> >
>
> I've also been seeing a lot of those messages since sometime last week. As it
> stands its not a useful message at any log level so I'd be inclined to remove it
> or else build in some fudge factor so it only reports if the Timer is
> significantly late. Hard to guess what's a good value for "significant".
I think that these messages are less important than the overrun
messages, but useful in retrospect - to understand that a timing delay
isn't the result of anything happening in qpidd, but caused by the
machine being so busy (for whatever reason) that the kernel couldn't
wake the timer thread up in time.
If you are seeing lots and lots of these messages it almost certainly
means that the io threads (or I guess another process entirely) are
monopolising the cpus to the extent that the timing thread can't be
restarted, and this is perhaps important in itself.
Currently the notion of significant is 1ms for active Timer tasks and
500ms for cancelled timer tasks. The significance of a delay will
strongly depend on what time dependent tasks are going on so it's
difficult to know currently the heartbeat related tasks are the most
time sensitive and they fail after delays of about 0.5 * the heartbeat
interval.
As it currently stands we could probably increase the limit to 50ms and
not miss really significant delays.
Thoughts?
Andrew
>
---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project: http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org
Re: Timer woken up late?
Posted by Alan Conway <ac...@redhat.com>.
On 08/12/2009 07:25 AM, Gordon Sim wrote:
> The output from make check-long is now showing lots of warnings of the
> following form:
>
> soak-1: 2009-08-12 06:40:56 warning Timer woken up 3ms late
>
> Is this a serious issue? If so what do we need to do to prevent it
> happening? If not, is warning the appropriate logging level?
>
>
I've also been seeing a lot of those messages since sometime last week. As it
stands its not a useful message at any log level so I'd be inclined to remove it
or else build in some fudge factor so it only reports if the Timer is
significantly late. Hard to guess what's a good value for "significant".
---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project: http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org