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

Groups > linux.kernel > #1665177 > unrolled thread

Re: WARN_ON_ONCE() in process_one_work()?

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: WARN_ON_ONCE() in process_one_work()? Tejun Heo <tj@kernel.org> - 2017-06-13 23:00 +0200
    Re: WARN_ON_ONCE() in process_one_work()? "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-06-14 00:40 +0200
      Re: WARN_ON_ONCE() in process_one_work()? "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-06-14 17:20 +0200
        Re: WARN_ON_ONCE() in process_one_work()? "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-06-15 17:40 +0200
          Re: WARN_ON_ONCE() in process_one_work()? "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-06-16 19:40 +0200
            Re: WARN_ON_ONCE() in process_one_work()? Tejun Heo <tj@kernel.org> - 2017-06-17 14:00 +0200
              Re: WARN_ON_ONCE() in process_one_work()? "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-06-17 19:40 +0200
                Re: WARN_ON_ONCE() in process_one_work()? Tejun Heo <tj@kernel.org> - 2017-06-18 12:50 +0200

#1665177 — Re: WARN_ON_ONCE() in process_one_work()?

Hello, Paul.

On Fri, May 05, 2017 at 10:11:59AM -0700, Paul E. McKenney wrote:
> Just following up...  I have hit this bug a couple of times over the
> past few days.  Anything I can do to help?

My apologies for dropping the ball on this.  I've gone over the hot
plug code in workqueue several times but can't really find how this
would happen.  Can you please apply the following patch and see what
it says when the problem happens?

Thanks.

diff --git a/kernel/workqueue.c b/kernel/workqueue.c
index c74bf39ef764..bd2ce3cbfb41 100644
--- a/kernel/workqueue.c
+++ b/kernel/workqueue.c
@@ -1691,13 +1691,20 @@ static struct worker *alloc_worker(int node)
 static void worker_attach_to_pool(struct worker *worker,
 				   struct worker_pool *pool)
 {
+	int ret;
+
 	mutex_lock(&pool->attach_mutex);
 
 	/*
 	 * set_cpus_allowed_ptr() will fail if the cpumask doesn't have any
 	 * online CPUs.  It'll be re-applied when any of the CPUs come up.
 	 */
-	set_cpus_allowed_ptr(worker->task, pool->attrs->cpumask);
+	ret = set_cpus_allowed_ptr(worker->task, pool->attrs->cpumask);
+
+	WARN(ret && !(pool->flags & POOL_DISASSOCIATED),
+	     "set_cpus_allowed_ptr failed, ret=%d pool->cpu/flags=%d/0x%x cpumask=%*pbl online=%*pbl active=%*pbl\n",
+	     ret, pool->cpu, pool->flags, cpumask_pr_args(pool->attrs->cpumask),
+	     cpumask_pr_args(cpu_online_mask), cpumask_pr_args(cpu_active_mask));
 
 	/*
 	 * The pool->attach_mutex ensures %POOL_DISASSOCIATED remains
@@ -2037,8 +2044,11 @@ __acquires(&pool->lock)
 	lockdep_copy_map(&lockdep_map, &work->lockdep_map);
 #endif
 	/* ensure we're on the correct CPU */
-	WARN_ON_ONCE(!(pool->flags & POOL_DISASSOCIATED) &&
-		     raw_smp_processor_id() != pool->cpu);
+	if (WARN_ON_ONCE(!(pool->flags & POOL_DISASSOCIATED) &&
+			 raw_smp_processor_id() != pool->cpu))
+		printk_once("XXX workfn=%pf pool->cpu/flags=%d/0x%x curcpu=%d online=%*pbl active=%*pbl\n",
+			    work->func, pool->cpu, pool->flags, raw_smp_processor_id(),
+			    cpumask_pr_args(cpu_online_mask), cpumask_pr_args(cpu_active_mask));
 
 	/*
 	 * A single work shouldn't be executed concurrently by

[toc] | [next] | [standalone]

#1665260

On Tue, Jun 13, 2017 at 04:58:37PM -0400, Tejun Heo wrote:
> Hello, Paul.
> 
> On Fri, May 05, 2017 at 10:11:59AM -0700, Paul E. McKenney wrote:
> > Just following up...  I have hit this bug a couple of times over the
> > past few days.  Anything I can do to help?
> 
> My apologies for dropping the ball on this.  I've gone over the hot
> plug code in workqueue several times but can't really find how this
> would happen.  Can you please apply the following patch and see what
> it says when the problem happens?

I have fired it up, thank you!

Last time I saw one failure in 21 hours of test runs, so I have kicked
of 42 one-hour test runs.  Will see what happens tomorrow morning,
Pacific Time.

							Thanx, Paul

> Thanks.
> 
> diff --git a/kernel/workqueue.c b/kernel/workqueue.c
> index c74bf39ef764..bd2ce3cbfb41 100644
> --- a/kernel/workqueue.c
> +++ b/kernel/workqueue.c
> @@ -1691,13 +1691,20 @@ static struct worker *alloc_worker(int node)
>  static void worker_attach_to_pool(struct worker *worker,
>  				   struct worker_pool *pool)
>  {
> +	int ret;
> +
>  	mutex_lock(&pool->attach_mutex);
> 
>  	/*
>  	 * set_cpus_allowed_ptr() will fail if the cpumask doesn't have any
>  	 * online CPUs.  It'll be re-applied when any of the CPUs come up.
>  	 */
> -	set_cpus_allowed_ptr(worker->task, pool->attrs->cpumask);
> +	ret = set_cpus_allowed_ptr(worker->task, pool->attrs->cpumask);
> +
> +	WARN(ret && !(pool->flags & POOL_DISASSOCIATED),
> +	     "set_cpus_allowed_ptr failed, ret=%d pool->cpu/flags=%d/0x%x cpumask=%*pbl online=%*pbl active=%*pbl\n",
> +	     ret, pool->cpu, pool->flags, cpumask_pr_args(pool->attrs->cpumask),
> +	     cpumask_pr_args(cpu_online_mask), cpumask_pr_args(cpu_active_mask));
> 
>  	/*
>  	 * The pool->attach_mutex ensures %POOL_DISASSOCIATED remains
> @@ -2037,8 +2044,11 @@ __acquires(&pool->lock)
>  	lockdep_copy_map(&lockdep_map, &work->lockdep_map);
>  #endif
>  	/* ensure we're on the correct CPU */
> -	WARN_ON_ONCE(!(pool->flags & POOL_DISASSOCIATED) &&
> -		     raw_smp_processor_id() != pool->cpu);
> +	if (WARN_ON_ONCE(!(pool->flags & POOL_DISASSOCIATED) &&
> +			 raw_smp_processor_id() != pool->cpu))
> +		printk_once("XXX workfn=%pf pool->cpu/flags=%d/0x%x curcpu=%d online=%*pbl active=%*pbl\n",
> +			    work->func, pool->cpu, pool->flags, raw_smp_processor_id(),
> +			    cpumask_pr_args(cpu_online_mask), cpumask_pr_args(cpu_active_mask));
> 
>  	/*
>  	 * A single work shouldn't be executed concurrently by
> 

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

#1665957

On Tue, Jun 13, 2017 at 03:31:03PM -0700, Paul E. McKenney wrote:
> On Tue, Jun 13, 2017 at 04:58:37PM -0400, Tejun Heo wrote:
> > Hello, Paul.
> > 
> > On Fri, May 05, 2017 at 10:11:59AM -0700, Paul E. McKenney wrote:
> > > Just following up...  I have hit this bug a couple of times over the
> > > past few days.  Anything I can do to help?
> > 
> > My apologies for dropping the ball on this.  I've gone over the hot
> > plug code in workqueue several times but can't really find how this
> > would happen.  Can you please apply the following patch and see what
> > it says when the problem happens?
> 
> I have fired it up, thank you!
> 
> Last time I saw one failure in 21 hours of test runs, so I have kicked
> of 42 one-hour test runs.  Will see what happens tomorrow morning,
> Pacific Time.

And none of the 42 runs resulted in a workqueue splat.  I will try again
this evening, Pacific Time.

Who knows, maybe your diagnostic patch is the fix.  ;-)

							Thanx, Paul

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

#1666808

On Wed, Jun 14, 2017 at 08:15:48AM -0700, Paul E. McKenney wrote:
> On Tue, Jun 13, 2017 at 03:31:03PM -0700, Paul E. McKenney wrote:
> > On Tue, Jun 13, 2017 at 04:58:37PM -0400, Tejun Heo wrote:
> > > Hello, Paul.
> > > 
> > > On Fri, May 05, 2017 at 10:11:59AM -0700, Paul E. McKenney wrote:
> > > > Just following up...  I have hit this bug a couple of times over the
> > > > past few days.  Anything I can do to help?
> > > 
> > > My apologies for dropping the ball on this.  I've gone over the hot
> > > plug code in workqueue several times but can't really find how this
> > > would happen.  Can you please apply the following patch and see what
> > > it says when the problem happens?
> > 
> > I have fired it up, thank you!
> > 
> > Last time I saw one failure in 21 hours of test runs, so I have kicked
> > of 42 one-hour test runs.  Will see what happens tomorrow morning,
> > Pacific Time.
> 
> And none of the 42 runs resulted in a workqueue splat.  I will try again
> this evening, Pacific Time.
> 
> Who knows, maybe your diagnostic patch is the fix.  ;-)

And this time, we did get something!  Here is the printk() output:

[ 2126.863410] XXX workfn=vmstat_update pool->cpu/flags=1/0x0 curcpu=2 online=0-2,7 active=0,2,7

Please see below for the full splat from dmesg.

Please let me know if you need additional email.  My test ID is KSIC
2017.06.14-15:50:08/TREE07.14, just to help me find it in my large pile
of test results.  ;-)

							Thanx, Paul

------------------------------------------------------------------------

[ 2126.840625] ------------[ cut here ]------------
[ 2126.841373] WARNING: CPU: 2 PID: 6 at /home/paulmck/public_git/linux-rcu/kernel/workqueue.c:2048 process_one_work+0x5f/0x440
[ 2126.843042] Modules linked in:
[ 2126.843521] CPU: 2 PID: 6 Comm: mm_percpu_wq Not tainted 4.12.0-rc4+ #1
[ 2126.844493] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[ 2126.845898] task: ffff985c5e59bc00 task.stack: ffffb8be000fc000
[ 2126.846773] RIP: 0010:process_one_work+0x5f/0x440
[ 2126.847470] RSP: 0018:ffffb8be000ffe60 EFLAGS: 00010002
[ 2126.848240] RAX: ffff985c5e595200 RBX: ffff985c5e56e840 RCX: 0000000000000000
[ 2126.849284] RDX: 0000000000000001 RSI: ffff985c5e8952c0 RDI: ffff985c5e56e840
[ 2126.850337] RBP: ffffb8be000ffe90 R08: 0000000000000002 R09: 0000000000000000
[ 2126.851378] R10: ffffb8be000ffe18 R11: 0000000000000000 R12: ffff985c5e899c00
[ 2126.852410] R13: ffff985c5e89e800 R14: 0000000000000000 R15: ffff985c5e8952c0
[ 2126.853440] FS:  0000000000000000(0000) GS:ffff985c5e900000(0000) knlGS:0000000000000000
[ 2126.854650] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2126.855500] CR2: 00000000000000b0 CR3: 000000001dcfc000 CR4: 00000000000006e0
[ 2126.856558] Call Trace:
[ 2126.856944]  rescuer_thread+0x207/0x350
[ 2126.857520]  kthread+0x104/0x140
[ 2126.858024]  ? process_one_work+0x440/0x440
[ 2126.858644]  ? kthread_create_on_node+0x40/0x40
[ 2126.859343]  ret_from_fork+0x22/0x30
[ 2126.859879] Code: e8 49 8b 45 08 44 8b b0 00 01 00 00 41 83 e6 20 f6 c1 04 44 89 75 d4 75 21 41 8b 54 24 04 65 44 8b 05 de 8a f9 74 41 39 d0 74 0f <0f> ff 80 3d b8 d5 ec 00 00 0f 84 92 03 00 00 48 ba eb 83 b5 80 
[ 2126.862715] ---[ end trace df0aaa02bf2d28ee ]---
[ 2126.863410] XXX workfn=vmstat_update pool->cpu/flags=1/0x0 curcpu=2 online=0-2,7 active=0,2,7

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

#1667919

On Thu, Jun 15, 2017 at 08:38:57AM -0700, Paul E. McKenney wrote:
> On Wed, Jun 14, 2017 at 08:15:48AM -0700, Paul E. McKenney wrote:
> > On Tue, Jun 13, 2017 at 03:31:03PM -0700, Paul E. McKenney wrote:
> > > On Tue, Jun 13, 2017 at 04:58:37PM -0400, Tejun Heo wrote:
> > > > Hello, Paul.
> > > > 
> > > > On Fri, May 05, 2017 at 10:11:59AM -0700, Paul E. McKenney wrote:
> > > > > Just following up...  I have hit this bug a couple of times over the
> > > > > past few days.  Anything I can do to help?
> > > > 
> > > > My apologies for dropping the ball on this.  I've gone over the hot
> > > > plug code in workqueue several times but can't really find how this
> > > > would happen.  Can you please apply the following patch and see what
> > > > it says when the problem happens?
> > > 
> > > I have fired it up, thank you!
> > > 
> > > Last time I saw one failure in 21 hours of test runs, so I have kicked
> > > of 42 one-hour test runs.  Will see what happens tomorrow morning,
> > > Pacific Time.
> > 
> > And none of the 42 runs resulted in a workqueue splat.  I will try again
> > this evening, Pacific Time.
> > 
> > Who knows, maybe your diagnostic patch is the fix.  ;-)
> 
> And this time, we did get something!  Here is the printk() output:
> 
> [ 2126.863410] XXX workfn=vmstat_update pool->cpu/flags=1/0x0 curcpu=2 online=0-2,7 active=0,2,7
> 
> Please see below for the full splat from dmesg.
> 
> Please let me know if you need additional email.  My test ID is KSIC
> 2017.06.14-15:50:08/TREE07.14, just to help me find it in my large pile
> of test results.  ;-)

And no test failures from yesterday evening.  So it looks like we get
somewhere on the order of one failure per 138 hours of TREE07 rcutorture
runtime with your printk() in the mix.

Was the above output from your printk() output of any help?

							Thanx, Paul

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

#1668235

Hello,

On Fri, Jun 16, 2017 at 10:36:58AM -0700, Paul E. McKenney wrote:
> And no test failures from yesterday evening.  So it looks like we get
> somewhere on the order of one failure per 138 hours of TREE07 rcutorture
> runtime with your printk() in the mix.
>
> Was the above output from your printk() output of any help?

Yeah, if my suspicion is correct, it'd require new kworker creation
racing against CPU offline, which would explain why it's so difficult
to repro.  Can you please see whether the following patch resolves the
issue?

Thanks.

diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index 803c3bc274c4..1500217ce4b4 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -980,8 +980,13 @@ struct migration_arg {
 static struct rq *__migrate_task(struct rq *rq, struct rq_flags *rf,
 				 struct task_struct *p, int dest_cpu)
 {
-	if (unlikely(!cpu_active(dest_cpu)))
-		return rq;
+	if (p->flags & PF_KTHREAD) {
+		if (unlikely(!cpu_online(dest_cpu)))
+			return rq;
+	} else {
+		if (unlikely(!cpu_active(dest_cpu)))
+			return rq;
+	}
 
 	/* Affinity changed (again). */
 	if (!cpumask_test_cpu(dest_cpu, &p->cpus_allowed))

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

#1668377

On Sat, Jun 17, 2017 at 07:53:14AM -0400, Tejun Heo wrote:
> Hello,
> 
> On Fri, Jun 16, 2017 at 10:36:58AM -0700, Paul E. McKenney wrote:
> > And no test failures from yesterday evening.  So it looks like we get
> > somewhere on the order of one failure per 138 hours of TREE07 rcutorture
> > runtime with your printk() in the mix.
> >
> > Was the above output from your printk() output of any help?
> 
> Yeah, if my suspicion is correct, it'd require new kworker creation
> racing against CPU offline, which would explain why it's so difficult
> to repro.  Can you please see whether the following patch resolves the
> issue?

That could explain why only Steve Rostedt and I saw the issue.  As far
as I know, we are the only ones who regularly run CPU-hotplug stress
tests.  ;-)

I have a weekend-long run going, but will give this a shot overnight on
Monday, Pacific Time.  Thank you for putting it together, looking forward
to seeing what it does!

							Thanx, Paul

> Thanks.
> 
> diff --git a/kernel/sched/core.c b/kernel/sched/core.c
> index 803c3bc274c4..1500217ce4b4 100644
> --- a/kernel/sched/core.c
> +++ b/kernel/sched/core.c
> @@ -980,8 +980,13 @@ struct migration_arg {
>  static struct rq *__migrate_task(struct rq *rq, struct rq_flags *rf,
>  				 struct task_struct *p, int dest_cpu)
>  {
> -	if (unlikely(!cpu_active(dest_cpu)))
> -		return rq;
> +	if (p->flags & PF_KTHREAD) {
> +		if (unlikely(!cpu_online(dest_cpu)))
> +			return rq;
> +	} else {
> +		if (unlikely(!cpu_active(dest_cpu)))
> +			return rq;
> +	}
> 
>  	/* Affinity changed (again). */
>  	if (!cpumask_test_cpu(dest_cpu, &p->cpus_allowed))
> 

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

#1668578

Hello,

On Sat, Jun 17, 2017 at 10:31:05AM -0700, Paul E. McKenney wrote:
> On Sat, Jun 17, 2017 at 07:53:14AM -0400, Tejun Heo wrote:
> > Hello,
> > 
> > On Fri, Jun 16, 2017 at 10:36:58AM -0700, Paul E. McKenney wrote:
> > > And no test failures from yesterday evening.  So it looks like we get
> > > somewhere on the order of one failure per 138 hours of TREE07 rcutorture
> > > runtime with your printk() in the mix.
> > >
> > > Was the above output from your printk() output of any help?
> > 
> > Yeah, if my suspicion is correct, it'd require new kworker creation
> > racing against CPU offline, which would explain why it's so difficult
> > to repro.  Can you please see whether the following patch resolves the
> > issue?
> 
> That could explain why only Steve Rostedt and I saw the issue.  As far
> as I know, we are the only ones who regularly run CPU-hotplug stress
> tests.  ;-)

I was a bit confused.  It has to be racing against either new kworker
being created on the wrong CPU or rescuer trying to migrate to the
CPU, and it looks like we're mostly seeing the rescuer condition, but,
yeah, this would only get triggered rarely.  Another contributing
factor could be the vmstat work putting on a workqueue w/ rescuer
recently.  It runs quite often, so probably has increased the chance
of hitting the right condition.

> I have a weekend-long run going, but will give this a shot overnight on
> Monday, Pacific Time.  Thank you for putting it together, looking forward
> to seeing what it does!

Thanks a lot for the testing and patience.  Sorry that it took so
long.  I'm not completely sure the patch is correct.  It might have to
be more specifc about which type of migration or require further
synchronization around migration, but hopefully it'll at least be able
to show that this was the cause of the problem.

Thanks!

-- 
tejun

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web