[PATCH] x86/nmi: Ignore negative NMI handler durations

[PATCH] x86/nmi: Ignore negative NMI handler durations

[Breno Leitao]

I am seeing NMI handlers in the Meta fleet reported as running for
about 584 years. Over 30 days, 11 AMD and Intel machines logged 637
such lines, for example:

  AMD EPYC 9D25 (family 0x1a, model 0x11, stepping 0x0):
  [ 1650.616627] INFO: NMI handler (nmi_cpu_backtrace_handler.llvm.9643156322683129580) took too long to run: 18446744073709.551 msecs

  Intel Xeon Platinum 8321HC (family 0x6, model 0x55, stepping 0xb):
  [360448.230129] INFO: NMI handler (perf_event_nmi_handler) took too long to run: 18446744071018.936 msecs

  Intel Xeon D-2191A (family 0x6, model 0x55, stepping 0x4):
  [81787.188959] INFO: NMI handler (ghes_notify_nmi) took too long to run: 18446744073709.545 msecs

nmi_handle() times each handler with two sched_clock() reads. When the
second read is lower than the first, the u64 subtraction wraps, and
nmi_check_duration() treats the result as a duration. In the three
examples, the clock went back by less than 1 us, by 2.7 s and by about
6 us.

The wrapped value is also stored in action->max_duration. Every later
real duration is smaller, so the handler is never reported again until
the next boot.

Whatever makes the clock read lower, a negative difference is not a
duration, so return before it is stored or reported. A clock that steps
forward is not covered, since that cannot be told from a real stall.

A backwards clock is still worth knowing about, so print the size of
the step once per boot. This uses pr_warn_once() rather than WARN, as a
stack trace says nothing about the clock and panic_on_warn machines
should not go down for it.

Fixes: 2ab00456ea8a ("x86: Warn when NMI handlers take large amounts of time")
Cc: stable@vger.kernel.org
Cc: Paul E. McKenney <paulmck@kernel.org>
Signed-off-by: Breno Leitao <leitao@debian.org>
---
 arch/x86/kernel/nmi.c | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/arch/x86/kernel/nmi.c b/arch/x86/kernel/nmi.c
index aae7254774680..57a0dab1ec7a9 100644
--- a/arch/x86/kernel/nmi.c
+++ b/arch/x86/kernel/nmi.c
@@ -130,6 +130,14 @@ static void nmi_check_duration(struct nmiaction *action, u64 duration, struct pt
 {
 	int remainder_ns, decimal_msecs;
 
+	/* sched_clock() went backwards? */
+	if ((s64)duration < 0) {
+		pr_warn_once("NMI handler (%ps): sched_clock() went backwards by %lld ns on CPU%d\n",
+			     action->handler, -(s64)duration,
+			     smp_processor_id());
+		return;
+	}
+
 	if (duration < nmi_longest_ns || duration < action->max_duration)
 		return;
 

---
base-commit: f1ac44c32cba88ad65dcecd4a279661d14e93651
base-tree: git://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git master
change-id: 20261027-nmi_negative-876c14def27b

Best regards,
--  
Breno Leitao <leitao@debian.org>

Re: [PATCH] x86/nmi: Ignore negative NMI handler durations

[Peter Zijlstra]

On Tue, Oct 27, 2026 at 03:43:51AM -0700, Breno Leitao wrote:
> I am seeing NMI handlers in the Meta fleet reported as running for
> about 584 years. Over 30 days, 11 AMD and Intel machines logged 637
> such lines, for example:
> 
>   AMD EPYC 9D25 (family 0x1a, model 0x11, stepping 0x0):
>   [ 1650.616627] INFO: NMI handler (nmi_cpu_backtrace_handler.llvm.9643156322683129580) took too long to run: 18446744073709.551 msecs
> 
>   Intel Xeon Platinum 8321HC (family 0x6, model 0x55, stepping 0xb):
>   [360448.230129] INFO: NMI handler (perf_event_nmi_handler) took too long to run: 18446744071018.936 msecs
> 
>   Intel Xeon D-2191A (family 0x6, model 0x55, stepping 0x4):
>   [81787.188959] INFO: NMI handler (ghes_notify_nmi) took too long to run: 18446744073709.545 msecs

All these are 'recent' machine and should have a stable TSC :-( I hate
computers.

> nmi_handle() times each handler with two sched_clock() reads. When the
> second read is lower than the first, the u64 subtraction wraps, and
> nmi_check_duration() treats the result as a duration. In the three
> examples, the clock went back by less than 1 us, by 2.7 s and by about
> 6 us.
> 
> The wrapped value is also stored in action->max_duration. Every later
> real duration is smaller, so the handler is never reported again until
> the next boot.
> 
> Whatever makes the clock read lower, a negative difference is not a
> duration, so return before it is stored or reported. A clock that steps
> forward is not covered, since that cannot be told from a real stall.
> 
> A backwards clock is still worth knowing about, so print the size of
> the step once per boot. This uses pr_warn_once() rather than WARN, as a
> stack trace says nothing about the clock and panic_on_warn machines
> should not go down for it.
> 
> Fixes: 2ab00456ea8a ("x86: Warn when NMI handlers take large amounts of time")
> Cc: stable@vger.kernel.org
> Cc: Paul E. McKenney <paulmck@kernel.org>
> Signed-off-by: Breno Leitao <leitao@debian.org>
> ---
>  arch/x86/kernel/nmi.c | 8 ++++++++
>  1 file changed, 8 insertions(+)
> 
> diff --git a/arch/x86/kernel/nmi.c b/arch/x86/kernel/nmi.c
> index aae7254774680..57a0dab1ec7a9 100644
> --- a/arch/x86/kernel/nmi.c
> +++ b/arch/x86/kernel/nmi.c
> @@ -130,6 +130,14 @@ static void nmi_check_duration(struct nmiaction *action, u64 duration, struct pt
>  {
>  	int remainder_ns, decimal_msecs;
>  
> +	/* sched_clock() went backwards? */
> +	if ((s64)duration < 0) {
> +		pr_warn_once("NMI handler (%ps): sched_clock() went backwards by %lld ns on CPU%d\n",
> +			     action->handler, -(s64)duration,
> +			     smp_processor_id());
> +		return;
> +	}

Fair enough I suppose. Thanks

Re: [PATCH] x86/nmi: Ignore negative NMI handler durations

[Rik van Riel]

On Tue, 2026-10-27 at 03:43 -0700, Breno Leitao wrote:
> I am seeing NMI handlers in the Meta fleet reported as running for
> about 584 years. Over 30 days, 11 AMD and Intel machines logged 637
> such lines, for example:
> 
>   AMD EPYC 9D25 (family 0x1a, model 0x11, stepping 0x0):
>   [ 1650.616627] INFO: NMI handler
> (nmi_cpu_backtrace_handler.llvm.9643156322683129580) took too long to
> run: 18446744073709.551 msecs
> 
>   Intel Xeon Platinum 8321HC (family 0x6, model 0x55, stepping 0xb):
>   [360448.230129] INFO: NMI handler (perf_event_nmi_handler) took too
> long to run: 18446744071018.936 msecs
> 
>   Intel Xeon D-2191A (family 0x6, model 0x55, stepping 0x4):
>   [81787.188959] INFO: NMI handler (ghes_notify_nmi) took too long to
> run: 18446744073709.545 msecs
> 
> nmi_handle() times each handler with two sched_clock() reads. When
> the
> second read is lower than the first, the u64 subtraction wraps, and
> nmi_check_duration() treats the result as a duration. In the three
> examples, the clock went back by less than 1 us, by 2.7 s and by
> about
> 6 us.
> 
The comment above ktime_get_mono_fast_ns() makes
me wonder whether for time deltas we should read
raw TSC values, and calculate the time delta between
them afterward.

The reason is that another CPU might adjust the time
slope between the first and second timestamp read.
I pasted the comment below.

Of course, that still leaves the actual misbehaving
CPUs. A two second time difference is not explained
by a clock conversion adjustment, so I suspect we 
will need this patch either way...

/**
 * ktime_get_mono_fast_ns - Fast NMI safe access to clock monotonic
 *
 * This timestamp is not guaranteed to be monotonic across an update.
 * The timestamp is calculated by:
 *
 *      now = base_mono + clock_delta * slope
 *
 * So if the update lowers the slope, readers who are forced to the
 * not yet updated second array are still using the old steeper slope.
 *
 * tmono
 * ^
 * |    o  n
 * |   o n
 * |  u
 * | o
 * |o
 * |12345678---> reader order
 *
 * o = old slope
 * u = update
 * n = new slope
 *
 * So reader 6 will observe time going backwards versus reader 5.
 *
 * While other CPUs are likely to be able to observe that, the only way
 * for a CPU local observation is when an NMI hits in the middle of
 * the update. Timestamps taken from that NMI context might be ahead
 * of the following timestamps. Callers need to be aware of that and
 * deal with it.
 */




-- 
All Rights Reversed.

Re: [PATCH] x86/nmi: Ignore negative NMI handler durations

[Peter Zijlstra]

On Tue, Oct 27, 2026 at 12:25:20PM -0400, Rik van Riel wrote:
> On Tue, 2026-10-27 at 03:43 -0700, Breno Leitao wrote:
> > I am seeing NMI handlers in the Meta fleet reported as running for
> > about 584 years. Over 30 days, 11 AMD and Intel machines logged 637
> > such lines, for example:
> > 
> >   AMD EPYC 9D25 (family 0x1a, model 0x11, stepping 0x0):
> >   [ 1650.616627] INFO: NMI handler
> > (nmi_cpu_backtrace_handler.llvm.9643156322683129580) took too long to
> > run: 18446744073709.551 msecs
> > 
> >   Intel Xeon Platinum 8321HC (family 0x6, model 0x55, stepping 0xb):
> >   [360448.230129] INFO: NMI handler (perf_event_nmi_handler) took too
> > long to run: 18446744071018.936 msecs
> > 
> >   Intel Xeon D-2191A (family 0x6, model 0x55, stepping 0x4):
> >   [81787.188959] INFO: NMI handler (ghes_notify_nmi) took too long to
> > run: 18446744073709.545 msecs
> > 
> > nmi_handle() times each handler with two sched_clock() reads. When
> > the
> > second read is lower than the first, the u64 subtraction wraps, and
> > nmi_check_duration() treats the result as a duration. In the three
> > examples, the clock went back by less than 1 us, by 2.7 s and by
> > about
> > 6 us.
> > 
> The comment above ktime_get_mono_fast_ns() makes
> me wonder whether for time deltas we should read
> raw TSC values, and calculate the time delta between
> them afterward.
> 

This is sched_clock(); that *never* changes slope -- after boot, on sane
hardware.