linux-kernel - Re: x86_pmu_start WARN

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <alpine.DEB.2.10.1402131700090.24354@vincent-weaver-1.um.maine.edu>
Date:	Thu, 13 Feb 2014 17:13:20 -0500 (EST)
From:	Vince Weaver <vincent.weaver@...ne.edu>
To:	Vince Weaver <vincent.weaver@...ne.edu>
cc:	Peter Zijlstra <peterz@...radead.org>,
	Dave Jones <davej@...hat.com>,
	Linux Kernel <linux-kernel@...r.kernel.org>,
	Ingo Molnar <mingo@...hat.com>,
	Paul Mackerras <paulus@...ba.org>
Subject: Re: x86_pmu_start WARN_ON.

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@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/