Re: [PATCH -v3] perf, x86: try to handle unknown nmis with running perfctrs

Robert Richter
2010-08-25T10:11:23Z

On 20.08.10 11:25:10, Ingo Molnar wrote:

> > Ingo Molnar <mingo@elte.hu> wrote:
> >
> > >
> > >it's not working so well, i'm getting:
> > >
> > > Uhhuh. NMI received for unknown reason 00 on CPU 9.
> > > Do you have a strange power saving mode enabled?
> > > Dazed and confused, but trying to continue
> > >
> > >on a nehalem box, after a perf top and perf stat run.
>
> FYI, it does not trigger on an AMD box.

Ingo,

do you mean it does not trigger false positives on AMD? Both patches
applied on top of current tip/perf/urgent (c6db67c) are working on the
systems I have.

You might use the debug patch below for diagnostics.

-Robert

--

>From 1bbb5aa64e96360529c34a593a072e1a84114f04 Mon Sep 17 00:00:00 2001
From: Robert Richter <robert.richter@amd.com>
Date: Wed, 11 Aug 2010 18:14:00 +0200
Subject: [PATCH] debug

Signed-off-by: Robert Richter <robert.richter@amd.com>
---
arch/x86/kernel/cpu/perf_event.c | 54 ++++++++++++++++++++++++++++++++++++-
1 files changed, 52 insertions(+), 2 deletions(-)

diff --git a/arch/x86/kernel/cpu/perf_event.c b/arch/x86/kernel/cpu/perf_event.c
index dd2fceb..059ef09 100644
--- a/arch/x86/kernel/cpu/perf_event.c
+++ b/arch/x86/kernel/cpu/perf_event.c
@@ -1203,10 +1203,43 @@ void perf_events_lapic_init(void)
struct pmu_nmi_state {
unsigned int marked;
int handled;
+ u64 timestamp;
};

static DEFINE_PER_CPU(struct pmu_nmi_state, nmi);

+struct nmi_debug {
+ int cpu;
+ unsigned int this_nmi;
+ unsigned int marked;
+ int handled;
+ u64 timestamp;
+ u64 delta;
+};
+
+static DEFINE_PER_CPU(struct nmi_debug[16], nmi_debug);
+
+static void nmi_handler_debug(void)
+{
+ struct nmi_debug *debug;
+ int i;
+
+ if (!printk_ratelimit())
+ return;
+
+ for (i = 0; i < 16; i++) {
+ debug = &__get_cpu_var(nmi_debug)[i];
+ printk(KERN_EMERG
+ "cpu #%d, nmi #%d, marked #%d, handled = %d, time = %llu, delta = %llu\n",
+ debug->cpu,
+ debug->this_nmi,
+ debug->marked,
+ debug->handled,
+ debug->timestamp,
+ debug->delta);
+ }
+}
+
static int __kprobes
perf_event_nmi_handler(struct notifier_block *self,
unsigned long cmd, void *__args)
@@ -1214,6 +1247,8 @@ perf_event_nmi_handler(struct notifier_block *self,
struct die_args *args = __args;
unsigned int this_nmi;
int handled;
+ struct nmi_debug *debug;
+ u64 timestamp;

if (!atomic_read(&active_events))
return NOTIFY_DONE;
@@ -1224,9 +1259,11 @@ perf_event_nmi_handler(struct notifier_block *self,
break;
case DIE_NMIUNKNOWN:
this_nmi = percpu_read(irq_stat.__nmi_count);
- if (this_nmi != __get_cpu_var(nmi).marked)
+ if (this_nmi != __get_cpu_var(nmi).marked) {
+ nmi_handler_debug();
/* let the kernel handle the unknown nmi */
return NOTIFY_DONE;
+ }
/*
* This one is a PMU back-to-back nmi. Two events
* trigger 'simultaneously' raising two back-to-back
@@ -1242,10 +1279,21 @@ perf_event_nmi_handler(struct notifier_block *self,
apic_write(APIC_LVTPC, APIC_DM_NMI);

handled = x86_pmu.handle_irq(args->regs);
+ this_nmi = percpu_read(irq_stat.__nmi_count);
+
+ debug = &__get_cpu_var(nmi_debug)[0xf & this_nmi];
+ debug->cpu = smp_processor_id();
+ debug->this_nmi = this_nmi;
+ debug->marked = __get_cpu_var(nmi).marked;
+ debug->handled = handled;
+ rdtscll(timestamp);
+ debug->delta = timestamp - __get_cpu_var(nmi).timestamp;
+ __get_cpu_var(nmi).timestamp = timestamp;
+ debug->timestamp = timestamp;
+
if (!handled)
return NOTIFY_DONE;

- this_nmi = percpu_read(irq_stat.__nmi_count);
if ((handled > 1) ||
/* the next nmi could be a back-to-back nmi */
((__get_cpu_var(nmi).marked == this_nmi) &&
@@ -1262,6 +1310,8 @@ perf_event_nmi_handler(struct notifier_block *self,
*/
__get_cpu_var(nmi).marked = this_nmi + 1;
__get_cpu_var(nmi).handled = handled;
+ debug->marked = __get_cpu_var(nmi).marked;
+ debug->handled = handled;
}

return NOTIFY_STOP;
--
1.7.1.1

--
Advanced Micro Devices, Inc.
Operating System Research Center