[PATCH 1/2] timekeeping: Avoid taking lock in NMI path with CONFIG_DEBUG_TIMEKEEPING

[PATCH 1/2] timekeeping: Avoid taking lock in NMI path with CONFIG_DEBUG_TIMEKEEPING

[John Stultz]

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);
 	} while (read_seqcount_retry(&tkf->seq, seq));
 
 	return now;
-- 
1.9.1

[tip:timers/urgent] timekeeping: Avoid taking lock in NMI path with CONFIG_DEBUG_TIMEKEEPING

[tip-bot for John Stultz]

Commit-ID:  27727df240c7cc84f2ba6047c6f18d5addfd25ef
Gitweb:     http://git.kernel.org/tip/27727df240c7cc84f2ba6047c6f18d5addfd25ef
Author:     John Stultz <john.stultz@linaro.org>
AuthorDate: Tue, 23 Aug 2016 16:08:21 -0700
Committer:  Thomas Gleixner <tglx@linutronix.de>
CommitDate: Wed, 24 Aug 2016 09:34:31 +0200

timekeeping: Avoid taking lock in NMI path with CONFIG_DEBUG_TIMEKEEPING

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.

Fixes: 4ca22c2648f9 "timekeeping: Add warnings when overflows or underflows are observed"
Reported-by: Steven Rostedt <rostedt@goodmis.org>
Reported-by: Peter Zijlstra <peterz@infradead.org>
Signed-off-by: John Stultz <john.stultz@linaro.org>
Cc: stable <stable@vger.kernel.org>
Link: http://lkml.kernel.org/r/1471993702-29148-2-git-send-email-john.stultz@linaro.org
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>

---
 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);
 	} while (read_seqcount_retry(&tkf->seq, seq));
 
 	return now;

Re: [PATCH 1/2] timekeeping: Avoid taking lock in NMI path with CONFIG_DEBUG_TIMEKEEPING

[Alexei Starovoitov]

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)

Re: [PATCH 1/2] timekeeping: Avoid taking lock in NMI path with CONFIG_DEBUG_TIMEKEEPING

[John Stultz]

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

[PATCH] timekeeping: Fix __ktime_get_fast_ns() regression

[John Stultz]

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

Re: [PATCH] timekeeping: Fix __ktime_get_fast_ns() regression

[Mathieu Desnoyers]

----- 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

[tip:timers/urgent] timekeeping: Fix __ktime_get_fast_ns() regression

[tip-bot for John Stultz]

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;

[PATCH 2/2] timekeeping: Cap array access in timekeeping_debug to protect against invalid sleep times

[John Stultz]

It was reported that hibernation could fail on the 2nd attempt,
where the system hangs at hibernate() -> syscore_resume() ->
i8237A_resume() -> claim_dma_lock(), because the lock has
already been taken.

However there is actually no other process would like to grab
this lock on that problematic platform.

Further investigation showed that the problem is triggered by
setting /sys/power/pm_trace to 1 before the 1st hibernation.

Since once pm_trace is enabled, the rtc becomes unmeaningful
after suspend, and meanwhile some BIOSes would like to adjust
the 'invalid' tsc(e.g, smaller than 1970) to the release date
of that motherboard during POST stage, thus after resumed, it
may seem that the system had a significant long sleep time might
due to meaningless tsc or RTC delta.

Then in timekeeping_resume -> tk_debug_account_sleep_time, if
the bit31 of the sleep time happened to be set to 1, the fls
returns 32 and then we add 1 to sleep_time_bin[32], which
caused a memory overwritten.

As depicted by System.map:
0xffffffff81c9d080 b sleep_time_bin
0xffffffff81c9d100 B dma_spin_lock
the dma_spin_lock.val is set to 1, which caused this problem.

This patch adds a sanity check in tk_debug_account_sleep_time()
to ensure we don't index past the sleep_time_bin array.

Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Rafael J. Wysocki <rjw@rjwysocki.net>
Cc: Janek Kozicki <cosurgi@gmail.com>
Cc: Chen Yu <yu.c.chen@intel.com>
Cc: Xunlei Pang <xpang@redhat.com>
Cc: Zhang Rui <rui.zhang@intel.com>
Cc: linux-pm@vger.kernel.org
Cc: stable <stable@vger.kernel.org>
Reported-by: Janek Kozicki <cosurgi@gmail.com>
Reported-by: Chen Yu <yu.c.chen@intel.com>
[jstultz: Problem diagnosed and original patch by Chen Yu, I've
 solved the issue slightly differently, but borrowed his excelent
 explanation of of the issue here.]
Signed-off-by: John Stultz <john.stultz@linaro.org>
---
 kernel/time/timekeeping_debug.c | 9 +++++++--
 1 file changed, 7 insertions(+), 2 deletions(-)

diff --git a/kernel/time/timekeeping_debug.c b/kernel/time/timekeeping_debug.c
index f6bd652..107310a6 100644
--- a/kernel/time/timekeeping_debug.c
+++ b/kernel/time/timekeeping_debug.c
@@ -23,7 +23,9 @@
 
 #include "timekeeping_internal.h"
 
-static unsigned int sleep_time_bin[32] = {0};
+#define NUM_BINS 32
+
+static unsigned int sleep_time_bin[NUM_BINS] = {0};
 
 static int tk_debug_show_sleep_time(struct seq_file *s, void *data)
 {
@@ -69,6 +71,9 @@ late_initcall(tk_debug_sleep_time_init);
 
 void tk_debug_account_sleep_time(struct timespec64 *t)
 {
-	sleep_time_bin[fls(t->tv_sec)]++;
+	/* Cap bin index so we don't overflow the array */
+	int bin = min(fls(t->tv_sec), NUM_BINS-1);
+
+	sleep_time_bin[bin]++;
 }
 
-- 
1.9.1

Re: [PATCH 2/2] timekeeping: Cap array access in timekeeping_debug to protect against invalid sleep times

[Chen Yu]

Hi John, some small typos below, others should be OK.

On Tue, Aug 23, 2016 at 04:08:22PM -0700, John Stultz wrote:
> It was reported that hibernation could fail on the 2nd attempt,
> where the system hangs at hibernate() -> syscore_resume() ->
> i8237A_resume() -> claim_dma_lock(), because the lock has
> already been taken.
> 
> However there is actually no other process would like to grab
> this lock on that problematic platform.
> 
> Further investigation showed that the problem is triggered by
> setting /sys/power/pm_trace to 1 before the 1st hibernation.
> 
> Since once pm_trace is enabled, the rtc becomes unmeaningful
> after suspend, and meanwhile some BIOSes would like to adjust
> the 'invalid' tsc(e.g, smaller than 1970) to the release date
I checked the previous commit log, and I have made a mistake, it
should be:
s/tsc/RTC
> of that motherboard during POST stage, thus after resumed, it
> may seem that the system had a significant long sleep time might
> due to meaningless tsc or RTC delta.
s/tsc or RTC/RTC
> 
> Then in timekeeping_resume -> tk_debug_account_sleep_time, if
> the bit31 of the sleep time happened to be set to 1, the fls
> returns 32 and then we add 1 to sleep_time_bin[32], which
> caused a memory overwritten.
> 
> As depicted by System.map:
> 0xffffffff81c9d080 b sleep_time_bin
> 0xffffffff81c9d100 B dma_spin_lock
> the dma_spin_lock.val is set to 1, which caused this problem.
> 
> This patch adds a sanity check in tk_debug_account_sleep_time()
> to ensure we don't index past the sleep_time_bin array.
> 
BTW, I've also post a fix to deal with pm_trace which might break
timekeeping at:
https://patchwork.kernel.org/patch/9287347/
could you please hel take a glance? thanks.

Yu

Re: [PATCH 2/2] timekeeping: Cap array access in timekeeping_debug to protect against invalid sleep times

[John Stultz]

On Tue, Aug 23, 2016 at 5:58 PM, Chen Yu <yu.c.chen@intel.com> wrote:
> Hi John, some small typos below, others should be OK.

Thanks. I realize you mailed me before on this, but I forgot to
integrate the changes. Apologies.

I've now integrated the changes and updated the git branch.  The HEAD
for the pull request is now: 4efd3c8faf189674eeafb0c14ff4c556ed6adcf7.

I'll send an updated v2 patch here shortly.

thanks
-john

[RFC][PATCH v2] timekeeping: Cap array access in timekeeping_debug to protect against invalid sleep times

[John Stultz]

It was reported that hibernation could fail on the 2nd attempt,
where the system hangs at hibernate() -> syscore_resume() ->
i8237A_resume() -> claim_dma_lock(), because the lock has
already been taken.

However there is actually no other process would like to grab
this lock on that problematic platform.

Further investigation showed that the problem is triggered by
setting /sys/power/pm_trace to 1 before the 1st hibernation.

Since once pm_trace is enabled, the RTC becomes unmeaningful
after suspend, and meanwhile some BIOSes would like to adjust
the 'invalid' RTC (e.g, smaller than 1970) to the release date
of that motherboard during POST stage, thus after resumed, it
may seem that the system had a significant long sleep time might
due to meaningless RTC delta.

Then in timekeeping_resume -> tk_debug_account_sleep_time, if
the bit31 of the sleep time happened to be set to 1, the fls
returns 32 and then we add 1 to sleep_time_bin[32], which
caused a memory overwritten.

As depicted by System.map:
0xffffffff81c9d080 b sleep_time_bin
0xffffffff81c9d100 B dma_spin_lock
the dma_spin_lock.val is set to 1, which caused this problem.

This patch adds a sanity check in tk_debug_account_sleep_time()
to ensure we don't index past the sleep_time_bin array.

Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Rafael J. Wysocki <rjw@rjwysocki.net>
Cc: Janek Kozicki <cosurgi@gmail.com>
Cc: Chen Yu <yu.c.chen@intel.com>
Cc: Xunlei Pang <xpang@redhat.com>
Cc: Zhang Rui <rui.zhang@intel.com>
Cc: linux-pm@vger.kernel.org
Cc: stable <stable@vger.kernel.org>
Reported-by: Janek Kozicki <cosurgi@gmail.com>
Reported-by: Chen Yu <yu.c.chen@intel.com>
[jstultz: Problem diagnosed and original patch by Chen Yu, I've
 solved the issue slightly differently, but borrowed his excelent
 explanation of of the issue here.]
Signed-off-by: John Stultz <john.stultz@linaro.org>
---
v2: Minor tweaks to the commit message

 kernel/time/timekeeping_debug.c | 9 +++++++--
 1 file changed, 7 insertions(+), 2 deletions(-)

diff --git a/kernel/time/timekeeping_debug.c b/kernel/time/timekeeping_debug.c
index f6bd652..107310a6 100644
--- a/kernel/time/timekeeping_debug.c
+++ b/kernel/time/timekeeping_debug.c
@@ -23,7 +23,9 @@
 
 #include "timekeeping_internal.h"
 
-static unsigned int sleep_time_bin[32] = {0};
+#define NUM_BINS 32
+
+static unsigned int sleep_time_bin[NUM_BINS] = {0};
 
 static int tk_debug_show_sleep_time(struct seq_file *s, void *data)
 {
@@ -69,6 +71,9 @@ late_initcall(tk_debug_sleep_time_init);
 
 void tk_debug_account_sleep_time(struct timespec64 *t)
 {
-	sleep_time_bin[fls(t->tv_sec)]++;
+	/* Cap bin index so we don't overflow the array */
+	int bin = min(fls(t->tv_sec), NUM_BINS-1);
+
+	sleep_time_bin[bin]++;
 }
 
-- 
1.9.1

[tip:timers/urgent] timekeeping: Cap array access in timekeeping_debug

[tip-bot for John Stultz]

Commit-ID:  a4f8f6667f099036c88f231dcad4cf233652c824
Gitweb:     http://git.kernel.org/tip/a4f8f6667f099036c88f231dcad4cf233652c824
Author:     John Stultz <john.stultz@linaro.org>
AuthorDate: Tue, 23 Aug 2016 16:08:22 -0700
Committer:  Thomas Gleixner <tglx@linutronix.de>
CommitDate: Wed, 24 Aug 2016 09:34:32 +0200

timekeeping: Cap array access in timekeeping_debug

It was reported that hibernation could fail on the 2nd attempt, where the
system hangs at hibernate() -> syscore_resume() -> i8237A_resume() ->
claim_dma_lock(), because the lock has already been taken.

However there is actually no other process would like to grab this lock on
that problematic platform.

Further investigation showed that the problem is triggered by setting
/sys/power/pm_trace to 1 before the 1st hibernation.

Since once pm_trace is enabled, the rtc becomes unmeaningful after suspend,
and meanwhile some BIOSes would like to adjust the 'invalid' RTC (e.g, smaller
than 1970) to the release date of that motherboard during POST stage, thus
after resumed, it may seem that the system had a significant long sleep time
which is a completely meaningless value.

Then in timekeeping_resume -> tk_debug_account_sleep_time, if the bit31 of the
sleep time happened to be set to 1, fls() returns 32 and we add 1 to
sleep_time_bin[32], which causes an out of bounds array access and therefor
memory being overwritten.

As depicted by System.map:
0xffffffff81c9d080 b sleep_time_bin
0xffffffff81c9d100 B dma_spin_lock
the dma_spin_lock.val is set to 1, which caused this problem.

This patch adds a sanity check in tk_debug_account_sleep_time()
to ensure we don't index past the sleep_time_bin array.

[jstultz: Problem diagnosed and original patch by Chen Yu, I've solved the
 issue slightly differently, but borrowed his excelent explanation of the
 issue here.]

Fixes: 5c83545f24ab "power: Add option to log time spent in suspend"
Reported-by: Janek Kozicki <cosurgi@gmail.com>
Reported-by: Chen Yu <yu.c.chen@intel.com>
Signed-off-by: John Stultz <john.stultz@linaro.org>
Cc: linux-pm@vger.kernel.org
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Xunlei Pang <xpang@redhat.com>
Cc: "Rafael J. Wysocki" <rjw@rjwysocki.net>
Cc: stable <stable@vger.kernel.org>
Cc: Zhang Rui <rui.zhang@intel.com>
Link: http://lkml.kernel.org/r/1471993702-29148-3-git-send-email-john.stultz@linaro.org
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>

---
 kernel/time/timekeeping_debug.c | 9 +++++++--
 1 file changed, 7 insertions(+), 2 deletions(-)

diff --git a/kernel/time/timekeeping_debug.c b/kernel/time/timekeeping_debug.c
index f6bd652..107310a 100644
--- a/kernel/time/timekeeping_debug.c
+++ b/kernel/time/timekeeping_debug.c
@@ -23,7 +23,9 @@
 
 #include "timekeeping_internal.h"
 
-static unsigned int sleep_time_bin[32] = {0};
+#define NUM_BINS 32
+
+static unsigned int sleep_time_bin[NUM_BINS] = {0};
 
 static int tk_debug_show_sleep_time(struct seq_file *s, void *data)
 {
@@ -69,6 +71,9 @@ late_initcall(tk_debug_sleep_time_init);
 
 void tk_debug_account_sleep_time(struct timespec64 *t)
 {
-	sleep_time_bin[fls(t->tv_sec)]++;
+	/* Cap bin index so we don't overflow the array */
+	int bin = min(fls(t->tv_sec), NUM_BINS-1);
+
+	sleep_time_bin[bin]++;
 }