Re: [trace events] WARNING: CPU: 0 PID: 91 at kernel/sched/core.c:7253 __might_sleep()

Re: [trace events] WARNING: CPU: 0 PID: 91 at kernel/sched/core.c:7253 __might_sleep()

[Peter Zijlstra]

On Wed, Oct 08, 2014 at 06:06:13PM +0800, Fengguang Wu wrote:
> [    8.867644] WARNING: CPU: 0 PID: 91 at kernel/sched/core.c:7253 __might_sleep+0x9a/0x378()
> [    8.869031] do not call blocking ops when !TASK_RUNNING; state=1 set at [<ffffffff8d79b511>] event_test_thread+0x48/0x93
> [    8.870533] Modules linked in:
> [    8.870979] CPU: 0 PID: 91 Comm: test-events Not tainted 3.17.0-rc7-00109-g2f85d18 #37
> [    8.872061] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.7.5-20140531_083030-gandalf 04/01/2014
> [    8.873428]  0000000000000000 ffff880010ec3c80 ffffffff8c696943 ffff880010ec3cb8
> [    8.874503]  ffffffff8be7cae5 ffffffff8bead236 0000000000000001 ffff88001161fa01
> [    8.888390]  0000000000000001 0000000000000000 ffff880010ec3d20 ffffffff8be7cb46
> [    8.890628] Call Trace:
> [    8.890978]  [<ffffffff8c696943>] dump_stack+0x19/0x1b
> [    8.891689]  [<ffffffff8be7cae5>] warn_slowpath_common+0x8f/0xa8
> [    8.892535]  [<ffffffff8bead236>] ? __might_sleep+0x9a/0x378
> [    8.893307]  [<ffffffff8be7cb46>] warn_slowpath_fmt+0x48/0x50
> [    8.894083]  [<ffffffff8be0dd55>] ? sched_clock+0x9/0xd
> [    8.894797]  [<ffffffff8d79b511>] ? event_test_thread+0x48/0x93
> [    8.895602]  [<ffffffff8d79b511>] ? event_test_thread+0x48/0x93
> [    8.896421]  [<ffffffff8bead236>] __might_sleep+0x9a/0x378
> [    8.897164]  [<ffffffff8c6a0227>] down_read+0x26/0x98
> [    8.897855]  [<ffffffff8be8f503>] exit_signals+0x27/0x1c2
> [    8.898598]  [<ffffffff8be7fedd>] do_exit+0x193/0x10bd
> [    8.899298]  [<ffffffff8bfd1969>] ? kfree+0x4a0/0x4d7
> [    8.900028]  [<ffffffff8d79b4c9>] ? event_trace_self_tests+0x6d7/0x6d7
> [    8.900946]  [<ffffffff8d79b4c9>] ? event_trace_self_tests+0x6d7/0x6d7
> [    8.914871]  [<ffffffff8bea4b65>] kthread+0x156/0x156
> [    8.915571]  [<ffffffff8c69c0f8>] ? wait_for_common+0x3e/0x224
> [    8.916381]  [<ffffffff8bea4a0f>] ? insert_kthread_work+0xe7/0xe7
> [    8.917203]  [<ffffffff8c6a353a>] ret_from_fork+0x7a/0xb0
> [    8.917937]  [<ffffffff8bea4a0f>] ? insert_kthread_work+0xe7/0xe7
> [    8.918800] ---[ end trace 14d02ef17adbc114 ]---


Steve, wth is that thing supposed to do?

	set_current_state(TASK_INTERRUPTIBLE);
	while (!kthread_should_stop())
		schedule();

That looks broken alright. It'll revert to a yield() 'spin' loop if it
ever gets a wakeup for anything other than the kthread_stop().

Did you mean to write something like:

	set_current_state(TASK_INTERRUPTIBLE);
	while (!kthread_should_stop()) {
		schedule();
		set_current_state(TASK_INTERRUPTIBLE);
	}
	__set_current_state(TASK_RUNNING);

?

Re: [trace events] WARNING: CPU: 0 PID: 91 at kernel/sched/core.c:7253 __might_sleep()

[Steven Rostedt]

On Wed, 8 Oct 2014 12:41:20 +0200
Peter Zijlstra <peterz@infradead.org> wrote:

> On Wed, Oct 08, 2014 at 06:06:13PM +0800, Fengguang Wu wrote:
> > [    8.867644] WARNING: CPU: 0 PID: 91 at kernel/sched/core.c:7253 __might_sleep+0x9a/0x378()
> > [    8.869031] do not call blocking ops when !TASK_RUNNING; state=1 set at [<ffffffff8d79b511>] event_test_thread+0x48/0x93

I'm curious, what blocking ops was called?

> > [    8.870533] Modules linked in:
> > [    8.870979] CPU: 0 PID: 91 Comm: test-events Not tainted 3.17.0-rc7-00109-g2f85d18 #37
> > [    8.872061] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.7.5-20140531_083030-gandalf 04/01/2014
> > [    8.873428]  0000000000000000 ffff880010ec3c80 ffffffff8c696943 ffff880010ec3cb8
> > [    8.874503]  ffffffff8be7cae5 ffffffff8bead236 0000000000000001 ffff88001161fa01
> > [    8.888390]  0000000000000001 0000000000000000 ffff880010ec3d20 ffffffff8be7cb46
> > [    8.890628] Call Trace:
> > [    8.890978]  [<ffffffff8c696943>] dump_stack+0x19/0x1b
> > [    8.891689]  [<ffffffff8be7cae5>] warn_slowpath_common+0x8f/0xa8
> > [    8.892535]  [<ffffffff8bead236>] ? __might_sleep+0x9a/0x378
> > [    8.893307]  [<ffffffff8be7cb46>] warn_slowpath_fmt+0x48/0x50
> > [    8.894083]  [<ffffffff8be0dd55>] ? sched_clock+0x9/0xd
> > [    8.894797]  [<ffffffff8d79b511>] ? event_test_thread+0x48/0x93
> > [    8.895602]  [<ffffffff8d79b511>] ? event_test_thread+0x48/0x93
> > [    8.896421]  [<ffffffff8bead236>] __might_sleep+0x9a/0x378
> > [    8.897164]  [<ffffffff8c6a0227>] down_read+0x26/0x98
> > [    8.897855]  [<ffffffff8be8f503>] exit_signals+0x27/0x1c2
> > [    8.898598]  [<ffffffff8be7fedd>] do_exit+0x193/0x10bd
> > [    8.899298]  [<ffffffff8bfd1969>] ? kfree+0x4a0/0x4d7
> > [    8.900028]  [<ffffffff8d79b4c9>] ? event_trace_self_tests+0x6d7/0x6d7
> > [    8.900946]  [<ffffffff8d79b4c9>] ? event_trace_self_tests+0x6d7/0x6d7
> > [    8.914871]  [<ffffffff8bea4b65>] kthread+0x156/0x156
> > [    8.915571]  [<ffffffff8c69c0f8>] ? wait_for_common+0x3e/0x224
> > [    8.916381]  [<ffffffff8bea4a0f>] ? insert_kthread_work+0xe7/0xe7
> > [    8.917203]  [<ffffffff8c6a353a>] ret_from_fork+0x7a/0xb0
> > [    8.917937]  [<ffffffff8bea4a0f>] ? insert_kthread_work+0xe7/0xe7
> > [    8.918800] ---[ end trace 14d02ef17adbc114 ]---
> 
> 
> Steve, wth is that thing supposed to do?
> 
> 	set_current_state(TASK_INTERRUPTIBLE);
> 	while (!kthread_should_stop())
> 		schedule();
> 
> That looks broken alright. It'll revert to a yield() 'spin' loop if it
> ever gets a wakeup for anything other than the kthread_stop().
> 
> Did you mean to write something like:
> 
> 	set_current_state(TASK_INTERRUPTIBLE);
> 	while (!kthread_should_stop()) {
> 		schedule();
> 		set_current_state(TASK_INTERRUPTIBLE);
> 	}
> 	__set_current_state(TASK_RUNNING);
> 
> ?

Wow, what a blast from the past. That code hasn't been touched since
2009!

Anyway, all that thread did was call test work on each cpu, and then
waits to be killed. It should only get a single wake up and that should
be from the kthread_stop() call. IOW, that loop should never be
executed more than once.

What exactly is the bug here?

-- Steve

Re: [trace events] WARNING: CPU: 0 PID: 91 at kernel/sched/core.c:7253 __might_sleep()

[Peter Zijlstra]

On Wed, Oct 08, 2014 at 11:08:25AM -0400, Steven Rostedt wrote:
> > Steve, wth is that thing supposed to do?
> > 
> > 	set_current_state(TASK_INTERRUPTIBLE);
> > 	while (!kthread_should_stop())
> > 		schedule();
> > 
> > That looks broken alright. It'll revert to a yield() 'spin' loop if it
> > ever gets a wakeup for anything other than the kthread_stop().
> > 
> > Did you mean to write something like:
> > 
> > 	set_current_state(TASK_INTERRUPTIBLE);
> > 	while (!kthread_should_stop()) {
> > 		schedule();
> > 		set_current_state(TASK_INTERRUPTIBLE);
> > 	}
> > 	__set_current_state(TASK_RUNNING);
> > 
> > ?
> 
> Wow, what a blast from the past. That code hasn't been touched since
> 2009!
> 
> Anyway, all that thread did was call test work on each cpu, and then
> waits to be killed. It should only get a single wake up and that should
> be from the kthread_stop() call. IOW, that loop should never be
> executed more than once.
> 
> What exactly is the bug here?

The bug is as explained, the loop is wrong and will revert to a yield
'spin' loop after a single wakeup.

The debugging that caught it is that you exit the loop without setting
TASK_RUNNING.

Re: [trace events] WARNING: CPU: 0 PID: 91 at kernel/sched/core.c:7253 __might_sleep()

[Steven Rostedt]

On Wed, 8 Oct 2014 17:48:38 +0200
Peter Zijlstra <peterz@infradead.org> wrote:

 
> > Wow, what a blast from the past. That code hasn't been touched since
> > 2009!
> > 
> > Anyway, all that thread did was call test work on each cpu, and then
> > waits to be killed. It should only get a single wake up and that should
> > be from the kthread_stop() call. IOW, that loop should never be
> > executed more than once.
> > 
> > What exactly is the bug here?
> 
> The bug is as explained, the loop is wrong and will revert to a yield
> 'spin' loop after a single wakeup.
> 
> The debugging that caught it is that you exit the loop without setting
> TASK_RUNNING.

I understand that it becomes a yield if something sends a wakeup before
killing it. I highly doubt that would ever happen since it doesn't call
anything that should wake it up and it only runs at boot up.

Looking at the original email that has the trace, I'm betting it hit
the race where kthread_stop() was called on the thread before it set
its state to TASK_INTERRUPTIBLE and then the first call to
kthread_should_stop() returned true and schedule() was never called and
the task exited with the TASK_INTERRUPTIBLE state.

Really no harm here. If we had called set_task_state(TASK_RUNNING)
before exiting this never would have been seen.

Anyway, as for a fix, if you want to do it fully with setting
TASK_INTERRUPTBILE again in the loop, I'm fine with it. I still don't
see any possible way it can be woken up before kthread_should_stop()
being true, but hey, lets make it more robust. Then if we ever
extend on the tests that are run, which could add a delayed wake up, it
would not turn into a yield.

-- Steve

Re: [trace events] WARNING: CPU: 0 PID: 91 at kernel/sched/core.c:7253 __might_sleep()

[Peter Zijlstra]

On Wed, Oct 08, 2014 at 12:17:18PM -0400, Steven Rostedt wrote:
> On Wed, 8 Oct 2014 17:48:38 +0200
> Peter Zijlstra <peterz@infradead.org> wrote:
> 
>  
> > > Wow, what a blast from the past. That code hasn't been touched since
> > > 2009!
> > > 
> > > Anyway, all that thread did was call test work on each cpu, and then
> > > waits to be killed. It should only get a single wake up and that should
> > > be from the kthread_stop() call. IOW, that loop should never be
> > > executed more than once.
> > > 
> > > What exactly is the bug here?
> > 
> > The bug is as explained, the loop is wrong and will revert to a yield
> > 'spin' loop after a single wakeup.
> > 
> > The debugging that caught it is that you exit the loop without setting
> > TASK_RUNNING.
> 
> I understand that it becomes a yield if something sends a wakeup before
> killing it. I highly doubt that would ever happen since it doesn't call
> anything that should wake it up and it only runs at boot up.

Still we should always assume spurious wakeups, its fragile not to and
has so far made life sad a few times.

> Looking at the original email that has the trace, I'm betting it hit
> the race where kthread_stop() was called on the thread before it set
> its state to TASK_INTERRUPTIBLE and then the first call to
> kthread_should_stop() returned true and schedule() was never called and
> the task exited with the TASK_INTERRUPTIBLE state.

Sure.

> Really no harm here. If we had called set_task_state(TASK_RUNNING)
> before exiting this never would have been seen.
> 
> Anyway, as for a fix, if you want to do it fully with setting
> TASK_INTERRUPTBILE again in the loop, I'm fine with it. I still don't
> see any possible way it can be woken up before kthread_should_stop()
> being true, but hey, lets make it more robust. Then if we ever
> extend on the tests that are run, which could add a delayed wake up, it
> would not turn into a yield.

Right, I'll send the patch. While looking I found another issue,
trace_selftest.c:trace_wakeup_test_thread() has a schedule() without a
loop around. We should really not do that.

[PATCH] trace: Robustify wait loop

[Peter Zijlstra]

On Wed, Oct 08, 2014 at 06:36:57PM +0200, Peter Zijlstra wrote:
> 
> Right, I'll send the patch. 


---
Subject: trace: Robustify wait loop
From: Peter Zijlstra (Intel) <peterz@infradead.org>
Date: Wed Oct  8 18:44:26 CEST 2014

The pending nested sleep debugging triggered on the potential stale
TASK_INTERRUPTIBLE in this code.

While there, fix the loop such that we won't revert to a while(1)
yield() 'spin' loop if we ever get a spurious wakeup.

And fix the actual issue by properly terminating the 'wait' loop by
setting TASK_RUNNING.

Reported-by: Fengguang Wu <fengguang.wu@intel.com>
Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
---
 kernel/trace/trace_events.c |    5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -2513,8 +2513,11 @@ static __init int event_test_thread(void
 	kfree(test_malloc);
 
 	set_current_state(TASK_INTERRUPTIBLE);
-	while (!kthread_should_stop())
+	while (!kthread_should_stop()) {
 		schedule();
+		set_current_state(TASK_INTERRUPTIBLE);
+	}
+	__set_current_state(TASK_RUNNING);
 
 	return 0;
 }

Re: [PATCH] trace: Robustify wait loop

[Steven Rostedt]

On Wed, 8 Oct 2014 18:51:10 +0200
Peter Zijlstra <peterz@infradead.org> wrote:

> On Wed, Oct 08, 2014 at 06:36:57PM +0200, Peter Zijlstra wrote:
> > 
> > Right, I'll send the patch. 
> 
> 

I'll see if I can get this in this merge window before I leave to
Dusseldorf.

BTW, what do you think of this solution? Feel free to ack it if you
like it.

-- Steve

diff --git a/kernel/trace/trace_selftest.c b/kernel/trace/trace_selftest.c
index 5ef60499dc8e..593f52b73551 100644
--- a/kernel/trace/trace_selftest.c
+++ b/kernel/trace/trace_selftest.c
@@ -1025,6 +1025,12 @@ trace_selftest_startup_nop(struct tracer *trace, struct trace_array *tr)
 #endif
 
 #ifdef CONFIG_SCHED_TRACER
+
+struct wakeup_test_data {
+	struct completion	is_ready;
+	int			go;
+};
+
 static int trace_wakeup_test_thread(void *data)
 {
 	/* Make this a -deadline thread */
@@ -1034,51 +1040,56 @@ static int trace_wakeup_test_thread(void *data)
 		.sched_deadline = 10000000ULL,
 		.sched_period = 10000000ULL
 	};
-	struct completion *x = data;
+	struct wakeup_test_data *x = data;
 
 	sched_setattr(current, &attr);
 
 	/* Make it know we have a new prio */
-	complete(x);
+	complete(&x->is_ready);
 
 	/* now go to sleep and let the test wake us up */
 	set_current_state(TASK_INTERRUPTIBLE);
-	schedule();
+	while (!x->go) {
+		schedule();
+		set_current_state(TASK_INTERRUPTIBLE);
+	}
 
-	complete(x);
+	complete(&x->is_ready);
+
+	set_current_state(TASK_INTERRUPTIBLE);
 
 	/* we are awake, now wait to disappear */
 	while (!kthread_should_stop()) {
-		/*
-		 * This will likely be the system top priority
-		 * task, do short sleeps to let others run.
-		 */
-		msleep(100);
+		schedule();
+		set_current_state(TASK_INTERRUPTIBLE);
 	}
 
+	__set_current_state(TASK_RUNNING);
+
 	return 0;
 }
-
 int
 trace_selftest_startup_wakeup(struct tracer *trace, struct trace_array *tr)
 {
 	unsigned long save_max = tr->max_latency;
 	struct task_struct *p;
-	struct completion is_ready;
+	struct wakeup_test_data data;
 	unsigned long count;
 	int ret;
 
-	init_completion(&is_ready);
+	memset(&data, 0, sizeof(data));
+
+	init_completion(&data.is_ready);
 
 	/* create a -deadline thread */
-	p = kthread_run(trace_wakeup_test_thread, &is_ready, "ftrace-test");
+	p = kthread_run(trace_wakeup_test_thread, &data, "ftrace-test");
 	if (IS_ERR(p)) {
 		printk(KERN_CONT "Failed to create ftrace wakeup test thread ");
 		return -1;
 	}
 
 	/* make sure the thread is running at -deadline policy */
-	wait_for_completion(&is_ready);
+	wait_for_completion(&data.is_ready);
 
 	/* start the tracing */
 	ret = tracer_init(trace, tr);
@@ -1099,18 +1110,20 @@ trace_selftest_startup_wakeup(struct tracer *trace, struct trace_array *tr)
 		msleep(100);
 	}
 
-	init_completion(&is_ready);
+	init_completion(&data.is_ready);
+
+	data.go = 1;
+	/* memory barrier is in the wake_up_process() */
 
 	wake_up_process(p);
 
 	/* Wait for the task to wake up */
-	wait_for_completion(&is_ready);
+	wait_for_completion(&data.is_ready);
 
 	/* stop the tracing. */
 	tracing_stop();
 	/* check both trace buffers */
 	ret = trace_test_buffer(&tr->trace_buffer, NULL);
-	printk("ret = %d\n", ret);
 	if (!ret)
 		ret = trace_test_buffer(&tr->max_buffer, &count);