Skip to contentSkip to conversation

Subject: Warning in workqueue.c

DISCUSSION Jason J. Herne 4 participants 23 messages Feb 7, 2014 – Mar 17, 2014

Subsystems (2)
Scheduler Workqueue
lore
Share & tools
lore

Jason J. Herne

author
#0 lore raw

I've been able to reproduce the following warning using several kernel versions on the S390 platform, including the latest master: 3.14-rc1 (38dbfb59d1175ef458d006556061adeaa8751b72).

[28718.212810] ------------[ cut here ]------------
[28718.212819] WARNING: at kernel/workqueue.c:2156
[28718.212822] Modules linked in: ipt_MASQUERADE iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack xt_CHECKSUM iptable_mangle bridge stp llc ip6table_filter ip6_tables ebtable_nat ebtables iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi tape_3590 qeth_l2 tape tape_class vhost_net tun vhost macvtap macvlan lcs dasd_eckd_mod dasd_mod qeth ccwgroup zfcp scsi_transport_fc scsi_tgt qdio dm_multipath [last unloaded: kvm]
[28718.212857] CPU: 2 PID: 20 Comm: kworker/3:0 Not tainted 3.14.0-rc1 #1
[28718.212862] task: 00000000f7b23260 ti: 00000000f7b2c000 task.ti: 00000000f7b2c000
[28718.212874] Krnl PSW : 0404c00180000000 000000000015b0be (process_one_work+0x2e6/0x4c0)
[28718.212881]            R:0 T:1 IO:0 EX:0 Key:0 M:1 W:0 P:0 AS:3 CC:0 PM:0 EA:3
Krnl GPRS: 0000000001727790 0000000000bc2a52 00000000f7f21900 0000000000b92500
[28718.212883]            0000000000b92500 0000000000105b24 0000000000000000 0000000000bc2a4e
[28718.212887]            0000000000000000 0000000084a2b500 0000000084a27000 0000000084a27018
[28718.212888]            00000000f7f21900 0000000000b92500 00000000f7b2fdd0 00000000f7b2fd70
[28718.212907] Krnl Code: 000000000015b0b2: 95001000		cli	0(%r1),0
           000000000015b0b6: a774fece		brc	7,15ae52
          #000000000015b0ba: a7f40001		brc	15,15b0bc
          >000000000015b0be: 92011000		mvi	0(%r1),1
           000000000015b0c2: a7f4fec8		brc	15,15ae52
           000000000015b0c6: e31003180004	lg	%r1,792
           000000000015b0cc: 58301024		l	%r3,36(%r1)
           000000000015b0d0: a73a0001		ahi	%r3,1
[28718.212937] Call Trace:
[28718.212940] ([<000000000015b08c>] process_one_work+0x2b4/0x4c0)
[28718.212944]  [<000000000015b858>] worker_thread+0x178/0x39c
[28718.212949]  [<0000000000164652>] kthread+0x10e/0x128
[28718.212956]  [<0000000000728c66>] kernel_thread_starter+0x6/0xc
[28718.212960]  [<0000000000728c60>] kernel_thread_starter+0x0/0xc
[28718.212962] Last Breaking-Event-Address:
[28718.212965]  [<000000000015b0ba>] process_one_work+0x2e2/0x4c0
[28718.212968] ---[ end trace 6d115577307998c2 ]---

The workload is:
2 processes onlining random cpus in a tight loop by using 'echo 1 > /sys/bus/cpu.../online' 2 processes offlining random cpus in a tight loop by using 'echo 0 > /sys/bus/cpu.../online' Otherwise, fairly idle system. load average: 5.82, 6.27, 6.27

The machine has 10 processors.
The warning message some times hits within a few minutes on starting the workload. Other times it takes several hours.

The particular spot in the code is:

	/*
	 * Ensure we're on the correct CPU.  DISASSOCIATED test is
	 * necessary to avoid spurious warnings from rescuers servicing the
	 * unbound or a disassociated pool.
	 */
	WARN_ON_ONCE(!(worker->flags & WORKER_UNBOUND) &&
		     !(pool->flags & POOL_DISASSOCIATED) &&
		     raw_smp_processor_id() != pool->cpu);

I'm not familiar with scheduling or work queuing internals so I'm not sure how to further debug. I would be happy to run tests and/or collect debugging data.

Signature · 1 line
-- Jason J. Herne ([email protected])
maintainer
#1 lore raw

Hello,

(cc'ing Lai as he knows a lot of workqueue code and quoting the whole body for him)

Hmmm.... my memory is a bit rusty and nothing rings a bell immediately. Can you please try the patch at the end of this message and report the debug message? Let's first find out what's going on.

Thanks

Quoted 68 lines · Jason J. Herne

I've been able to reproduce the following warning using several kernel versions on the S390 platform, including the latest master:
3.14-rc1 (38dbfb59d1175ef458d006556061adeaa8751b72).

[28718.212810] ------------[ cut here ]------------
[28718.212819] WARNING: at kernel/workqueue.c:2156
[28718.212822] Modules linked in: ipt_MASQUERADE iptable_nat

nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack xt_CHECKSUM iptable_mangle bridge stp llc ip6table_filter ip6_tables ebtable_nat ebtables iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi tape_3590 qeth_l2 tape tape_class vhost_net tun vhost macvtap macvlan lcs dasd_eckd_mod dasd_mod qeth ccwgroup zfcp scsi_transport_fc scsi_tgt qdio dm_multipath [last unloaded: kvm]

[28718.212857] CPU: 2 PID: 20 Comm: kworker/3:0 Not tainted 3.14.0-rc1 #1
[28718.212862] task: 00000000f7b23260 ti: 00000000f7b2c000 task.ti:
00000000f7b2c000
[28718.212874] Krnl PSW : 0404c00180000000 000000000015b0be
(process_one_work+0x2e6/0x4c0)
[28718.212881]            R:0 T:1 IO:0 EX:0 Key:0 M:1 W:0 P:0 AS:3
CC:0 PM:0 EA:3
Krnl GPRS: 0000000001727790 0000000000bc2a52 00000000f7f21900
0000000000b92500
[28718.212883]            0000000000b92500 0000000000105b24
0000000000000000 0000000000bc2a4e
[28718.212887]            0000000000000000 0000000084a2b500
0000000084a27000 0000000084a27018
[28718.212888]            00000000f7f21900 0000000000b92500
00000000f7b2fdd0 00000000f7b2fd70
[28718.212907] Krnl Code: 000000000015b0b2: 95001000		cli	0(%r1),0
           000000000015b0b6: a774fece		brc	7,15ae52
          #000000000015b0ba: a7f40001		brc	15,15b0bc
          >000000000015b0be: 92011000		mvi	0(%r1),1
           000000000015b0c2: a7f4fec8		brc	15,15ae52
           000000000015b0c6: e31003180004	lg	%r1,792
           000000000015b0cc: 58301024		l	%r3,36(%r1)
           000000000015b0d0: a73a0001		ahi	%r3,1
[28718.212937] Call Trace:
[28718.212940] ([<000000000015b08c>] process_one_work+0x2b4/0x4c0)
[28718.212944]  [<000000000015b858>] worker_thread+0x178/0x39c
[28718.212949]  [<0000000000164652>] kthread+0x10e/0x128
[28718.212956]  [<0000000000728c66>] kernel_thread_starter+0x6/0xc
[28718.212960]  [<0000000000728c60>] kernel_thread_starter+0x0/0xc
[28718.212962] Last Breaking-Event-Address:
[28718.212965]  [<000000000015b0ba>] process_one_work+0x2e2/0x4c0
[28718.212968] ---[ end trace 6d115577307998c2 ]---

The workload is:
2 processes onlining random cpus in a tight loop by using 'echo 1 > /sys/bus/cpu.../online'
2 processes offlining random cpus in a tight loop by using 'echo 0 > /sys/bus/cpu.../online'
Otherwise, fairly idle system. load average: 5.82, 6.27, 6.27

The machine has 10 processors.
The warning message some times hits within a few minutes on starting the workload. Other times it takes several hours.

The particular spot in the code is:

	/*
	 * Ensure we're on the correct CPU.  DISASSOCIATED test is
	 * necessary to avoid spurious warnings from rescuers servicing the
	 * unbound or a disassociated pool.
	 */
	WARN_ON_ONCE(!(worker->flags & WORKER_UNBOUND) &&
		     !(pool->flags & POOL_DISASSOCIATED) &&
		     raw_smp_processor_id() != pool->cpu);
Quoted 7 lines

I'm not familiar with scheduling or work queuing internals so I'm not sure how to further debug.
I would be happy to run tests and/or collect debugging data.

Signature · 1 line
-- Jason J. Herne ([email protected])
kernel/workqueue.c +6 -3
index 82ef9f3..1cc6d05 100644
@@ -2151,9 +2151,12 @@ __acquires(&pool->lock)
 	 * necessary to avoid spurious warnings from rescuers servicing the
 	 * unbound or a disassociated pool.
 	 */
-	WARN_ON_ONCE(!(worker->flags & WORKER_UNBOUND) &&
-		     !(pool->flags & POOL_DISASSOCIATED) &&
-		     raw_smp_processor_id() != pool->cpu);
+	if (WARN_ON_ONCE(!(worker->flags & WORKER_UNBOUND) &&
+			 !(pool->flags & POOL_DISASSOCIATED) &&
+			 raw_smp_processor_id() != pool->cpu))
+		pr_warning("XXX: worker->flags=0x%x pool->flags=0x%x cpu=%d pool->cpu=%d\n",
+			   worker->flags, pool->flags, raw_smp_processor_id(),
+			   pool->cpu);
 
 	/*
 	 * A single work shouldn't be executed concurrently by
author
#2 lore raw
Quoted 8 lines · Tejun Heo

Hello,

(cc'ing Lai as he knows a lot of workqueue code and quoting the whole body for him)

Hmmm.... my memory is a bit rusty and nothing rings a bell immediately. Can you please try the patch at the end of this message and report the debug message? Let's first find out what's going on.

I hit it quickly this time :) Here you go:

[  644.517558] ------------[ cut here ]------------
[  644.517567] WARNING: at kernel/workqueue.c:2156
[  644.517569] Modules linked in: ipt_MASQUERADE iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack xt_CHECKSUM iptable_mangle bridge stp llc ip6table_filter ip6_tables ebtable_nat ebtables iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi qeth_l2 tape_3590 tape tape_class vhost_net tun vhost macvtap macvlan lcs dasd_eckd_mod dasd_mod qeth ccwgroup zfcp scsi_transport_fc scsi_tgt qdio dm_multipath [last unloaded: kvm]
[  644.517603] CPU: 6 PID: 24 Comm: kworker/4:0 Not tainted 3.14.0-rc1 #2
[  644.517607] task: 00000000f7b49930 ti: 00000000f7b58000 task.ti: 00000000f7b58000
[  644.517616] Krnl PSW : 0404c00180000000 000000000015b2a2 (process_one_work+0x4ca/0x4ec)
[  644.517620]            R:0 T:1 IO:0 EX:0 Key:0 M:1 W:0 P:0 AS:3 CC:0 PM:0 EA:3
Krnl GPRS: 000000000020f16f 00000000f7f0ce00 0000000000bc2a52 0000000000000001
[  644.517625]            0000000000000000 0000000000000006 0000000000000004 0000000000bc2a4e
[  644.517629]            0000000000000000 0000000084a37500 0000000084a33000 0000000084a33018
[  644.517632]            00000000f7f21c00 0000000000b92500 00000000f7b5bdd0 00000000f7b5bd70
[  644.517651] Krnl Code: 000000000015b294: ddf29640c05b	trt 1600(243,%r9),91(%r12)
           000000000015b29a: a7f4fe56		brc	15,15af46
          #000000000015b29e: a7f40001		brc	15,15b2a0
          >000000000015b2a2: 92012000		mvi	0(%r2),1
           000000000015b2a6: a7f4ff10		brc	15,15b0c6
           000000000015b2aa: c03000533bd1	larl	%r3,bc2a4c
           000000000015b2b0: 95003000		cli	0(%r3),0
           000000000015b2b4: a774ff4e		brc	7,15b150
[  644.517679] Call Trace:
[  644.517683] ([<000000000015b094>] process_one_work+0x2bc/0x4ec)
[  644.517686]  [<000000000015b884>] worker_thread+0x178/0x39c
[  644.517690]  [<000000000016467e>] kthread+0x10e/0x128
[  644.517696]  [<0000000000728c96>] kernel_thread_starter+0x6/0xc
[  644.517699]  [<0000000000728c90>] kernel_thread_starter+0x0/0xc
[  644.517701] Last Breaking-Event-Address:
[  644.517705]  [<000000000015b29e>] process_one_work+0x4c6/0x4ec
[  644.517707] ---[ end trace 681ce8162e7857a0 ]---
[  644.517710] XXX: worker->flags=0x1 pool->flags=0x0 cpu=6 pool->cpu=4
[  731.367023] XXX: worker->flags=0x1 pool->flags=0x0 cpu=1 pool->cpu=7
Signature · 1 line
-- Jason J. Herne ([email protected])
maintainer
#3 lore raw

Hello,

Quoted 2 lines · Jason J. Herne
[  644.517710] XXX: worker->flags=0x1 pool->flags=0x0 cpu=6 pool->cpu=4
[  731.367023] XXX: worker->flags=0x1 pool->flags=0x0 cpu=1 pool->cpu=7

Sorry, still no idea how this can happen. Can you please try the following?

Thanks!

kernel/workqueue.c +35 -5
index 82ef9f3..1b11ec0 100644
@@ -2151,9 +2151,27 @@ __acquires(&pool->lock)
 	 * necessary to avoid spurious warnings from rescuers servicing the
 	 * unbound or a disassociated pool.
 	 */
-	WARN_ON_ONCE(!(worker->flags & WORKER_UNBOUND) &&
-		     !(pool->flags & POOL_DISASSOCIATED) &&
-		     raw_smp_processor_id() != pool->cpu);
+	if (WARN_ON_ONCE(!(worker->flags & WORKER_UNBOUND) &&
+			 !(pool->flags & POOL_DISASSOCIATED) &&
+			 raw_smp_processor_id() != pool->cpu)) {
+		static char buf[PAGE_SIZE];
+		unsigned long now = jiffies;
+
+		pr_warning("XXX: worker->flags=0x%x pool->flags=0x%x cpu=%d pool->cpu=%d rescue_wq=%p\n",
+			   worker->flags, pool->flags, raw_smp_processor_id(),
+			   pool->cpu, worker->rescue_wq);
+		pr_warning("XXX: last_unbind=%ld last_rebind=%ld last_rebound_clear=%ld nr_exected_after_rebound_clear=%d\n",
+			   worker->last_unbind ? worker->last_unbind - now : 999,
+			   worker->last_rebind ? worker->last_rebind - now : 999,
+			   worker->last_rebound_clear ? worker->last_rebound_clear - now : 999,
+			   worker->nr_executed_after_rebound_clear);
+
+		cpulist_scnprintf(buf, sizeof(buf), &current->cpus_allowed);
+		pr_warning("XXX: cpus_allowed=%s\n", buf);
+
+		cpulist_scnprintf(buf, sizeof(buf), &worker->cpus_allowed_after_rebinding);
+		pr_warning("XXX: cpus_allowed_after_rebinding=%s\n", buf);
+	}
 
 	/*
 	 * A single work shouldn't be executed concurrently by

@@ -2199,6 +2217,8 @@ __acquires(&pool->lock)
 	 */
 	set_work_pool_and_clear_pending(work, pool->id);
 
+	worker->nr_executed_after_rebound_clear++;
+
 	spin_unlock_irq(&pool->lock);
 
 	lock_map_acquire_read(&pwq->wq->lockdep_map);

@@ -2321,6 +2341,10 @@ recheck:
 	 * management if applicable and concurrency management is restored
 	 * after being rebound.  See rebind_workers() for details.
 	 */
+	if (worker->flags & WORKER_REBOUND) {
+		worker->last_rebound_clear = jiffies;
+		worker->nr_executed_after_rebound_clear = 0;
+	}
 	worker_clr_flags(worker, WORKER_PREP | WORKER_REBOUND);
 
 	do {

@@ -4576,8 +4600,10 @@ static void wq_unbind_fn(struct work_struct *work)
 		 * before the last CPU down must be on the cpu.  After
 		 * this, they may become diasporas.
 		 */
-		for_each_pool_worker(worker, wi, pool)
+		for_each_pool_worker(worker, wi, pool) {
 			worker->flags |= WORKER_UNBOUND;
+			worker->last_unbind = jiffies;
+		}
 
 		pool->flags |= POOL_DISASSOCIATED;
 

@@ -4633,9 +4659,13 @@ static void rebind_workers(struct worker_pool *pool)
 	 * of all workers first and then clear UNBOUND.  As we're called
 	 * from CPU_ONLINE, the following shouldn't fail.
 	 */
-	for_each_pool_worker(worker, wi, pool)
+	for_each_pool_worker(worker, wi, pool) {
 		WARN_ON_ONCE(set_cpus_allowed_ptr(worker->task,
 						  pool->attrs->cpumask) < 0);
+		worker->last_rebind = jiffies;
+		cpumask_copy(&worker->cpus_allowed_after_rebinding,
+			     &worker->task->cpus_allowed);
+	}
 
 	spin_lock_irq(&pool->lock);
kernel/workqueue_internal.h +5 -0
index 7e2204d..95d68c4 100644
@@ -50,6 +50,11 @@ struct worker {
 
 	/* used only by rescuers to point to the target workqueue */
 	struct workqueue_struct	*rescue_wq;	/* I: the workqueue to rescue */
+	unsigned long		last_unbind;
+	unsigned long		last_rebind;
+	unsigned long		last_rebound_clear;
+	int			nr_executed_after_rebound_clear;
+	cpumask_t		cpus_allowed_after_rebinding;
 };
 
 /**
author
#4 lore raw
Quoted 9 lines · Tejun Heo

Hello,

Quoted 2 lines · Jason J. Herne
[  644.517710] XXX: worker->flags=0x1 pool->flags=0x0 cpu=6 pool->cpu=4
[  731.367023] XXX: worker->flags=0x1 pool->flags=0x0 cpu=1 pool->cpu=7

Sorry, still no idea how this can happen. Can you please try the following?

Here are the results:

[  950.778326] ------------[ cut here ]------------
[  950.778334] WARNING: at kernel/workqueue.c:2156
[  950.778336] Modules linked in: ipt_MASQUERADE iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack xt_CHECKSUM iptable_mangle bridge stp llc ip6table_filter ip6_tables ebtable_nat ebtables iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi tape_3590 tape tape_class qeth_l2 vhost_net tun vhost macvtap macvlan lcs dasd_eckd_mod dasd_mod qeth ccwgroup zfcp scsi_transport_fc scsi_tgt qdio dm_multipath [last unloaded: kvm]
[  950.778370] CPU: 6 PID: 16 Comm: kworker/2:0 Not tainted 3.14.0-rc1 #1
[  950.778375] task: 00000000f7cc4b90 ti: 00000000f7ce8000 task.ti: 00000000f7ce8000
[  950.778385] Krnl PSW : 0404c00180000000 000000000015b386 (process_one_work+0x59a/0x5c0)
[  950.778389]            R:0 T:1 IO:0 EX:0 Key:0 M:1 W:0 P:0 AS:3 CC:0 PM:0 EA:3
Krnl GPRS: 00000000001ee417 00000000f7f0ce00 0000000000bc2a52 0000000000000001
[  950.778396]            0000000000000000 0000000000000006 0000000000000002 0000000000bc2a4e
[  950.778400]            0000000000000000 0000000084a1f500 0000000084a1b000 0000000084a1b018
[  950.778404]            00000000f7f52900 0000000000b92500 00000000f7cebdd0 00000000f7cebd68
[  950.778423] Krnl Code: 000000000015b37a: 92013000		mvi	0(%r3),1
           000000000015b37e: a7f4ff31		brc	15,15b1e0
          #000000000015b382: a7f40001		brc	15,15b384
          >000000000015b386: 92012000		mvi	0(%r2),1
           000000000015b38a: a7f4feae		brc	15,15b0e6
           000000000015b38e: 41102018		la	%r1,24(%r2)
           000000000015b392: e31020180020	cg	%r1,24(%r2)
           000000000015b398: a784ff59		brc	8,15b24a
[  950.778451] Call Trace:
[  950.778455] ([<000000000015b0b4>] process_one_work+0x2c8/0x5c0)
[  950.778459]  [<000000000015b98e>] worker_thread+0x19a/0x3c0
[  950.778463]  [<00000000001647c2>] kthread+0x10e/0x128
[  950.778469]  [<0000000000728dd6>] kernel_thread_starter+0x6/0xc
[  950.778472]  [<0000000000728dd0>] kernel_thread_starter+0x0/0xc
[  950.778475] Last Breaking-Event-Address:
[  950.778478]  [<000000000015b382>] process_one_work+0x596/0x5c0
[  950.778481] ---[ end trace 643b2850ca4b7ed8 ]---
[  950.778485] XXX: worker->flags=0x1 pool->flags=0x0 cpu=6 pool->cpu=2 rescue_wq=          (null)
[  950.778488] XXX: last_unbind=-7 last_rebind=0 last_rebound_clear=0 nr_exected_after_rebound_clear=0
[  950.778492] XXX: cpus_allowed=2
[  950.778495] XXX: cpus_allowed_after_rebinding=2
Signature · 1 line
-- Jason J. Herne ([email protected])
maintainer
#5 lore raw

Hello,

Quoted 6 lines · Jason J. Herne
[  950.778485] XXX: worker->flags=0x1 pool->flags=0x0 cpu=6
pool->cpu=2 rescue_wq=          (null)
[  950.778488] XXX: last_unbind=-7 last_rebind=0
last_rebound_clear=0 nr_exected_after_rebound_clear=0
[  950.778492] XXX: cpus_allowed=2
[  950.778495] XXX: cpus_allowed_after_rebinding=2

So, everything looks kosher from workqueue side. Weird. cpus_allowed is properly set and everything. The worker just isn't running on the cpu it's supposed to be on. Can you please try the following?

kernel/workqueue.c +39 -5
index 82ef9f3..f71ee11 100644
@@ -2151,9 +2151,31 @@ __acquires(&pool->lock)
 	 * necessary to avoid spurious warnings from rescuers servicing the
 	 * unbound or a disassociated pool.
 	 */
-	WARN_ON_ONCE(!(worker->flags & WORKER_UNBOUND) &&
-		     !(pool->flags & POOL_DISASSOCIATED) &&
-		     raw_smp_processor_id() != pool->cpu);
+	if (WARN_ON_ONCE(!(worker->flags & WORKER_UNBOUND) &&
+			 !(pool->flags & POOL_DISASSOCIATED) &&
+			 raw_smp_processor_id() != pool->cpu)) {
+		static char buf[PAGE_SIZE];
+		unsigned long now = jiffies;
+
+		pr_warning("XXX: worker->flags=0x%x pool->flags=0x%x cpu=%d pool->cpu=%d(%d) rescue_wq=%p\n",
+			   worker->flags, pool->flags, raw_smp_processor_id(),
+			   pool->cpu, cpu_online(pool->cpu), worker->rescue_wq);
+		pr_warning("XXX: last_unbind=%ld last_rebind=%ld last_rebound_clear=%ld nr_exected_after_rebound_clear=%d\n",
+			   worker->last_unbind ? worker->last_unbind - now : 999,
+			   worker->last_rebind ? worker->last_rebind - now : 999,
+			   worker->last_rebound_clear ? worker->last_rebound_clear - now : 999,
+			   worker->nr_executed_after_rebound_clear);
+
+		cpulist_scnprintf(buf, sizeof(buf), &current->cpus_allowed);
+		pr_warning("XXX: cpus_allowed=%s\n", buf);
+
+		cpulist_scnprintf(buf, sizeof(buf), &worker->cpus_allowed_after_rebinding);
+		pr_warning("XXX: cpus_allowed_after_rebinding=%s\n", buf);
+
+		schedule();
+
+		pr_warning("XXX: after schedule(), cpu=%d\n", raw_smp_processor_id());
+	}
 
 	/*
 	 * A single work shouldn't be executed concurrently by

@@ -2199,6 +2221,8 @@ __acquires(&pool->lock)
 	 */
 	set_work_pool_and_clear_pending(work, pool->id);
 
+	worker->nr_executed_after_rebound_clear++;
+
 	spin_unlock_irq(&pool->lock);
 
 	lock_map_acquire_read(&pwq->wq->lockdep_map);

@@ -2321,6 +2345,10 @@ recheck:
 	 * management if applicable and concurrency management is restored
 	 * after being rebound.  See rebind_workers() for details.
 	 */
+	if (worker->flags & WORKER_REBOUND) {
+		worker->last_rebound_clear = jiffies;
+		worker->nr_executed_after_rebound_clear = 0;
+	}
 	worker_clr_flags(worker, WORKER_PREP | WORKER_REBOUND);
 
 	do {

@@ -4576,8 +4604,10 @@ static void wq_unbind_fn(struct work_struct *work)
 		 * before the last CPU down must be on the cpu.  After
 		 * this, they may become diasporas.
 		 */
-		for_each_pool_worker(worker, wi, pool)
+		for_each_pool_worker(worker, wi, pool) {
 			worker->flags |= WORKER_UNBOUND;
+			worker->last_unbind = jiffies;
+		}
 
 		pool->flags |= POOL_DISASSOCIATED;
 

@@ -4633,9 +4663,13 @@ static void rebind_workers(struct worker_pool *pool)
 	 * of all workers first and then clear UNBOUND.  As we're called
 	 * from CPU_ONLINE, the following shouldn't fail.
 	 */
-	for_each_pool_worker(worker, wi, pool)
+	for_each_pool_worker(worker, wi, pool) {
 		WARN_ON_ONCE(set_cpus_allowed_ptr(worker->task,
 						  pool->attrs->cpumask) < 0);
+		worker->last_rebind = jiffies;
+		cpumask_copy(&worker->cpus_allowed_after_rebinding,
+			     &worker->task->cpus_allowed);
+	}
 
 	spin_lock_irq(&pool->lock);
kernel/workqueue_internal.h +5 -0
index 7e2204d..95d68c4 100644
@@ -50,6 +50,11 @@ struct worker {
 
 	/* used only by rescuers to point to the target workqueue */
 	struct workqueue_struct	*rescue_wq;	/* I: the workqueue to rescue */
+	unsigned long		last_unbind;
+	unsigned long		last_rebind;
+	unsigned long		last_rebound_clear;
+	int			nr_executed_after_rebound_clear;
+	cpumask_t		cpus_allowed_after_rebinding;
 };
 
 /**
author
#6 lore raw
Quoted 10 lines · Tejun Heo

Hello,

Quoted 6 lines · Jason J. Herne
[  950.778485] XXX: worker->flags=0x1 pool->flags=0x0 cpu=6
pool->cpu=2 rescue_wq=          (null)
[  950.778488] XXX: last_unbind=-7 last_rebind=0
last_rebound_clear=0 nr_exected_after_rebound_clear=0
[  950.778492] XXX: cpus_allowed=2
[  950.778495] XXX: cpus_allowed_after_rebinding=2
Quoted 3 lines

So, everything looks kosher from workqueue side. Weird. cpus_allowed is properly set and everything. The worker just isn't running on the cpu it's supposed to be on. Can you please try the following?

Thanks for the fast responses. Here is the output from the last patch:

[34437.173991] WARNING: at kernel/workqueue.c:2156
[34437.173993] Modules linked in: ipt_MASQUERADE iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack xt_CHECKSUM iptable_mangle bridge stp llc ip6table_filter ip6_tables ebtable_nat ebtables iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi qeth_l2 tape_3590 tape tape_class vhost_net tun vhost macvtap macvlan lcs dasd_eckd_mod dasd_mod qeth ccwgroup zfcp scsi_transport_fc scsi_tgt qdio dm_multipath [last unloaded: kvm]
[34437.174030] CPU: 2 PID: 12 Comm: kworker/1:0 Not tainted 3.14.0-rc1 #1
[34437.174034] task: 00000000f7c9e4c0 ti: 00000000f7cbc000 task.ti: 00000000f7cbc000
[34437.174046] Krnl PSW : 0404c00180000000 000000000015b406 (process_one_work+0x61a/0x640)
[34437.174051]            R:0 T:1 IO:0 EX:0 Key:0 M:1 W:0 P:0 AS:3 CC:0 PM:0 EA:3
Krnl GPRS: 000000007c325b00 0000000000bc2a52 00000000f7f52780 0000000000000001
[34437.174057]            0000000000000000 0000000000000002 0000000000000001 0000000000bc2a4e
[34437.174061]            0000000000000000 0000000084a13500 0000000084a0f000 0000000084a0f018
[34437.174065]            00000000f7f52780 0000000000735d18 00000000f7cbfdd0 00000000f7cbfd58
[34437.174085] Krnl Code: 000000000015b3fa: 92013000		mvi	0(%r3),1
           000000000015b3fe: a7f4ff31		brc	15,15b260
          #000000000015b402: a7f40001		brc	15,15b404
          >000000000015b406: 92011000		mvi	0(%r1),1
           000000000015b40a: a7f4fe84		brc	15,15b112
           000000000015b40e: 41102018		la	%r1,24(%r2)
           000000000015b412: e31020180020	cg	%r1,24(%r2)
           000000000015b418: a784ff59		brc	8,15b2ca
[34437.174115] Call Trace:
[34437.174118] ([<000000000015b0e0>] process_one_work+0x2f4/0x640)
[34437.174122]  [<000000000015ba0e>] worker_thread+0x19a/0x3c0
[34437.174126]  [<0000000000164842>] kthread+0x10e/0x128
[34437.174132]  [<0000000000728e56>] kernel_thread_starter+0x6/0xc
[34437.174136]  [<0000000000728e50>] kernel_thread_starter+0x0/0xc
[34437.174138] Last Breaking-Event-Address:
[34437.174141]  [<000000000015b402>] process_one_work+0x616/0x640
[34437.174144] ---[ end trace 52d8ee96597a2415 ]---
[34437.174148] XXX: worker->flags=0x1 pool->flags=0x0 cpu=2 pool->cpu=1(1) rescue_wq=          (null)
[34437.174152] XXX: last_unbind=-34 last_rebind=0 last_rebound_clear=0 nr_exected_after_rebound_clear=0
[34437.174156] XXX: cpus_allowed=1
[34437.174158] XXX: cpus_allowed_after_rebinding=1
[34437.174161] BUG: scheduling while atomic: kworker/1:0/12/0x00000002
[34437.174164] Modules linked in: ipt_MASQUERADE iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack xt_CHECKSUM iptable_mangle bridge stp llc ip6table_filter ip6_tables ebtable_nat ebtables iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi qeth_l2 tape_3590 tape tape_class vhost_net tun vhost macvtap macvlan lcs dasd_eckd_mod dasd_mod qeth ccwgroup zfcp scsi_transport_fc scsi_tgt qdio dm_multipath [last unloaded: kvm]
[34437.174194] CPU: 2 PID: 12 Comm: kworker/1:0 Tainted: G        W 3.14.0-rc1 #1
[34437.174197]        00000000f7cbfb80 00000000f7cbfb90 0000000000000002 0000000000000000
       00000000f7cbfc20 00000000f7cbfb98 00000000f7cbfb98 0000000000115f6a
       0000000000000003 0000000000c4da00 000000000000000a 000000000000000a
       00000000f7cbfbe0 00000000f7cbfb80 0000000000000000 0000000000000000
       0000000000000000 0000000000115f6a 00000000f7cbfb80 00000000f7cbfbd0
[34437.174273] Call Trace:
[34437.174279] ([<0000000000115e5c>] show_trace+0x100/0x148)
[34437.174282]  [<0000000000115f18>] show_stack+0x74/0xf4
[34437.174288]  [<0000000000720a9c>] dump_stack+0x88/0xb8
[34437.174291]  [<000000000071aa40>] __schedule_bug+0x78/0x90
[34437.174295]  [<00000000007237e4>] __schedule+0xb8c/0xbac
[34437.174299]  [<000000000015b21e>] process_one_work+0x432/0x640
[34437.174302]  [<000000000015ba0e>] worker_thread+0x19a/0x3c0
[34437.174306]  [<0000000000164842>] kthread+0x10e/0x128
[34437.174309]  [<0000000000728e56>] kernel_thread_starter+0x6/0xc
[34437.174313]  [<0000000000728e50>] kernel_thread_starter+0x0/0xc
[34437.174317] XXX: after schedule(), cpu=2
Signature · 1 line
-- Jason J. Herne ([email protected])
#7 lore raw
Quoted 11 lines · Jason J. Herne
Quoted 10 lines · Tejun Heo

Hello,

Quoted 6 lines · Jason J. Herne
[  950.778485] XXX: worker->flags=0x1 pool->flags=0x0 cpu=6
pool->cpu=2 rescue_wq=          (null)
[  950.778488] XXX: last_unbind=-7 last_rebind=0
last_rebound_clear=0 nr_exected_after_rebound_clear=0
[  950.778492] XXX: cpus_allowed=2
[  950.778495] XXX: cpus_allowed_after_rebinding=2
Quoted 6 lines
Quoted 3 lines

So, everything looks kosher from workqueue side. Weird. cpus_allowed is properly set and everything. The worker just isn't running on the cpu it's supposed to be on. Can you please try the following?

Thanks for the fast responses. Here is the output from the last patch:

I can't hit the bug. Could you give me more information to help me to reproduce the bug? I think we need to use "git-bisect" to address the suspicious patch.

Thanks,
Lai

Quoted 57 lines

[34437.173991] WARNING: at kernel/workqueue.c:2156
[34437.173993] Modules linked in: ipt_MASQUERADE iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack xt_CHECKSUM iptable_mangle bridge stp llc ip6table_filter ip6_tables ebtable_nat ebtables iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi qeth_l2 tape_3590 tape tape_class vhost_net tun vhost macvtap macvlan lcs dasd_eckd_mod dasd_mod qeth ccwgroup zfcp scsi_transport_fc scsi_tgt qdio dm_multipath [last unloaded: kvm]
[34437.174030] CPU: 2 PID: 12 Comm: kworker/1:0 Not tainted 3.14.0-rc1 #1
[34437.174034] task: 00000000f7c9e4c0 ti: 00000000f7cbc000 task.ti: 00000000f7cbc000
[34437.174046] Krnl PSW : 0404c00180000000 000000000015b406 (process_one_work+0x61a/0x640)
[34437.174051]            R:0 T:1 IO:0 EX:0 Key:0 M:1 W:0 P:0 AS:3 CC:0 PM:0 EA:3
Krnl GPRS: 000000007c325b00 0000000000bc2a52 00000000f7f52780 0000000000000001
[34437.174057]            0000000000000000 0000000000000002 0000000000000001 0000000000bc2a4e
[34437.174061]            0000000000000000 0000000084a13500 0000000084a0f000 0000000084a0f018
[34437.174065]            00000000f7f52780 0000000000735d18 00000000f7cbfdd0 00000000f7cbfd58
[34437.174085] Krnl Code: 000000000015b3fa: 92013000        mvi    0(%r3),1
           000000000015b3fe: a7f4ff31        brc    15,15b260
          #000000000015b402: a7f40001        brc    15,15b404
          >000000000015b406: 92011000        mvi    0(%r1),1
           000000000015b40a: a7f4fe84        brc    15,15b112
           000000000015b40e: 41102018        la    %r1,24(%r2)
           000000000015b412: e31020180020    cg    %r1,24(%r2)
           000000000015b418: a784ff59        brc    8,15b2ca
[34437.174115] Call Trace:
[34437.174118] ([<000000000015b0e0>] process_one_work+0x2f4/0x640)
[34437.174122]  [<000000000015ba0e>] worker_thread+0x19a/0x3c0
[34437.174126]  [<0000000000164842>] kthread+0x10e/0x128
[34437.174132]  [<0000000000728e56>] kernel_thread_starter+0x6/0xc
[34437.174136]  [<0000000000728e50>] kernel_thread_starter+0x0/0xc
[34437.174138] Last Breaking-Event-Address:
[34437.174141]  [<000000000015b402>] process_one_work+0x616/0x640
[34437.174144] ---[ end trace 52d8ee96597a2415 ]---
[34437.174148] XXX: worker->flags=0x1 pool->flags=0x0 cpu=2 pool->cpu=1(1) rescue_wq=          (null)
[34437.174152] XXX: last_unbind=-34 last_rebind=0 last_rebound_clear=0 nr_exected_after_rebound_clear=0
[34437.174156] XXX: cpus_allowed=1
[34437.174158] XXX: cpus_allowed_after_rebinding=1
[34437.174161] BUG: scheduling while atomic: kworker/1:0/12/0x00000002
[34437.174164] Modules linked in: ipt_MASQUERADE iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack xt_CHECKSUM iptable_mangle bridge stp llc ip6table_filter ip6_tables ebtable_nat ebtables iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi qeth_l2 tape_3590 tape tape_class vhost_net tun vhost macvtap macvlan lcs dasd_eckd_mod dasd_mod qeth ccwgroup zfcp scsi_transport_fc scsi_tgt qdio dm_multipath [last unloaded: kvm]
[34437.174194] CPU: 2 PID: 12 Comm: kworker/1:0 Tainted: G        W 3.14.0-rc1 #1
[34437.174197]        00000000f7cbfb80 00000000f7cbfb90 0000000000000002 0000000000000000
       00000000f7cbfc20 00000000f7cbfb98 00000000f7cbfb98 0000000000115f6a
       0000000000000003 0000000000c4da00 000000000000000a 000000000000000a
       00000000f7cbfbe0 00000000f7cbfb80 0000000000000000 0000000000000000
       0000000000000000 0000000000115f6a 00000000f7cbfb80 00000000f7cbfbd0
[34437.174273] Call Trace:
[34437.174279] ([<0000000000115e5c>] show_trace+0x100/0x148)
[34437.174282]  [<0000000000115f18>] show_stack+0x74/0xf4
[34437.174288]  [<0000000000720a9c>] dump_stack+0x88/0xb8
[34437.174291]  [<000000000071aa40>] __schedule_bug+0x78/0x90
[34437.174295]  [<00000000007237e4>] __schedule+0xb8c/0xbac
[34437.174299]  [<000000000015b21e>] process_one_work+0x432/0x640
[34437.174302]  [<000000000015ba0e>] worker_thread+0x19a/0x3c0
[34437.174306]  [<0000000000164842>] kthread+0x10e/0x128
[34437.174309]  [<0000000000728e56>] kernel_thread_starter+0x6/0xc
[34437.174313]  [<0000000000728e50>] kernel_thread_starter+0x0/0xc
[34437.174317] XXX: after schedule(), cpu=2
#8 lore raw
In reply to Jason J. Herne
Quoted 62 lines · Jason J. Herne
Quoted 10 lines · Tejun Heo

Hello,

Quoted 6 lines · Jason J. Herne
[  950.778485] XXX: worker->flags=0x1 pool->flags=0x0 cpu=6
pool->cpu=2 rescue_wq=          (null)
[  950.778488] XXX: last_unbind=-7 last_rebind=0
last_rebound_clear=0 nr_exected_after_rebound_clear=0
[  950.778492] XXX: cpus_allowed=2
[  950.778495] XXX: cpus_allowed_after_rebinding=2
Quoted 3 lines

So, everything looks kosher from workqueue side. Weird. cpus_allowed is properly set and everything. The worker just isn't running on the cpu it's supposed to be on. Can you please try the following?

Thanks for the fast responses. Here is the output from the last patch:

[34437.173991] WARNING: at kernel/workqueue.c:2156
[34437.173993] Modules linked in: ipt_MASQUERADE iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack xt_CHECKSUM iptable_mangle bridge stp llc ip6table_filter ip6_tables ebtable_nat ebtables iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi qeth_l2 tape_3590 tape tape_class vhost_net tun vhost macvtap macvlan lcs dasd_eckd_mod dasd_mod qeth ccwgroup zfcp scsi_transport_fc scsi_tgt qdio dm_multipath [last unloaded: kvm]
[34437.174030] CPU: 2 PID: 12 Comm: kworker/1:0 Not tainted 3.14.0-rc1 #1
[34437.174034] task: 00000000f7c9e4c0 ti: 00000000f7cbc000 task.ti: 00000000f7cbc000
[34437.174046] Krnl PSW : 0404c00180000000 000000000015b406 (process_one_work+0x61a/0x640)
[34437.174051]            R:0 T:1 IO:0 EX:0 Key:0 M:1 W:0 P:0 AS:3 CC:0 PM:0 EA:3
Krnl GPRS: 000000007c325b00 0000000000bc2a52 00000000f7f52780 0000000000000001
[34437.174057]            0000000000000000 0000000000000002 0000000000000001 0000000000bc2a4e
[34437.174061]            0000000000000000 0000000084a13500 0000000084a0f000 0000000084a0f018
[34437.174065]            00000000f7f52780 0000000000735d18 00000000f7cbfdd0 00000000f7cbfd58
[34437.174085] Krnl Code: 000000000015b3fa: 92013000        mvi    0(%r3),1
           000000000015b3fe: a7f4ff31        brc    15,15b260
          #000000000015b402: a7f40001        brc    15,15b404
          >000000000015b406: 92011000        mvi    0(%r1),1
           000000000015b40a: a7f4fe84        brc    15,15b112
           000000000015b40e: 41102018        la    %r1,24(%r2)
           000000000015b412: e31020180020    cg    %r1,24(%r2)
           000000000015b418: a784ff59        brc    8,15b2ca
[34437.174115] Call Trace:
[34437.174118] ([<000000000015b0e0>] process_one_work+0x2f4/0x640)
[34437.174122]  [<000000000015ba0e>] worker_thread+0x19a/0x3c0
[34437.174126]  [<0000000000164842>] kthread+0x10e/0x128
[34437.174132]  [<0000000000728e56>] kernel_thread_starter+0x6/0xc
[34437.174136]  [<0000000000728e50>] kernel_thread_starter+0x0/0xc
[34437.174138] Last Breaking-Event-Address:
[34437.174141]  [<000000000015b402>] process_one_work+0x616/0x640
[34437.174144] ---[ end trace 52d8ee96597a2415 ]---
[34437.174148] XXX: worker->flags=0x1 pool->flags=0x0 cpu=2 pool->cpu=1(1) rescue_wq=          (null)
[34437.174152] XXX: last_unbind=-34 last_rebind=0 last_rebound_clear=0 nr_exected_after_rebound_clear=0
[34437.174156] XXX: cpus_allowed=1
[34437.174158] XXX: cpus_allowed_after_rebinding=1
[34437.174161] BUG: scheduling while atomic: kworker/1:0/12/0x00000002
[34437.174164] Modules linked in: ipt_MASQUERADE iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack xt_CHECKSUM iptable_mangle bridge stp llc ip6table_filter ip6_tables ebtable_nat ebtables iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi qeth_l2 tape_3590 tape tape_class vhost_net tun vhost macvtap macvlan lcs dasd_eckd_mod dasd_mod qeth ccwgroup zfcp scsi_transport_fc scsi_tgt qdio dm_multipath [last unloaded: kvm]
[34437.174194] CPU: 2 PID: 12 Comm: kworker/1:0 Tainted: G        W 3.14.0-rc1 #1
[34437.174197]        00000000f7cbfb80 00000000f7cbfb90 0000000000000002 0000000000000000
       00000000f7cbfc20 00000000f7cbfb98 00000000f7cbfb98 0000000000115f6a
       0000000000000003 0000000000c4da00 000000000000000a 000000000000000a
       00000000f7cbfbe0 00000000f7cbfb80 0000000000000000 0000000000000000
       0000000000000000 0000000000115f6a 00000000f7cbfb80 00000000f7cbfbd0
[34437.174273] Call Trace:
[34437.174279] ([<0000000000115e5c>] show_trace+0x100/0x148)
[34437.174282]  [<0000000000115f18>] show_stack+0x74/0xf4
[34437.174288]  [<0000000000720a9c>] dump_stack+0x88/0xb8
Quoted 8 lines
[34437.174291]  [<000000000071aa40>] __schedule_bug+0x78/0x90
[34437.174295]  [<00000000007237e4>] __schedule+0xb8c/0xbac
[34437.174299]  [<000000000015b21e>] process_one_work+0x432/0x640
[34437.174302]  [<000000000015ba0e>] worker_thread+0x19a/0x3c0
[34437.174306]  [<0000000000164842>] kthread+0x10e/0x128
[34437.174309]  [<0000000000728e56>] kernel_thread_starter+0x6/0xc
[34437.174313]  [<0000000000728e50>] kernel_thread_starter+0x0/0xc
[34437.174317] XXX: after schedule(), cpu=2

Could you use the following patch for test if Tejun doesn't give you a new one.

kernel/workqueue.c +49 -5
index b010eac..cdd7a10 100644
@@ -825,6 +825,7 @@ void wq_worker_waking_up(struct task_struct *task, int cpu)
 {
 	struct worker *worker = kthread_data(task);
 
+	worker->wake_up = jiffies;
 	if (!(worker->flags & WORKER_NOT_RUNNING)) {
 		WARN_ON_ONCE(worker->pool->cpu != cpu);
 		atomic_inc(&worker->pool->nr_running);

@@ -851,6 +852,7 @@ struct task_struct *wq_worker_sleeping(struct task_struct *task, int cpu)
 	struct worker *worker = kthread_data(task), *to_wakeup = NULL;
 	struct worker_pool *pool;
 
+	worker->sleep = jiffies;
 	/*
 	 * Rescuers, which may not have all the fields set up like normal
 	 * workers, also reach here, let's not access anything before

@@ -2134,6 +2136,7 @@ __acquires(&pool->lock)
 	bool cpu_intensive = pwq->wq->flags & WQ_CPU_INTENSIVE;
 	int work_color;
 	struct worker *collision;
+	int worker_bug = 0;
 #ifdef CONFIG_LOCKDEP
 	/*
 	 * It is permissible to free the struct work_struct from

@@ -2151,9 +2154,31 @@ __acquires(&pool->lock)
 	 * necessary to avoid spurious warnings from rescuers servicing the
 	 * unbound or a disassociated pool.
 	 */
-	WARN_ON_ONCE(!(worker->flags & WORKER_UNBOUND) &&
-		     !(pool->flags & POOL_DISASSOCIATED) &&
-		     raw_smp_processor_id() != pool->cpu);
+	if (WARN_ON_ONCE(!(worker->flags & WORKER_UNBOUND) &&
+			 !(pool->flags & POOL_DISASSOCIATED) &&
+			 raw_smp_processor_id() != pool->cpu)) {
+		static char buf[PAGE_SIZE];
+		unsigned long now = jiffies;
+
+		worker_bug = 1;
+		pr_warning("XXX: worker->flags=0x%x pool->flags=0x%x cpu=%d pool->cpu=%d(%d) rescue_wq=%p\n",
+			   worker->flags, pool->flags, raw_smp_processor_id(),
+			   pool->cpu, cpu_online(pool->cpu), worker->rescue_wq);
+		pr_warning("XXX: last_unbind=%ld last_rebind=%ld last_rebound_clear=%ld nr_exected_after_rebound_clear=%d\n",
+			   worker->last_unbind ? worker->last_unbind - now : 999,
+			   worker->last_rebind ? worker->last_rebind - now : 999,
+			   worker->last_rebound_clear ? worker->last_rebound_clear - now : 999,
+			   worker->nr_executed_after_rebound_clear);
+		pr_warning("XXX: sleep=%ld wakeup=%ld\n",
+			   worker->sleep ? worker->sleep - now : 999,
+			   worker->wake_up ? worker->wake_up - now : 999);
+
+		cpulist_scnprintf(buf, sizeof(buf), &current->cpus_allowed);
+		pr_warning("XXX: cpus_allowed=%s\n", buf);
+
+		cpulist_scnprintf(buf, sizeof(buf), &worker->cpus_allowed_after_rebinding);
+		pr_warning("XXX: cpus_allowed_after_rebinding=%s\n", buf);
+	}
 
 	/*
 	 * A single work shouldn't be executed concurrently by

@@ -2199,8 +2224,15 @@ __acquires(&pool->lock)
 	 */
 	set_work_pool_and_clear_pending(work, pool->id);
 
+	worker->nr_executed_after_rebound_clear++;
+
 	spin_unlock_irq(&pool->lock);
 
+	if (worker_bug) {
+		schedule();
+
+		pr_warning("XXX: after schedule(), cpu=%d\n", raw_smp_processor_id());
+	}
 	lock_map_acquire_read(&pwq->wq->lockdep_map);
 	lock_map_acquire(&lockdep_map);
 	trace_workqueue_execute_start(work);

@@ -2298,6 +2330,7 @@ woke_up:
 	}
 
 	worker_leave_idle(worker);
+	worker->wake_up = jiffies;
 recheck:
 	/* no more worker necessary? */
 	if (!need_more_worker(pool))

@@ -2321,6 +2354,10 @@ recheck:
 	 * management if applicable and concurrency management is restored
 	 * after being rebound.  See rebind_workers() for details.
 	 */
+	if (worker->flags & WORKER_REBOUND) {
+		worker->last_rebound_clear = jiffies;
+		worker->nr_executed_after_rebound_clear = 0;
+	}
 	worker_clr_flags(worker, WORKER_PREP | WORKER_REBOUND);
 
 	do {

@@ -2341,6 +2378,7 @@ recheck:
 
 	worker_set_flags(worker, WORKER_PREP, false);
 sleep:
+	worker->sleep = jiffies;
 	if (unlikely(need_to_manage_workers(pool)) && manage_workers(worker))
 		goto recheck;
 

@@ -4576,8 +4614,10 @@ static void wq_unbind_fn(struct work_struct *work)
 		 * before the last CPU down must be on the cpu.  After
 		 * this, they may become diasporas.
 		 */
-		for_each_pool_worker(worker, wi, pool)
+		for_each_pool_worker(worker, wi, pool) {
 			worker->flags |= WORKER_UNBOUND;
+			worker->last_unbind = jiffies;
+		}
 
 		pool->flags |= POOL_DISASSOCIATED;
 

@@ -4633,9 +4673,13 @@ static void rebind_workers(struct worker_pool *pool)
 	 * of all workers first and then clear UNBOUND.  As we're called
 	 * from CPU_ONLINE, the following shouldn't fail.
 	 */
-	for_each_pool_worker(worker, wi, pool)
+	for_each_pool_worker(worker, wi, pool) {
 		WARN_ON_ONCE(set_cpus_allowed_ptr(worker->task,
 						  pool->attrs->cpumask) < 0);
+		worker->last_rebind = jiffies;
+		cpumask_copy(&worker->cpus_allowed_after_rebinding,
+			     &worker->task->cpus_allowed);
+	}
 
 	spin_lock_irq(&pool->lock);
kernel/workqueue_internal.h +7 -0
index 7e2204d..db17e2c 100644
@@ -50,6 +50,13 @@ struct worker {
 
 	/* used only by rescuers to point to the target workqueue */
 	struct workqueue_struct	*rescue_wq;	/* I: the workqueue to rescue */
+	unsigned long		last_unbind;
+	unsigned long		last_rebind;
+	unsigned long		sleep;
+	unsigned long		wake_up;
+	unsigned long		last_rebound_clear;
+	int			nr_executed_after_rebound_clear;
+	cpumask_t		cpus_allowed_after_rebinding;
 };
 
 /**
author
#9 lore raw
Quoted 3 lines · Lai Jiangshan

On 02/12/2014 11:18 PM, Jason J. Herne wrote:

Could you use the following patch for test if Tejun doesn't give you a new one.

Lai,

Here is the output using the patch you asked me to run with.

[ 5779.795687] ------------[ cut here ]------------
[ 5779.795695] WARNING: at kernel/workqueue.c:2159
[ 5779.795698] Modules linked in: ipt_MASQUERADE iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack xt_CHECKSUM iptable_mangle bridge stp llc ip6table_filter ip6_tables ebtable_nat ebtables iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi tape_3590 qeth_l2 tape tape_class vhost_net tun vhost macvtap macvlan lcs dasd_eckd_mod dasd_mod qeth ccwgroup zfcp scsi_transport_fc scsi_tgt qdio dm_multipath [last unloaded: kvm]
[ 5779.795733] CPU: 4 PID: 270 Comm: kworker/5:1 Not tainted 3.14.0-rc1 #1
[ 5779.795738] task: 0000000001938000 ti: 00000000f4d9c000 task.ti: 00000000f4d9c000
[ 5779.795750] Krnl PSW : 0404c00180000000 000000000015b452 (process_one_work+0x666/0x688)
[ 5779.795756]            R:0 T:1 IO:0 EX:0 Key:0 M:1 W:0 P:0 AS:3 CC:0 PM:0 EA:3
Krnl GPRS: 000003210f9db000 0000000000bc2a52 0000000001b640c0 0000000000000001
[ 5779.795757]            0000000000000000 0000000000000004 0000000000000005 00000000ffffffff
[ 5779.795759]            0000000000000000 0000000084a43500 0000000084a3f000 0000000084a3f018
[ 5779.795763]            0000000001b640c0 0000000000735d18 00000000f4d9fdc8 00000000f4d9fd50
[ 5779.795781] Krnl Code: 000000000015b444: dd1a9640c05b	trt 1600(27,%r9),91(%r12)
           000000000015b44a: a7f4fd9e		brc	15,15af86
          #000000000015b44e: a7f40001		brc	15,15b450
          >000000000015b452: 92011000		mvi	0(%r1),1
           000000000015b456: a7f4fe63		brc	15,15b11c
           000000000015b45a: c03000533af9	larl	%r3,bc2a4c
           000000000015b460: 95003000		cli	0(%r3),0
           000000000015b464: a774ff3e		brc	7,15b2e0
[ 5779.795810] Call Trace:
[ 5779.795814] ([<000000000015b0ea>] process_one_work+0x2fe/0x688)
[ 5779.795817]  [<000000000015ba62>] worker_thread+0x1a6/0x3d4
[ 5779.795822]  [<00000000001648c2>] kthread+0x10e/0x128
[ 5779.795828]  [<0000000000728ed6>] kernel_thread_starter+0x6/0xc
[ 5779.795832]  [<0000000000728ed0>] kernel_thread_starter+0x0/0xc
[ 5779.795834] Last Breaking-Event-Address:
[ 5779.795837]  [<000000000015b44e>] process_one_work+0x662/0x688
[ 5779.795840] ---[ end trace 8b6353b0f2821ec9 ]---
[ 5779.795844] XXX: worker->flags=0x1 pool->flags=0x0 cpu=4 pool->cpu=5(1) rescue_wq=          (null)
[ 5779.795848] XXX: last_unbind=-44 last_rebind=0 last_rebound_clear=0 nr_exected_after_rebound_clear=0
[ 5779.795852] XXX: sleep=-39 wakeup=0
[ 5779.795855] XXX: cpus_allowed=5
[ 5779.795857] XXX: cpus_allowed_after_rebinding=5
[ 5779.795861] XXX: after schedule(), cpu=4

You had asked about reproducing this. This is on the S390 platform, I'm not sure if that makes any difference.

The workload is:
2 processes onlining random cpus in a tight loop by using 'echo 1 > /sys/bus/cpu.../online' 2 processes offlining random cpus in a tight loop by using 'echo 0 > /sys/bus/cpu.../online' Otherwise, fairly idle system. load average: 5.82, 6.27, 6.27

The machine has 10 processors.
The warning message some times hits within a few minutes on starting the workload. Other times it takes several hours.

Please let me know if you have further questions.

Signature · 1 line
-- Jason J. Herne ([email protected])
maintainer
#10 lore raw

Hello,

(cc'ing Ingo and Peter)

Quoted 2 lines · Jason J. Herne
[ 5779.795687] ------------[ cut here ]------------
[ 5779.795695] WARNING: at kernel/workqueue.c:2159

....

Quoted 10 lines
[ 5779.795844] XXX: worker->flags=0x1 pool->flags=0x0 cpu=4 pool->cpu=5(1) rescue_wq=          (null)
[ 5779.795848] XXX: last_unbind=-44 last_rebind=0 last_rebound_clear=0 nr_exected_after_rebound_clear=0
[ 5779.795852] XXX: sleep=-39 wakeup=0
[ 5779.795855] XXX: cpus_allowed=5
[ 5779.795857] XXX: cpus_allowed_after_rebinding=5
[ 5779.795861] XXX: after schedule(), cpu=4

You had asked about reproducing this. This is on the S390 platform, I'm not sure if that makes any difference.

Quoted 8 lines

The workload is:
2 processes onlining random cpus in a tight loop by using 'echo 1 > /sys/bus/cpu.../online' 2 processes offlining random cpus in a tight loop by using 'echo 0 > /sys/bus/cpu.../online' Otherwise, fairly idle system. load average: 5.82, 6.27, 6.27

The machine has 10 processors.
The warning message some times hits within a few minutes on starting the workload. Other times it takes several hours.

Ingo, Peter, Jason is reporting workqueue triggering warning because a worker is running on the wrong CPU, which is relatively reliably reproducible with the above workload on s390. The weird thing is that everything looks correct from workqueue side. The worker has proper cpus_allowed set and the CPU it's supposed to run on is online and yet the worker is on the wrong CPU and even doing explicit schedule() after detecting the condition doesn't change the situation. Any ideas?

Jason, I don't have much idea from workqueue side. Have you been running this test with older kernels too? Can you confirm whether this failure is something recent? Bisection would be awesome but just confirming, say, 3.12 doesn't have this issue would be very helpful.

Thanks!

Signature · 1 line
tejun
author
#11 lore raw
Quoted 4 lines · Tejun Heo

Jason, I don't have much idea from workqueue side. Have you been running this test with older kernels too? Can you confirm whether this failure is something recent? Bisection would be awesome but just confirming, say, 3.12 doesn't have this issue would be very helpful.

I will try to find a kernel where this is not reproducible and attempt bisect from there. I will let you know what I find.

Signature · 1 line
-- Jason J. Herne ([email protected])
maintainer
#12 lore raw

Hello, Jason.

Quoted 2 lines · Jason J. Herne

I will try to find a kernel where this is not reproducible and attempt bisect from there. I will let you know what I find.

Yes, even just finding that there's an earlier version where this doesn't happen would be great.

Thank you very much.

Signature · 1 line
tejun
maintainer
#13 lore raw
In reply to Tejun Heo
Quoted 23 lines · Tejun Heo

Hello,

(cc'ing Ingo and Peter)

Quoted 2 lines · Jason J. Herne
[ 5779.795687] ------------[ cut here ]------------
[ 5779.795695] WARNING: at kernel/workqueue.c:2159

....

Quoted 15 lines
[ 5779.795844] XXX: worker->flags=0x1 pool->flags=0x0 cpu=4 pool->cpu=5(1) rescue_wq=          (null)
[ 5779.795848] XXX: last_unbind=-44 last_rebind=0 last_rebound_clear=0 nr_exected_after_rebound_clear=0
[ 5779.795852] XXX: sleep=-39 wakeup=0
[ 5779.795855] XXX: cpus_allowed=5
[ 5779.795857] XXX: cpus_allowed_after_rebinding=5
[ 5779.795861] XXX: after schedule(), cpu=4

You had asked about reproducing this. This is on the S390 platform, I'm not sure if that makes any difference.

The workload is:
2 processes onlining random cpus in a tight loop by using 'echo 1 > /sys/bus/cpu.../online' 2 processes offlining random cpus in a tight loop by using 'echo 0 > /sys/bus/cpu.../online' Otherwise, fairly idle system. load average: 5.82, 6.27, 6.27

Quoted 7 lines
Quoted 3 lines

The machine has 10 processors.
The warning message some times hits within a few minutes on starting the workload. Other times it takes several hours.

Ingo, Peter, Jason is reporting workqueue triggering warning because a worker is running on the wrong CPU, which is relatively reliably reproducible with the above workload on s390.

Wasn't that a feature of workqueues? You know we've had arguments about that behaviour -- I'm strongly in favour of flushing and killing workers on unplug, but you let them run on the wrong cpu.

So strongly in fact, I'd call the current behaviour quite insane and broken :-)

Quoted 5 lines

The weird thing is that
everything looks correct from workqueue side. The worker has proper cpus_allowed set and the CPU it's supposed to run on is online and yet the worker is on the wrong CPU and even doing explicit schedule() after detecting the condition doesn't change the situation.

Yeah, just calling schedule() won't fix placement, you need to actually block and wake-up. But given you've called things like set_cpus_allowed_ptr() and such to set the mask back to 5..

You can try something like the below which makes it slightly more aggressive about moving tasks about.

Quoted 1 line

Any ideas?

Not really; s390 doesn't have NUMA, so all those changes are out.

---
 kernel/sched/core.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)
kernel/sched/core.c +2 -1
index fb9764fbc537..20bd4de44bb3 100644
@@ -4504,7 +4504,8 @@ int set_cpus_allowed_ptr(struct task_struct *p, const struct cpumask *new_mask)
 
 	rq = task_rq_lock(p, &flags);
 
-	if (cpumask_equal(&p->cpus_allowed, new_mask))
+	if (cpumask_equal(&p->cpus_allowed, new_mask) && 
+	    cpumask_test_cpu(rq->cpu, &p->cpus_allowed))
 		goto out;
 
 	if (!cpumask_intersects(new_mask, cpu_active_mask)) {
maintainer
#14 lore raw

Hey, Peter.

Quoted 10 lines · Peter Zijlstra
Quoted 3 lines

Ingo, Peter, Jason is reporting workqueue triggering warning because a worker is running on the wrong CPU, which is relatively reliably reproducible with the above workload on s390.

Wasn't that a feature of workqueues? You know we've had arguments about that behaviour -- I'm strongly in favour of flushing and killing workers on unplug, but you let them run on the wrong cpu.

So strongly in fact, I'd call the current behaviour quite insane and broken :-)

Hey, we now even keep normal kthreads across cpu down/ups. :)

Quoted 3 lines

Yeah, just calling schedule() won't fix placement, you need to actually block and wake-up. But given you've called things like set_cpus_allowed_ptr() and such to set the mask back to 5..

Hmmm... I see. It's kinda weird that the code has been there for so long and this is the first time it's getting reported.

Quoted 16 lines

You can try something like the below which makes it slightly more aggressive about moving tasks about.

Quoted 1 line

Any ideas?

Not really; s390 doesn't have NUMA, so all those changes are out.

---
 kernel/sched/core.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)
kernel/sched/core.c +0 -0
index fb9764fbc537..20bd4de44bb3 100644

kernel/sched/core.c int set_cpus_allowed_ptr(struct task_struct *p, const struct cpumask *new_mask) · line 4511

Quoted 9 lines
kernel/sched/core.c +2 -1
@@ -4504,7 +4504,8 @@ int set_cpus_allowed_ptr(struct task_struct *p, const struct cpumask *new_mask)
 
 	rq = task_rq_lock(p, &flags);
 
-	if (cpumask_equal(&p->cpus_allowed, new_mask))
+	if (cpumask_equal(&p->cpus_allowed, new_mask) && 
+	    cpumask_test_cpu(rq->cpu, &p->cpus_allowed))
 		goto out;
 
 	if (!cpumask_intersects(new_mask, cpu_active_mask)) {

Hmmm... weird, p's rq shouldn't have changed without its cpus_allowed busted. Anyways, let's wait for Jason's test results and see whether this is a regression at all.

Thanks.

Signature · 1 line
tejun
maintainer
#15 lore raw
Quoted 1 line · Tejun Heo

Hey, we now even keep normal kthreads across cpu down/ups. :)

Well, we keep them, but parked, they're not allowed to run.

maintainer
#16 lore raw
Quoted 4 lines · Peter Zijlstra
Quoted 1 line · Tejun Heo

Hey, we now even keep normal kthreads across cpu down/ups. :)

Well, we keep them, but parked, they're not allowed to run.

Yeah, that's true. In the long term, I think we'll need to have better distinction between the work items which actually need affinity for correctness and which is just doing it as an optimization. It's already happening now in a rather ad-hoc way with WQ_POWER_EFFICIENT. Anyways, once we actually make that distinction clearly, it should probably be possible to flush all per-cpu ones and keep them parked across offline. Right now, we have mixture of the two and the knowledge is only present in cpu_down callbacks of each user making it difficult to do that.

Thanks.

Signature · 1 line
tejun
author
#17 lore raw
In reply to Tejun Heo
Quoted 4 lines · Tejun Heo

...
Hmmm... weird, p's rq shouldn't have changed without its cpus_allowed busted. Anyways, let's wait for Jason's test results and see whether this is a regression at all.

I was unable to determine exactly when this behavior was introduced. The reason for this is because I keep hitting other bugs that prevent the test case from running, the most notable of which causes an immediate system hang. I also hit other warnings and bug messages and I'm not sure if they are related or if they will influence the probability of hitting the problem we are trying to solve here. What I did find is the following:

We hit this problem as far back as v3.10.
The warning was introduced after v3.5 but before v3.6.

Signature · 1 line
-- Jason J. Herne ([email protected])
maintainer
#18 lore raw
Quoted 14 lines · Jason J. Herne
Quoted 4 lines · Tejun Heo

...
Hmmm... weird, p's rq shouldn't have changed without its cpus_allowed busted. Anyways, let's wait for Jason's test results and see whether this is a regression at all.

I was unable to determine exactly when this behavior was introduced. The reason for this is because I keep hitting other bugs that prevent the test case from running, the most notable of which causes an immediate system hang. I also hit other warnings and bug messages and I'm not sure if they are related or if they will influence the probability of hitting the problem we are trying to solve here. What I did find is the following:

Quoted 2 lines

We hit this problem as far back as v3.10.
The warning was introduced after v3.5 but before v3.6.

That's a bummer but it at least isn't a very new regression. Peter, any ideas on debugging this? I can make workqueue to play block / unblock dance to try to work around the issue but that'd be very yucky. It'd be great to root cause where the cpu selection anomaly is coming from.

Thanks.

Signature · 1 line
tejun
maintainer
#19 lore raw
Quoted 5 lines · Tejun Heo

That's a bummer but it at least isn't a very new regression. Peter, any ideas on debugging this? I can make workqueue to play block / unblock dance to try to work around the issue but that'd be very yucky. It'd be great to root cause where the cpu selection anomaly is coming from.

I'm assuming you're using set_cpus_allowed_ptr() to flip them between CPUs; the below adds some error paths to that code. In particular we propagate the __migrate_task() fail (returns the number of tasks migrated) through the stop_one_cpu() into set_cpus_allowed_ptr().

This way we can see if there was a problem with the migration.

You should be able to now reliably use the return value of set_cpus_allowed_ptr() to tell if it is now running on a CPU in its allowed mask.

I've also included an #if 0 retry loop for the fail case; but I suspect that that might end up deadlocking your machine if you hit that just wrong, something like the waking CPU endlessly trying to migrate the task over while the wakee CPU is waiting for completion of something from the waking CPU.

But its worth a prod I suppose.

kernel/sched/core.c +19 -6
index 84b23cec0aeb..4c384efac8b3 100644
@@ -4554,18 +4554,28 @@ int set_cpus_allowed_ptr(struct task_struct *p, const struct cpumask *new_mask)
 
 	do_set_cpus_allowed(p, new_mask);
 
+again: __maybe_unused
+
 	/* Can the task run on the task's current CPU? If so, we're done */
-	if (cpumask_test_cpu(task_cpu(p), new_mask))
+	if (cpumask_test_cpu(task_cpu(p), tsk_cpus_allowed(p)))
 		goto out;
 
-	dest_cpu = cpumask_any_and(cpu_active_mask, new_mask);
+	dest_cpu = cpumask_any_and(cpu_active_mask, tsk_cpus_allowed(p));
 	if (p->on_rq) {
 		struct migration_arg arg = { p, dest_cpu };
+
 		/* Need help from migration thread: drop lock and wait. */
 		task_rq_unlock(rq, p, &flags);
-		stop_one_cpu(cpu_of(rq), migration_cpu_stop, &arg);
+		ret = stop_one_cpu(cpu_of(rq), migration_cpu_stop, &arg);
+#if 0
+		if (ret) {
+			rq = task_rq_lock(p, &flags);
+			goto again;
+		}
+#endif
 		tlb_migrate_finish(p->mm);
-		return 0;
+
+		return ret;
 	}
 out:
 	task_rq_unlock(rq, p, &flags);

@@ -4679,15 +4689,18 @@ void sched_setnuma(struct task_struct *p, int nid)
 static int migration_cpu_stop(void *data)
 {
 	struct migration_arg *arg = data;
+	int ret = 0;
 
 	/*
 	 * The original target cpu might have gone down and we might
 	 * be on another cpu but it doesn't matter.
 	 */
 	local_irq_disable();
-	__migrate_task(arg->task, raw_smp_processor_id(), arg->dest_cpu);
+	if (!__migrate_task(arg->task, raw_smp_processor_id(), arg->dest_cpu))
+		ret = -EAGAIN;
 	local_irq_enable();
-	return 0;
+
+	return ret;
 }
 
 #ifdef CONFIG_HOTPLUG_CPU
author
#20 lore raw
Quoted 77 lines · Peter Zijlstra
Quoted 5 lines · Tejun Heo

That's a bummer but it at least isn't a very new regression. Peter, any ideas on debugging this? I can make workqueue to play block / unblock dance to try to work around the issue but that'd be very yucky. It'd be great to root cause where the cpu selection anomaly is coming from.

I'm assuming you're using set_cpus_allowed_ptr() to flip them between CPUs; the below adds some error paths to that code. In particular we propagate the __migrate_task() fail (returns the number of tasks migrated) through the stop_one_cpu() into set_cpus_allowed_ptr().

This way we can see if there was a problem with the migration.

You should be able to now reliably use the return value of set_cpus_allowed_ptr() to tell if it is now running on a CPU in its allowed mask.

I've also included an #if 0 retry loop for the fail case; but I suspect that that might end up deadlocking your machine if you hit that just wrong, something like the waking CPU endlessly trying to migrate the task over while the wakee CPU is waiting for completion of something from the waking CPU.

But its worth a prod I suppose.

kernel/sched/core.c +15 -4
index 84b23cec0aeb..4c384efac8b3 100644
@@ -4554,18 +4554,28 @@ int set_cpus_allowed_ptr(struct task_struct *p, const struct cpumask *new_mask)
 
  	do_set_cpus_allowed(p, new_mask);
 
+again: __maybe_unused
+
  	/* Can the task run on the task's current CPU? If so, we're done */
-	if (cpumask_test_cpu(task_cpu(p), new_mask))
+	if (cpumask_test_cpu(task_cpu(p), tsk_cpus_allowed(p)))
  		goto out;
 
-	dest_cpu = cpumask_any_and(cpu_active_mask, new_mask);
+	dest_cpu = cpumask_any_and(cpu_active_mask, tsk_cpus_allowed(p));
  	if (p->on_rq) {
  		struct migration_arg arg = { p, dest_cpu };
+
  		/* Need help from migration thread: drop lock and wait. */
  		task_rq_unlock(rq, p, &flags);
-		stop_one_cpu(cpu_of(rq), migration_cpu_stop, &arg);
+		ret = stop_one_cpu(cpu_of(rq), migration_cpu_stop, &arg);
+#if 0
+		if (ret) {
+			rq = task_rq_lock(p, &flags);
+			goto again;
+		}
+#endif
  		tlb_migrate_finish(p->mm);
-		return 0;
+
+		return ret;
  	}
  out:
  	task_rq_unlock(rq, p, &flags);

@@ -4679,15 +4689,18 @@ void sched_setnuma(struct task_struct *p, int nid)
  static int migration_cpu_stop(void *data)
  {
  	struct migration_arg *arg = data;
+	int ret = 0;
 
  	/*
  	 * The original target cpu might have gone down and we might
  	 * be on another cpu but it doesn't matter.
  	 */
  	local_irq_disable();

kernel/sched/core.c void sched_setnuma(struct task_struct *p, int nid) · line 4706

Quoted 10 lines
kernel/sched/core.c +4 -2
-	__migrate_task(arg->task, raw_smp_processor_id(), arg->dest_cpu);
+	if (!__migrate_task(arg->task, raw_smp_processor_id(), arg->dest_cpu))
+		ret = -EAGAIN;
  	local_irq_enable();
-	return 0;
+
+	return ret;
  }
 
  #ifdef CONFIG_HOTPLUG_CPU

Peter,

Did you intend for me to run with this patch or was it posted for discussion only? If you want it run, please tell me what to look for. Also, if I should run this, should I include any other patches, either the last one you posted in this thread or any of Tejun's?

Thanks.

Signature · 1 line
-- Jason J. Herne ([email protected])
author
#21 lore raw
Quoted 94 lines · Jason J. Herne
Quoted 88 lines · Peter Zijlstra
Quoted 5 lines · Tejun Heo

That's a bummer but it at least isn't a very new regression. Peter, any ideas on debugging this? I can make workqueue to play block / unblock dance to try to work around the issue but that'd be very yucky. It'd be great to root cause where the cpu selection anomaly is coming from.

I'm assuming you're using set_cpus_allowed_ptr() to flip them between CPUs; the below adds some error paths to that code. In particular we propagate the __migrate_task() fail (returns the number of tasks migrated) through the stop_one_cpu() into set_cpus_allowed_ptr().

This way we can see if there was a problem with the migration.

You should be able to now reliably use the return value of set_cpus_allowed_ptr() to tell if it is now running on a CPU in its allowed mask.

I've also included an #if 0 retry loop for the fail case; but I suspect that that might end up deadlocking your machine if you hit that just wrong, something like the waking CPU endlessly trying to migrate the task over while the wakee CPU is waiting for completion of something from the waking CPU.

But its worth a prod I suppose.

kernel/sched/core.c +14 -4
index 84b23cec0aeb..4c384efac8b3 100644
@@ -4554,18 +4554,28 @@ int set_cpus_allowed_ptr(struct task_struct
 *p, const struct cpumask *new_mask)
 
      do_set_cpus_allowed(p, new_mask);
 
+again: __maybe_unused
+
      /* Can the task run on the task's current CPU? If so, we're done */
-    if (cpumask_test_cpu(task_cpu(p), new_mask))
+    if (cpumask_test_cpu(task_cpu(p), tsk_cpus_allowed(p)))
          goto out;
 
-    dest_cpu = cpumask_any_and(cpu_active_mask, new_mask);
+    dest_cpu = cpumask_any_and(cpu_active_mask, tsk_cpus_allowed(p));
      if (p->on_rq) {
          struct migration_arg arg = { p, dest_cpu };
+
          /* Need help from migration thread: drop lock and wait. */
          task_rq_unlock(rq, p, &flags);
-        stop_one_cpu(cpu_of(rq), migration_cpu_stop, &arg);
+        ret = stop_one_cpu(cpu_of(rq), migration_cpu_stop, &arg);
+#if 0
+        if (ret) {
+            rq = task_rq_lock(p, &flags);
+            goto again;
+        }
+#endif
          tlb_migrate_finish(p->mm);
-        return 0;
+
+        return ret;
      }
  out:

      task_rq_unlock(rq, p, &flags);
kernel/sched/core.c +5 -2
@@ -4679,15 +4689,18 @@ void sched_setnuma(struct task_struct *p, int
 nid)
  static int migration_cpu_stop(void *data)
  {
      struct migration_arg *arg = data;
+    int ret = 0;
 
      /*
       * The original target cpu might have gone down and we might
       * be on another cpu but it doesn't matter.
       */
      local_irq_disable();
-    __migrate_task(arg->task, raw_smp_processor_id(), arg->dest_cpu);
+    if (!__migrate_task(arg->task, raw_smp_processor_id(),
 arg->dest_cpu))
+        ret = -EAGAIN;
      local_irq_enable();
-    return 0;
+
+    return ret;
  }
Quoted 2 lines
  #ifdef CONFIG_HOTPLUG_CPU

Peter,

Quoted 7 lines

Did you intend for me to run with this patch or was it posted for discussion only? If you want it run, please tell me what to look for. Also, if I should run this, should I include any other patches, either the last one you posted in this thread or any of Tejun's?

Thanks.

Ping?

Signature · 1 line
-- Jason J. Herne ([email protected])
maintainer
#22 lore raw
In reply to Jason J. Herne
Quoted 5 lines · Jason J. Herne

Did you intend for me to run with this patch or was it posted for discussion only? If you want it run, please tell me what to look for.
Also, if I should run this, should I include any other patches, either the last one you posted in this thread or any of Tejun's?

It needs some workqueue side debugging too; I'm not entirely sure where the moving back to the online cpu happens, but you want to check the set_cpus_allowed_ptr() return value there.