[Query] Spurious interrupts from clockevent device on X86 Ivybridge

[Query] Spurious interrupts from clockevent device on X86 Ivybridge

[Santosh Shukla]

Hi Guys,

I have been chasing spurious clockevent interrupts (In HIGHRES mode) on my x86
IvyBridge server and stuck on some blockers (mostly due to lack of knowledge)
and need some help..

What does spurious mean ?
I take it as the case when a core is unnecessarily interrupted by the clockevent
device while we didn't wanted it to.

I tried to catch them with the help of few new trace points in
hrtimer_interrupt() when it didn't serviced any pending hrtimers..

The causes I could find:
- Clockevent device's counter overflow: When we need to program a clockevt
  device for times larger than it can handle, we program it for max time and
  then reprogram again on expiration. Because of hardware counter limitations we
  have to do it this way and this isn't really a spurious interrupt as we
  programmed it that way.

- Hardware timer firing before its expiration: Yes, its hard to digest but from
  my tests it looks like this does happen. Will circulate another mail once I am
  sure about it.

- Difference between time returned by hrtimer_update_base() and clockevt
  device's notion of time: Wanted to discuss this here..


An example of what I am witnessing in my tests:

clockevt device programmed to fire after 199 ms and it fires exactly after that
time (Verified with ftrace time-diff and tsc diff [tsc: timestamp counter
instructions for x86]).

But when hrtimer_interrupt() tries to find the hrtimer for which the event
occurred, it finds the value returned by hrtimer_update_base() being lesser than
the softexpires of the timer for which the event was programmed. And the diff is
approximately 1 us most of the times I see the spurious interrupt.

<idle>-0     [010] d...    68.961171: clk_evt_program: delta:199933679
expires=69071000000 /* programmed for 199 ms */
<idle>-0     [010] d...    68.961171: lapic_next_deadline:
cur_tsc:365799488705427 new_tsc:365799907536051 delta:199443 usec /*
sets new_tsc */
<idle>-0     [010] d.h.    69.161183: local_timer_entry: vector=239
<idle>-0     [010] d.h.    69.161185: local_apic_timer_interrupt:
cur_tsc:365799907547595 delta:199448 usec /* Interrupt arrived
afterexactly 199 ms */
<idle>-0     [010] d.h.    69.161187:
hrtimer_interrupt:function=tick_sched_timer expires=69071000000
softexpires=69071000000
basenow:69070997234 /* But Softexpires > basenow ?? */
<idle>-0     [010] d.h.    69.161188: clk_evt_program: delta:1000
expires=69071000000 /* new expiry value (1 us) */
<idle>-0     [010] d.h.    69.161189: lapic_next_deadline:
cur_tsc:365799907556179 new_tsc:365799907558259 delta:0 usec /* sets
new tsc value */
<idle>-0     [010] d.h.    69.161189: local_timer_exit: vector=239

Tested on: Ivybrdge V2, 12 core X86 server, though it occurs on ARM as well
(but not that frequent).

Regards,
Santosh

Re: [Query] Spurious interrupts from clockevent device on X86 Ivybridge

[Preeti U Murthy]

Hi Santhosh,

On 12/10/2014 11:00 AM, Santosh Shukla wrote:
> Hi Guys,
> 
> I have been chasing spurious clockevent interrupts (In HIGHRES mode) on my x86
> IvyBridge server and stuck on some blockers (mostly due to lack of knowledge)
> and need some help..
> 
> What does spurious mean ?
> I take it as the case when a core is unnecessarily interrupted by the clockevent
> device while we didn't wanted it to.

Right. We get an interrupt when nobody had asked for it to be delivered
or had asked for it to be delivered and later canceled the request. It
is most often in the latter situation, that there can be race
conditions. If these race conditions are not taken care of, they can
result in spurious interrupts.

> 
> I tried to catch them with the help of few new trace points in
> hrtimer_interrupt() when it didn't serviced any pending hrtimers..
> 
> The causes I could find:
> - Clockevent device's counter overflow: When we need to program a clockevt
>   device for times larger than it can handle, we program it for max time and
>   then reprogram again on expiration. Because of hardware counter limitations we
>   have to do it this way and this isn't really a spurious interrupt as we
>   programmed it that way.

Yes this is a possible cause for spurious interrupts. On PowerPC we
check for such a situation specifically before we begin to handle timers.

> 
> - Hardware timer firing before its expiration: Yes, its hard to digest but from
>   my tests it looks like this does happen. Will circulate another mail once I am
>   sure about it.

Yep, will need more information if at all this is happening.

> 
> - Difference between time returned by hrtimer_update_base() and clockevt
>   device's notion of time: Wanted to discuss this here..
> 
> 
> An example of what I am witnessing in my tests:
> 
> clockevt device programmed to fire after 199 ms and it fires exactly after that
> time (Verified with ftrace time-diff and tsc diff [tsc: timestamp counter
> instructions for x86]).
> 
> But when hrtimer_interrupt() tries to find the hrtimer for which the event
> occurred, it finds the value returned by hrtimer_update_base() being lesser than
> the softexpires of the timer for which the event was programmed. And the diff is
> approximately 1 us most of the times I see the spurious interrupt.
> 
> <idle>-0     [010] d...    68.961171: clk_evt_program: delta:199933679
> expires=69071000000 /* programmed for 199 ms */
> <idle>-0     [010] d...    68.961171: lapic_next_deadline:
> cur_tsc:365799488705427 new_tsc:365799907536051 delta:199443 usec /*
> sets new_tsc */
> <idle>-0     [010] d.h.    69.161183: local_timer_entry: vector=239
> <idle>-0     [010] d.h.    69.161185: local_apic_timer_interrupt:
> cur_tsc:365799907547595 delta:199448 usec /* Interrupt arrived
> afterexactly 199 ms */
> <idle>-0     [010] d.h.    69.161187:
> hrtimer_interrupt:function=tick_sched_timer expires=69071000000
> softexpires=69071000000
> basenow:69070997234 /* But Softexpires > basenow ?? */
> <idle>-0     [010] d.h.    69.161188: clk_evt_program: delta:1000
> expires=69071000000 /* new expiry value (1 us) */
> <idle>-0     [010] d.h.    69.161189: lapic_next_deadline:
> cur_tsc:365799907556179 new_tsc:365799907558259 delta:0 usec /* sets
> new tsc value */
> <idle>-0     [010] d.h.    69.161189: local_timer_exit: vector=239

Since the difference is 1us and not a noticeably high value, it is most
probably because during hrtimer handling, we traverse all queued timers
and call their handlers, till we find timers whose expiry is in the
future. I would not be surprised if we overshoot the expiry of the
timers at the end of the list by a microsecond by the time we call their
handlers.

Regards
Preeti U Murthy
> 
> Tested on: Ivybrdge V2, 12 core X86 server, though it occurs on ARM as well
> (but not that frequent).
> 
> Regards,
> Santosh
> 

Re: [Query] Spurious interrupts from clockevent device on X86 Ivybridge

[Viresh Kumar]

On 10 December 2014 at 18:03, Preeti U Murthy <preeti@linux.vnet.ibm.com> wrote:

> Right. We get an interrupt when nobody had asked for it to be delivered
> or had asked for it to be delivered and later canceled the request. It
> is most often in the latter situation, that there can be race
> conditions. If these race conditions are not taken care of, they can
> result in spurious interrupts.

But the delta time will be very small then, right ?

> Since the difference is 1us and not a noticeably high value, it is most
> probably because during hrtimer handling, we traverse all queued timers
> and call their handlers, till we find timers whose expiry is in the
> future. I would not be surprised if we overshoot the expiry of the
> timers at the end of the list by a microsecond by the time we call their
> handlers.

Looks like you misunderstood what he wrote. He isn't saying that we
serviced the timers/hrtimers sometime after we should have.

What he is saying is: we got the clockevent device's interrupt at the
time we requested but hrtimer_update_base() returned a time
lesser than what it *should* have. And that results in a spurious
interrupt.. We enqueue again for 1 us and service the timer then.

Or am I missing something ?

--
viresh

Re: [Query] Spurious interrupts from clockevent device on X86 Ivybridge

[Thomas Gleixner]

On Wed, 10 Dec 2014, Santosh Shukla wrote:
> The causes I could find:
> - Clockevent device's counter overflow: When we need to program a clockevt
>   device for times larger than it can handle, we program it for max time and
>   then reprogram again on expiration. Because of hardware counter limitations we
>   have to do it this way and this isn't really a spurious interrupt as we
>   programmed it that way.
> 
> - Hardware timer firing before its expiration: Yes, its hard to digest but from
>   my tests it looks like this does happen. Will circulate another mail once I am
>   sure about it.

Nothing we can do about.
 
> - Difference between time returned by hrtimer_update_base() and clockevt
>   device's notion of time: Wanted to discuss this here..

The clock event device and the clock source can run at different
frequencies. So the conversion from nsec to event ticks can cause
slight errors which are only observable when the delta gets larger.

The clock event device conversion from nsecs to timer ticks is
calculated at setup time once. It's known to be not completely
precise.

The clock source conversion which we use for reading time can be
changed by recalibration (we do that for TSC) and by NTP adjustments.

So even if we would calibrate the clock event device better, then we
still would need to take the NTP adjustments into account. And given
the zoo of timers we have, certainly not a trivial exercise.

Need to think about a bit more.

Thanks,

	tglx

Re: [Query] Spurious interrupts from clockevent device on X86 Ivybridge

[Preeti U Murthy]

On 12/10/2014 06:22 PM, Viresh Kumar wrote:
> On 10 December 2014 at 18:03, Preeti U Murthy <preeti@linux.vnet.ibm.com> wrote:
> 
>> Right. We get an interrupt when nobody had asked for it to be delivered
>> or had asked for it to be delivered and later canceled the request. It
>> is most often in the latter situation, that there can be race
>> conditions. If these race conditions are not taken care of, they can
>> result in spurious interrupts.
> 
> But the delta time will be very small then, right ?

I was talking of the case where we get an interrupt from the clockevent
device but dont find the hrtimer to service and not really of an anomaly
in timekeeping.
   For instance one of the issues that we had seen earlier wherein we
cancel the tick-sched-timer before going tickless, but since we had
programmed the clock event device to fire, we get a spurious interrupt.

> 
>> Since the difference is 1us and not a noticeably high value, it is most
>> probably because during hrtimer handling, we traverse all queued timers
>> and call their handlers, till we find timers whose expiry is in the
>> future. I would not be surprised if we overshoot the expiry of the
>> timers at the end of the list by a microsecond by the time we call their
>> handlers.
> 
> Looks like you misunderstood what he wrote. He isn't saying that we
> serviced the timers/hrtimers sometime after we should have.
> 
> What he is saying is: we got the clockevent device's interrupt at the
> time we requested but hrtimer_update_base() returned a time
> lesser than what it *should* have. And that results in a spurious
> interrupt.. We enqueue again for 1 us and service the timer then.

Oh ok I see. I understand this better now after reading Thomas's
explanation.

Regards
Preeti U Murthy

Re: [Query] Spurious interrupts from clockevent device on X86 Ivybridge

[Santosh Shukla]

On 11 December 2014 at 10:14, Preeti U Murthy <preeti@linux.vnet.ibm.com> wrote:
> On 12/10/2014 06:22 PM, Viresh Kumar wrote:
>> On 10 December 2014 at 18:03, Preeti U Murthy <preeti@linux.vnet.ibm.com> wrote:
>>
>>> Right. We get an interrupt when nobody had asked for it to be delivered
>>> or had asked for it to be delivered and later canceled the request. It
>>> is most often in the latter situation, that there can be race
>>> conditions. If these race conditions are not taken care of, they can
>>> result in spurious interrupts.
>>
>> But the delta time will be very small then, right ?
>
> I was talking of the case where we get an interrupt from the clockevent
> device but dont find the hrtimer to service and not really of an anomaly
> in timekeeping.
>    For instance one of the issues that we had seen earlier wherein we
> cancel the tick-sched-timer before going tickless, but since we had
> programmed the clock event device to fire, we get a spurious interrupt.
>

I verified this case before reporting; In my case tick_sched_timer do
get cancelled before expire duration but then  clk_evt_device get
reprogrammed for next time node in list.  __remove_hrtimer() takes
care of that.

And in case there is no timer in list; We shut down the
clk_evt_device. Therefore no spurious interrupt in either of two
possible cases.

Re: [Query] Spurious interrupts from clockevent device on X86 Ivybridge

[Viresh Kumar]

On 11 December 2014 at 10:14, Preeti U Murthy <preeti@linux.vnet.ibm.com> wrote:
> I was talking of the case where we get an interrupt from the clockevent
> device but dont find the hrtimer to service and not really of an anomaly
> in timekeeping.

For sure that's a problem then and its obviously spurious unless we wanted
it to behave that way.

>    For instance one of the issues that we had seen earlier wherein we
> cancel the tick-sched-timer before going tickless, but since we had
> programmed the clock event device to fire, we get a spurious interrupt.

Yeah and so we need something like ONESHOT_STOPPED there..

I thought you are also talking about some *possible* races which might
occur between cancelling a timer and hrtimer_interrupt() getting called.
Don't know if such a race is possible though.

Re: [Query] Spurious interrupts from clockevent device on X86 Ivybridge

[Preeti U Murthy]

On 12/11/2014 10:26 AM, Santosh Shukla wrote:
> On 11 December 2014 at 10:14, Preeti U Murthy <preeti@linux.vnet.ibm.com> wrote:
>> On 12/10/2014 06:22 PM, Viresh Kumar wrote:
>>> On 10 December 2014 at 18:03, Preeti U Murthy <preeti@linux.vnet.ibm.com> wrote:
>>>
>>>> Right. We get an interrupt when nobody had asked for it to be delivered
>>>> or had asked for it to be delivered and later canceled the request. It
>>>> is most often in the latter situation, that there can be race
>>>> conditions. If these race conditions are not taken care of, they can
>>>> result in spurious interrupts.
>>>
>>> But the delta time will be very small then, right ?
>>
>> I was talking of the case where we get an interrupt from the clockevent
>> device but dont find the hrtimer to service and not really of an anomaly
>> in timekeeping.
>>    For instance one of the issues that we had seen earlier wherein we
>> cancel the tick-sched-timer before going tickless, but since we had
>> programmed the clock event device to fire, we get a spurious interrupt.
>>
> 
> I verified this case before reporting; In my case tick_sched_timer do
> get cancelled before expire duration but then  clk_evt_device get
> reprogrammed for next time node in list.  __remove_hrtimer() takes
> care of that.

Right. The scenario I described happens in the Low Resolution Mode. You
are right, this does not happen in the High Resolution Mode.

Regards
Preeti U Murthy