Re: x86_pmu_start WARN_ON.

[Peter Zijlstra <peterz@infradead.org>]

On Wed, Feb 19, 2014 at 05:34:49PM -0500, Vince Weaver wrote:
> So where would the NMI counter event get disabled?  Would it never get 
> disabled, just because it's always running and always gets the same fixed 
> slot?  Why isn't this a problem all the time, not just with corner cases?

Well it could get another counter assignment I suppose; there's no
guarantee it always ends up in the fixed counter although that's rather
likely.

> Is somehow n_added getting confused?

I'd expect worse than a warning if that happened, but who knows.

You could try with the below; make sure you've got CONFIG_FUNCTION_TRACER=y.

Then (assuming debugfs is mounted in /debug ; most modern distros have
it at /sys/kernel/debug but they're wrong!):

# echo 0 > /debug/tracing/tracing_on
# echo function > /debug/tracing/current_tracer
# echo nop > /debug/tracing/current_tracer
# echo 0 > /debug/tracing/trace
# echo 1 > /debug/tracing/tracing_on

And make it go *BOOM*, then:

# cat /debug/tracing/trace | bzip2 -9 > ~/trace.bz2

And send that (and look at it of course).

@rostedt: WTF is disable_trace_on_warning a boot option only?

---
 arch/x86/kernel/cpu/perf_event.c | 65 +++++++++++++++++++++++++++++++++++++++-
 1 file changed, 64 insertions(+), 1 deletion(-)

diff --git a/arch/x86/kernel/cpu/perf_event.c b/arch/x86/kernel/cpu/perf_event.c
index 895604f2e916..d3edf301deb8 100644
--- a/arch/x86/kernel/cpu/perf_event.c
+++ b/arch/x86/kernel/cpu/perf_event.c
@@ -509,6 +509,42 @@ void x86_pmu_disable_all(void)
 	}
 }
 
+static void x86_pmu_state(struct pmu *pmu)
+{
+	struct cpu_hw_events *cpuc = &__get_cpu_var(cpu_hw_events);
+	int i;
+
+	trace_printk("Events: {\n");
+	for (i = 0; i < X86_PMC_IDX_MAX; i++) {
+		struct perf_event *event = cpuc->events[i];
+		int active = test_bit(i, cpuc->active_mask);
+		int running = test_bit(i, cpuc->running);
+
+		if (active || running) {
+			trace_printk("  %d: state: %c%c config: %lx (%p)\n",
+					i, active ? 'A' : '.',
+					running ? 'R' : '.',
+					event ? event->attr.config : -1L,
+					event);
+		}
+	}
+	trace_printk("}\n");
+
+
+	trace_printk("n_events: %d, n_added: %d, n_txn: %d\n",
+			cpuc->n_events, cpuc->n_added, cpuc->n_txn);
+	trace_printk("Assignment: {\n");
+	for (i = 0; i < cpuc->n_events; i++) {
+		struct perf_event *event = cpuc->event_list[i];
+
+		trace_printk("  %d->%d tag: %lx config: %lx (%p)\n",
+				i, cpuc->assign[i], cpuc->tags[i],
+				event ? event->attr.config : -1L,
+				event);
+	}
+	trace_printk("}\n");
+}
+
 static void x86_pmu_disable(struct pmu *pmu)
 {
 	struct cpu_hw_events *cpuc = &__get_cpu_var(cpu_hw_events);
@@ -524,6 +560,9 @@ static void x86_pmu_disable(struct pmu *pmu)
 	barrier();
 
 	x86_pmu.disable_all();
+
+	trace_printk("x86_pmu_disable\n");
+	x86_pmu_state(pmu);
 }
 
 void x86_pmu_enable_all(int added)
@@ -820,6 +859,7 @@ static int collect_events(struct cpu_hw_events *cpuc, struct perf_event *leader,
 			return -EINVAL;
 		cpuc->event_list[n] = leader;
 		n++;
+		trace_printk("Adding event: %lx (%p)\n", leader->attr.config, leader);
 	}
 	if (!dogrp)
 		return n;
@@ -834,6 +874,7 @@ static int collect_events(struct cpu_hw_events *cpuc, struct perf_event *leader,
 
 		cpuc->event_list[n] = event;
 		n++;
+		trace_printk("Adding event: %lx (%p)\n", event->attr.config, event);
 	}
 	return n;
 }
@@ -885,6 +926,9 @@ static void x86_pmu_enable(struct pmu *pmu)
 	if (cpuc->enabled)
 		return;
 
+	trace_printk("x86_pmu_enable\n");
+	x86_pmu_state(pmu);
+
 	if (cpuc->n_added) {
 		int n_running = cpuc->n_events - cpuc->n_added;
 		/*
@@ -898,6 +942,11 @@ static void x86_pmu_enable(struct pmu *pmu)
 			event = cpuc->event_list[i];
 			hwc = &event->hw;
 
+			trace_printk("K%d: hwc->idx: %d, hwc->last_cpu: %d,"
+				     " hwc->last_tag: %lx hwc->state: %x\n",
+				     i, hwc->idx, hwc->last_cpu,
+				     hwc->last_tag, hwc->state);
+
 			/*
 			 * we can avoid reprogramming counter if:
 			 * - assigned same counter as last time
@@ -915,6 +964,8 @@ static void x86_pmu_enable(struct pmu *pmu)
 			if (hwc->state & PERF_HES_STOPPED)
 				hwc->state |= PERF_HES_ARCH;
 
+			trace_printk("stopping: %d\n", i);
+
 			x86_pmu_stop(event, PERF_EF_UPDATE);
 		}
 
@@ -922,6 +973,11 @@ static void x86_pmu_enable(struct pmu *pmu)
 			event = cpuc->event_list[i];
 			hwc = &event->hw;
 
+			trace_printk("S%d: hwc->idx: %d, hwc->last_cpu: %d,"
+				     " hwc->last_tag: %lx hwc->state: %x\n",
+				     i, hwc->idx, hwc->last_cpu,
+				     hwc->last_tag, hwc->state);
+
 			if (!match_prev_assignment(hwc, cpuc, i))
 				x86_assign_hw_event(event, cpuc, i);
 			else if (i < n_running)
@@ -930,12 +986,17 @@ static void x86_pmu_enable(struct pmu *pmu)
 			if (hwc->state & PERF_HES_ARCH)
 				continue;
 
+			trace_printk("starting: %d\n", i);
+
 			x86_pmu_start(event, PERF_EF_RELOAD);
 		}
 		cpuc->n_added = 0;
 		perf_events_lapic_init();
 	}
 
+	x86_pmu_state(pmu);
+	trace_printk("x86_pmu_enabled\n");
+
 	cpuc->enabled = 1;
 	barrier();
 
@@ -1073,8 +1134,10 @@ static void x86_pmu_start(struct perf_event *event, int flags)
 	struct cpu_hw_events *cpuc = &__get_cpu_var(cpu_hw_events);
 	int idx = event->hw.idx;
 
-	if (WARN_ON_ONCE(!(event->hw.state & PERF_HES_STOPPED)))
+	if (WARN_ON_ONCE(!(event->hw.state & PERF_HES_STOPPED))) {
+		tracing_off();
 		return;
+	}
 
 	if (WARN_ON_ONCE(idx == -1))
 		return;