Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1495635 > unrolled thread
| Started by | Alexei Starovoitov <alexei.starovoitov@gmail.com> |
|---|---|
| First post | 2016-10-05 02:40 +0200 |
| Last post | 2016-10-05 16:00 +0200 |
| Articles | 5 — 4 participants |
Back to article view | Back to linux.kernel
This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by
below is the oldest one visible, not the original post.
Re: [PATCH 1/2] timekeeping: Avoid taking lock in NMI path with CONFIG_DEBUG_TIMEKEEPING Alexei Starovoitov <alexei.starovoitov@gmail.com> - 2016-10-05 02:40 +0200
Re: [PATCH 1/2] timekeeping: Avoid taking lock in NMI path with CONFIG_DEBUG_TIMEKEEPING John Stultz <john.stultz@linaro.org> - 2016-10-05 03:00 +0200
[PATCH] timekeeping: Fix __ktime_get_fast_ns() regression John Stultz <john.stultz@linaro.org> - 2016-10-05 05:00 +0200
Re: [PATCH] timekeeping: Fix __ktime_get_fast_ns() regression Mathieu Desnoyers <mathieu.desnoyers@efficios.com> - 2016-10-05 13:00 +0200
[tip:timers/urgent] timekeeping: Fix __ktime_get_fast_ns() regression tip-bot for John Stultz <tipbot@zytor.com> - 2016-10-05 16:00 +0200
| From | Alexei Starovoitov <alexei.starovoitov@gmail.com> |
|---|---|
| Date | 2016-10-05 02:40 +0200 |
| Subject | Re: [PATCH 1/2] timekeeping: Avoid taking lock in NMI path with CONFIG_DEBUG_TIMEKEEPING |
| Message-ID | <soIpz-1De-1@gated-at.bofh.it> |
On Tue, Aug 23, 2016 at 04:08:21PM -0700, John Stultz wrote:
> When I added some extra sanity checking in timekeeping_get_ns() under
> CONFIG_DEBUG_TIMEKEEPING, I missed that the NMI safe __ktime_get_fast_ns()
> method was using timekeeping_get_ns().
>
> Thus the locking added to the debug checks broke the NMI-safety of
> __ktime_get_fast_ns().
>
> This patch open-codes the timekeeping_get_ns() logic for
> __ktime_get_fast_ns(), so can avoid any deadlocks in NMI.
>
> Cc: Steven Rostedt <rostedt@goodmis.org>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Cc: Ingo Molnar <mingo@kernel.org>
> Cc: Thomas Gleixner <tglx@linutronix.de>
> Cc: stable <stable@vger.kernel.org> # 4.1+
> Reported-by: Steven Rostedt <rostedt@goodmis.org>
> Reported-by: Peter Zijlstra <peterz@infradead.org>
> Signed-off-by: John Stultz <john.stultz@linaro.org>
> ---
> kernel/time/timekeeping.c | 5 ++++-
> 1 file changed, 4 insertions(+), 1 deletion(-)
>
> diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
> index 3b65746..e07fb09 100644
> --- a/kernel/time/timekeeping.c
> +++ b/kernel/time/timekeeping.c
> @@ -401,7 +401,10 @@ static __always_inline u64 __ktime_get_fast_ns(struct tk_fast *tkf)
> do {
> seq = raw_read_seqcount_latch(&tkf->seq);
> tkr = tkf->base + (seq & 0x01);
> - now = ktime_to_ns(tkr->base) + timekeeping_get_ns(tkr);
> + now = ktime_to_ns(tkr->base);
> +
> + now += clocksource_delta(tkr->read(tkr->clock),
> + tkr->cycle_last, tkr->mask);
we're seeing the time jumping backwards between __ktime_get_fast_ns calls.
and looks like this patch broke it, since delta is being added to ns.
It seems it should be:
now += timekeeping_delta_to_ns(clocksource_delta(...));
or better fix possible?
Reported-by: Brendan Gregg <bgregg@netflix.com>
# perf record -F 9 --cpu 0 --clockid CLOCK_MONOTONIC -- sleep 1
# perf script
swapper 0 [000] 2942480.468981: 111111111 cpu-clock: ffffffff810013aa xen_hypercall_sched_op+0xa (vmlinux)
swapper 0 [000] 2942480.471468: 111111111 cpu-clock: ffffffff810013aa xen_hypercall_sched_op+0xa (vmlinux)
swapper 0 [000] 2942480.473959: 111111111 cpu-clock: ffffffff810013aa xen_hypercall_sched_op+0xa (vmlinux)
swapper 0 [000] 2942480.475202: 111111111 cpu-clock: ffffffff810013aa xen_hypercall_sched_op+0xa (vmlinux)
swapper 0 [000] 2942480.477691: 111111111 cpu-clock: ffffffff810013aa xen_hypercall_sched_op+0xa (vmlinux)
swapper 0 [000] 2942481.470226: 111111111 cpu-clock: ffffffff810013aa xen_hypercall_sched_op+0xa (vmlinux)
swapper 0 [000] 2942481.472569: 111111111 cpu-clock: ffffffff810013aa xen_hypercall_sched_op+0xa (vmlinux)
swapper 0 [000] 2942481.476460: 111111111 cpu-clock: ffffffff810013aa xen_hypercall_sched_op+0xa (vmlinux)
swapper 0 [000] 2942481.478943: 111111111 cpu-clock: ffffffff810013aa xen_hypercall_sched_op+0xa (vmlinux)
Note the timestamp jump.
fixed (rolled back patch):
# perf record -F 9 --cpu 0 --clockid CLOCK_MONOTONIC -- sleep 1
# perf script
swapper 0 [000] 589.729663: 111111111 cpu-clock: ffffffff810013aa xen_hypercall_sched_op+0xa (vmlinux)
swapper 0 [000] 589.840772: 111111111 cpu-clock: ffffffff810013aa xen_hypercall_sched_op+0xa (vmlinux)
swapper 0 [000] 589.951883: 111111111 cpu-clock: ffffffff810013aa xen_hypercall_sched_op+0xa (vmlinux)
swapper 0 [000] 590.062994: 111111111 cpu-clock: ffffffff810013aa xen_hypercall_sched_op+0xa (vmlinux)
swapper 0 [000] 590.174075: 111111111 cpu-clock: ffffffff810013aa xen_hypercall_sched_op+0xa (vmlinux)
swapper 0 [000] 590.285217: 111111111 cpu-clock: ffffffff810013aa xen_hypercall_sched_op+0xa (vmlinux)
swapper 0 [000] 590.396328: 111111111 cpu-clock: ffffffff810013aa xen_hypercall_sched_op+0xa (vmlinux)
swapper 0 [000] 590.507439: 111111111 cpu-clock: ffffffff810013aa xen_hypercall_sched_op+0xa (vmlinux)
swapper 0 [000] 590.618550: 111111111 cpu-clock: ffffffff810013aa xen_hypercall_sched_op+0xa (vmlinux)
[toc] | [next] | [standalone]
| From | John Stultz <john.stultz@linaro.org> |
|---|---|
| Date | 2016-10-05 03:00 +0200 |
| Subject | Re: [PATCH 1/2] timekeeping: Avoid taking lock in NMI path with CONFIG_DEBUG_TIMEKEEPING |
| Message-ID | <soIIV-1JZ-1@gated-at.bofh.it> |
| In reply to | #1495635 |
On Tue, Oct 4, 2016 at 5:30 PM, Alexei Starovoitov
<alexei.starovoitov@gmail.com> wrote:
> On Tue, Aug 23, 2016 at 04:08:21PM -0700, John Stultz wrote:
>> When I added some extra sanity checking in timekeeping_get_ns() under
>> CONFIG_DEBUG_TIMEKEEPING, I missed that the NMI safe __ktime_get_fast_ns()
>> method was using timekeeping_get_ns().
>>
>> Thus the locking added to the debug checks broke the NMI-safety of
>> __ktime_get_fast_ns().
>>
>> This patch open-codes the timekeeping_get_ns() logic for
>> __ktime_get_fast_ns(), so can avoid any deadlocks in NMI.
>>
>> Cc: Steven Rostedt <rostedt@goodmis.org>
>> Cc: Peter Zijlstra <peterz@infradead.org>
>> Cc: Ingo Molnar <mingo@kernel.org>
>> Cc: Thomas Gleixner <tglx@linutronix.de>
>> Cc: stable <stable@vger.kernel.org> # 4.1+
>> Reported-by: Steven Rostedt <rostedt@goodmis.org>
>> Reported-by: Peter Zijlstra <peterz@infradead.org>
>> Signed-off-by: John Stultz <john.stultz@linaro.org>
>> ---
>> kernel/time/timekeeping.c | 5 ++++-
>> 1 file changed, 4 insertions(+), 1 deletion(-)
>>
>> diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
>> index 3b65746..e07fb09 100644
>> --- a/kernel/time/timekeeping.c
>> +++ b/kernel/time/timekeeping.c
>> @@ -401,7 +401,10 @@ static __always_inline u64 __ktime_get_fast_ns(struct tk_fast *tkf)
>> do {
>> seq = raw_read_seqcount_latch(&tkf->seq);
>> tkr = tkf->base + (seq & 0x01);
>> - now = ktime_to_ns(tkr->base) + timekeeping_get_ns(tkr);
>> + now = ktime_to_ns(tkr->base);
>> +
>> + now += clocksource_delta(tkr->read(tkr->clock),
>> + tkr->cycle_last, tkr->mask);
>
> we're seeing the time jumping backwards between __ktime_get_fast_ns calls.
> and looks like this patch broke it, since delta is being added to ns.
> It seems it should be:
> now += timekeeping_delta_to_ns(clocksource_delta(...));
> or better fix possible?
Gah! Yes. Quite right. I'm not sure how I missed that. Thanks for
catching it quickly and apologies!
I've got an initial fix but I'm sitting down for dinner so I'll send
it out a bit later after I can test it.
thanks
-john
[toc] | [prev] | [next] | [standalone]
| From | John Stultz <john.stultz@linaro.org> |
|---|---|
| Date | 2016-10-05 05:00 +0200 |
| Subject | [PATCH] timekeeping: Fix __ktime_get_fast_ns() regression |
| Message-ID | <soKB3-33h-3@gated-at.bofh.it> |
| In reply to | #1495635 |
In commit 27727df240c7 ("Avoid taking lock in NMI path with
CONFIG_DEBUG_TIMEKEEPING"), I changed the logic to open-code
the timekeeping_get_ns() function, but I forgot to include
the unit conversion from cycles to nanoseconds, breaking the
function's output, which impacts users like perf.
This would result in bogus perf timestamps like:
swapper 0 [000] 253.427536: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 254.426573: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 254.426687: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 254.426800: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 254.426905: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 254.427022: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 254.427127: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 254.427239: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 254.427346: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 254.427463: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 255.426572: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
Instead of more reasonable expected timestamps like:
swapper 0 [000] 39.953768: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 40.064839: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 40.175956: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 40.287103: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 40.398217: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 40.509324: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 40.620437: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 40.731546: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 40.842654: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 40.953772: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 41.064881: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
This patch adds the proper use of timekeeping_delta_to_ns()
to convert the cycle delta to nanoseconds as needed.
Thanks to Brendan and Alexei for finding this quickly after
the v4.8 release. Unfortunately the problematic commit has
landed in some -stable trees so they'll need this fix as
well.
Many apologies for this mistake. I'll be looking to add a
perf-clock sanity test to the kselftest timers tests soon.
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: stable <stable@vger.kernel.org>
Cc: Brendan Gregg <bgregg@netflix.com>
Cc: Alexei Starovoitov <alexei.starovoitov@gmail.com>
Fixes: 27727df240c7 "timekeeping: Avoid taking lock in NMI path with CONFIG_DEBUG_TIMEKEEPING"
Reported-by: Brendan Gregg <bgregg@netflix.com>
Reported-by: Alexei Starovoitov <alexei.starovoitov@gmail.com>
Signed-off-by: John Stultz <john.stultz@linaro.org>
---
Thomas/Ingo:
I've reproduced the issue and validated this fixes it, but given my limited perf
usage so far, I'd appreciate waiting for a Tested-by: from one of the reporters
before considering for tip/timers/urgent.
kernel/time/timekeeping.c | 7 +++++--
1 file changed, 5 insertions(+), 2 deletions(-)
diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
index e07fb09..37dec7e 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -403,8 +403,11 @@ static __always_inline u64 __ktime_get_fast_ns(struct tk_fast *tkf)
tkr = tkf->base + (seq & 0x01);
now = ktime_to_ns(tkr->base);
- now += clocksource_delta(tkr->read(tkr->clock),
- tkr->cycle_last, tkr->mask);
+ now += timekeeping_delta_to_ns(tkr,
+ clocksource_delta(
+ tkr->read(tkr->clock),
+ tkr->cycle_last,
+ tkr->mask));
} while (read_seqcount_retry(&tkf->seq, seq));
return now;
--
1.9.1
[toc] | [prev] | [next] | [standalone]
| From | Mathieu Desnoyers <mathieu.desnoyers@efficios.com> |
|---|---|
| Date | 2016-10-05 13:00 +0200 |
| Subject | Re: [PATCH] timekeeping: Fix __ktime_get_fast_ns() regression |
| Message-ID | <soS5A-8ff-17@gated-at.bofh.it> |
| In reply to | #1495675 |
----- On Oct 4, 2016, at 10:55 PM, John Stultz john.stultz@linaro.org wrote:
> In commit 27727df240c7 ("Avoid taking lock in NMI path with
> CONFIG_DEBUG_TIMEKEEPING"), I changed the logic to open-code
> the timekeeping_get_ns() function, but I forgot to include
> the unit conversion from cycles to nanoseconds, breaking the
> function's output, which impacts users like perf.
It also impacts LTTng. I've had reports of timestamp borkage from
LTTng end users yesterday with kernels 4.7.5 and 4.7.4.
Some stable branches sleuthing indicates that the following
kernel versions are affected: 4.8, 4.7.4+, 4.4.20+, 4.1.32+
I plan to add kernel version range checks in lttng-modules to
work-around this mess, but I need an upper bound. Is there any way
we can get this upstream and cherry-picked into stable branches
ASAP ?
Tested-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Reviewed-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
LTTng kernel traces with Linux 4.8:
[06:37:40.248222037] (+0.000001057) compudjdev power_cpu_idle: { cpu_id = 10 }, { state = 1, cpu_id = 10 }
[06:37:40.248222037] (+0.000000000) compudjdev x86_irq_vectors_local_timer_entry: { cpu_id = 10 }, { vector = 239 }
[06:37:40.248222037] (+0.000000000) compudjdev timer_hrtimer_cancel: { cpu_id = 10 }, { hrtimer = 0xFFFF880FC1692700 }
[06:37:40.248222037] (+0.000000000) compudjdev timer_hrtimer_expire_entry: { cpu_id = 10 }, { hrtimer = 0xFFFF880FC1692700, now = 211036043790, function = 0xFFFFFFFF8116FD40 }
[06:37:40.248222037] (+0.000000000) compudjdev irq_softirq_raise: { cpu_id = 10 }, { vec = 1 }
[06:37:40.248222037] (+0.000000000) compudjdev rcu_utilization: { cpu_id = 10 }, { s = "Start scheduler-tick" }
[06:37:40.248222037] (+0.000000000) compudjdev irq_softirq_raise: { cpu_id = 10 }, { vec = 9 }
[...]
% lttng view | grep "cpu_id = 0" | grep "(+0.000000000)" |wc -l
76156
LTTng kernel traces with Linux 4.8 + this fix applied:
[06:46:52.648061087] (+0.000001455) compudjdev power_cpu_idle: { cpu_id = 23 }, { state = 1, cpu_id = 23 }
[06:46:52.652011654] (+0.003950567) compudjdev x86_irq_vectors_local_timer_entry: { cpu_id = 9 }, { vector = 239 }
[06:46:52.652012324] (+0.000000670) compudjdev timer_hrtimer_cancel: { cpu_id = 9 }, { hrtimer = 0xFFFF880FC1652700 }
[06:46:52.652012654] (+0.000000330) compudjdev timer_hrtimer_expire_entry: { cpu_id = 9 }, { hrtimer = 0xFFFF880FC1652700, now = 91808012323, function = 0xFFFFFFFF8116FD80 }
[06:46:52.652013354] (+0.000000700) compudjdev irq_softirq_raise: { cpu_id = 9 }, { vec = 1 }
[06:46:52.652013784] (+0.000000430) compudjdev rcu_utilization: { cpu_id = 9 }, { s = "Start scheduler-tick" }
% lttng view | grep "cpu_id = 0" | grep "(+0.000000000)" |wc -l
2
Which confirms that this fix addresses the issue.
This issue seems to affect perf, ftrace "mono" clock source, and
eBPF in Linux.
Thanks,
Mathieu
>
> This would result in bogus perf timestamps like:
> swapper 0 [000] 253.427536: 111111111 cpu-clock: ffffffff810a0de6
> native_safe_halt+0x6 ([kernel.kallsyms])
> swapper 0 [000] 254.426573: 111111111 cpu-clock: ffffffff810a0de6
> native_safe_halt+0x6 ([kernel.kallsyms])
> swapper 0 [000] 254.426687: 111111111 cpu-clock: ffffffff810a0de6
> native_safe_halt+0x6 ([kernel.kallsyms])
> swapper 0 [000] 254.426800: 111111111 cpu-clock: ffffffff810a0de6
> native_safe_halt+0x6 ([kernel.kallsyms])
> swapper 0 [000] 254.426905: 111111111 cpu-clock: ffffffff810a0de6
> native_safe_halt+0x6 ([kernel.kallsyms])
> swapper 0 [000] 254.427022: 111111111 cpu-clock: ffffffff810a0de6
> native_safe_halt+0x6 ([kernel.kallsyms])
> swapper 0 [000] 254.427127: 111111111 cpu-clock: ffffffff810a0de6
> native_safe_halt+0x6 ([kernel.kallsyms])
> swapper 0 [000] 254.427239: 111111111 cpu-clock: ffffffff810a0de6
> native_safe_halt+0x6 ([kernel.kallsyms])
> swapper 0 [000] 254.427346: 111111111 cpu-clock: ffffffff810a0de6
> native_safe_halt+0x6 ([kernel.kallsyms])
> swapper 0 [000] 254.427463: 111111111 cpu-clock: ffffffff810a0de6
> native_safe_halt+0x6 ([kernel.kallsyms])
> swapper 0 [000] 255.426572: 111111111 cpu-clock: ffffffff810a0de6
> native_safe_halt+0x6 ([kernel.kallsyms])
>
> Instead of more reasonable expected timestamps like:
> swapper 0 [000] 39.953768: 111111111 cpu-clock: ffffffff810a0de6
> native_safe_halt+0x6 ([kernel.kallsyms])
> swapper 0 [000] 40.064839: 111111111 cpu-clock: ffffffff810a0de6
> native_safe_halt+0x6 ([kernel.kallsyms])
> swapper 0 [000] 40.175956: 111111111 cpu-clock: ffffffff810a0de6
> native_safe_halt+0x6 ([kernel.kallsyms])
> swapper 0 [000] 40.287103: 111111111 cpu-clock: ffffffff810a0de6
> native_safe_halt+0x6 ([kernel.kallsyms])
> swapper 0 [000] 40.398217: 111111111 cpu-clock: ffffffff810a0de6
> native_safe_halt+0x6 ([kernel.kallsyms])
> swapper 0 [000] 40.509324: 111111111 cpu-clock: ffffffff810a0de6
> native_safe_halt+0x6 ([kernel.kallsyms])
> swapper 0 [000] 40.620437: 111111111 cpu-clock: ffffffff810a0de6
> native_safe_halt+0x6 ([kernel.kallsyms])
> swapper 0 [000] 40.731546: 111111111 cpu-clock: ffffffff810a0de6
> native_safe_halt+0x6 ([kernel.kallsyms])
> swapper 0 [000] 40.842654: 111111111 cpu-clock: ffffffff810a0de6
> native_safe_halt+0x6 ([kernel.kallsyms])
> swapper 0 [000] 40.953772: 111111111 cpu-clock: ffffffff810a0de6
> native_safe_halt+0x6 ([kernel.kallsyms])
> swapper 0 [000] 41.064881: 111111111 cpu-clock: ffffffff810a0de6
> native_safe_halt+0x6 ([kernel.kallsyms])
>
> This patch adds the proper use of timekeeping_delta_to_ns()
> to convert the cycle delta to nanoseconds as needed.
>
> Thanks to Brendan and Alexei for finding this quickly after
> the v4.8 release. Unfortunately the problematic commit has
> landed in some -stable trees so they'll need this fix as
> well.
>
> Many apologies for this mistake. I'll be looking to add a
> perf-clock sanity test to the kselftest timers tests soon.
>
> Cc: Steven Rostedt <rostedt@goodmis.org>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Cc: Ingo Molnar <mingo@kernel.org>
> Cc: Thomas Gleixner <tglx@linutronix.de>
> Cc: stable <stable@vger.kernel.org>
> Cc: Brendan Gregg <bgregg@netflix.com>
> Cc: Alexei Starovoitov <alexei.starovoitov@gmail.com>
> Fixes: 27727df240c7 "timekeeping: Avoid taking lock in NMI path with
> CONFIG_DEBUG_TIMEKEEPING"
> Reported-by: Brendan Gregg <bgregg@netflix.com>
> Reported-by: Alexei Starovoitov <alexei.starovoitov@gmail.com>
> Signed-off-by: John Stultz <john.stultz@linaro.org>
> ---
> Thomas/Ingo:
> I've reproduced the issue and validated this fixes it, but given my limited perf
> usage so far, I'd appreciate waiting for a Tested-by: from one of the reporters
> before considering for tip/timers/urgent.
>
> kernel/time/timekeeping.c | 7 +++++--
> 1 file changed, 5 insertions(+), 2 deletions(-)
>
> diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
> index e07fb09..37dec7e 100644
> --- a/kernel/time/timekeeping.c
> +++ b/kernel/time/timekeeping.c
> @@ -403,8 +403,11 @@ static __always_inline u64 __ktime_get_fast_ns(struct
> tk_fast *tkf)
> tkr = tkf->base + (seq & 0x01);
> now = ktime_to_ns(tkr->base);
>
> - now += clocksource_delta(tkr->read(tkr->clock),
> - tkr->cycle_last, tkr->mask);
> + now += timekeeping_delta_to_ns(tkr,
> + clocksource_delta(
> + tkr->read(tkr->clock),
> + tkr->cycle_last,
> + tkr->mask));
> } while (read_seqcount_retry(&tkf->seq, seq));
>
> return now;
> --
> 1.9.1
--
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com
[toc] | [prev] | [next] | [standalone]
| From | tip-bot for John Stultz <tipbot@zytor.com> |
|---|---|
| Date | 2016-10-05 16:00 +0200 |
| Subject | [tip:timers/urgent] timekeeping: Fix __ktime_get_fast_ns() regression |
| Message-ID | <soUTM-1HA-5@gated-at.bofh.it> |
| In reply to | #1495675 |
Commit-ID: 58bfea9532552d422bde7afa207e1a0f08dffa7d
Gitweb: http://git.kernel.org/tip/58bfea9532552d422bde7afa207e1a0f08dffa7d
Author: John Stultz <john.stultz@linaro.org>
AuthorDate: Tue, 4 Oct 2016 19:55:48 -0700
Committer: Thomas Gleixner <tglx@linutronix.de>
CommitDate: Wed, 5 Oct 2016 15:44:46 +0200
timekeeping: Fix __ktime_get_fast_ns() regression
In commit 27727df240c7 ("Avoid taking lock in NMI path with
CONFIG_DEBUG_TIMEKEEPING"), I changed the logic to open-code
the timekeeping_get_ns() function, but I forgot to include
the unit conversion from cycles to nanoseconds, breaking the
function's output, which impacts users like perf.
This results in bogus perf timestamps like:
swapper 0 [000] 253.427536: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 254.426573: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 254.426687: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 254.426800: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 254.426905: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 254.427022: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 254.427127: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 254.427239: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 254.427346: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 254.427463: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 255.426572: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
Instead of more reasonable expected timestamps like:
swapper 0 [000] 39.953768: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 40.064839: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 40.175956: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 40.287103: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 40.398217: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 40.509324: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 40.620437: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 40.731546: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 40.842654: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 40.953772: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
swapper 0 [000] 41.064881: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms])
Add the proper use of timekeeping_delta_to_ns() to convert
the cycle delta to nanoseconds as needed.
Thanks to Brendan and Alexei for finding this quickly after
the v4.8 release. Unfortunately the problematic commit has
landed in some -stable trees so they'll need this fix as
well.
Many apologies for this mistake. I'll be looking to add a
perf-clock sanity test to the kselftest timers tests soon.
Fixes: 27727df240c7 "timekeeping: Avoid taking lock in NMI path with CONFIG_DEBUG_TIMEKEEPING"
Reported-by: Brendan Gregg <bgregg@netflix.com>
Reported-by: Alexei Starovoitov <alexei.starovoitov@gmail.com>
Tested-and-reviewed-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: John Stultz <john.stultz@linaro.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: stable <stable@vger.kernel.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Link: http://lkml.kernel.org/r/1475636148-26539-1-git-send-email-john.stultz@linaro.org
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
---
kernel/time/timekeeping.c | 7 +++++--
1 file changed, 5 insertions(+), 2 deletions(-)
diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
index e07fb09..37dec7e 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -403,8 +403,11 @@ static __always_inline u64 __ktime_get_fast_ns(struct tk_fast *tkf)
tkr = tkf->base + (seq & 0x01);
now = ktime_to_ns(tkr->base);
- now += clocksource_delta(tkr->read(tkr->clock),
- tkr->cycle_last, tkr->mask);
+ now += timekeeping_delta_to_ns(tkr,
+ clocksource_delta(
+ tkr->read(tkr->clock),
+ tkr->cycle_last,
+ tkr->mask));
} while (read_seqcount_retry(&tkf->seq, seq));
return now;
[toc] | [prev] | [standalone]
Back to top | Article view | linux.kernel
csiph-web