* Deadlock in cleanup_net and addrconf_verify_work locks up workqueue
@ 2020-02-11 19:23 Sargun Dhillon
2020-02-12 5:08 ` Eric Dumazet
0 siblings, 1 reply; 4+ messages in thread
From: Sargun Dhillon @ 2020-02-11 19:23 UTC (permalink / raw)
To: netdev, LKML
Cc: Tetsuo Handa, Gabriel Hartmann, Rob Gulewich, Bruce Curtis,
Hannes Frederic Sowa
We've found a workqueue stall / deadlock. Our workload is a container-oriented
workload in which we utilize IPv6. Our container (namespace) churn is quite
frequent, and containers can be terminated before their networking is
even setup.
We're running 4.19.73 in production, and in investigation of the underlying
causes, I don't think that future versions of 4.19 fix it.
We've narrowed it down to a lockup between ipv6_addrconf, and cleanup_net.
crash> bt 8
PID: 8 TASK: ffff9a1072b50000 CPU: 24 COMMAND: "kworker/u192:0"
#0 [ffffbfe2c00fbb70] __schedule at ffffffffa7f02bf7
#1 [ffffbfe2c00fbc10] schedule at ffffffffa7f031e8
#2 [ffffbfe2c00fbc18] schedule_timeout at ffffffffa7f0700e
#3 [ffffbfe2c00fbc90] wait_for_completion at ffffffffa7f03b50
#4 [ffffbfe2c00fbce0] __flush_work at ffffffffa76a2532
#5 [ffffbfe2c00fbd58] rollback_registered_many at ffffffffa7dbcdf4
#6 [ffffbfe2c00fbdc0] unregister_netdevice_many at ffffffffa7dbd31e
#7 [ffffbfe2c00fbdd0] default_device_exit_batch at ffffffffa7dbd512
#8 [ffffbfe2c00fbe40] cleanup_net at ffffffffa7dab970
#9 [ffffbfe2c00fbe98] process_one_work at ffffffffa76a17c4
#10 [ffffbfe2c00fbed8] worker_thread at ffffffffa76a19dd
#11 [ffffbfe2c00fbf10] kthread at ffffffffa76a7fd3
#12 [ffffbfe2c00fbf50] ret_from_fork at ffffffffa80001ff
crash> bt 1369493
PID: 1369493 TASK: ffff9a03684d9600 CPU: 58 COMMAND: "kworker/58:1"
#0 [ffffbfe30d68fd48] __schedule at ffffffffa7f02bf7
#1 [ffffbfe30d68fde8] schedule at ffffffffa7f031e8
#2 [ffffbfe30d68fdf0] schedule_preempt_disabled at ffffffffa7f0349a
#3 [ffffbfe30d68fdf8] __mutex_lock at ffffffffa7f04aed
#4 [ffffbfe30d68fe90] addrconf_verify_work at ffffffffa7e8d1aa
#5 [ffffbfe30d68fe98] process_one_work at ffffffffa76a17c4
#6 [ffffbfe30d68fed8] worker_thread at ffffffffa76a19dd
#7 [ffffbfe30d68ff10] kthread at ffffffffa76a7fd3
#8 [ffffbfe30d68ff50] ret_from_fork at ffffffffa80001ff
struct -x mutex.owner.counter rtnl_mutex
owner.counter = 0xffff9a1072b50001
0xffff9a1072b50001 & (~0x07) = 0xffff9a1072b50000
This points back to PID 8 / CPU 24. It is working on cleanup_net, and a part
of cleanup net involves calling ops_exit_list, and as part of that it calls
default_device_exit_batch. default_device_exit_batch takes the rtnl lock before
calling into unregister_netdevice_many, and rollback_registered_many.
rollback_registered_many calls flush_all_backlogs. This will never complete
because it is holding the rtnl lock, and PID 1369493 / CPU 58 is waiting
for rtnl_lock.
If relevant, the workqueue stalls themselves look something like:
BUG: workqueue lockup - pool cpus=70 node=0 flags=0x0 nice=0 stuck for 3720s!
BUG: workqueue lockup - pool cpus=70 node=0 flags=0x0 nice=-20 stuck for 3719s!
Showing busy workqueues and worker pools:
workqueue events: flags=0x0
pwq 32: cpus=16 node=0 flags=0x0 nice=0 active=2/256
in-flight: 1274779:slab_caches_to_rcu_destroy_workfn slab_caches_to_rcu_destroy_workfn
workqueue events_highpri: flags=0x10
pwq 141: cpus=70 node=0 flags=0x0 nice=-20 active=1/256
pending: flush_backlog BAR(8)
workqueue events_power_efficient: flags=0x82
pwq 193: cpus=0-23,48-71 node=0 flags=0x4 nice=0 active=1/256
in-flight: 1396446:check_lifetime
workqueue mm_percpu_wq: flags=0x8
pwq 140: cpus=70 node=0 flags=0x0 nice=0 active=1/256
pending: vmstat_update
workqueue netns: flags=0xe000a
pwq 192: cpus=0-95 flags=0x4 nice=0 active=1/1
in-flight: 8:cleanup_net
delayed: cleanup_net
workqueue writeback: flags=0x4e
pwq 193: cpus=0-23,48-71 node=0 flags=0x4 nice=0 active=1/256
in-flight: 1334335:wb_workfn
workqueue kblockd: flags=0x18
pwq 141: cpus=70 node=0 flags=0x0 nice=-20 active=1/256
pending: blk_mq_run_work_fn
workqueue ipv6_addrconf: flags=0x40008
pwq 116: cpus=58 node=0 flags=0x0 nice=0 active=1/1
in-flight: 1369493:addrconf_verify_work
workqueue ena: flags=0xe000a
pwq 192: cpus=0-95 flags=0x4 nice=0 active=1/1
in-flight: 7505:ena_fw_reset_device [ena]
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: Deadlock in cleanup_net and addrconf_verify_work locks up workqueue
2020-02-11 19:23 Deadlock in cleanup_net and addrconf_verify_work locks up workqueue Sargun Dhillon
@ 2020-02-12 5:08 ` Eric Dumazet
2020-02-12 5:36 ` Eric Dumazet
0 siblings, 1 reply; 4+ messages in thread
From: Eric Dumazet @ 2020-02-12 5:08 UTC (permalink / raw)
To: Sargun Dhillon, netdev, LKML
Cc: Tetsuo Handa, Gabriel Hartmann, Rob Gulewich, Bruce Curtis,
Hannes Frederic Sowa
On 2/11/20 11:23 AM, Sargun Dhillon wrote:
> We've found a workqueue stall / deadlock. Our workload is a container-oriented
> workload in which we utilize IPv6. Our container (namespace) churn is quite
> frequent, and containers can be terminated before their networking is
> even setup.
>
> We're running 4.19.73 in production, and in investigation of the underlying
> causes, I don't think that future versions of 4.19 fix it.
>
> We've narrowed it down to a lockup between ipv6_addrconf, and cleanup_net.
Sure, PID 1369493 addrconf_verify_work() is waiting for RTNL.
But PID 8 ?
__flush_work() is being called.
But from where ? Stacks seem not complete.
>
> crash> bt 8
> PID: 8 TASK: ffff9a1072b50000 CPU: 24 COMMAND: "kworker/u192:0"
> #0 [ffffbfe2c00fbb70] __schedule at ffffffffa7f02bf7
> #1 [ffffbfe2c00fbc10] schedule at ffffffffa7f031e8
> #2 [ffffbfe2c00fbc18] schedule_timeout at ffffffffa7f0700e
> #3 [ffffbfe2c00fbc90] wait_for_completion at ffffffffa7f03b50
> #4 [ffffbfe2c00fbce0] __flush_work at ffffffffa76a2532
> #5 [ffffbfe2c00fbd58] rollback_registered_many at ffffffffa7dbcdf4
> #6 [ffffbfe2c00fbdc0] unregister_netdevice_many at ffffffffa7dbd31e
> #7 [ffffbfe2c00fbdd0] default_device_exit_batch at ffffffffa7dbd512
> #8 [ffffbfe2c00fbe40] cleanup_net at ffffffffa7dab970
> #9 [ffffbfe2c00fbe98] process_one_work at ffffffffa76a17c4
> #10 [ffffbfe2c00fbed8] worker_thread at ffffffffa76a19dd
> #11 [ffffbfe2c00fbf10] kthread at ffffffffa76a7fd3
> #12 [ffffbfe2c00fbf50] ret_from_fork at ffffffffa80001ff
>
> crash> bt 1369493
> PID: 1369493 TASK: ffff9a03684d9600 CPU: 58 COMMAND: "kworker/58:1"
> #0 [ffffbfe30d68fd48] __schedule at ffffffffa7f02bf7
> #1 [ffffbfe30d68fde8] schedule at ffffffffa7f031e8
> #2 [ffffbfe30d68fdf0] schedule_preempt_disabled at ffffffffa7f0349a
> #3 [ffffbfe30d68fdf8] __mutex_lock at ffffffffa7f04aed
> #4 [ffffbfe30d68fe90] addrconf_verify_work at ffffffffa7e8d1aa
> #5 [ffffbfe30d68fe98] process_one_work at ffffffffa76a17c4
> #6 [ffffbfe30d68fed8] worker_thread at ffffffffa76a19dd
> #7 [ffffbfe30d68ff10] kthread at ffffffffa76a7fd3
> #8 [ffffbfe30d68ff50] ret_from_fork at ffffffffa80001ff
>
>
>
> struct -x mutex.owner.counter rtnl_mutex
> owner.counter = 0xffff9a1072b50001
>
> 0xffff9a1072b50001 & (~0x07) = 0xffff9a1072b50000
>
> This points back to PID 8 / CPU 24. It is working on cleanup_net, and a part
> of cleanup net involves calling ops_exit_list, and as part of that it calls
> default_device_exit_batch. default_device_exit_batch takes the rtnl lock before
> calling into unregister_netdevice_many, and rollback_registered_many.
> rollback_registered_many calls flush_all_backlogs. This will never complete
> because it is holding the rtnl lock, and PID 1369493 / CPU 58 is waiting
> for rtnl_lock.
But PID 1369493 is waiting on a mutex, thus properly yielding the cpu.
(schedule() is clearly shown)
This should not prevent other threads
from making progress so that flush_all_backlogs() completes eventually.
flush_all_backlogs() does not care of how many threads are currently blocked
because they can not grab rtnl while flush_all_backlogs() is running.
>
> If relevant, the workqueue stalls themselves look something like:
> BUG: workqueue lockup - pool cpus=70 node=0 flags=0x0 nice=0 stuck for 3720s!
> BUG: workqueue lockup - pool cpus=70 node=0 flags=0x0 nice=-20 stuck for 3719s!
> Showing busy workqueues and worker pools:
> workqueue events: flags=0x0
> pwq 32: cpus=16 node=0 flags=0x0 nice=0 active=2/256
> in-flight: 1274779:slab_caches_to_rcu_destroy_workfn slab_caches_to_rcu_destroy_workfn
> workqueue events_highpri: flags=0x10
> pwq 141: cpus=70 node=0 flags=0x0 nice=-20 active=1/256
> pending: flush_backlog BAR(8)
> workqueue events_power_efficient: flags=0x82
> pwq 193: cpus=0-23,48-71 node=0 flags=0x4 nice=0 active=1/256
> in-flight: 1396446:check_lifetime
> workqueue mm_percpu_wq: flags=0x8
> pwq 140: cpus=70 node=0 flags=0x0 nice=0 active=1/256
> pending: vmstat_update
> workqueue netns: flags=0xe000a
> pwq 192: cpus=0-95 flags=0x4 nice=0 active=1/1
> in-flight: 8:cleanup_net
> delayed: cleanup_net
> workqueue writeback: flags=0x4e
> pwq 193: cpus=0-23,48-71 node=0 flags=0x4 nice=0 active=1/256
> in-flight: 1334335:wb_workfn
> workqueue kblockd: flags=0x18
> pwq 141: cpus=70 node=0 flags=0x0 nice=-20 active=1/256
> pending: blk_mq_run_work_fn
> workqueue ipv6_addrconf: flags=0x40008
> pwq 116: cpus=58 node=0 flags=0x0 nice=0 active=1/1
> in-flight: 1369493:addrconf_verify_work
> workqueue ena: flags=0xe000a
> pwq 192: cpus=0-95 flags=0x4 nice=0 active=1/1
> in-flight: 7505:ena_fw_reset_device [ena]
>
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: Deadlock in cleanup_net and addrconf_verify_work locks up workqueue
2020-02-12 5:08 ` Eric Dumazet
@ 2020-02-12 5:36 ` Eric Dumazet
2023-01-04 13:06 ` Dongyang
0 siblings, 1 reply; 4+ messages in thread
From: Eric Dumazet @ 2020-02-12 5:36 UTC (permalink / raw)
To: Sargun Dhillon, netdev, LKML
Cc: Tetsuo Handa, Gabriel Hartmann, Rob Gulewich, Bruce Curtis,
Hannes Frederic Sowa
On 2/11/20 9:08 PM, Eric Dumazet wrote:
>
>
> On 2/11/20 11:23 AM, Sargun Dhillon wrote:
>> We've found a workqueue stall / deadlock. Our workload is a container-oriented
>> workload in which we utilize IPv6. Our container (namespace) churn is quite
>> frequent, and containers can be terminated before their networking is
>> even setup.
>>
>> We're running 4.19.73 in production, and in investigation of the underlying
>> causes, I don't think that future versions of 4.19 fix it.
>>
>> We've narrowed it down to a lockup between ipv6_addrconf, and cleanup_net.
>
> Sure, PID 1369493 addrconf_verify_work() is waiting for RTNL.
>
> But PID 8 ?
>
> __flush_work() is being called.
>
> But from where ? Stacks seem not complete.
>
>
>>
>> crash> bt 8
>> PID: 8 TASK: ffff9a1072b50000 CPU: 24 COMMAND: "kworker/u192:0"
>> #0 [ffffbfe2c00fbb70] __schedule at ffffffffa7f02bf7
>> #1 [ffffbfe2c00fbc10] schedule at ffffffffa7f031e8
>> #2 [ffffbfe2c00fbc18] schedule_timeout at ffffffffa7f0700e
>> #3 [ffffbfe2c00fbc90] wait_for_completion at ffffffffa7f03b50
>> #4 [ffffbfe2c00fbce0] __flush_work at ffffffffa76a2532
>> #5 [ffffbfe2c00fbd58] rollback_registered_many at ffffffffa7dbcdf4
>> #6 [ffffbfe2c00fbdc0] unregister_netdevice_many at ffffffffa7dbd31e
>> #7 [ffffbfe2c00fbdd0] default_device_exit_batch at ffffffffa7dbd512
>> #8 [ffffbfe2c00fbe40] cleanup_net at ffffffffa7dab970
>> #9 [ffffbfe2c00fbe98] process_one_work at ffffffffa76a17c4
>> #10 [ffffbfe2c00fbed8] worker_thread at ffffffffa76a19dd
>> #11 [ffffbfe2c00fbf10] kthread at ffffffffa76a7fd3
>> #12 [ffffbfe2c00fbf50] ret_from_fork at ffffffffa80001ff
>>
>> crash> bt 1369493
>> PID: 1369493 TASK: ffff9a03684d9600 CPU: 58 COMMAND: "kworker/58:1"
>> #0 [ffffbfe30d68fd48] __schedule at ffffffffa7f02bf7
>> #1 [ffffbfe30d68fde8] schedule at ffffffffa7f031e8
>> #2 [ffffbfe30d68fdf0] schedule_preempt_disabled at ffffffffa7f0349a
>> #3 [ffffbfe30d68fdf8] __mutex_lock at ffffffffa7f04aed
>> #4 [ffffbfe30d68fe90] addrconf_verify_work at ffffffffa7e8d1aa
>> #5 [ffffbfe30d68fe98] process_one_work at ffffffffa76a17c4
>> #6 [ffffbfe30d68fed8] worker_thread at ffffffffa76a19dd
>> #7 [ffffbfe30d68ff10] kthread at ffffffffa76a7fd3
>> #8 [ffffbfe30d68ff50] ret_from_fork at ffffffffa80001ff
>>
>>
>>
>> struct -x mutex.owner.counter rtnl_mutex
>> owner.counter = 0xffff9a1072b50001
>>
>> 0xffff9a1072b50001 & (~0x07) = 0xffff9a1072b50000
>>
>> This points back to PID 8 / CPU 24. It is working on cleanup_net, and a part
>> of cleanup net involves calling ops_exit_list, and as part of that it calls
>> default_device_exit_batch. default_device_exit_batch takes the rtnl lock before
>> calling into unregister_netdevice_many, and rollback_registered_many.
>> rollback_registered_many calls flush_all_backlogs. This will never complete
>> because it is holding the rtnl lock, and PID 1369493 / CPU 58 is waiting
>> for rtnl_lock.
>
> But PID 1369493 is waiting on a mutex, thus properly yielding the cpu.
> (schedule() is clearly shown)
>
> This should not prevent other threads
> from making progress so that flush_all_backlogs() completes eventually.
>
> flush_all_backlogs() does not care of how many threads are currently blocked
> because they can not grab rtnl while flush_all_backlogs() is running.
>
>>
>> If relevant, the workqueue stalls themselves look something like:
>> BUG: workqueue lockup - pool cpus=70 node=0 flags=0x0 nice=0 stuck for 3720s!
>> BUG: workqueue lockup - pool cpus=70 node=0 flags=0x0 nice=-20 stuck for 3719s!
>> Showing busy workqueues and worker pools:
>> workqueue events: flags=0x0
>> pwq 32: cpus=16 node=0 flags=0x0 nice=0 active=2/256
>> in-flight: 1274779:slab_caches_to_rcu_destroy_workfn slab_caches_to_rcu_destroy_workfn
>> workqueue events_highpri: flags=0x10
>> pwq 141: cpus=70 node=0 flags=0x0 nice=-20 active=1/256
>> pending: flush_backlog BAR(8)
>> workqueue events_power_efficient: flags=0x82
>> pwq 193: cpus=0-23,48-71 node=0 flags=0x4 nice=0 active=1/256
>> in-flight: 1396446:check_lifetime
>> workqueue mm_percpu_wq: flags=0x8
>> pwq 140: cpus=70 node=0 flags=0x0 nice=0 active=1/256
>> pending: vmstat_update
>> workqueue netns: flags=0xe000a
>> pwq 192: cpus=0-95 flags=0x4 nice=0 active=1/1
>> in-flight: 8:cleanup_net
>> delayed: cleanup_net
>> workqueue writeback: flags=0x4e
>> pwq 193: cpus=0-23,48-71 node=0 flags=0x4 nice=0 active=1/256
>> in-flight: 1334335:wb_workfn
>> workqueue kblockd: flags=0x18
>> pwq 141: cpus=70 node=0 flags=0x0 nice=-20 active=1/256
>> pending: blk_mq_run_work_fn
>> workqueue ipv6_addrconf: flags=0x40008
>> pwq 116: cpus=58 node=0 flags=0x0 nice=0 active=1/1
>> in-flight: 1369493:addrconf_verify_work
>> workqueue ena: flags=0xe000a
>> pwq 192: cpus=0-95 flags=0x4 nice=0 active=1/1
>> in-flight: 7505:ena_fw_reset_device [ena]
>>
Can you test the following :
diff --git a/net/ipv6/addrconf.c b/net/ipv6/addrconf.c
index cb493e15959c4d1bb68cf30f4099a8daa785bb84..bcc7ce03f13881415f64c7329559c7ed1e6321f3 100644
--- a/net/ipv6/addrconf.c
+++ b/net/ipv6/addrconf.c
@@ -4410,8 +4410,6 @@ static void addrconf_verify_rtnl(void)
now = jiffies;
next = round_jiffies_up(now + ADDR_CHECK_FREQUENCY);
- cancel_delayed_work(&addr_chk_work);
-
for (i = 0; i < IN6_ADDR_HSIZE; i++) {
restart:
hlist_for_each_entry_rcu_bh(ifp, &inet6_addr_lst[i], addr_lst) {
^ permalink raw reply related [flat|nested] 4+ messages in thread
* Re: Deadlock in cleanup_net and addrconf_verify_work locks up workqueue
2020-02-12 5:36 ` Eric Dumazet
@ 2023-01-04 13:06 ` Dongyang
0 siblings, 0 replies; 4+ messages in thread
From: Dongyang @ 2023-01-04 13:06 UTC (permalink / raw)
To: eric.dumazet, sargun
Cc: brucec, ghartmann, hannes, linux-kernel, netdev, penguin-kernel,
rgulewich, dongyang626
Hello guys,
At the beginning of the New Year, I also encountered this issue.
Hi Sargun,
Did you finally resolve this issue? As it was passed ~3 years, hope you still remember something about this case, thanks.
Hi Eric,
Below is my log, please let me give some feedback about your previous comments. Thanks.
Jan 1 00:06:30 kernel: [109121.968881] 000: perf: interrupt took too long (3914 > 3912), lowering kernel.perf_event_max_sample_rate to 51000
Jan 2 00:00:06 kernel: [195138.235171] 026: audit: type=1400 audit(1672588806.418:41): apparmor="DENIED" operation="capable" profile="/usr/sbin/cups-browsed" pid=6221 comm="cups-browsed" capability=23 capname="sys_nice"
Jan 2 00:04:08 kernel: [195380.604772] 027: INFO: task kworker/u56:2:6079 blocked for more than 122 seconds.
Jan 2 00:04:08 kernel: [195380.604776] 027: Tainted: G OE 5.4.161-rt67-rc1 #1
Jan 2 00:04:08 kernel: [195380.604777] 027: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jan 2 00:04:08 kernel: [195380.604779] 027: kworker/u56:2 D 0 6079 2 0x80084000
Jan 2 00:04:08 kernel: [195380.604789] 027: Workqueue: netns cleanup_net
Jan 2 00:04:08 kernel: [195380.604790] 027: Call Trace:
Jan 2 00:04:08 kernel: [195380.604793] 027: __schedule+0x3d4/0x8a0
Jan 2 00:04:08 kernel: [195380.604799] 027: ? __switch_to_asm+0x34/0x70
Jan 2 00:04:08 kernel: [195380.604801] 027: schedule+0x49/0x100
Jan 2 00:04:08 kernel: [195380.604804] 027: schedule_timeout+0x1ed/0x3b0
Jan 2 00:04:08 kernel: [195380.604807] 027: wait_for_completion+0x86/0xe0
Jan 2 00:04:08 kernel: [195380.604810] 027: __flush_work+0x121/0x1d0
Jan 2 00:04:08 kernel: [195380.604814] 027: ? flush_workqueue_prep_pwqs+0x140/0x140
Jan 2 00:04:08 kernel: [195380.604817] 027: flush_work+0x10/0x20
Jan 2 00:04:08 kernel: [195380.604819] 027: rollback_registered_many+0x1b2/0x530
Jan 2 00:04:08 kernel: [195380.604824] 027: unregister_netdevice_many.part.0+0x12/0x90
Jan 2 00:04:08 kernel: [195380.604826] 027: default_device_exit_batch+0x15c/0x190
Jan 2 00:04:08 kernel: [195380.604828] 027: ? do_wait_intr_irq+0x90/0x90
Jan 2 00:04:08 kernel: [195380.604832] 027: ops_exit_list.isra.0+0x61/0x70
Jan 2 00:04:08 kernel: [195380.604835] 027: cleanup_net+0x269/0x3a0
Jan 2 00:04:08 kernel: [195380.604837] 027: process_one_work+0x1c8/0x470
Jan 2 00:04:08 kernel: [195380.604840] 027: worker_thread+0x4a/0x3d0
Jan 2 00:04:08 kernel: [195380.604843] 027: kthread+0x133/0x180
Jan 2 00:04:08 kernel: [195380.604846] 027: ? process_one_work+0x470/0x470
Jan 2 00:04:08 kernel: [195380.604848] 027: ? kthread_park+0x90/0x90
Jan 2 00:04:08 kernel: [195380.604850] 027: ret_from_fork+0x35/0x40
Jan 2 00:06:11 kernel: [195503.484781] 000: INFO: task kworker/u56:2:6079 blocked for more than 245 seconds.
Jan 2 00:06:11 kernel: [195503.484784] 000: Tainted: G OE 5.4.161-rt67-rc1 #1
Jan 2 00:06:11 kernel: [195503.484786] 000: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jan 2 00:06:11 kernel: [195503.484788] 000: kworker/u56:2 D 0 6079 2 0x80084000
Jan 2 00:06:11 kernel: [195503.484797] 000: Workqueue: netns cleanup_net
Jan 2 00:06:11 kernel: [195503.484798] 000: Call Trace:
Jan 2 00:06:11 kernel: [195503.484802] 000: __schedule+0x3d4/0x8a0
Jan 2 00:06:11 kernel: [195503.484806] 000: ? __switch_to_asm+0x34/0x70
Jan 2 00:06:11 kernel: [195503.484809] 000: schedule+0x49/0x100
Jan 2 00:06:11 kernel: [195503.484811] 000: schedule_timeout+0x1ed/0x3b0
Jan 2 00:06:11 kernel: [195503.484815] 000: wait_for_completion+0x86/0xe0
Jan 2 00:06:11 kernel: [195503.484818] 000: __flush_work+0x121/0x1d0
Jan 2 00:06:11 kernel: [195503.484822] 000: ? flush_workqueue_prep_pwqs+0x140/0x140
Jan 2 00:06:11 kernel: [195503.484825] 000: flush_work+0x10/0x20
Jan 2 00:06:11 kernel: [195503.484827] 000: rollback_registered_many+0x1b2/0x530
Jan 2 00:06:11 kernel: [195503.484832] 000: unregister_netdevice_many.part.0+0x12/0x90
Jan 2 00:06:11 kernel: [195503.484834] 000: default_device_exit_batch+0x15c/0x190
Jan 2 00:06:11 kernel: [195503.484837] 000: ? do_wait_intr_irq+0x90/0x90
Jan 2 00:06:11 kernel: [195503.484840] 000: ops_exit_list.isra.0+0x61/0x70
Jan 2 00:06:11 kernel: [195503.484843] 000: cleanup_net+0x269/0x3a0
Jan 2 00:06:11 kernel: [195503.484846] 000: process_one_work+0x1c8/0x470
Jan 2 00:06:11 kernel: [195503.484849] 000: worker_thread+0x4a/0x3d0
Jan 2 00:06:11 kernel: [195503.484852] 000: kthread+0x133/0x180
Jan 2 00:06:11 kernel: [195503.484854] 000: ? process_one_work+0x470/0x470
Jan 2 00:06:11 kernel: [195503.484856] 000: ? kthread_park+0x90/0x90
Jan 2 00:06:11 kernel: [195503.484858] 000: ret_from_fork+0x35/0x40
Jan 2 00:06:11 kernel: [195503.484863] 000: INFO: task kworker/26:0:6200 blocked for more than 122 seconds.
Jan 2 00:06:11 kernel: [195503.484864] 000: Tainted: G OE 5.4.161-rt67-rc1 #1
Jan 2 00:06:11 kernel: [195503.484865] 000: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jan 2 00:06:11 kernel: [195503.484866] 000: kworker/26:0 D 0 6200 2 0x80084000
Jan 2 00:06:11 kernel: [195503.484873] 000: Workqueue: ipv6_addrconf addrconf_verify_work
Jan 2 00:06:11 kernel: [195503.484874] 000: Call Trace:
Jan 2 00:06:11 kernel: [195503.484875] 000: __schedule+0x3d4/0x8a0
Jan 2 00:06:11 kernel: [195503.484877] 000: schedule+0x49/0x100
Jan 2 00:06:11 kernel: [195503.484879] 000: __rt_mutex_slowlock+0x8a/0x150
Jan 2 00:06:11 kernel: [195503.484882] 000: rt_mutex_slowlock_locked+0xbb/0x280
Jan 2 00:06:11 kernel: [195503.484884] 000: ? __switch_to_asm+0x40/0x70
Jan 2 00:06:11 kernel: [195503.484886] 000: rt_mutex_slowlock+0x76/0xc0
Jan 2 00:06:11 kernel: [195503.484889] 000: __rt_mutex_lock_state+0x75/0x90
Jan 2 00:06:11 kernel: [195503.484891] 000: _mutex_lock+0x13/0x20
Jan 2 00:06:11 kernel: [195503.484894] 000: rtnl_lock+0x15/0x20
Jan 2 00:06:11 kernel: [195503.484897] 000: addrconf_verify_work+0xe/0x20
Jan 2 00:06:11 kernel: [195503.484899] 000: process_one_work+0x1c8/0x470
Jan 2 00:06:11 kernel: [195503.484902] 000: worker_thread+0x4a/0x3d0
Jan 2 00:06:11 kernel: [195503.484905] 000: kthread+0x133/0x180
Jan 2 00:06:11 kernel: [195503.484906] 000: ? process_one_work+0x470/0x470
Jan 2 00:06:11 kernel: [195503.484908] 000: ? kthread_park+0x90/0x90
Jan 2 00:06:11 kernel: [195503.484910] 000: ret_from_fork+0x35/0x40
Jan 2 00:08:14 kernel: [195626.364781] 027: INFO: task kworker/u56:2:6079 blocked for more than 368 seconds.
Jan 2 00:08:14 kernel: [195626.364785] 027: Tainted: G OE 5.4.161-rt67-rc1 #1
Jan 2 00:08:14 kernel: [195626.364786] 027: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jan 2 00:08:14 kernel: [195626.364788] 027: kworker/u56:2 D 0 6079 2 0x80084000
Jan 2 00:08:14 kernel: [195626.364797] 027: Workqueue: netns cleanup_net
Jan 2 00:08:14 kernel: [195626.364798] 027: Call Trace:
Jan 2 00:08:14 kernel: [195626.364802] 027: __schedule+0x3d4/0x8a0
Jan 2 00:08:14 kernel: [195626.364807] 027: ? __switch_to_asm+0x34/0x70
Jan 2 00:08:14 kernel: [195626.364810] 027: schedule+0x49/0x100
Jan 2 00:08:14 kernel: [195626.364812] 027: schedule_timeout+0x1ed/0x3b0
Jan 2 00:08:14 kernel: [195626.364816] 027: wait_for_completion+0x86/0xe0
Jan 2 00:08:14 kernel: [195626.364818] 027: __flush_work+0x121/0x1d0
Jan 2 00:08:14 kernel: [195626.364822] 027: ? flush_workqueue_prep_pwqs+0x140/0x140
Jan 2 00:08:14 kernel: [195626.364825] 027: flush_work+0x10/0x20
Jan 2 00:08:14 kernel: [195626.364827] 027: rollback_registered_many+0x1b2/0x530
Jan 2 00:08:14 kernel: [195626.364832] 027: unregister_netdevice_many.part.0+0x12/0x90
Jan 2 00:08:14 kernel: [195626.364835] 027: default_device_exit_batch+0x15c/0x190
Jan 2 00:08:14 kernel: [195626.364837] 027: ? do_wait_intr_irq+0x90/0x90
Jan 2 00:08:14 kernel: [195626.364841] 027: ops_exit_list.isra.0+0x61/0x70
Jan 2 00:08:14 kernel: [195626.364843] 027: cleanup_net+0x269/0x3a0
Jan 2 00:08:14 kernel: [195626.364846] 027: process_one_work+0x1c8/0x470
Jan 2 00:08:14 kernel: [195626.364849] 027: worker_thread+0x4a/0x3d0
Jan 2 00:08:14 kernel: [195626.364852] 027: kthread+0x133/0x180
Jan 2 00:08:14 kernel: [195626.364855] 027: ? process_one_work+0x470/0x470
Jan 2 00:08:14 kernel: [195626.364857] 027: ? kthread_park+0x90/0x90
Jan 2 00:08:14 kernel: [195626.364859] 027: ret_from_fork+0x35/0x40
Jan 2 00:08:14 kernel: [195626.364863] 027: INFO: task kworker/26:0:6200 blocked for more than 245 seconds.
Jan 2 00:08:14 kernel: [195626.364865] 027: Tainted: G OE 5.4.161-rt67-rc1 #1
Jan 2 00:08:14 kernel: [195626.364866] 027: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jan 2 00:08:14 kernel: [195626.364867] 027: kworker/26:0 D 0 6200 2 0x80084000
Jan 2 00:08:14 kernel: [195626.364873] 027: Workqueue: ipv6_addrconf addrconf_verify_work
Jan 2 00:08:14 kernel: [195626.364874] 027: Call Trace:
Jan 2 00:08:14 kernel: [195626.364875] 027: __schedule+0x3d4/0x8a0
Jan 2 00:08:14 kernel: [195626.364878] 027: schedule+0x49/0x100
Jan 2 00:08:14 kernel: [195626.364880] 027: __rt_mutex_slowlock+0x8a/0x150
Jan 2 00:08:14 kernel: [195626.364882] 027: rt_mutex_slowlock_locked+0xbb/0x280
Jan 2 00:08:14 kernel: [195626.364885] 027: ? __switch_to_asm+0x40/0x70
Jan 2 00:08:14 kernel: [195626.364886] 027: rt_mutex_slowlock+0x76/0xc0
Jan 2 00:08:14 kernel: [195626.364889] 027: __rt_mutex_lock_state+0x75/0x90
Jan 2 00:08:14 kernel: [195626.364892] 027: _mutex_lock+0x13/0x20
Jan 2 00:08:14 kernel: [195626.364894] 027: rtnl_lock+0x15/0x20
Jan 2 00:08:14 kernel: [195626.364898] 027: addrconf_verify_work+0xe/0x20
Jan 2 00:08:14 kernel: [195626.364900] 027: process_one_work+0x1c8/0x470
Jan 2 00:08:14 kernel: [195626.364902] 027: worker_thread+0x4a/0x3d0
Jan 2 00:08:14 kernel: [195626.364905] 027: kthread+0x133/0x180
Jan 2 00:08:14 kernel: [195626.364907] 027: ? process_one_work+0x470/0x470
Jan 2 00:08:14 kernel: [195626.364909] 027: ? kthread_park+0x90/0x90
Jan 2 00:08:14 kernel: [195626.364911] 027: ret_from_fork+0x35/0x40
................
Jan 2 00:14:23 kernel: [195995.004768] 000: INFO: task kworker/u56:2:6079 blocked for more than 737 seconds.
Jan 2 00:14:23 kernel: [195995.004771] 000: Tainted: G OE 5.4.161-rt67-rc1 #1
Jan 2 00:14:23 kernel: [195995.004772] 000: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jan 2 00:14:23 kernel: [195995.004774] 000: kworker/u56:2 D 0 6079 2 0x80084000
Jan 2 00:14:23 kernel: [195995.004783] 000: Workqueue: netns cleanup_net
Jan 2 00:14:23 kernel: [195995.004784] 000: Call Trace:
Jan 2 00:14:23 kernel: [195995.004788] 000: __schedule+0x3d4/0x8a0
Jan 2 00:14:23 kernel: [195995.004793] 000: ? __switch_to_asm+0x34/0x70
Jan 2 00:14:23 kernel: [195995.004795] 000: schedule+0x49/0x100
Jan 2 00:14:23 kernel: [195995.004797] 000: schedule_timeout+0x1ed/0x3b0
Jan 2 00:14:23 kernel: [195995.004801] 000: wait_for_completion+0x86/0xe0
Jan 2 00:14:23 kernel: [195995.004804] 000: __flush_work+0x121/0x1d0
Jan 2 00:14:23 kernel: [195995.004807] 000: ? flush_workqueue_prep_pwqs+0x140/0x140
Jan 2 00:14:23 kernel: [195995.004810] 000: flush_work+0x10/0x20
Jan 2 00:14:23 kernel: [195995.004813] 000: rollback_registered_many+0x1b2/0x530
Jan 2 00:14:23 kernel: [195995.004817] 000: unregister_netdevice_many.part.0+0x12/0x90
Jan 2 00:14:23 kernel: [195995.004819] 000: default_device_exit_batch+0x15c/0x190
Jan 2 00:14:23 kernel: [195995.004822] 000: ? do_wait_intr_irq+0x90/0x90
Jan 2 00:14:23 kernel: [195995.004825] 000: ops_exit_list.isra.0+0x61/0x70
Jan 2 00:14:23 kernel: [195995.004828] 000: cleanup_net+0x269/0x3a0
Jan 2 00:14:23 kernel: [195995.004831] 000: process_one_work+0x1c8/0x470
Jan 2 00:14:23 kernel: [195995.004834] 000: worker_thread+0x4a/0x3d0
Jan 2 00:14:23 kernel: [195995.004837] 000: kthread+0x133/0x180
Jan 2 00:14:23 kernel: [195995.004839] 000: ? process_one_work+0x470/0x470
Jan 2 00:14:23 kernel: [195995.004841] 000: ? kthread_park+0x90/0x90
Jan 2 00:14:23 kernel: [195995.004843] 000: ret_from_fork+0x35/0x40
After "task kworker/u56:2:6079 blocked for more than 737 seconds.",
the network seems down, both ssh, ifconfig can't work.
>> Sure, PID 1369493 addrconf_verify_work() is waiting for RTNL.
>>
>> But PID 8 ?
>>
>> __flush_work() is being called.
>>
>> But from where ? Stacks seem not complete.
__flush_work is just from the work queue, so, Yes,
we don't know who put it into the queue. And don't know whether the clean netns work is reasonable.
Maybe I need to add a trace at the put_net.
put_net
__put_net queue_work(netns_wq, &net_cleanup_work);
DECLARE_WORK(net_cleanup_work, cleanup_net);
cleanup_net
ops_exit_list
default_device_exit_batch
unregister_netdevice_many
rollback_registered_many
flush_work
__flush_work
>> But PID 1369493 is waiting on a mutex, thus properly yielding the cpu.
>> (schedule() is clearly shown)
>>
>> This should not prevent other threads
>> from making progress so that flush_all_backlogs() completes eventually.
>>
>> flush_all_backlogs() does not care of how many threads are currently blocked
>> because they can not grab rtnl while flush_all_backlogs() is running.
In my log, we can see even the schedule is shown but the task is still in the D status.
It seems the "addrconf_verify_work" is blocked by "cleanup_net".
But why the "cleanup_net" is blocked?
Currently, my plan is trying to add trace/print at the "__flush_work" to see: what work is blocked,
then research this work is owned by who.
As an expert, if you can give some advice, it will be very grateful.
BTW, this is a RT kernel, I'm also checking the system workload.
BR,
Dongyang
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2023-01-04 13:07 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2020-02-11 19:23 Deadlock in cleanup_net and addrconf_verify_work locks up workqueue Sargun Dhillon
2020-02-12 5:08 ` Eric Dumazet
2020-02-12 5:36 ` Eric Dumazet
2023-01-04 13:06 ` Dongyang
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.