LinuxLists.cc - x86_pmu_start WARN

2014-01-30 19:03:36

Subject: x86_pmu_start WARN_ON.

I gave Vince's perf_fuzzer a run, hoping to trigger a different perf bug
that I've been seeing. Instead I hit a different bug.

WARNING: CPU: 1 PID: 9277 at arch/x86/kernel/cpu/perf_event.c:1076 x86_pmu_start+0xd1/0x110()
CPU: 1 PID: 9277 Comm: perf_fuzzer Not tainted 3.13.0+ #101
0000000000000009 0000000047887442 ffff88024d043da8 ffffffffbd7387ba
0000000000000000 ffff88024d043de0 ffffffffbd06d28d ffff88024d04bba0
ffff880104c9ef60 0000000000000004 0000000000000002 ffff88024d04bddc
Call Trace:
<IRQ> [<ffffffffbd7387ba>] dump_stack+0x4e/0x7a
[<ffffffffbd06d28d>] warn_slowpath_common+0x7d/0xa0
[<ffffffffbd06d3ba>] warn_slowpath_null+0x1a/0x20
[<ffffffffbd018421>] x86_pmu_start+0xd1/0x110
[<ffffffffbd018b9f>] x86_pmu_enable+0x22f/0x320
[<ffffffffbd150bca>] perf_pmu_enable+0x2a/0x30
[<ffffffffbd152711>] perf_cpu_hrtimer_handler+0xe1/0x1f0
[<ffffffffbd097582>] __run_hrtimer+0x72/0x250
[<ffffffffbd152630>] ? perf_event_context_sched_in.isra.85+0xc0/0xc0
[<ffffffffbd097e97>] hrtimer_interrupt+0x107/0x260
[<ffffffffbd030744>] local_apic_timer_interrupt+0x34/0x60
[<ffffffffbd74deba>] smp_trace_apic_timer_interrupt+0x4a/0x125
[<ffffffffbd74cb2f>] trace_apic_timer_interrupt+0x6f/0x80
<EOI> [<ffffffffbd743e4d>] ? retint_swapgs+0xe/0x13

1076 if (WARN_ON_ONCE(!(event->hw.state & PERF_HES_STOPPED)))
1077 return;

It reproduces pretty quickly for me (within a minute or two of runtime).
Oddly the generated test case from the log file doesn't reproduce.

Dave

2014-02-10 21:24:49

[permalink] [raw]

Subject: [tip:perf/core] perf/x86: Fix event scheduling

Commit-ID: 26e61e8939b1fe8729572dabe9a9e97d930dd4f6
Gitweb: http://git.kernel.org/tip/26e61e8939b1fe8729572dabe9a9e97d930dd4f6
Author: Peter Zijlstra <[email protected]>
AuthorDate: Fri, 21 Feb 2014 16:03:12 +0100
Committer: Ingo Molnar <[email protected]>
CommitDate: Thu, 27 Feb 2014 12:38:02 +0100

perf/x86: Fix event scheduling

Vince "Super Tester" Weaver reported a new round of syscall fuzzing (Trinity) failures,
with perf WARN_ON()s triggering. He also provided traces of the failures.

This is I think the relevant bit:

> pec_1076_warn-2804 [000] d... 147.926153: x86_pmu_disable: x86_pmu_disable
> pec_1076_warn-2804 [000] d... 147.926153: x86_pmu_state: Events: {
> pec_1076_warn-2804 [000] d... 147.926156: x86_pmu_state: 0: state: .R config: ffffffffffffffff ( (null))
> pec_1076_warn-2804 [000] d... 147.926158: x86_pmu_state: 33: state: AR config: 0 (ffff88011ac99800)
> pec_1076_warn-2804 [000] d... 147.926159: x86_pmu_state: }
> pec_1076_warn-2804 [000] d... 147.926160: x86_pmu_state: n_events: 1, n_added: 0, n_txn: 1
> pec_1076_warn-2804 [000] d... 147.926161: x86_pmu_state: Assignment: {
> pec_1076_warn-2804 [000] d... 147.926162: x86_pmu_state: 0->33 tag: 1 config: 0 (ffff88011ac99800)
> pec_1076_warn-2804 [000] d... 147.926163: x86_pmu_state: }
> pec_1076_warn-2804 [000] d... 147.926166: collect_events: Adding event: 1 (ffff880119ec8800)

So we add the insn:p event (fd[23]).

At this point we should have:

n_events = 2, n_added = 1, n_txn = 1

> pec_1076_warn-2804 [000] d... 147.926170: collect_events: Adding event: 0 (ffff8800c9e01800)
> pec_1076_warn-2804 [000] d... 147.926172: collect_events: Adding event: 4 (ffff8800cbab2c00)

We try and add the {BP,cycles,br_insn} group (fd[3], fd[4], fd[15]).
These events are 0:cycles and 4:br_insn, the BP event isn't x86_pmu so
that's not visible.

group_sched_in()
pmu->start_txn() /* nop - BP pmu */
event_sched_in()
event->pmu->add()

So here we should end up with:

0: n_events = 3, n_added = 2, n_txn = 2
4: n_events = 4, n_added = 3, n_txn = 3

But seeing the below state on x86_pmu_enable(), the must have failed,
because the 0 and 4 events aren't there anymore.

Looking at group_sched_in(), since the BP is the leader, its
event_sched_in() must have succeeded, for otherwise we would not have
seen the sibling adds.

But since neither 0 or 4 are in the below state; their event_sched_in()
must have failed; but I don't see why, the complete state: 0,0,1:p,4
fits perfectly fine on a core2.

However, since we try and schedule 4 it means the 0 event must have
succeeded! Therefore the 4 event must have failed, its failure will
have put group_sched_in() into the fail path, which will call:

event_sched_out()
event->pmu->del()

on 0 and the BP event.

Now x86_pmu_del() will reduce n_events; but it will not reduce n_added;
giving what we see below:

n_event = 2, n_added = 2, n_txn = 2

> pec_1076_warn-2804 [000] d... 147.926177: x86_pmu_enable: x86_pmu_enable
> pec_1076_warn-2804 [000] d... 147.926177: x86_pmu_state: Events: {
> pec_1076_warn-2804 [000] d... 147.926179: x86_pmu_state: 0: state: .R config: ffffffffffffffff ( (null))
> pec_1076_warn-2804 [000] d... 147.926181: x86_pmu_state: 33: state: AR config: 0 (ffff88011ac99800)
> pec_1076_warn-2804 [000] d... 147.926182: x86_pmu_state: }
> pec_1076_warn-2804 [000] d... 147.926184: x86_pmu_state: n_events: 2, n_added: 2, n_txn: 2
> pec_1076_warn-2804 [000] d... 147.926184: x86_pmu_state: Assignment: {
> pec_1076_warn-2804 [000] d... 147.926186: x86_pmu_state: 0->33 tag: 1 config: 0 (ffff88011ac99800)
> pec_1076_warn-2804 [000] d... 147.926188: x86_pmu_state: 1->0 tag: 1 config: 1 (ffff880119ec8800)
> pec_1076_warn-2804 [000] d... 147.926188: x86_pmu_state: }
> pec_1076_warn-2804 [000] d... 147.926190: x86_pmu_enable: S0: hwc->idx: 33, hwc->last_cpu: 0, hwc->last_tag: 1 hwc->state: 0

So the problem is that x86_pmu_del(), when called from a
group_sched_in() that fails (for whatever reason), and without x86_pmu
TXN support (because the leader is !x86_pmu), will corrupt the n_added
state.

Reported-and-Tested-by: Vince Weaver <[email protected]>
Signed-off-by: Peter Zijlstra <[email protected]>
Cc: Paul Mackerras <[email protected]>
Cc: Steven Rostedt <[email protected]>
Cc: Stephane Eranian <[email protected]>
Cc: Dave Jones <[email protected]>
Cc: <[email protected]>
Link: http://lkml.kernel.org/r/[email protected]
Signed-off-by: Ingo Molnar <[email protected]>
---
arch/x86/kernel/cpu/perf_event.c | 3 +++
1 file changed, 3 insertions(+)

diff --git a/arch/x86/kernel/cpu/perf_event.c b/arch/x86/kernel/cpu/perf_event.c
index 895604f..79f9f84 100644
--- a/arch/x86/kernel/cpu/perf_event.c
+++ b/arch/x86/kernel/cpu/perf_event.c
@@ -1192,6 +1192,9 @@ static void x86_pmu_del(struct perf_event *event, int flags)
for (i = 0; i < cpuc->n_events; i++) {
if (event == cpuc->event_list[i]) {

+ if (i >= cpuc->n_events - cpuc->n_added)
+ --cpuc->n_added;
+
if (x86_pmu.put_event_constraints)
x86_pmu.put_event_constraints(cpuc, event);