Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1461326 > unrolled thread

perf: fuzzer WARNING event_function_local.constprop

Back to article view | Back to linux.kernel

Contents

  perf: fuzzer WARNING event_function_local.constprop Vince Weaver <vincent.weaver@maine.edu> - 2016-08-12 19:00 +0200
    Re: perf: fuzzer WARNING event_function_local.constprop Peter Zijlstra <peterz@infradead.org> - 2016-08-16 12:10 +0200
      Re: perf: fuzzer WARNING event_function_local.constprop Vince Weaver <vincent.weaver@maine.edu> - 2016-08-16 18:20 +0200
        Re: perf: fuzzer WARNING event_function_local.constprop Peter Zijlstra <peterz@infradead.org> - 2016-08-16 19:10 +0200

#1461326 — perf: fuzzer WARNING event_function_local.constprop

Got this while fuzzing on the Haswell machine.  It's relatively repeatable 
if anyone wants me to chase it down more.

It maps to
	int ret = event_function(&efs);
	WARN_ON_ONCE(ret);
In event_function_local()

[166817.446302] ------------[ cut here ]------------
[166817.451347] WARNING: CPU: 1 PID: 0 at kernel/events/core.c:254 event_function_local.constprop.106+0x4c/0x50
[166817.535510] CPU: 1 PID: 0 Comm: swapper/1 Not tainted 4.8.0-rc1+ #187
[166817.542500] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
[166817.550535]  0000000000000000 ffff88011ea43ca8 ffffffff81437641 0000000000000000
[166817.558676]  0000000000000000 ffff88011ea43ce8 ffffffff81076bab 000000fe8116864d
[166817.566785]  0000000000000002 0000000000014000 ffff8800ac3ae3e8 ffff8800ac3ae000
[166817.574918] Call Trace:
[166817.577654]  <IRQ>  [<ffffffff81437641>] dump_stack+0x63/0x82
[166817.583957]  [<ffffffff81076bab>] __warn+0xcb/0xf0
[166817.589185]  [<ffffffff81076c9d>] warn_slowpath_null+0x1d/0x20
[166817.595550]  [<ffffffff8116bbac>] event_function_local.constprop.106+0x4c/0x50
[166817.603398]  [<ffffffff8116e3a0>] ? task_ctx_sched_out+0x50/0x50
[166817.609948]  [<ffffffff81174c71>] perf_pending_event+0xd1/0xe0
[166817.616291]  [<ffffffff8115dea8>] irq_work_run_list+0x48/0x70
[166817.622566]  [<ffffffff8115dee8>] irq_work_run+0x18/0x40
[166817.628357]  [<ffffffff81032cee>] smp_irq_work_interrupt+0x2e/0x40
[166817.635090]  [<ffffffff81723a02>] irq_work_interrupt+0x82/0x90
[166817.641445]  [<ffffffff81721b81>] ? _raw_spin_unlock_irqrestore+0x31/0x40
[166817.648822]  [<ffffffff810bb9b2>] complete+0x42/0x50
[166817.654231]  [<ffffffff810df8f0>] ? trace_raw_output_rcu_utilization+0x60/0x60
[166817.662107]  [<ffffffff810df902>] wakeme_after_rcu+0x12/0x20
[166817.668302]  [<ffffffff810e3aa5>] rcu_process_callbacks+0x2f5/0x6a0
[166817.675140]  [<ffffffff810e3a3f>] ? rcu_process_callbacks+0x28f/0x6a0
[166817.682143]  [<ffffffff81724c83>] __do_softirq+0x113/0x2c6
[166817.688121]  [<ffffffff8107ca53>] irq_exit+0xa3/0xb0
[166817.693553]  [<ffffffff81724a42>] smp_apic_timer_interrupt+0x42/0x50
[166817.700467]  [<ffffffff81722da2>] apic_timer_interrupt+0x82/0x90
[166817.706980]  <EOI>  [<ffffffff815ad21b>] ? cpuidle_enter_state+0x12b/0x2d0
[166817.714482]  [<ffffffff815ad3f7>] cpuidle_enter+0x17/0x20
[166817.720354]  [<ffffffff810bbada>] call_cpuidle+0x2a/0x50
[166817.726144]  [<ffffffff810bbeaf>] cpu_startup_entry+0x28f/0x340
[166817.732587]  [<ffffffff8104fda3>] start_secondary+0x133/0x140
[166817.738867] ---[ end trace 05ef6c9af3dc0e24 ]---

[toc] | [next] | [standalone]

#1463642

On Fri, Aug 12, 2016 at 12:59:11PM -0400, Vince Weaver wrote:
> 
> Got this while fuzzing on the Haswell machine.  It's relatively repeatable 
> if anyone wants me to chase it down more.
> 
> It maps to
> 	int ret = event_function(&efs);
> 	WARN_ON_ONCE(ret);
> In event_function_local()

Blergh, so I've been running perf_fuzzer for almost two hours and
_nothing_ :/

In any case, while it was running I think I've figured out how this can
happen.


Could you see if the below cures things?

---
 kernel/events/core.c | 60 +++++++++++++++++++++++++++++++++++++++++-----------
 1 file changed, 48 insertions(+), 12 deletions(-)

diff --git a/kernel/events/core.c b/kernel/events/core.c
index 7090cc734a8e..406f79a6f22f 100644
--- a/kernel/events/core.c
+++ b/kernel/events/core.c
@@ -242,18 +242,6 @@ static int event_function(void *info)
 	return ret;
 }
 
-static void event_function_local(struct perf_event *event, event_f func, void *data)
-{
-	struct event_function_struct efs = {
-		.event = event,
-		.func = func,
-		.data = data,
-	};
-
-	int ret = event_function(&efs);
-	WARN_ON_ONCE(ret);
-}
-
 static void event_function_call(struct perf_event *event, event_f func, void *data)
 {
 	struct perf_event_context *ctx = event->ctx;
@@ -303,6 +291,54 @@ static void event_function_call(struct perf_event *event, event_f func, void *da
 	raw_spin_unlock_irq(&ctx->lock);
 }
 
+/*
+ * Similar to event_function_call() + event_function(), but hard assumes IRQs
+ * are already disabled and we're on the right CPU.
+ */
+static void event_function_local(struct perf_event *event, event_f func, void *data)
+{
+	struct perf_event_context *ctx = event->ctx;
+	struct perf_cpu_context *cpuctx = __get_cpu_context(ctx);
+	struct task_struct *task = READ_ONCE(ctx->task);
+	struct perf_event_context *task_ctx = NULL;
+
+	WARN_ON_ONCE(!irqs_disabled());
+
+	if (task) {
+		if (task == TASK_TOMBSTONE)
+			return;
+
+		task_ctx = ctx;
+	}
+
+	perf_ctx_lock(cpuctx, task_ctx);
+
+	task = ctx->task;
+	if (task == TASK_TOMBSTONE)
+		goto unlock;
+
+	if (task) {
+		/*
+		 * We must be either inactive or active and the right task,
+		 * otherwise we're screwed, since we cannot IPI to somewhere
+		 * else.
+		 */
+		if (ctx->is_active) {
+			if (WARN_ON_ONCE(task != current))
+				goto unlock;
+
+			if (WARN_ON_ONCE(cpuctx->task_ctx != ctx))
+				goto unlock;
+		}
+	} else {
+		WARN_ON_ONCE(&cpuctx->ctx != ctx);
+	}
+
+	func(event, cpuctx, ctx, data);
+unlock:
+	perf_ctx_unlock(cpuctx, task_ctx);
+}
+
 #define PERF_FLAG_ALL (PERF_FLAG_FD_NO_GROUP |\
 		       PERF_FLAG_FD_OUTPUT  |\
 		       PERF_FLAG_PID_CGROUP |\

[toc] | [prev] | [next] | [standalone]

#1463923

On Tue, 16 Aug 2016, Peter Zijlstra wrote:

> Could you see if the below cures things?
> 
> ---
>  kernel/events/core.c | 60 +++++++++++++++++++++++++++++++++++++++++-----------
>  1 file changed, 48 insertions(+), 12 deletions(-)

yes, it seems to fix things, or at least my reliable test case no longer 
will trigger it.

Vince

[toc] | [prev] | [next] | [standalone]

#1463944

On Tue, Aug 16, 2016 at 12:17:27PM -0400, Vince Weaver wrote:
> On Tue, 16 Aug 2016, Peter Zijlstra wrote:
> 
> > Could you see if the below cures things?
> > 
> > ---
> >  kernel/events/core.c | 60 +++++++++++++++++++++++++++++++++++++++++-----------
> >  1 file changed, 48 insertions(+), 12 deletions(-)
> 
> yes, it seems to fix things, or at least my reliable test case no longer 
> will trigger it.

Awesome, I'll go write a Changelog and such.

Meanwhile I found a livelock in ftrace-perf, once I get that sorted I'll
go look at the other things you reported.

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web