Re: x86_pmu_start WARN_ON.

From: Vince Weaver
Date: Thu Feb 13 2014 - 17:11:56 EST

On Thu, 13 Feb 2014, Vince Weaver wrote:

> The plot thickens. The WARN_ON is not caused by the cycles event that we
> open, but it's caused by the NMI Watchdog cycles event.

The WARN_ON_ONCE at line 1076 in perf_event.c is triggering because
in x86_pmu_enable() is calling x86_pmu_start() for all of the active x86
events (three plus the NMI watchdog) the NMI watchdog is unexpectedly
not having PERF_HES_STOPPED set (it's hw.state is 0).

What's the deal with the PERF_HES_STOPPED name? Is HES an acronym?
Or is it just a male event?
Also it's not really clear what PERF_HES_ARCH indicates.

Things rapidly get complicated beyond that, as the NMI watchdog is a
kernel-created event bound to the CPU, wheras 2 of the events are x86 hw
events with a breakpoint-event groupleader (and the fact one of the events
has precise set).

>From the stacktrace it looks like it is the close of a completely
unrelated tracepoint event that triggers this all off, but I'm not
sure why a list_del_event() call of the tracepoint name would
trigger a schedule_timeout() and an ensuing __perf_event_task_sched_in()
which is what eventually triggers the problem.

Scattering printks around doesn't see to work because a lot of the related
calls are happening in contexts where printks don't really work.

Anyway I just wanted to summarize my findings as I might not have a chance
to look at this again for a while. For completion I'm including the
backtrace below.

Vince

[ 49.972034] ------------[ cut here ]------------
[ 49.976014] WARNING: CPU: 1 PID: 2867 at arch/x86/kernel/cpu/perf_event.c:1076 x86_pmu_start+0x38/0x102()
[ 49.976014] Modules linked in: cpufreq_userspace cpufreq_stats cpufreq_powersave cpufreq_conservative f71882fg evdev mcs7830 usbnet ohci_pci video acpi_cpufreq processor thermal_sys wmi psmouse serio_raw pcspkr coretemp button ohci_hcd i2c_nforce2 ehci_pci ehci_hcd sg sd_mod usbcore usb_common
[ 49.976014] CPU: 1 PID: 2867 Comm: pec_1076_warn Not tainted 3.14.0-rc2+ #7
[ 49.976014] Hardware name: AOpen DE7000/nMCP7ALPx-DE R1.06 Oct.19.2012, BIOS 080015 10/19/2012
[ 49.976014] 0000000000000000 ffffffff817f256d ffffffff814e750b 0000000000000000
[ 49.976014] ffffffff8103bf2c ffff8800ca005820 ffffffff81012119 ffff88011fc93400
[ 49.976014] 0000000000000021 ffff88011b31dc00 ffff88011fc8b940 0000000000000000
[ 49.976014] Call Trace:
[ 49.976014] [<ffffffff814e750b>] ? dump_stack+0x41/0x56
[ 49.976014] [<ffffffff8103bf2c>] ? warn_slowpath_common+0x79/0x92
[ 49.976014] [<ffffffff81012119>] ? x86_pmu_start+0x38/0x102
[ 49.976014] [<ffffffff81012119>] ? x86_pmu_start+0x38/0x102
[ 49.976014] [<ffffffff810123b6>] ? x86_pmu_enable+0x1d3/0x285
[ 49.976014] [<ffffffff810bca20>] ? perf_event_context_sched_in+0x6d/0x8d
[ 49.976014] [<ffffffff810bca61>] ? __perf_event_task_sched_in+0x21/0x108
[ 49.976014] [<ffffffff810666cc>] ? idle_balance+0x11a/0x157
[ 49.976014] [<ffffffff81062905>] ? finish_task_switch+0x40/0xa5
[ 49.976014] [<ffffffff814e7ee5>] ? __schedule+0x46a/0x4bd
[ 49.976014] [<ffffffff814e753d>] ? schedule_timeout+0x1d/0xb4
[ 49.976014] [<ffffffff810b9d96>] ? list_del_event+0x78/0x8f
[ 49.976014] [<ffffffff814e7520>] ? dump_stack+0x56/0x56
[ 49.976014] [<ffffffff814e8627>] ? __wait_for_common+0xce/0x14a
[ 49.976014] [<ffffffff8106287d>] ? try_to_wake_up+0x19a/0x19a
[ 49.976014] [<ffffffff810a1b5a>] ? get_tracepoint+0x20/0x53
[ 49.976014] [<ffffffff8107ea5a>] ? T.944+0x1c8/0x1c8
[ 49.976014] [<ffffffff8107ca0c>] ? wait_rcu_gp+0x3f/0x46
[ 49.976014] [<ffffffff8107ca13>] ? wait_rcu_gp+0x46/0x46
[ 49.976014] [<ffffffff810b2027>] ? perf_trace_event_unreg+0x2e/0xbd
[ 49.976014] [<ffffffff810b20e4>] ? perf_trace_destroy+0x2e/0x3b
[ 49.976014] [<ffffffff810bc0d2>] ? __free_event+0x2d/0x52
[ 49.976014] [<ffffffff810bfdff>] ? perf_event_release_kernel+0x74/0x7b
[ 49.976014] [<ffffffff810bfeb0>] ? perf_release+0x10/0x14
[ 49.976014] [<ffffffff81105b17>] ? __fput+0xdf/0x1a4
[ 49.976014] [<ffffffff810538e9>] ? task_work_run+0x7f/0x96
[ 49.976014] [<ffffffff814f0a70>] ? int_signal+0x12/0x17
[ 49.976014] ---[ end trace 0b1abb2bc23cc0c5 ]---
[ 49.976014] VMW: idx=33 state=0 type=0 config=0 samp_per=5e5fc1760

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/