Re: Workqueues splat due to ending up on wrong CPU

From: Paul E. McKenney
Date: Wed Nov 27 2019 - 10:50:31 EST

Next message: Bartosz Golaszewski: "Re: [PATCH 7/8] gpiolib: add new ioctl() for monitoring changes in line info"
Previous message: Arnaldo Carvalho de Melo: "Re: [PATCH 3/3] bpftool: Allow to link libbpf dynamically"
In reply to: Paul E. McKenney: "Re: Workqueues splat due to ending up on wrong CPU"
Next in thread: Paul E. McKenney: "Re: Workqueues splat due to ending up on wrong CPU"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Tue, Nov 26, 2019 at 02:05:33PM -0800, Paul E. McKenney wrote:
> On Tue, Nov 26, 2019 at 10:33:34AM -0800, Tejun Heo wrote:
> > Hello, Paul.
> >
> > On Mon, Nov 25, 2019 at 03:03:12PM -0800, Paul E. McKenney wrote:
> > > I am seeing this occasionally during rcutorture runs in the presence
> > > of CPU hotplug. This is on v5.4-rc1 in process_one_work() at the first
> > > WARN_ON():
> > >
> > > WARN_ON_ONCE(!(pool->flags & POOL_DISASSOCIATED) &&
> > > raw_smp_processor_id() != pool->cpu);
> >
> > Hmm... so it's saying that this worker's pool is supposed to be bound
> > to a cpu but it's currently running on the wrong cpu.
>
> Probably because the bound-to CPU recently went offline. And maybe
> back online and back offline recently as well.
>
> > > What should I do to help further debug this?
> >
> > Do you always see rescuer_thread in the backtrace? Can you please
> > apply the following patch and reproduce the problem?
>
> The short answer is "yes", they all have rescuer_thread() in the
> backtrace.

And 420 hours of test overnight failed to reproduce the problem. I kicked
off an additional 672 hours that should complete tomorrow (Thursday PST)
morning. If it is still -ENOREPRODUCE, I will be making some rcutorture
changes to avoid unrelated false-positive rcutorture splats due to fun
with hyperthreading on large systems and rerun. Just in case timing due
to hyperthreading is required to make this splat happen or some such...

Thanx, Paul

> Here is the one from October:
>
> ------------------------------------------------------------------------
>
> [ 951.674908] WARNING: CPU: 2 PID: 4 at kernel/workqueue.c:2185 process_one_work+0x48/0x3b0
> [ 951.676859] Modules linked in:
> [ 951.677284] CPU: 2 PID: 4 Comm: rcu_par_gp Not tainted 5.3.0-rc2+ #4
> [ 951.678144] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.12.0-1 04/01/2014
> [ 951.679330] RIP: 0010:process_one_work+0x48/0x3b0
> [ 951.680010] Code: 00 00 00 00 4c 0f 44 e0 49 8b 44 24 08 44 8b a8 00 01 00 00 41 83 e5 20 f6 45 10 04 75 0e 65 8b 05 cd e0 98 5f 39 45 04 74 02 <0f> 0b 48 ba eb 83 b5 80 46 86 c8 61 48 0f af d6 48 c1 ea 3a 48 8b
> [ 951.682598] RSP: 0000:ffffa3624002fe80 EFLAGS: 00010093
> [ 951.683315] RAX: 0000000000000002 RBX: ffffa242dec107a8 RCX: ffffa242df228898
> [ 951.684307] RDX: ffffa242df228898 RSI: ffffffffa1a4e2b8 RDI: ffffa242dec10780
> [ 951.685356] RBP: ffffa242df228880 R08: 0000000000000000 R09: 0000000000000000
> [ 951.686394] R10: 0000000000000000 R11: 0000000000000000 R12: ffffa242df22cf00
> [ 951.687422] R13: 0000000000000000 R14: ffffa242df2288a0 R15: ffffa242dec10780
> [ 951.688397] FS: 0000000000000000(0000) GS:ffffa242df280000(0000) knlGS:0000000000000000
> [ 951.689497] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 951.690284] CR2: 00000000000000b0 CR3: 000000001e20a000 CR4: 00000000000006e0
> [ 951.691248] Call Trace:
> [ 951.691602] rescuer_thread+0x244/0x320
> [ 951.692130] ? worker_thread+0x3c0/0x3c0
> [ 951.692676] kthread+0x10d/0x130
> [ 951.693126] ? kthread_create_on_node+0x60/0x60
> [ 951.693771] ret_from_fork+0x35/0x40
> [ 951.694297] ---[ end trace e04817902e40095b ]---
>
> ------------------------------------------------------------------------
>
> And the other one from August:
>
> ------------------------------------------------------------------------
>
> [ 1668.624302] WARNING: CPU: 1 PID: 4 at kernel/workqueue.c:2185 process_one_work+0x84/0x5b0
> [ 1668.625806] Modules linked in:
> [ 1668.626133] CPU: 1 PID: 4 Comm: rcu_par_gp Not tainted 5.3.0-rc2+ #420
> [ 1668.626806] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.10.2-1ubuntu1 04/01/2014
> [ 1668.627673] RIP: 0010:process_one_work+0x84/0x5b0
> [ 1668.628146] Code: 48 8b 46 20 41 83 e6 20 41 f6 44 24 44 04 48 89 45 b0 48 8b 46 38 48 89 45 c8 75 10 65 8b 05 13 80 58 54 41 39 44 24 38 74 02 <0f> 0b 48 ba eb 83 b5 80 46 86 c8 61 48 0f af d3 48 c1 ea 3a 49 8b
> [ 1668.630099] RSP: 0000:ffffa2668002be50 EFLAGS: 00010006
> [ 1668.630650] RAX: 0000000000000001 RBX: fffffffface678e8 RCX: 0000000000000000
> [ 1668.631399] RDX: ffff8e00df329508 RSI: fffffffface678e8 RDI: ffff8e00dec94600
> [ 1668.632149] RBP: ffffa2668002beb0 R08: 0000000000000000 R09: 0000000000000000
> [ 1668.632902] R10: 0000000000000000 R11: 0000000000000000 R12: ffff8e00df3294c0
> [ 1668.633651] R13: ffff8e00df32de00 R14: 0000000000000000 R15: ffff8e00dec94600
> [ 1668.634377] FS: 0000000000000000(0000) GS:ffff8e00df240000(0000) knlGS:0000000000000000
> [ 1668.635226] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 1668.635814] CR2: 0000000000000148 CR3: 000000001581e000 CR4: 00000000000006e0
> [ 1668.636536] Call Trace:
> [ 1668.636803] rescuer_thread+0x20b/0x340
> [ 1668.637194] ? worker_thread+0x3d0/0x3d0
> [ 1668.637566] kthread+0x10e/0x130
> [ 1668.637886] ? kthread_park+0xa0/0xa0
> [ 1668.638278] ret_from_fork+0x35/0x40
> [ 1668.638657] ---[ end trace 6290de3b1c80098a ]---
>
> ------------------------------------------------------------------------
>
> I have started running your patch. Not enough data to be statistically
> significant, but it looks like rcutorture scenario TREE02 is the
> best bet, so I will focus on that one.
>
> Thanx, Paul
>
> > Thanks.
> >
> > diff --git a/kernel/workqueue.c b/kernel/workqueue.c
> > index 914b845ad4ff..6f7f185cd146 100644
> > --- a/kernel/workqueue.c
> > +++ b/kernel/workqueue.c
> > @@ -1842,13 +1842,18 @@ static struct worker *alloc_worker(int node)
> > static void worker_attach_to_pool(struct worker *worker,
> > struct worker_pool *pool)
> > {
> > + int ret;
> > +
> > mutex_lock(&wq_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);
> > + if (ret && !(pool->flags & POOL_DISASSOCIATED))
> > + printk("XXX worker pid %d failed to attach to cpus of pool %d, ret=%d\n",
> > + task_pid_nr(worker->task), pool->id, ret);
> >
> > /*
> > * The wq_pool_attach_mutex ensures %POOL_DISASSOCIATED remains
> > @@ -2183,8 +2188,10 @@ __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);
> > + WARN_ONCE(!(pool->flags & POOL_DISASSOCIATED) &&
> > + raw_smp_processor_id() != pool->cpu,
> > + "expected on cpu %d but on cpu %d, pool %d, workfn=%pf\n",
> > + pool->cpu, raw_smp_processor_id(), pool->id, work->func);
> >
> > /*
> > * A single work shouldn't be executed concurrently by
> >
> > --
> > tejun

Next message: Bartosz Golaszewski: "Re: [PATCH 7/8] gpiolib: add new ioctl() for monitoring changes in line info"
Previous message: Arnaldo Carvalho de Melo: "Re: [PATCH 3/3] bpftool: Allow to link libbpf dynamically"
In reply to: Paul E. McKenney: "Re: Workqueues splat due to ending up on wrong CPU"
Next in thread: Paul E. McKenney: "Re: Workqueues splat due to ending up on wrong CPU"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]