* [nohz_full/apic] multiple timer interrupts a second
@ 2017-11-03 21:12 Luiz Capitulino
2017-11-04 9:14 ` Nicolai Stange
0 siblings, 1 reply; 3+ messages in thread
From: Luiz Capitulino @ 2017-11-03 21:12 UTC (permalink / raw)
To: fweisbec; +Cc: tglx, mtosatti, williams, nicstange, linux-kernel
[CC'ing lkml this time]
Hi,
I've observed that smp_apic_timer_interrupt() is sometimes called
two or more times a second on a nohz_full core which has a single
task taking 100% of the core. In one of the calls, hrtimer_interrupt()
runs tick_sched_timer(), but in others it doesn't call any handler.
Here's an example (Linus HEAD f34157878):
<...>-1831 [008] 1060.115578: funcgraph_entry: | smp_apic_timer_interrupt() {
<...>-1831 [008] 1060.115578: funcgraph_entry: | hrtimer_interrupt() {
<...>-1831 [008] 1060.115578: hrtimer_expire_entry: hrtimer=0xffff8edfefd12d60 function=tick_sched_timer now=1060079001980
<...>-1831 [008] 1060.115578: funcgraph_entry: 1.172 us | tick_sched_timer();
<...>-1831 [008] 1060.115580: funcgraph_exit: 1.757 us | }
<...>-1831 [008] 1060.115580: hrtimer_start: hrtimer=0xffff8edfefd12d60 function=tick_sched_timer expires=1061079000000 softexpires=1061079000000
<...>-1831 [008] 1060.115581: funcgraph_exit: 3.026 us | }
<...>-1831 [008] 1061.115577: funcgraph_entry: | smp_apic_timer_interrupt() {
<...>-1831 [008] 1061.115577: funcgraph_entry: 0.261 us | hrtimer_interrupt(); <---------- NO handler called
<...>-1831 [008] 1061.115578: funcgraph_exit: 1.349 us | }
<...>-1831 [008] 1061.115579: funcgraph_entry: | smp_apic_timer_interrupt() {
<...>-1831 [008] 1061.115579: funcgraph_entry: | hrtimer_interrupt() {
<...>-1831 [008] 1061.115579: hrtimer_expire_entry: hrtimer=0xffff8edfefd12d60 function=tick_sched_timer now=1061079001473
<...>-1831 [008] 1061.115580: funcgraph_entry: 1.413 us | tick_sched_timer();
<...>-1831 [008] 1061.115581: funcgraph_exit: 2.124 us | }
<...>-1831 [008] 1061.115582: hrtimer_start: hrtimer=0xffff8edfefd12d60 function=tick_sched_timer expires=1062079000000 softexpires=1062079000000
<...>-1831 [008] 1061.115582: funcgraph_exit: 3.255 us | }
Is this expected for some reason?
I guess what's happening is that the deadline timer is firing
earlier than expected. From a few dozen to a few hundreds
nanoseconds earlier. When this happens, hrtimer_interrupt()
skips calling the hrtimer handler (since it's early) and the
apic is programmed to fire in the next microsecond.
On further research I saw that Nicolai tried to fix a very similar
problem last year:
commit 1a9e4c564ab174e53ed86def922804a5ddc63e7d
Author: Nicolai Stange <nicstange@gmail.com>
Date: Thu Jul 14 17:22:54 2016 +0200
x86/timers/apic: Fix imprecise timer interrupts by eliminating TSC clockevents frequency roundoff error
I noticed the following bug/misbehavior on certain Intel systems: with a
single task running on a NOHZ CPU on an Intel Haswell, I recognized
that I did not only get the one expected local_timer APIC interrupt, but
two per second at minimum. (!)
Maybe this issue is still present?
^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: [nohz_full/apic] multiple timer interrupts a second
2017-11-03 21:12 [nohz_full/apic] multiple timer interrupts a second Luiz Capitulino
@ 2017-11-04 9:14 ` Nicolai Stange
2017-11-06 14:00 ` Luiz Capitulino
0 siblings, 1 reply; 3+ messages in thread
From: Nicolai Stange @ 2017-11-04 9:14 UTC (permalink / raw)
To: Luiz Capitulino
Cc: fweisbec, tglx, mtosatti, williams, nicstange, linux-kernel, John Stultz
Hi Luiz,
[John Stultz added to CC]
On Fri, Nov 03 2017, Luiz Capitulino wrote:
> [CC'ing lkml this time]
>
> I've observed that smp_apic_timer_interrupt() is sometimes called
> two or more times a second on a nohz_full core which has a single
> task taking 100% of the core. In one of the calls, hrtimer_interrupt()
> runs tick_sched_timer(), but in others it doesn't call any handler.
> Here's an example (Linus HEAD f34157878):
>
> <...>-1831 [008] 1060.115578: funcgraph_entry: | smp_apic_timer_interrupt() {
> <...>-1831 [008] 1060.115578: funcgraph_entry: | hrtimer_interrupt() {
> <...>-1831 [008] 1060.115578: hrtimer_expire_entry: hrtimer=0xffff8edfefd12d60 function=tick_sched_timer now=1060079001980
> <...>-1831 [008] 1060.115578: funcgraph_entry: 1.172 us | tick_sched_timer();
> <...>-1831 [008] 1060.115580: funcgraph_exit: 1.757 us | }
> <...>-1831 [008] 1060.115580: hrtimer_start: hrtimer=0xffff8edfefd12d60 function=tick_sched_timer expires=1061079000000 softexpires=1061079000000
> <...>-1831 [008] 1060.115581: funcgraph_exit: 3.026 us | }
> <...>-1831 [008] 1061.115577: funcgraph_entry: | smp_apic_timer_interrupt() {
> <...>-1831 [008] 1061.115577: funcgraph_entry: 0.261 us | hrtimer_interrupt(); <---------- NO handler called
> <...>-1831 [008] 1061.115578: funcgraph_exit: 1.349 us | }
> <...>-1831 [008] 1061.115579: funcgraph_entry: | smp_apic_timer_interrupt() {
> <...>-1831 [008] 1061.115579: funcgraph_entry: | hrtimer_interrupt() {
> <...>-1831 [008] 1061.115579: hrtimer_expire_entry: hrtimer=0xffff8edfefd12d60 function=tick_sched_timer now=1061079001473
> <...>-1831 [008] 1061.115580: funcgraph_entry: 1.413 us | tick_sched_timer();
> <...>-1831 [008] 1061.115581: funcgraph_exit: 2.124 us | }
> <...>-1831 [008] 1061.115582: hrtimer_start: hrtimer=0xffff8edfefd12d60 function=tick_sched_timer expires=1062079000000 softexpires=1062079000000
> <...>-1831 [008] 1061.115582: funcgraph_exit: 3.255 us | }
>
> Is this expected for some reason?
>
> I guess what's happening is that the deadline timer is firing
> earlier than expected. From a few dozen to a few hundreds
> nanoseconds earlier. When this happens, hrtimer_interrupt()
> skips calling the hrtimer handler (since it's early) and the
> apic is programmed to fire in the next microsecond.
Exactly.
> On further research I saw that Nicolai tried to fix a very similar
> problem last year:
>
> commit 1a9e4c564ab174e53ed86def922804a5ddc63e7d
> Author: Nicolai Stange <nicstange@gmail.com>
> Date: Thu Jul 14 17:22:54 2016 +0200
>
> x86/timers/apic: Fix imprecise timer interrupts by eliminating TSC clockevents frequency roundoff error
>
> I noticed the following bug/misbehavior on certain Intel systems: with a
> single task running on a NOHZ CPU on an Intel Haswell, I recognized
> that I did not only get the one expected local_timer APIC interrupt, but
> two per second at minimum. (!)
Note that there's also 6731b0d611a1 ("x86/timers/apic: Inform TSC
deadline clockevent device about recalibration").
> Maybe this issue is still present?
Yes it is. The reason is that NTP frequency adjustments would make it
into the mono clocksource's frequency but not into the
clock_event_device's.
I sent a series back then [1] addressing this.
However, in the meanwhile, I changed jobs and thus, got somehow
distracted. My bad :/
The result is that this got merged only up to what corresponds to
[10/28] in [1].
I'll pick this up again now and try to get the rest accepted for
inclusion.
Thanks,
Nicolai
[1] last time I sent this series as a whole can be found at
http://lkml.kernel.org/r/20161119160055.12491-2-nicstange@gmail.com
^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: [nohz_full/apic] multiple timer interrupts a second
2017-11-04 9:14 ` Nicolai Stange
@ 2017-11-06 14:00 ` Luiz Capitulino
0 siblings, 0 replies; 3+ messages in thread
From: Luiz Capitulino @ 2017-11-06 14:00 UTC (permalink / raw)
To: Nicolai Stange
Cc: fweisbec, tglx, mtosatti, williams, linux-kernel, John Stultz
On Sat, 04 Nov 2017 10:14:52 +0100
Nicolai Stange <nicstange@gmail.com> wrote:
> Hi Luiz,
>
> [John Stultz added to CC]
>
> On Fri, Nov 03 2017, Luiz Capitulino wrote:
>
> > [CC'ing lkml this time]
> >
> > I've observed that smp_apic_timer_interrupt() is sometimes called
> > two or more times a second on a nohz_full core which has a single
> > task taking 100% of the core. In one of the calls, hrtimer_interrupt()
> > runs tick_sched_timer(), but in others it doesn't call any handler.
> > Here's an example (Linus HEAD f34157878):
> >
> > <...>-1831 [008] 1060.115578: funcgraph_entry: | smp_apic_timer_interrupt() {
> > <...>-1831 [008] 1060.115578: funcgraph_entry: | hrtimer_interrupt() {
> > <...>-1831 [008] 1060.115578: hrtimer_expire_entry: hrtimer=0xffff8edfefd12d60 function=tick_sched_timer now=1060079001980
> > <...>-1831 [008] 1060.115578: funcgraph_entry: 1.172 us | tick_sched_timer();
> > <...>-1831 [008] 1060.115580: funcgraph_exit: 1.757 us | }
> > <...>-1831 [008] 1060.115580: hrtimer_start: hrtimer=0xffff8edfefd12d60 function=tick_sched_timer expires=1061079000000 softexpires=1061079000000
> > <...>-1831 [008] 1060.115581: funcgraph_exit: 3.026 us | }
> > <...>-1831 [008] 1061.115577: funcgraph_entry: | smp_apic_timer_interrupt() {
> > <...>-1831 [008] 1061.115577: funcgraph_entry: 0.261 us | hrtimer_interrupt(); <---------- NO handler called
> > <...>-1831 [008] 1061.115578: funcgraph_exit: 1.349 us | }
> > <...>-1831 [008] 1061.115579: funcgraph_entry: | smp_apic_timer_interrupt() {
> > <...>-1831 [008] 1061.115579: funcgraph_entry: | hrtimer_interrupt() {
> > <...>-1831 [008] 1061.115579: hrtimer_expire_entry: hrtimer=0xffff8edfefd12d60 function=tick_sched_timer now=1061079001473
> > <...>-1831 [008] 1061.115580: funcgraph_entry: 1.413 us | tick_sched_timer();
> > <...>-1831 [008] 1061.115581: funcgraph_exit: 2.124 us | }
> > <...>-1831 [008] 1061.115582: hrtimer_start: hrtimer=0xffff8edfefd12d60 function=tick_sched_timer expires=1062079000000 softexpires=1062079000000
> > <...>-1831 [008] 1061.115582: funcgraph_exit: 3.255 us | }
> >
> > Is this expected for some reason?
> >
> > I guess what's happening is that the deadline timer is firing
> > earlier than expected. From a few dozen to a few hundreds
> > nanoseconds earlier. When this happens, hrtimer_interrupt()
> > skips calling the hrtimer handler (since it's early) and the
> > apic is programmed to fire in the next microsecond.
>
> Exactly.
>
>
> > On further research I saw that Nicolai tried to fix a very similar
> > problem last year:
> >
> > commit 1a9e4c564ab174e53ed86def922804a5ddc63e7d
> > Author: Nicolai Stange <nicstange@gmail.com>
> > Date: Thu Jul 14 17:22:54 2016 +0200
> >
> > x86/timers/apic: Fix imprecise timer interrupts by eliminating TSC clockevents frequency roundoff error
> >
> > I noticed the following bug/misbehavior on certain Intel systems: with a
> > single task running on a NOHZ CPU on an Intel Haswell, I recognized
> > that I did not only get the one expected local_timer APIC interrupt, but
> > two per second at minimum. (!)
>
> Note that there's also 6731b0d611a1 ("x86/timers/apic: Inform TSC
> deadline clockevent device about recalibration").
>
>
> > Maybe this issue is still present?
>
> Yes it is. The reason is that NTP frequency adjustments would make it
> into the mono clocksource's frequency but not into the
> clock_event_device's.
>
> I sent a series back then [1] addressing this.
>
> However, in the meanwhile, I changed jobs and thus, got somehow
> distracted. My bad :/
>
> The result is that this got merged only up to what corresponds to
> [10/28] in [1].
>
> I'll pick this up again now and try to get the rest accepted for
> inclusion.
OK. If you get a new version, please include me in the CC so that
I can give it a try.
>
>
> Thanks,
>
> Nicolai
>
>
> [1] last time I sent this series as a whole can be found at
> http://lkml.kernel.org/r/20161119160055.12491-2-nicstange@gmail.com
>
^ permalink raw reply [flat|nested] 3+ messages in thread
end of thread, other threads:[~2017-11-06 14:01 UTC | newest]
Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-11-03 21:12 [nohz_full/apic] multiple timer interrupts a second Luiz Capitulino
2017-11-04 9:14 ` Nicolai Stange
2017-11-06 14:00 ` Luiz Capitulino
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).