deadlocks on pernet_ops_rwsem

We started hitting a deadlock on pernet_ops_rwsem, not very often, these are the CI branches were we saw it:

2025-09-18--03-00
2025-09-18--15-00
2025-09-18--18-00
2025-09-19--21-00
2025-09-21--15-00
2025-09-21--18-00
2025-09-22--00-00
2025-09-22--09-00
2025-09-23--06-00
2025-09-24--21-00
2025-09-27--21-00
2025-09-28--09-00
2025-10-01--00-00
2025-10-01--06-00

First hit seems to be:
https://netdev-3.bots.linux.dev/vmksft-net-dbg/results/302741/65-l2tp-sh/stderr
Two most recent:
https://netdev-3.bots.linux.dev/vmksft-net-dbg/results/321640/110-ip-local-port-range-sh/stderr
https://netdev-3.bots.linux.dev/vmksft-net-dbg/results/321281/63-fdb-notify-sh/stderr

The stack traces aren't very helpful, they mostly show the victim not who caused the deadlock :(

Any ideas?

Not many here. The above are debug builds, so we should get a lockdep splat on deadlock, the logs lack it. I guess the request_module() breaks the lockdep checks?

Quoted 3 lines

Not many here. The above are debug builds, so we should get a lockdep splat on deadlock, the logs lack it. I guess the request_module() breaks the lockdep checks?

To be clear -- AFAICT lockdep misses this.

The splat is from the "stuck task" checker.

2 min wait to load a module during test init would definitely be a sign of something going sideways.. but I think it's worse than that, these time out completely and we kill the VM. I think the modprobe is truly stuck here.

In one of the splats lockdep was able to say:

[ 4302.448228][   T44] INFO: task modprobe:31634 <writer> blocked on an rw-semaphore likely owned by task kworker/u16:0:12 <reader>

but most are more useless:

[ 4671.090728][   T44] INFO: task modprobe:2342 is blocked on an rw-semaphore, but the owner is not found.

(?!?)

From: Jakub Kicinski <[email protected]>
Date: Wed, 1 Oct 2025 10:22:23 -0700

Quoted 11 lines

To be clear -- AFAICT lockdep misses this.

The splat is from the "stuck task" checker.

2 min wait to load a module during test init would definitely be a sign of something going sideways.. but I think it's worse than that, these time out completely and we kill the VM. I think the modprobe is truly stuck here.

In one of the splats lockdep was able to say:

Quoted 7 lines

[ 4302.448228][   T44] INFO: task modprobe:31634 <writer> blocked on an rw-semaphore likely owned by task kworker/u16:0:12 <reader>

but most are more useless:

[ 4671.090728][   T44] INFO: task modprobe:2342 is blocked on an rw-semaphore, but the owner is not found.

(?!?)

Even when it caught the possible owner, lockdep seems confused :/

[ 4302.448228][   T44] INFO: task modprobe:31634 <writer> blocked on an rw-semaphore likely owned by task kworker/u16:0:12 <reader>

modprobe:31634 seems to be blocked by kworker/u16:0:12,

[ 4302.449035][   T44] task:kworker/u16:0   state:R  running task     stack:26368 pid:12    tgid:12    ppid:2      task_flags:0x4208060 flags:0x00004000
[ 4302.449872][   T44] Workqueue: netns cleanup_net
...
[ 4302.460889][   T44] Showing all locks held in the system:
[ 4302.461368][   T44] 4 locks held by kworker/u16:0/12:

but no lock shows up here for kworker/u16:0/12,

[ 4302.461597][   T44] 2 locks held by kworker/u18:0/36:
[ 4302.461926][   T44]  #0: ffff8880010d9d48 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x7e5/0x1650
[ 4302.462429][   T44]  #1: ffffc9000028fd40 ((work_completion)(&sub_info->work)){+.+.}-{0:0}, at: process_one_work+0xded/0x1650
[ 4302.463011][   T44] 1 lock held by khungtaskd/44:
[ 4302.463261][   T44]  #0: ffffffffb7b83f80 (rcu_read_lock){....}-{1:3}, at: debug_show_all_locks+0x36/0x260
[ 4302.463717][   T44] 1 lock held by modprobe/31634:
[ 4302.463982][   T44]  #0: ffffffffb8270430 (pernet_ops_rwsem){++++}-{4:4}, at: register_pernet_subsys+0x1a/0x40

and modprobe/31634 is holding pernet_ops_rwsem ???

Was there any update on packages (especially qemu?) used by CI around 2025-09-18 ?

Quoted 49 lines · On Wed, 1 Oct 2025 18:50:22 +0000 Kuniyuki Iwashima wrote:

From: Jakub Kicinski <[email protected]>
Date: Wed, 1 Oct 2025 10:22:23 -0700

Quoted 11 lines

To be clear -- AFAICT lockdep misses this.

The splat is from the "stuck task" checker.

2 min wait to load a module during test init would definitely be a sign of something going sideways.. but I think it's worse than that, these time out completely and we kill the VM. I think the modprobe is truly stuck here.

In one of the splats lockdep was able to say:

Quoted 7 lines

[ 4302.448228][   T44] INFO: task modprobe:31634 <writer> blocked on an rw-semaphore likely owned by task kworker/u16:0:12 <reader>

but most are more useless:

[ 4671.090728][   T44] INFO: task modprobe:2342 is blocked on an rw-semaphore, but the owner is not found.

(?!?)

Even when it caught the possible owner, lockdep seems confused :/

[ 4302.448228][   T44] INFO: task modprobe:31634 <writer> blocked on an rw-semaphore likely owned by task kworker/u16:0:12 <reader>

modprobe:31634 seems to be blocked by kworker/u16:0:12,

[ 4302.449035][   T44] task:kworker/u16:0   state:R  running task     stack:26368 pid:12    tgid:12    ppid:2      task_flags:0x4208060 flags:0x00004000
[ 4302.449872][   T44] Workqueue: netns cleanup_net
...
[ 4302.460889][   T44] Showing all locks held in the system:
[ 4302.461368][   T44] 4 locks held by kworker/u16:0/12:

but no lock shows up here for kworker/u16:0/12,

[ 4302.461597][   T44] 2 locks held by kworker/u18:0/36:
[ 4302.461926][   T44]  #0: ffff8880010d9d48 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x7e5/0x1650
[ 4302.462429][   T44]  #1: ffffc9000028fd40 ((work_completion)(&sub_info->work)){+.+.}-{0:0}, at: process_one_work+0xded/0x1650
[ 4302.463011][   T44] 1 lock held by khungtaskd/44:
[ 4302.463261][   T44]  #0: ffffffffb7b83f80 (rcu_read_lock){....}-{1:3}, at: debug_show_all_locks+0x36/0x260
[ 4302.463717][   T44] 1 lock held by modprobe/31634:
[ 4302.463982][   T44]  #0: ffffffffb8270430 (pernet_ops_rwsem){++++}-{4:4}, at: register_pernet_subsys+0x1a/0x40

and modprobe/31634 is holding pernet_ops_rwsem ???

Quoted 2 lines

Was there any update on packages (especially qemu?) used by CI around 2025-09-18 ?

No updates according to the logs. First hit was on Thursday so I thought maybe it came from Linus. But looking at the branches we fast forwarded 2025-09-18--21-00 and there were 2 hits earlier that day (2025-09-18--03-00, 2025-09-18--15-00)

Quoted 7 lines

Quoted 2 lines

Was there any update on packages (especially qemu?) used by CI around 2025-09-18 ?

No updates according to the logs. First hit was on Thursday so I thought maybe it came from Linus. But looking at the branches we fast forwarded 2025-09-18--21-00 and there were 2 hits earlier that day (2025-09-18--03-00, 2025-09-18--15-00)

Is there a good SHA1 around the time of the earliest report?

There do not seem to be any recent changes to rwsem, let alone specifically to pernet_ops_rwsem.