6.12-rc1: Lockdep regression bissected (virtio-net/console/scheduler)
From: Breno Leitao
Date: Thu Oct 03 2024 - 10:52:20 EST
Upstream kernel (6.12-rc1) has a new lockdep splat, that I am sharing to
get more visibility:
WARNING: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected
This is happening because the HARDIRQ-irq-unsafe "_xmit_ETHER#2" lock is
acquired in virtnet_poll_tx() while holding the HARDIRQ-irq-safe, and
lockdep doesn't like it much.
I've bisected the problem, and weirdly enough, this problem started to
show up after a unrelated(?) change in the scheduler:
52e11f6df293e816a ("sched/fair: Implement delayed dequeue")
At this time, I have the impression that the commit above exposed the
problem that was there already.
Here is the full log, based on commit 7ec462100ef91 ("Merge tag
'pull-work.unaligned' of git://git.kernel.org/pub/scm/linux/kernel/git/viro/vfs")
=====================================================
WARNING: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected
6.12.0-rc1-kbuilder-00046-g7ec462100ef9-dirty #19 Not tainted
-----------------------------------------------------
swapper/0/1 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire:
ffff88810497c318 (_xmit_ETHER#2){+.-.}-{3:3}, at: virtnet_poll_tx (./include/linux/netdevice.h:4361 drivers/net/virtio_net.c:2969)
and this task is already holding:
ffffffff82a83a88 (console_owner){-...}-{0:0}, at: console_flush_all (./include/linux/rcupdate.h:? ./include/linux/srcu.h:267 kernel/printk/printk.c:288 kernel/printk/printk.c:3157)
which would create a new lock dependency:
(console_owner){-...}-{0:0} -> (_xmit_ETHER#2){+.-.}-{3:3}
but this new dependency connects a HARDIRQ-irq-safe lock:
(console_owner){-...}-{0:0}
... which became HARDIRQ-irq-safe at:
lock_acquire (kernel/locking/lockdep.c:5825)
console_flush_all (kernel/printk/printk.c:1905 kernel/printk/printk.c:3086 kernel/printk/printk.c:3180)
console_unlock (kernel/printk/printk.c:3239 kernel/printk/printk.c:3279)
wake_up_klogd_work_func (kernel/printk/printk.c:4466)
irq_work_run_list (kernel/irq_work.c:222 kernel/irq_work.c:252)
update_process_times (kernel/time/timer.c:2524)
tick_handle_periodic (kernel/time/tick-common.c:120)
__sysvec_apic_timer_interrupt (./arch/x86/include/asm/jump_label.h:27 ./include/linux/jump_label.h:207 ./arch/x86/include/asm/trace/irq_vectors.h:41 arch/x86/kernel/apic/apic.c:1044)
sysvec_apic_timer_interrupt (arch/x86/kernel/apic/apic.c:1037 arch/x86/kernel/apic/apic.c:1037)
asm_sysvec_apic_timer_interrupt (./arch/x86/include/asm/idtentry.h:702)
clear_page_erms (arch/x86/lib/clear_page_64.S:50)
alloc_pages_bulk_noprof (mm/page_alloc.c:? mm/page_alloc.c:4660)
__vmalloc_node_range_noprof (mm/vmalloc.c:? mm/vmalloc.c:3646 mm/vmalloc.c:3828)
dup_task_struct (kernel/fork.c:314 kernel/fork.c:1115)
copy_process (kernel/fork.c:2207)
kernel_clone (kernel/fork.c:2787)
kernel_thread (kernel/fork.c:2849)
kthreadd (kernel/kthread.c:414 kernel/kthread.c:765)
ret_from_fork (arch/x86/kernel/process.c:153)
ret_from_fork_asm (arch/x86/entry/entry_64.S:257)
to a HARDIRQ-irq-unsafe lock:
(_xmit_ETHER#2){+.-.}-{3:3}
... which became HARDIRQ-irq-unsafe at:
...
lock_acquire (kernel/locking/lockdep.c:5825)
_raw_spin_trylock (./include/linux/spinlock_api_smp.h:90 kernel/locking/spinlock.c:138)
virtnet_poll (./include/linux/spinlock.h:? ./include/linux/netdevice.h:4384 drivers/net/virtio_net.c:2768 drivers/net/virtio_net.c:2821)
__napi_poll (./arch/x86/include/asm/jump_label.h:27 ./include/linux/jump_label.h:207 ./include/trace/events/napi.h:14 net/core/dev.c:6772)
net_rx_action (net/core/dev.c:6842 net/core/dev.c:6962)
handle_softirqs (./arch/x86/include/asm/jump_label.h:27 ./include/linux/jump_label.h:207 ./include/trace/events/irq.h:142 kernel/softirq.c:555)
do_softirq (kernel/softirq.c:455)
__local_bh_enable_ip (kernel/softirq.c:?)
virtnet_open (drivers/net/virtio_net.c:2877 drivers/net/virtio_net.c:2925)
__dev_open (net/core/dev.c:1476)
dev_open (net/core/dev.c:1513)
netpoll_setup (net/core/netpoll.c:701)
init_netconsole (drivers/net/netconsole.c:1261 drivers/net/netconsole.c:1312)
do_one_initcall (init/main.c:1269)
do_initcall_level (init/main.c:1330)
do_initcalls (init/main.c:1344)
kernel_init_freeable (init/main.c:1584)
kernel_init (init/main.c:1471)
ret_from_fork (arch/x86/kernel/process.c:153)
ret_from_fork_asm (arch/x86/entry/entry_64.S:257)
other info that might help us debug this:
Possible interrupt unsafe locking scenario:
CPU0 CPU1
---- ----
lock(_xmit_ETHER#2);
local_irq_disable();
lock(console_owner);
lock(_xmit_ETHER#2);
<Interrupt>
lock(console_owner);
*** DEADLOCK ***
5 locks held by swapper/0/1:
#0: ffffffff82a836b8 (console_mutex){+.+.}-{4:4}, at: register_console (kernel/printk/printk.c:113 kernel/printk/printk.c:3933)
#1: ffffffff82a83ab0 (console_lock){+.+.}-{0:0}, at: _printk (kernel/printk/printk.c:2435)
#2: ffffffff82a836f0 (console_srcu){....}-{0:0}, at: console_flush_all (./include/linux/rcupdate.h:? ./include/linux/srcu.h:267 kernel/printk/printk.c:288 kernel/printk/printk.c:3157)
#3: ffffffff82a83a88 (console_owner){-...}-{0:0}, at: console_flush_all (./include/linux/rcupdate.h:? ./include/linux/srcu.h:267 kernel/printk/printk.c:288 kernel/printk/printk.c:3157)
#4: ffffffff83183f80 (printk_legacy_map-wait-type-override){....}-{4:4}, at: console_flush_all (./include/linux/rcupdate.h:? ./include/linux/srcu.h:267 kernel/printk/printk.c:288 kernel/printk/printk.c:3157)
the dependencies between HARDIRQ-irq-safe lock and the holding lock:
-> (console_owner){-...}-{0:0} ops: 2187 {
IN-HARDIRQ-W at:
lock_acquire (kernel/locking/lockdep.c:5825)
console_flush_all (kernel/printk/printk.c:1905 kernel/printk/printk.c:3086 kernel/printk/printk.c:3180)
console_unlock (kernel/printk/printk.c:3239 kernel/printk/printk.c:3279)
wake_up_klogd_work_func (kernel/printk/printk.c:4466)
irq_work_run_list (kernel/irq_work.c:222 kernel/irq_work.c:252)
update_process_times (kernel/time/timer.c:2524)
tick_handle_periodic (kernel/time/tick-common.c:120)
__sysvec_apic_timer_interrupt (./arch/x86/include/asm/jump_label.h:27 ./include/linux/jump_label.h:207 ./arch/x86/include/asm/trace/irq_vectors.h:41 arch/x86/kernel/apic/apic.c:1044)
sysvec_apic_timer_interrupt (arch/x86/kernel/apic/apic.c:1037 arch/x86/kernel/apic/apic.c:1037)
asm_sysvec_apic_timer_interrupt (./arch/x86/include/asm/idtentry.h:702)
clear_page_erms (arch/x86/lib/clear_page_64.S:50)
alloc_pages_bulk_noprof (mm/page_alloc.c:? mm/page_alloc.c:4660)
__vmalloc_node_range_noprof (mm/vmalloc.c:? mm/vmalloc.c:3646 mm/vmalloc.c:3828)
dup_task_struct (kernel/fork.c:314 kernel/fork.c:1115)
copy_process (kernel/fork.c:2207)
kernel_clone (kernel/fork.c:2787)
kernel_thread (kernel/fork.c:2849)
kthreadd (kernel/kthread.c:414 kernel/kthread.c:765)
ret_from_fork (arch/x86/kernel/process.c:153)
ret_from_fork_asm (arch/x86/entry/entry_64.S:257)
INITIAL USE at:
}
... key at: console_owner_dep_map+0x0/0x28
the dependencies between the lock to be acquired
and HARDIRQ-irq-unsafe lock:
-> (_xmit_ETHER#2){+.-.}-{3:3} ops: 5 {
HARDIRQ-ON-W at:
lock_acquire (kernel/locking/lockdep.c:5825)
_raw_spin_trylock (./include/linux/spinlock_api_smp.h:90 kernel/locking/spinlock.c:138)
virtnet_poll (./include/linux/spinlock.h:? ./include/linux/netdevice.h:4384 drivers/net/virtio_net.c:2768 drivers/net/virtio_net.c:2821)
__napi_poll (./arch/x86/include/asm/jump_label.h:27 ./include/linux/jump_label.h:207 ./include/trace/events/napi.h:14 net/core/dev.c:6772)
net_rx_action (net/core/dev.c:6842 net/core/dev.c:6962)
handle_softirqs (./arch/x86/include/asm/jump_label.h:27 ./include/linux/jump_label.h:207 ./include/trace/events/irq.h:142 kernel/softirq.c:555)
do_softirq (kernel/softirq.c:455)
__local_bh_enable_ip (kernel/softirq.c:?)
virtnet_open (drivers/net/virtio_net.c:2877 drivers/net/virtio_net.c:2925)
__dev_open (net/core/dev.c:1476)
dev_open (net/core/dev.c:1513)
netpoll_setup (net/core/netpoll.c:701)
init_netconsole (drivers/net/netconsole.c:1261 drivers/net/netconsole.c:1312)
do_one_initcall (init/main.c:1269)
do_initcall_level (init/main.c:1330)
do_initcalls (init/main.c:1344)
kernel_init_freeable (init/main.c:1584)
kernel_init (init/main.c:1471)
ret_from_fork (arch/x86/kernel/process.c:153)
ret_from_fork_asm (arch/x86/entry/entry_64.S:257)
IN-SOFTIRQ-W at:
lock_acquire (kernel/locking/lockdep.c:5825)
_raw_spin_lock (./include/linux/spinlock_api_smp.h:133 kernel/locking/spinlock.c:154)
virtnet_poll_tx (./include/linux/netdevice.h:4361 drivers/net/virtio_net.c:2969)
__napi_poll (./arch/x86/include/asm/jump_label.h:27 ./include/linux/jump_label.h:207 ./include/trace/events/napi.h:14 net/core/dev.c:6772)
net_rx_action (net/core/dev.c:6842 net/core/dev.c:6962)
handle_softirqs (./arch/x86/include/asm/jump_label.h:27 ./include/linux/jump_label.h:207 ./include/trace/events/irq.h:142 kernel/softirq.c:555)
do_softirq (kernel/softirq.c:455)
__local_bh_enable_ip (kernel/softirq.c:?)
virtnet_open (drivers/net/virtio_net.c:2919)
__dev_open (net/core/dev.c:1476)
dev_open (net/core/dev.c:1513)
netpoll_setup (net/core/netpoll.c:701)
init_netconsole (drivers/net/netconsole.c:1261 drivers/net/netconsole.c:1312)
do_one_initcall (init/main.c:1269)
do_initcall_level (init/main.c:1330)
do_initcalls (init/main.c:1344)
kernel_init_freeable (init/main.c:1584)
kernel_init (init/main.c:1471)
ret_from_fork (arch/x86/kernel/process.c:153)
ret_from_fork_asm (arch/x86/entry/entry_64.S:257)
INITIAL USE at:
lock_acquire (kernel/locking/lockdep.c:5825)
_raw_spin_trylock (./include/linux/spinlock_api_smp.h:90 kernel/locking/spinlock.c:138)
virtnet_poll (./include/linux/spinlock.h:? ./include/linux/netdevice.h:4384 drivers/net/virtio_net.c:2768 drivers/net/virtio_net.c:2821)
__napi_poll (./arch/x86/include/asm/jump_label.h:27 ./include/linux/jump_label.h:207 ./include/trace/events/napi.h:14 net/core/dev.c:6772)
net_rx_action (net/core/dev.c:6842 net/core/dev.c:6962)
handle_softirqs (./arch/x86/include/asm/jump_label.h:27 ./include/linux/jump_label.h:207 ./include/trace/events/irq.h:142 kernel/softirq.c:555)
do_softirq (kernel/softirq.c:455)
__local_bh_enable_ip (kernel/softirq.c:?)
virtnet_open (drivers/net/virtio_net.c:2877 drivers/net/virtio_net.c:2925)
__dev_open (net/core/dev.c:1476)
dev_open (net/core/dev.c:1513)
netpoll_setup (net/core/netpoll.c:701)
init_netconsole (drivers/net/netconsole.c:1261 drivers/net/netconsole.c:1312)
do_one_initcall (init/main.c:1269)
do_initcall_level (init/main.c:1330)
do_initcalls (init/main.c:1344)
kernel_init_freeable (init/main.c:1584)
kernel_init (init/main.c:1471)
ret_from_fork (arch/x86/kernel/process.c:153)
ret_from_fork_asm (arch/x86/entry/entry_64.S:257)
}
... key at: netdev_xmit_lock_key+0x10/0x390
... acquired at:
_raw_spin_lock (./include/linux/spinlock_api_smp.h:133 kernel/locking/spinlock.c:154)
virtnet_poll_tx (./include/linux/netdevice.h:4361 drivers/net/virtio_net.c:2969)
netpoll_poll_dev (net/core/netpoll.c:167 net/core/netpoll.c:180 net/core/netpoll.c:210)
netpoll_send_skb (net/core/netpoll.c:360 net/core/netpoll.c:386)
netpoll_send_udp (net/core/netpoll.c:494)
write_ext_msg (drivers/net/netconsole.c:1187)
console_flush_all (kernel/printk/printk.c:3009 kernel/printk/printk.c:3093 kernel/printk/printk.c:3180)
console_unlock (kernel/printk/printk.c:3239 kernel/printk/printk.c:3279)
vprintk_emit (kernel/printk/printk.c:?)
_printk (kernel/printk/printk.c:2435)
register_console (kernel/printk/printk.c:4070)
init_netconsole (drivers/net/netconsole.c:1344)
do_one_initcall (init/main.c:1269)
do_initcall_level (init/main.c:1330)
do_initcalls (init/main.c:1344)
kernel_init_freeable (init/main.c:1584)
kernel_init (init/main.c:1471)
ret_from_fork (arch/x86/kernel/process.c:153)
ret_from_fork_asm (arch/x86/entry/entry_64.S:257)
stack backtrace:
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.16.3-0-ga6ed6b701f0a-prebuilt.qemu.org 04/01/2014
Call Trace:
<TASK>
dump_stack_lvl (lib/dump_stack.c:123)
__lock_acquire (kernel/locking/lockdep.c:? kernel/locking/lockdep.c:2888 kernel/locking/lockdep.c:3165 kernel/locking/lockdep.c:3280 kernel/locking/lockdep.c:3904 kernel/locking/lockdep.c:5202)
? virtnet_poll_tx (./include/linux/netdevice.h:4361 drivers/net/virtio_net.c:2969)
lock_acquire (kernel/locking/lockdep.c:5825)
? virtnet_poll_tx (./include/linux/netdevice.h:4361 drivers/net/virtio_net.c:2969)
? lock_acquire (kernel/locking/lockdep.c:5825)
? down_trylock (kernel/locking/semaphore.c:?)
_raw_spin_lock (./include/linux/spinlock_api_smp.h:133 kernel/locking/spinlock.c:154)
? virtnet_poll_tx (./include/linux/netdevice.h:4361 drivers/net/virtio_net.c:2969)
virtnet_poll_tx (./include/linux/netdevice.h:4361 drivers/net/virtio_net.c:2969)
netpoll_poll_dev (net/core/netpoll.c:167 net/core/netpoll.c:180 net/core/netpoll.c:210)
netpoll_send_skb (net/core/netpoll.c:360 net/core/netpoll.c:386)
netpoll_send_udp (net/core/netpoll.c:494)
? console_flush_all (./include/linux/rcupdate.h:? ./include/linux/srcu.h:267 kernel/printk/printk.c:288 kernel/printk/printk.c:3157)
write_ext_msg (drivers/net/netconsole.c:1187)
? console_flush_all (./include/linux/rcupdate.h:? ./include/linux/srcu.h:267 kernel/printk/printk.c:288 kernel/printk/printk.c:3157)
? console_flush_all (kernel/printk/printk.c:1905 kernel/printk/printk.c:3086 kernel/printk/printk.c:3180)
? console_flush_all (./include/linux/rcupdate.h:? ./include/linux/srcu.h:267 kernel/printk/printk.c:288 kernel/printk/printk.c:3157)
console_flush_all (kernel/printk/printk.c:3009 kernel/printk/printk.c:3093 kernel/printk/printk.c:3180)
? console_flush_all (./include/linux/rcupdate.h:? ./include/linux/srcu.h:267 kernel/printk/printk.c:288 kernel/printk/printk.c:3157)
console_unlock (kernel/printk/printk.c:3239 kernel/printk/printk.c:3279)
vprintk_emit (kernel/printk/printk.c:?)
_printk (kernel/printk/printk.c:2435)
register_console (kernel/printk/printk.c:4070)
init_netconsole (drivers/net/netconsole.c:1344)
? option_setup (drivers/net/netconsole.c:1301)
do_one_initcall (init/main.c:1269)
? __lock_acquire (kernel/locking/lockdep.c:?)
? __lock_acquire (kernel/locking/lockdep.c:?)
? stack_depot_save_flags (lib/stackdepot.c:664)
? stack_depot_save_flags (lib/stackdepot.c:664)
? __create_object (mm/kmemleak.c:763)
? lock_acquire (kernel/locking/lockdep.c:5825)
? __create_object (mm/kmemleak.c:763)
? __create_object (mm/kmemleak.c:766)
? parse_args (kernel/params.c:153 kernel/params.c:186)
do_initcall_level (init/main.c:1330)
? kernel_init (init/main.c:1471)
do_initcalls (init/main.c:1344)
kernel_init_freeable (init/main.c:1584)
? rest_init (init/main.c:1461)
kernel_init (init/main.c:1471)
ret_from_fork (arch/x86/kernel/process.c:153)
? rest_init (init/main.c:1461)
ret_from_fork_asm (arch/x86/entry/entry_64.S:257)
</TASK>
printk: legacy console [netcon0] enabled
netconsole: network logging started
PS: I've hacked around and removed the target_list_lock lock
completely, and I still see the problem, so, that lock doesn't seem to
be related to the problem.
Thanks,
--breno