* 6.12-rc1: Lockdep regression bissected (virtio-net/console/scheduler)
@ 2024-10-03 14:51 Breno Leitao
2024-10-03 15:06 ` Breno Leitao
2024-10-03 15:32 ` Peter Zijlstra
0 siblings, 2 replies; 9+ messages in thread
From: Breno Leitao @ 2024-10-03 14:51 UTC (permalink / raw)
To: peterz, gregkh, pmladek, mst, jasowang, xuanzhuo, kuba
Cc: virtualization, netdev, linux-kernel, vschneid, axboe
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
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 6.12-rc1: Lockdep regression bissected (virtio-net/console/scheduler)
2024-10-03 14:51 6.12-rc1: Lockdep regression bissected (virtio-net/console/scheduler) Breno Leitao
@ 2024-10-03 15:06 ` Breno Leitao
2024-10-03 15:32 ` Peter Zijlstra
1 sibling, 0 replies; 9+ messages in thread
From: Breno Leitao @ 2024-10-03 15:06 UTC (permalink / raw)
To: peterz, gregkh, pmladek, mst, jasowang, xuanzhuo, kuba
Cc: virtualization, netdev, linux-kernel, vschneid, axboe
On Thu, Oct 03, 2024 at 07:51:20AM -0700, Breno Leitao wrote:
> 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")
Errata. The commit is missing the first number. The right one is:
152e11f6df293e816a ("sched/fair: Implement delayed dequeue")
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 6.12-rc1: Lockdep regression bissected (virtio-net/console/scheduler)
2024-10-03 14:51 6.12-rc1: Lockdep regression bissected (virtio-net/console/scheduler) Breno Leitao
2024-10-03 15:06 ` Breno Leitao
@ 2024-10-03 15:32 ` Peter Zijlstra
2024-10-03 15:41 ` Breno Leitao
1 sibling, 1 reply; 9+ messages in thread
From: Peter Zijlstra @ 2024-10-03 15:32 UTC (permalink / raw)
To: Breno Leitao
Cc: gregkh, pmladek, mst, jasowang, xuanzhuo, kuba, virtualization,
netdev, linux-kernel, vschneid, axboe
On Thu, Oct 03, 2024 at 07:51:20AM -0700, Breno Leitao wrote:
> 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")
This looks like the normal lockdep splat you get when the scheduler does
printk. I suspect you tripped a WARN, but since you only provided the
lockdep output and not the whole log, I cannot tell.
There is a fix in:
git://git.kernel.org/pub/scm/linux/kernel/git/peterz/queue.git sched/urgent
that might, or might not help. I can't tell.
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 6.12-rc1: Lockdep regression bissected (virtio-net/console/scheduler)
2024-10-03 15:32 ` Peter Zijlstra
@ 2024-10-03 15:41 ` Breno Leitao
2024-10-04 9:08 ` Breno Leitao
0 siblings, 1 reply; 9+ messages in thread
From: Breno Leitao @ 2024-10-03 15:41 UTC (permalink / raw)
To: Peter Zijlstra
Cc: gregkh, pmladek, mst, jasowang, xuanzhuo, kuba, virtualization,
netdev, linux-kernel, vschneid, axboe
Hello Peter,
On Thu, Oct 03, 2024 at 05:32:31PM +0200, Peter Zijlstra wrote:
> On Thu, Oct 03, 2024 at 07:51:20AM -0700, Breno Leitao wrote:
> > 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")
>
> This looks like the normal lockdep splat you get when the scheduler does
> printk. I suspect you tripped a WARN, but since you only provided the
> lockdep output and not the whole log, I cannot tell.
Thanks for the quick answer. I didn't see a warning before the lockdep
splat, at least in the usual way I am familiar with. Let me past the
full log below.
> There is a fix in:
>
> git://git.kernel.org/pub/scm/linux/kernel/git/peterz/queue.git sched/urgent
>
> that might, or might not help. I can't tell.
Thanks. I will try it soon.
I just booted a clean VM, here is the full log:
Linux version 6.11.0-rc1-kbuilder-00044-g152e11f6df29 (leit@devvm32600.lla0.foobar.com) (clang version 20.0.0git (https://github.com/llvm/llvm-project.git d0f67773b213383b6e1c9331fb00f2d4c14bfcb2), LLD 18.0.0) #47 SMP Thu Oct 3 07:23:47 PDT 2024
Command line: virtme_hostname=virtme-ng nr_open=2500000 virtme_link_mods=/home/leit/Devel/upstream/.virtme_mods/lib/modules/0.0.0 console=hvc0 earlyprintk=serial,ttyS0,115200 virtme_console=ttyS0 psmouse.proto=exps "virtme_stty_con=rows 45 cols 101 iutf8" TERM=xterm-256color virtme.dhcp net.ifnames=0 biosdevname=0 virtme_chdir=home/leit/Devel/upstream netconsole=+6666@2401:db00:3120:21a9:1111:0000:0270:0000/eth0,1514@2803:6080:a89c:a670::1/02:90:fb:66:aa:e5 init=/home/leit/venv/lib/python3.8/site-packages/virtme/guest/bin/virtme-ng-init
KERNEL supported cpus:
Intel GenuineIntel
AMD AuthenticAMD
BIOS-provided physical RAM map:
BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
BIOS-e820: [mem 0x0000000000100000-0x00000000bffdffff] usable
BIOS-e820: [mem 0x00000000bffe0000-0x00000000bfffffff] reserved
BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved
BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
BIOS-e820: [mem 0x0000000100000000-0x00000002bfffffff] usable
BIOS-e820: [mem 0x000000fd00000000-0x000000ffffffffff] reserved
printk: legacy bootconsole [earlyser0] enabled
NX (Execute Disable) protection: active
APIC: Static calls initialized
SMBIOS 2.8 present.
DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.16.3-0-ga6ed6b701f0a-prebuilt.qemu.org 04/01/2014
DMI: Memory slots populated: 1/1
Hypervisor detected: KVM
kvm-clock: Using msrs 4b564d01 and 4b564d00
kvm-clock: using sched offset of 932970338 cycles
clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
tsc: Detected 1199.999 MHz processor
e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
e820: remove [mem 0x000a0000-0x000fffff] usable
last_pfn = 0x2c0000 max_arch_pfn = 0x400000000
MTRR map: 4 entries (3 fixed + 1 variable; max 19), built from 8 variable MTRRs
x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT
last_pfn = 0xbffe0 max_arch_pfn = 0x400000000
Using GB pages for direct mapping
RAMDISK: [mem 0xbf996000-0xbffdffff]
ACPI: Early table checksum verification disabled
ACPI: RSDP 0x00000000000F5270 000014 (v00 BOCHS )
ACPI: RSDT 0x00000000BFFE2C55 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001)
ACPI: FACP 0x00000000BFFE2889 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001)
ACPI: DSDT 0x00000000BFFE0040 002849 (v01 BOCHS BXPC 00000001 BXPC 00000001)
ACPI: FACS 0x00000000BFFE0000 000040
ACPI: APIC 0x00000000BFFE28FD 000110 (v03 BOCHS BXPC 00000001 BXPC 00000001)
ACPI: HPET 0x00000000BFFE2A0D 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001)
ACPI: SRAT 0x00000000BFFE2A45 0001E8 (v01 BOCHS BXPC 00000001 BXPC 00000001)
ACPI: WAET 0x00000000BFFE2C2D 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001)
ACPI: Reserving FACP table memory at [mem 0xbffe2889-0xbffe28fc]
ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2888]
ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f]
ACPI: Reserving APIC table memory at [mem 0xbffe28fd-0xbffe2a0c]
ACPI: Reserving HPET table memory at [mem 0xbffe2a0d-0xbffe2a44]
ACPI: Reserving SRAT table memory at [mem 0xbffe2a45-0xbffe2c2c]
ACPI: Reserving WAET table memory at [mem 0xbffe2c2d-0xbffe2c54]
SRAT: PXM 0 -> APIC 0x00 -> Node 0
SRAT: PXM 0 -> APIC 0x01 -> Node 0
SRAT: PXM 0 -> APIC 0x02 -> Node 0
SRAT: PXM 0 -> APIC 0x03 -> Node 0
SRAT: PXM 0 -> APIC 0x04 -> Node 0
SRAT: PXM 0 -> APIC 0x05 -> Node 0
SRAT: PXM 0 -> APIC 0x06 -> Node 0
SRAT: PXM 0 -> APIC 0x07 -> Node 0
SRAT: PXM 0 -> APIC 0x08 -> Node 0
SRAT: PXM 0 -> APIC 0x09 -> Node 0
SRAT: PXM 0 -> APIC 0x0a -> Node 0
SRAT: PXM 0 -> APIC 0x0b -> Node 0
SRAT: PXM 0 -> APIC 0x0c -> Node 0
SRAT: PXM 0 -> APIC 0x0d -> Node 0
SRAT: PXM 0 -> APIC 0x0e -> Node 0
SRAT: PXM 0 -> APIC 0x0f -> Node 0
SRAT: PXM 0 -> APIC 0x10 -> Node 0
SRAT: PXM 0 -> APIC 0x11 -> Node 0
SRAT: PXM 0 -> APIC 0x12 -> Node 0
SRAT: PXM 0 -> APIC 0x13 -> Node 0
ACPI: SRAT: Node 0 PXM 0 [mem 0x00000000-0x0009ffff]
ACPI: SRAT: Node 0 PXM 0 [mem 0x00100000-0xbfffffff]
ACPI: SRAT: Node 0 PXM 0 [mem 0x100000000-0x2bfffffff]
NUMA: Node 0 [mem 0x00000000-0x0009ffff] + [mem 0x00100000-0xbfffffff] -> [mem 0x00000000-0xbfffffff]
NUMA: Node 0 [mem 0x00000000-0xbfffffff] + [mem 0x100000000-0x2bfffffff] -> [mem 0x00000000-0x2bfffffff]
NODE_DATA(0) allocated [mem 0x2bfffa000-0x2bfffdfff]
Zone ranges:
DMA [mem 0x0000000000001000-0x0000000000ffffff]
DMA32 [mem 0x0000000001000000-0x00000000ffffffff]
Normal [mem 0x0000000100000000-0x00000002bfffffff]
Device empty
Movable zone start for each node
Early memory node ranges
node 0: [mem 0x0000000000001000-0x000000000009efff]
node 0: [mem 0x0000000000100000-0x00000000bffdffff]
node 0: [mem 0x0000000100000000-0x00000002bfffffff]
Initmem setup node 0 [mem 0x0000000000001000-0x00000002bfffffff]
On node 0, zone DMA: 1 pages in unavailable ranges
On node 0, zone DMA: 97 pages in unavailable ranges
On node 0, zone Normal: 32 pages in unavailable ranges
ACPI: PM-Timer IO Port: 0x608
ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
ACPI: Using ACPI (MADT) for SMP configuration information
ACPI: HPET id: 0x8086a201 base: 0xfed00000
TSC deadline timer available
CPU topo: Max. logical packages: 1
CPU topo: Max. logical dies: 1
CPU topo: Max. dies per package: 1
CPU topo: Max. threads per core: 1
CPU topo: Num. cores per package: 20
CPU topo: Num. threads per package: 20
CPU topo: Allowing 20 present CPUs plus 0 hotplug CPUs
kvm-guest: APIC: eoi() replaced with kvm_guest_apic_eoi_write()
kvm-guest: KVM setup pv remote TLB flush
kvm-guest: setup PV sched yield
[mem 0xc0000000-0xfeffbfff] available for PCI devices
Booting paravirtualized kernel on KVM
clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
setup_percpu: NR_CPUS:512 nr_cpumask_bits:20 nr_cpu_ids:20 nr_node_ids:1
percpu: Embedded 82 pages/cpu s299008 r8192 d28672 u524288
pcpu-alloc: s299008 r8192 d28672 u524288 alloc=1*2097152
pcpu-alloc: [0] 00 01 02 03 [0] 04 05 06 07
pcpu-alloc: [0] 08 09 10 11 [0] 12 13 14 15
pcpu-alloc: [0] 16 17 18 19
Kernel command line: virtme_hostname=virtme-ng nr_open=2500000 virtme_link_mods=/home/leit/Devel/upstream/.virtme_mods/lib/modules/0.0.0 console=hvc0 earlyprintk=serial,ttyS0,115200 virtme_console=ttyS0 psmouse.proto=exps "virtme_stty_con=rows 45 cols 101 iutf8" TERM=xterm-256color virtme.dhcp net.ifnames=0 biosdevname=0 virtme_chdir=home/leit/Devel/upstream netconsole=+6666@2401:db00:3120:21a9:face:0000:0270:0000/eth0,1514@2803:6080:a89c:a670::1/02:90:fb:66:aa:e5 init=/home/leit/venv/lib/python3.8/site-packages/virtme/guest/bin/virtme-ng-init
Unknown kernel command line parameters "virtme_hostname=virtme-ng nr_open=2500000 virtme_link_mods=/home/leit/Devel/upstream/.virtme_mods/lib/modules/0.0.0 virtme_console=ttyS0 virtme_stty_con=rows 45 cols 101 iutf8 biosdevname=0 virtme_chdir=home/leit/Devel/upstream", will be passed to user space.
random: crng init done
Dentry cache hash table entries: 2097152 (order: 12, 16777216 bytes, linear)
Inode-cache hash table entries: 1048576 (order: 11, 8388608 bytes, linear)
Fallback order for Node 0: 0
Built 1 zonelists, mobility grouping on. Total pages: 2621310
Policy zone: Normal
mem auto-init: stack:off, heap alloc:off, heap free:off
stackdepot: allocating hash table via alloc_large_system_hash
stackdepot hash table entries: 1048576 (order: 12, 16777216 bytes, linear)
software IO TLB: area num 32.
SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=20, Nodes=1
ftrace: allocating 46490 entries in 182 pages
ftrace: allocated 182 pages with 5 groups
Running RCU self tests
Running RCU synchronous self tests
rcu: Hierarchical RCU implementation.
rcu: RCU lockdep checking is enabled.
rcu: RCU restricting CPUs from NR_CPUS=512 to nr_cpu_ids=20.
Rude variant of Tasks RCU enabled.
Tracing variant of Tasks RCU enabled.
rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies.
rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=20
Running RCU synchronous self tests
RCU Tasks Rude: Setting shift to 5 and lim to 1 rcu_task_cb_adjust=1.
RCU Tasks Trace: Setting shift to 5 and lim to 1 rcu_task_cb_adjust=1.
NR_IRQS: 33024, nr_irqs: 584, preallocated irqs: 16
rcu: srcu_init: Setting srcu_struct sizes based on contention.
kfence: initialized - using 2097152 bytes for 255 objects at 0x(____ptrval____)-0x(____ptrval____)
Console: colour *CGA 80x25
Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
... MAX_LOCKDEP_SUBCLASSES: 8
... MAX_LOCK_DEPTH: 48
... MAX_LOCKDEP_KEYS: 8192
... CLASSHASH_SIZE: 4096
... MAX_LOCKDEP_ENTRIES: 32768
... MAX_LOCKDEP_CHAINS: 65536
... CHAINHASH_SIZE: 32768
memory used by lock dependency info: 6429 kB
memory used for stack traces: 4224 kB
per task-struct memory footprint: 1920 bytes
ACPI: Core revision 20240322
clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns
APIC: Switch to symmetric I/O mode setup
x2apic enabled
APIC: Switched APIC routing to: physical x2apic
kvm-guest: APIC: send_IPI_mask() replaced with kvm_send_ipi_mask()
kvm-guest: APIC: send_IPI_mask_allbutself() replaced with kvm_send_ipi_mask_allbutself()
kvm-guest: setup PV IPIs
..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
tsc: Marking TSC unstable due to TSCs unsynchronized
Calibrating delay loop (skipped) preset value.. 2399.99 BogoMIPS (lpj=1199999)
x86/cpu: User Mode Instruction Prevention (UMIP) activated
Last level iTLB entries: 4KB 512, 2MB 255, 4MB 127
Last level dTLB entries: 4KB 512, 2MB 255, 4MB 127, 1GB 0
Spectre V2 : User space: Vulnerable
Speculative Store Bypass: Vulnerable
x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
x86/fpu: Supporting XSAVE feature 0x020: 'AVX-512 opmask'
x86/fpu: Supporting XSAVE feature 0x040: 'AVX-512 Hi256'
x86/fpu: Supporting XSAVE feature 0x080: 'AVX-512 ZMM_Hi256'
x86/fpu: Supporting XSAVE feature 0x200: 'Protection Keys User registers'
x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256
x86/fpu: xstate_offset[5]: 832, xstate_sizes[5]: 64
x86/fpu: xstate_offset[6]: 896, xstate_sizes[6]: 512
x86/fpu: xstate_offset[7]: 1408, xstate_sizes[7]: 1024
x86/fpu: xstate_offset[9]: 2432, xstate_sizes[9]: 8
x86/fpu: Enabled xstate features 0x2e7, context size is 2440 bytes, using 'compacted' format.
Freeing SMP alternatives memory: 48K
pid_max: default: 32768 minimum: 301
LSM: initializing lsm=capability,ima
Mount-cache hash table entries: 32768 (order: 6, 262144 bytes, linear)
Mountpoint-cache hash table entries: 32768 (order: 6, 262144 bytes, linear)
Running RCU synchronous self tests
Running RCU synchronous self tests
smpboot: CPU0: AMD EPYC-Milan Processor (family: 0x19, model: 0x1, stepping: 0x1)
psi: inconsistent task state! task=1:swapper/0 cpu=0 psi_flags=4 clear=0 set=4
Running RCU Tasks Rude wait API self tests
Running RCU Tasks Trace wait API self tests
Performance Events: Fam17h+ core perfctr, AMD PMU driver.
... version: 0
... bit width: 48
... generic registers: 6
... value mask: 0000ffffffffffff
... max period: 00007fffffffffff
... fixed-purpose events: 0
... event mask: 000000000000003f
Callback from call_rcu_tasks_trace() invoked.
signal: max sigframe size: 3376
rcu: Hierarchical SRCU implementation.
rcu: Max phase no-delay instances is 400.
Timer migration: 2 hierarchy levels; 8 children per group; 2 crossnode level
smp: Bringing up secondary CPUs ...
smpboot: x86: Booting SMP configuration:
.... node #0, CPUs: #1 #2 #3 #4 #5 #6 #7 #8 #9 #10 #11 #12 #13 #14 #15 #16
Callback from call_rcu_tasks_rude() invoked.
#17 #18 #19
smp: Brought up 1 node, 20 CPUs
smpboot: Total of 20 processors activated (47999.96 BogoMIPS)
Memory: 10121020K/10485240K available (18432K kernel code, 9105K rwdata, 6216K rodata, 1884K init, 21012K bss, 350648K reserved, 0K cma-reserved)
devtmpfs: initialized
x86/mm: Memory block size: 128MB
Running RCU synchronous self tests
Running RCU synchronous self tests
clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
futex hash table entries: 8192 (order: 8, 1048576 bytes, linear)
NET: Registered PF_NETLINK/PF_ROUTE protocol family
DMA: preallocated 2048 KiB GFP_KERNEL pool for atomic allocations
DMA: preallocated 2048 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations
DMA: preallocated 2048 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations
audit: initializing netlink subsys (disabled)
audit: type=2000 audit(1727965453.220:1): state=initialized audit_enabled=0 res=1
thermal_sys: Registered thermal governor 'step_wise'
thermal_sys: Registered thermal governor 'user_space'
cpuidle: using governor menu
dca service started, version 1.12.1
PCI: Using configuration type 1 for base access
PCI: Using configuration type 1 for extended access
kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible.
HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages
HugeTLB: 16380 KiB vmemmap can be freed for a 1.00 GiB page
HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages
HugeTLB: 28 KiB vmemmap can be freed for a 2.00 MiB page
cryptd: max_cpu_qlen set to 1000
raid6: avx512x4 gen() 31451 MB/s
raid6: avx512x2 gen() 34478 MB/s
raid6: avx512x1 gen() 31905 MB/s
raid6: avx2x4 gen() 34476 MB/s
raid6: avx2x2 gen() 37438 MB/s
raid6: avx2x1 gen() 32283 MB/s
raid6: using algorithm avx2x2 gen() 37438 MB/s
raid6: .... xor() 29574 MB/s, rmw enabled
raid6: using avx512x2 recovery algorithm
ACPI: Added _OSI(Module Device)
ACPI: Added _OSI(Processor Device)
ACPI: Added _OSI(3.0 _SCP Extensions)
ACPI: Added _OSI(Processor Aggregator Device)
ACPI: 1 ACPI AML tables successfully acquired and loaded
ACPI: Interpreter enabled
ACPI: PM: (supports S0 S5)
ACPI: Using IOAPIC for interrupt routing
PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
PCI: Using E820 reservations for host bridge windows
ACPI: Enabled 2 GPEs in block 00 to 0F
ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
acpi PNP0A03:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI EDR HPX-Type3]
PCI host bridge to bus 0000:00
pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window]
pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window]
pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window]
pci_bus 0000:00: root bus resource [mem 0xc000000000-0xc07fffffff window]
pci_bus 0000:00: root bus resource [bus 00-ff]
pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 conventional PCI endpoint
pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 conventional PCI endpoint
pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 conventional PCI endpoint
pci 0000:00:01.1: BAR 4 [io 0xc060-0xc06f]
pci 0000:00:01.1: BAR 0 [io 0x01f0-0x01f7]: legacy IDE quirk
pci 0000:00:01.1: BAR 1 [io 0x03f6]: legacy IDE quirk
pci 0000:00:01.1: BAR 2 [io 0x0170-0x0177]: legacy IDE quirk
pci 0000:00:01.1: BAR 3 [io 0x0376]: legacy IDE quirk
pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 conventional PCI endpoint
pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI
pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB
pci 0000:00:02.0: [1af4:105a] type 00 class 0x018000 conventional PCI endpoint
pci 0000:00:02.0: BAR 1 [mem 0xfebc0000-0xfebc0fff]
pci 0000:00:02.0: BAR 4 [mem 0xc000000000-0xc000003fff 64bit pref]
pci 0000:00:03.0: [8086:25ab] type 00 class 0x088000 conventional PCI endpoint
pci 0000:00:03.0: BAR 0 [mem 0xfebc1000-0xfebc100f]
pci 0000:00:04.0: [1af4:1003] type 00 class 0x078000 conventional PCI endpoint
pci 0000:00:04.0: BAR 0 [io 0xc000-0xc03f]
pci 0000:00:04.0: BAR 1 [mem 0xfebc2000-0xfebc2fff]
pci 0000:00:04.0: BAR 4 [mem 0xc000004000-0xc000007fff 64bit pref]
pci 0000:00:05.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint
pci 0000:00:05.0: BAR 0 [io 0xc040-0xc05f]
pci 0000:00:05.0: BAR 1 [mem 0xfebc3000-0xfebc3fff]
pci 0000:00:05.0: BAR 4 [mem 0xc000008000-0xc00000bfff 64bit pref]
pci 0000:00:05.0: ROM [mem 0xfeb80000-0xfebbffff pref]
ACPI: PCI: Interrupt link LNKA configured for IRQ 10
ACPI: PCI: Interrupt link LNKB configured for IRQ 10
ACPI: PCI: Interrupt link LNKC configured for IRQ 11
ACPI: PCI: Interrupt link LNKD configured for IRQ 11
ACPI: PCI: Interrupt link LNKS configured for IRQ 9
iommu: Default domain type: Translated
iommu: DMA domain TLB invalidation policy: lazy mode
SCSI subsystem initialized
libata version 3.00 loaded.
ACPI: bus type USB registered
usbcore: registered new interface driver usbfs
usbcore: registered new interface driver hub
usbcore: registered new device driver usb
pps_core: LinuxPPS API ver. 1 registered
pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
PTP clock support registered
PCI: Using ACPI for IRQ routing
PCI: pci_cache_line_size set to 64 bytes
e820: reserve RAM buffer [mem 0x0009fc00-0x0009ffff]
e820: reserve RAM buffer [mem 0xbffe0000-0xbfffffff]
hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0
hpet0: 3 comparators, 64-bit 100.000000 MHz counter
clocksource: Switched to clocksource kvm-clock
VFS: Disk quotas dquot_6.6.0
VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
pnp: PnP ACPI init
pnp 00:02: [dma 2]
pnp: PnP ACPI: found 5 devices
clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
NET: Registered PF_INET protocol family
IP idents hash table entries: 262144 (order: 9, 2097152 bytes, linear)
tcp_listen_portaddr_hash hash table entries: 8192 (order: 7, 589824 bytes, linear)
Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)
TCP established hash table entries: 131072 (order: 8, 1048576 bytes, linear)
TCP bind hash table entries: 65536 (order: 11, 9437184 bytes, vmalloc hugepage)
TCP: Hash tables configured (established 131072 bind 65536)
UDP hash table entries: 8192 (order: 8, 1310720 bytes, linear)
UDP-Lite hash table entries: 8192 (order: 8, 1310720 bytes, linear)
NET: Registered PF_UNIX/PF_LOCAL protocol family
NET: Registered PF_XDP protocol family
pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window]
pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window]
pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window]
pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window]
pci_bus 0000:00: resource 8 [mem 0xc000000000-0xc07fffffff window]
pci 0000:00:01.0: PIIX3: Enabling Passive Release
pci 0000:00:00.0: Limiting direct PCI/PCI transfers
PCI: CLS 0 bytes, default 64
PCI-DMA: Using software bounce buffering for IO (SWIOTLB)
Trying to unpack rootfs image as initramfs...
software IO TLB: mapped [mem 0x00000000bb996000-0x00000000bf996000] (64MB)
kvm_intel: VMX not supported by CPU 1
kvm_amd: TSC scaling supported
kvm_amd: Nested Virtualization enabled
kvm_amd: Nested Paging enabled
kvm_amd: LBR virtualization supported
Freeing initrd memory: 6440K
Initialise system trusted keyrings
workingset: timestamp_bits=43 max_order=22 bucket_order=0
9p: Installing v9fs 9p2000 file system support
NET: Registered PF_ALG protocol family
xor: automatically using best checksumming function avx
Key type asymmetric registered
Asymmetric key parser 'x509' registered
Block layer SCSI generic (bsg) driver version 0.4 loaded (major 246)
io scheduler mq-deadline registered
io scheduler kyber registered
ioatdma: Intel(R) QuickData Technology Driver 5.00
ACPI: \_SB_.LNKB: Enabled at IRQ 10
ACPI: \_SB_.LNKD: Enabled at IRQ 11
ACPI: \_SB_.LNKA: Enabled at IRQ 10
Serial: 8250/16550 driver, 16 ports, IRQ sharing enabled
00:03: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
printk: legacy console [hvc0] enabled
printk: legacy bootconsole [earlyser0] disabled
brd: module loaded
usbcore: registered new interface driver ark3116
usbserial: USB Serial support registered for ark3116
usbcore: registered new interface driver pl2303
usbserial: USB Serial support registered for pl2303
i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
serio: i8042 KBD port at 0x60,0x64 irq 1
serio: i8042 AUX port at 0x60,0x64 irq 12
rtc_cmos 00:04: RTC can wake from S4
rtc_cmos 00:04: registered as rtc0
rtc_cmos 00:04: setting system clock to 2024-10-03T14:24:13 UTC (1727965453)
rtc_cmos 00:04: alarms up to one day, y3k, 242 bytes nvram, hpet irqs
i6300ESB timer 0000:00:03.0: initialized. heartbeat=30 sec (nowayout=0)
input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0
usbcore: registered new interface driver usbhid
usbhid: USB HID core driver
Initializing XFRM netlink socket
NET: Registered PF_INET6 protocol family
Segment Routing with IPv6
In-situ OAM (IOAM) with IPv6
NET: Registered PF_PACKET protocol family
9pnet: Installing 9P2000 support
Key type dns_resolver registered
IPI shorthand broadcast: enabled
AES CTR mode by8 optimization enabled
registered taskstats version 1
Loading compiled-in X.509 certificates
virtme initramfs: initramfs does not have module crypto-pkcs1pad(rsa,sha512)
virtme initramfs: initramfs does not have module crypto-pkcs1pad(rsa,sha512)-all
Loaded X.509 cert 'Build time autogenerated kernel key: 1a58da0881b870ef3decd7cf414d45e41b0e363a'
Demotion targets for Node 0: null
kmemleak: Kernel memory leak detector initialized (mem pool available: 15766)
kmemleak: Automatic memory scanning thread started
Btrfs loaded, zoned=no, fsverity=yes
ima: No TPM chip found, activating TPM-bypass!
ima: Allocated hash algorithm: sha256
ima: No architecture policies found
netpoll: netconsole: local port 6666
netpoll: netconsole: local IPv6 address 2401:db00:3120:21a9:face:0:270:0
netpoll: netconsole: interface 'eth0'
netpoll: netconsole: remote port 1514
netpoll: netconsole: remote IPv6 address 2803:6080:a89c:a670::1
netpoll: netconsole: remote ethernet address 02:90:fb:66:aa:e5
netpoll: netconsole: device eth0 not up yet, forcing it
printk: legacy console [netcon_ext0] enabled
=====================================================
WARNING: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected
6.11.0-rc1-kbuilder-00044-g152e11f6df29 #47 Not tainted
-----------------------------------------------------
swapper/0/1 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire:
ffff8881027702d8 (_xmit_ETHER#2){+.-.}-{3:3}, at: virtnet_poll_tx+0x94/0x210
and this task is already holding:
ffffffff8325b808 (target_list_lock){....}-{3:3}, at: write_ext_msg+0x4e/0x3a0
which would create a new lock dependency:
(target_list_lock){....}-{3:3} -> (_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+0xe6/0x240
console_flush_all+0x31d/0x580
console_unlock+0x49/0x160
wake_up_klogd_work_func+0x68/0xa0
irq_work_run_list+0x9b/0xe0
update_process_times+0x88/0xa0
tick_handle_periodic+0x22/0x80
__sysvec_apic_timer_interrupt+0x74/0x1c0
sysvec_apic_timer_interrupt+0x6c/0x80
asm_sysvec_apic_timer_interrupt+0x1a/0x20
clear_page_erms+0xb/0x10
alloc_pages_bulk_noprof+0x48d/0x690
__vmalloc_node_range_noprof+0x3ad/0x7c0
dup_task_struct+0x12a/0x2a0
copy_process+0x17a/0x1380
kernel_clone+0x97/0x340
kernel_thread+0xb8/0xe0
kthreadd+0x201/0x240
ret_from_fork+0x34/0x40
ret_from_fork_asm+0x11/0x20
to a HARDIRQ-irq-unsafe lock:
(_xmit_ETHER#2){+.-.}-{3:3}
... which became HARDIRQ-irq-unsafe at:
...
lock_acquire+0xe6/0x240
_raw_spin_trylock+0x45/0x60
virtnet_poll+0xa2/0xe90
__napi_poll+0x28/0x210
net_rx_action+0x1de/0x3c0
handle_softirqs+0x187/0x460
do_softirq+0x68/0xc0
__local_bh_enable_ip+0xee/0x100
virtnet_open+0x1ad/0x320
__dev_open+0xdb/0x170
dev_open+0x30/0x90
netpoll_setup+0x188/0x420
init_netconsole+0x136/0x360
do_one_initcall+0xee/0x310
do_initcall_level+0xa1/0x110
do_initcalls+0x43/0x70
kernel_init_freeable+0x17e/0x200
kernel_init+0x1a/0x130
ret_from_fork+0x34/0x40
ret_from_fork_asm+0x11/0x20
other info that might help us debug this:
Chain exists of:
console_owner --> target_list_lock --> _xmit_ETHER#2
Possible interrupt unsafe locking scenario:
CPU0 CPU1
---- ----
lock(_xmit_ETHER#2);
local_irq_disable();
lock(console_owner);
lock(target_list_lock);
<Interrupt>
lock(console_owner);
*** DEADLOCK ***
5 locks held by swapper/0/1:
#0: ffffffff82a835f8 (console_mutex){+.+.}-{4:4}, at: register_console+0x47/0x350
#1: ffffffff82a839e8 (console_lock){+.+.}-{0:0}, at: _printk+0x5d/0x80
#2: ffffffff82a83630 (console_srcu){....}-{0:0}, at: console_flush_all+0x6a/0x580
#3: ffffffff83183ea0 (console_owner){-...}-{0:0}, at: console_flush_all+0x6a/0x580
#4: ffffffff8325b808 (target_list_lock){....}-{3:3}, at: write_ext_msg+0x4e/0x3a0
the dependencies between HARDIRQ-irq-safe lock and the holding lock:
-> (console_owner){-...}-{0:0} ops: 2584 {
IN-HARDIRQ-W at:
lock_acquire+0xe6/0x240
console_flush_all+0x31d/0x580
console_unlock+0x49/0x160
wake_up_klogd_work_func+0x68/0xa0
irq_work_run_list+0x9b/0xe0
update_process_times+0x88/0xa0
tick_handle_periodic+0x22/0x80
__sysvec_apic_timer_interrupt+0x74/0x1c0
sysvec_apic_timer_interrupt+0x6c/0x80
asm_sysvec_apic_timer_interrupt+0x1a/0x20
clear_page_erms+0xb/0x10
alloc_pages_bulk_noprof+0x48d/0x690
__vmalloc_node_range_noprof+0x3ad/0x7c0
dup_task_struct+0x12a/0x2a0
copy_process+0x17a/0x1380
kernel_clone+0x97/0x340
kernel_thread+0xb8/0xe0
kthreadd+0x201/0x240
ret_from_fork+0x34/0x40
ret_from_fork_asm+0x11/0x20
INITIAL USE at:
}
... key at: [<ffffffff83183ea0>] console_owner_dep_map+0x0/0x28
-> (target_list_lock){....}-{3:3} ops: 3 {
INITIAL USE at:
lock_acquire+0xe6/0x240
_raw_spin_lock_irqsave+0x5a/0x90
init_netconsole+0x23b/0x360
do_one_initcall+0xee/0x310
do_initcall_level+0xa1/0x110
do_initcalls+0x43/0x70
kernel_init_freeable+0x17e/0x200
kernel_init+0x1a/0x130
ret_from_fork+0x34/0x40
ret_from_fork_asm+0x11/0x20
}
... key at: [<ffffffff8325b808>] target_list_lock+0x18/0x40
... acquired at:
_raw_spin_lock_irqsave+0x5a/0x90
write_ext_msg+0x4e/0x3a0
console_flush_all+0x332/0x580
console_unlock+0x49/0x160
vprintk_emit+0x226/0x350
_printk+0x5d/0x80
register_console+0x2d0/0x350
init_netconsole+0x2a6/0x360
do_one_initcall+0xee/0x310
do_initcall_level+0xa1/0x110
do_initcalls+0x43/0x70
kernel_init_freeable+0x17e/0x200
kernel_init+0x1a/0x130
ret_from_fork+0x34/0x40
ret_from_fork_asm+0x11/0x20
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+0xe6/0x240
_raw_spin_trylock+0x45/0x60
virtnet_poll+0xa2/0xe90
__napi_poll+0x28/0x210
net_rx_action+0x1de/0x3c0
handle_softirqs+0x187/0x460
do_softirq+0x68/0xc0
__local_bh_enable_ip+0xee/0x100
virtnet_open+0x1ad/0x320
__dev_open+0xdb/0x170
dev_open+0x30/0x90
netpoll_setup+0x188/0x420
init_netconsole+0x136/0x360
do_one_initcall+0xee/0x310
do_initcall_level+0xa1/0x110
do_initcalls+0x43/0x70
kernel_init_freeable+0x17e/0x200
kernel_init+0x1a/0x130
ret_from_fork+0x34/0x40
ret_from_fork_asm+0x11/0x20
IN-SOFTIRQ-W at:
lock_acquire+0xe6/0x240
_raw_spin_lock+0x30/0x40
virtnet_poll_tx+0x94/0x210
__napi_poll+0x28/0x210
net_rx_action+0x1de/0x3c0
handle_softirqs+0x187/0x460
do_softirq+0x68/0xc0
__local_bh_enable_ip+0xee/0x100
virtnet_open+0x89/0x320
__dev_open+0xdb/0x170
dev_open+0x30/0x90
netpoll_setup+0x188/0x420
init_netconsole+0x136/0x360
do_one_initcall+0xee/0x310
do_initcall_level+0xa1/0x110
do_initcalls+0x43/0x70
kernel_init_freeable+0x17e/0x200
kernel_init+0x1a/0x130
ret_from_fork+0x34/0x40
ret_from_fork_asm+0x11/0x20
INITIAL USE at:
lock_acquire+0xe6/0x240
_raw_spin_trylock+0x45/0x60
virtnet_poll+0xa2/0xe90
__napi_poll+0x28/0x210
net_rx_action+0x1de/0x3c0
handle_softirqs+0x187/0x460
do_softirq+0x68/0xc0
__local_bh_enable_ip+0xee/0x100
virtnet_open+0x1ad/0x320
__dev_open+0xdb/0x170
dev_open+0x30/0x90
netpoll_setup+0x188/0x420
init_netconsole+0x136/0x360
do_one_initcall+0xee/0x310
do_initcall_level+0xa1/0x110
do_initcalls+0x43/0x70
kernel_init_freeable+0x17e/0x200
kernel_init+0x1a/0x130
ret_from_fork+0x34/0x40
ret_from_fork_asm+0x11/0x20
}
... key at: [<ffffffff84a45430>] netdev_xmit_lock_key+0x10/0x390
... acquired at:
_raw_spin_lock+0x30/0x40
virtnet_poll_tx+0x94/0x210
netpoll_poll_dev+0x15d/0x240
netpoll_send_skb+0x268/0x350
netpoll_send_udp+0x3f7/0x470
write_ext_msg+0xe2/0x3a0
console_flush_all+0x332/0x580
console_unlock+0x49/0x160
vprintk_emit+0x226/0x350
_printk+0x5d/0x80
register_console+0x2d0/0x350
init_netconsole+0x2a6/0x360
do_one_initcall+0xee/0x310
do_initcall_level+0xa1/0x110
do_initcalls+0x43/0x70
kernel_init_freeable+0x17e/0x200
kernel_init+0x1a/0x130
ret_from_fork+0x34/0x40
ret_from_fork_asm+0x11/0x20
stack backtrace:
CPU: 1 UID: 0 PID: 1 Comm: swapper/0 Not tainted 6.11.0-rc1-kbuilder-00044-g152e11f6df29 #47
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+0x9f/0xf0
__lock_acquire+0x2cd0/0x2d10
? virtnet_poll_tx+0x94/0x210
lock_acquire+0xe6/0x240
? virtnet_poll_tx+0x94/0x210
? lock_acquire+0xe6/0x240
? down_trylock+0x12/0x30
_raw_spin_lock+0x30/0x40
? virtnet_poll_tx+0x94/0x210
virtnet_poll_tx+0x94/0x210
netpoll_poll_dev+0x15d/0x240
netpoll_send_skb+0x268/0x350
netpoll_send_udp+0x3f7/0x470
write_ext_msg+0xe2/0x3a0
console_flush_all+0x332/0x580
? console_flush_all+0x6a/0x580
console_unlock+0x49/0x160
? __down_trylock_console_sem+0x9e/0xe0
vprintk_emit+0x226/0x350
_printk+0x5d/0x80
register_console+0x2d0/0x350
init_netconsole+0x2a6/0x360
? option_setup+0x30/0x30
do_one_initcall+0xee/0x310
? __lock_acquire+0xe4b/0x2d10
? __lock_acquire+0xe4b/0x2d10
? stack_depot_save_flags+0x60d/0x6c0
? asm_sysvec_call_function+0x1a/0x20
? parse_args+0x11d/0x420
? parse_args+0x16b/0x420
do_initcall_level+0xa1/0x110
? kernel_init+0x1a/0x130
do_initcalls+0x43/0x70
kernel_init_freeable+0x17e/0x200
? rest_init+0x1f0/0x1f0
kernel_init+0x1a/0x130
ret_from_fork+0x34/0x40
? rest_init+0x1f0/0x1f0
ret_from_fork_asm+0x11/0x20
</TASK>
printk: legacy console [netcon0] enabled
netconsole: network logging started
Unstable clock detected, switching default tracing clock to "global"
If you want to keep using the local clock, then add:
"trace_clock=local"
on the kernel command line
clk: Disabling unused clocks
Freeing unused decrypted memory: 2036K
Freeing unused kernel image (initmem) memory: 1884K
Write protecting the kernel read-only data: 26624k
Freeing unused kernel image (rodata/data gap) memory: 1976K
Run /init as init process
with arguments:
/init
with environment:
HOME=/
TERM=xterm-256color
virtme_hostname=virtme-ng
nr_open=2500000
virtme_link_mods=/home/leit/Devel/upstream/.virtme_mods/lib/modules/0.0.0
virtme_console=ttyS0
virtme_stty_con=rows 45 cols 101 iutf8
biosdevname=0
virtme_chdir=home/leit/Devel/upstream
virtme initramfs: loading fuse.ko...
fuse: module verification failed: signature and/or required key missing - tainting kernel
fuse: init (API version 7.40)
virtme initramfs: loading virtiofs.ko...
virtme initramfs: mounting hostfs...
virtme initramfs: done; switching to real root
virtme-ng-init: /etc/tmpfiles.d/chef.conf:13: Line references path below legacy directory /var/run/, updating /var/run/ccache → /run/ccache; please update the tmpfiles.d/ drop-in file accordingly.
virtme-ng-init: setting up network device eth0
virtme-ng-init: WARNING: failed to run: "busybox" udhcpc -i eth0 -n -q -f -s /home/leit/venv/lib/python3.8/site-packages/virtme/guest/virtme-udhcpc-script
virtme-ng-init: Starting systemd-udevd version v255.5-1.4.hs+fb.el9
virtme-ng-init: triggering udev coldplug
input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input3
ACPI: button: Power Button [PWRF]
virtme-ng-init: waiting for udev to settle
Linux agpgart interface v0.103
virtme-ng-init: udev is done
virtme-ng-init: initialization done
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 6.12-rc1: Lockdep regression bissected (virtio-net/console/scheduler)
2024-10-03 15:41 ` Breno Leitao
@ 2024-10-04 9:08 ` Breno Leitao
2024-10-04 10:49 ` Petr Mladek
0 siblings, 1 reply; 9+ messages in thread
From: Breno Leitao @ 2024-10-04 9:08 UTC (permalink / raw)
To: Peter Zijlstra
Cc: gregkh, pmladek, mst, jasowang, xuanzhuo, kuba, virtualization,
netdev, linux-kernel, vschneid, axboe
Hello Peter,
On Thu, Oct 03, 2024 at 08:41:53AM -0700, Breno Leitao wrote:
> > > 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")
> >
> > This looks like the normal lockdep splat you get when the scheduler does
> > printk. I suspect you tripped a WARN, but since you only provided the
> > lockdep output and not the whole log, I cannot tell.
>
> Thanks for the quick answer. I didn't see a warning before the lockdep
> splat, at least in the usual way I am familiar with. Let me past the
> full log below.
>
> > There is a fix in:
> >
> > git://git.kernel.org/pub/scm/linux/kernel/git/peterz/queue.git sched/urgent
> >
> > that might, or might not help. I can't tell.
>
> Thanks. I will try it soon.
I've just tested your branch "sched/urgent", and the problem is still
there. I've tested against:
d4ac164bde7a ("sched/eevdf: Fix wakeup-preempt by checking cfs_rq->nr_running")
Here is the full log:
Linux version 6.12.0-rc1-kbuilder-virtme-00033-gd4ac164bde7a (leit@devvm32600.lla0.foo.com) (clang version 20.0.0git (https://github.com/llvm/llvm-project.git d0f67773b213383b6e1c9331fb00f2d4c14bfcb2), LLD 18.0.0) #50 SMP PREEMPT_DYNAMIC Fri Oct 4 01:54:44 PDT 2024
Command line: virtme_hostname=virtme-ng nr_open=2500000 virtme_link_mods=/home/leit/Devel/upstream/.virtme_mods/lib/modules/0.0.0 console=hvc0 earlyprintk=serial,ttyS0,115200 virtme_console=ttyS0 psmouse.proto=exps "virtme_stty_con=rows 43 cols 235 iutf8" TERM=xterm-256color virtme.dhcp net.ifnames=0 biosdevname=0 virtme_chdir=home/leit/Devel/upstream netconsole=+6666@2401:db00:3120:21a9:face:0000:0270:0000/eth0,1514@2803:6080:a89c:a670::1/02:90:fb:66:aa:e5 init=/home/leit/venv/lib/python3.8/site-packages/virtme/guest/bin/virtme-ng-init
BIOS-provided physical RAM map:
BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
BIOS-e820: [mem 0x0000000000100000-0x00000000bffdffff] usable
BIOS-e820: [mem 0x00000000bffe0000-0x00000000bfffffff] reserved
BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved
BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
BIOS-e820: [mem 0x0000000100000000-0x00000002bfffffff] usable
BIOS-e820: [mem 0x000000fd00000000-0x000000ffffffffff] reserved
printk: legacy bootconsole [earlyser0] enabled
NX (Execute Disable) protection: active
APIC: Static calls initialized
SMBIOS 2.8 present.
DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.16.3-0-ga6ed6b701f0a-prebuilt.qemu.org 04/01/2014
DMI: Memory slots populated: 1/1
e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
e820: remove [mem 0x000a0000-0x000fffff] usable
last_pfn = 0x2c0000 max_arch_pfn = 0x10000000000
MTRR map: 4 entries (3 fixed + 1 variable; max 19), built from 8 variable MTRRs
x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT
last_pfn = 0xbffe0 max_arch_pfn = 0x10000000000
found SMP MP-table at [mem 0x000f5470-0x000f547f]
RAMDISK: [mem 0xbf218000-0xbffdffff]
ACPI: Early table checksum verification disabled
ACPI: RSDP 0x00000000000F5270 000014 (v00 BOCHS )
ACPI: RSDT 0x00000000BFFE2C55 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001)
ACPI: FACP 0x00000000BFFE2889 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001)
ACPI: DSDT 0x00000000BFFE0040 002849 (v01 BOCHS BXPC 00000001 BXPC 00000001)
ACPI: FACS 0x00000000BFFE0000 000040
ACPI: APIC 0x00000000BFFE28FD 000110 (v03 BOCHS BXPC 00000001 BXPC 00000001)
ACPI: HPET 0x00000000BFFE2A0D 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001)
ACPI: SRAT 0x00000000BFFE2A45 0001E8 (v01 BOCHS BXPC 00000001 BXPC 00000001)
ACPI: WAET 0x00000000BFFE2C2D 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001)
ACPI: Reserving FACP table memory at [mem 0xbffe2889-0xbffe28fc]
ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2888]
ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f]
ACPI: Reserving APIC table memory at [mem 0xbffe28fd-0xbffe2a0c]
ACPI: Reserving HPET table memory at [mem 0xbffe2a0d-0xbffe2a44]
ACPI: Reserving SRAT table memory at [mem 0xbffe2a45-0xbffe2c2c]
ACPI: Reserving WAET table memory at [mem 0xbffe2c2d-0xbffe2c54]
ACPI: SRAT: Node 0 PXM 0 [mem 0x00000000-0x0009ffff]
ACPI: SRAT: Node 0 PXM 0 [mem 0x00100000-0xbfffffff]
ACPI: SRAT: Node 0 PXM 0 [mem 0x100000000-0x2bfffffff]
NUMA: Node 0 [mem 0x00001000-0x0009ffff] + [mem 0x00100000-0xbfffffff] -> [mem 0x00001000-0xbfffffff]
NUMA: Node 0 [mem 0x00001000-0xbfffffff] + [mem 0x100000000-0x2bfffffff] -> [mem 0x00001000-0x2bfffffff]
NODE_DATA(0) allocated [mem 0x2bebf6ac0-0x2bebfbdff]
Zone ranges:
DMA [mem 0x0000000000001000-0x0000000000ffffff]
DMA32 [mem 0x0000000001000000-0x00000000ffffffff]
Normal [mem 0x0000000100000000-0x00000002bfffffff]
Device empty
Movable zone start for each node
Early memory node ranges
node 0: [mem 0x0000000000001000-0x000000000009efff]
node 0: [mem 0x0000000000100000-0x00000000bffdffff]
node 0: [mem 0x0000000100000000-0x00000002bfffffff]
Initmem setup node 0 [mem 0x0000000000001000-0x00000002bfffffff]
On node 0, zone DMA: 1 pages in unavailable ranges
On node 0, zone DMA: 97 pages in unavailable ranges
On node 0, zone Normal: 32 pages in unavailable ranges
kasan: KernelAddressSanitizer initialized
ACPI: PM-Timer IO Port: 0x608
ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
ACPI: Using ACPI (MADT) for SMP configuration information
ACPI: HPET id: 0x8086a201 base: 0xfed00000
TSC deadline timer available
CPU topo: Max. logical packages: 1
CPU topo: Max. logical dies: 1
CPU topo: Max. dies per package: 1
CPU topo: Max. threads per core: 1
CPU topo: Num. cores per package: 20
CPU topo: Num. threads per package: 20
CPU topo: Allowing 20 present CPUs plus 0 hotplug CPUs
[mem 0xc0000000-0xfeffbfff] available for PCI devices
clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
setup_percpu: NR_CPUS:512 nr_cpumask_bits:20 nr_cpu_ids:20 nr_node_ids:1
percpu: Embedded 89 pages/cpu s326416 r8192 d29936 u524288
pcpu-alloc: s326416 r8192 d29936 u524288 alloc=1*2097152
pcpu-alloc: [0] 00 01 02 03 [0] 04 05 06 07
pcpu-alloc: [0] 08 09 10 11 [0] 12 13 14 15
pcpu-alloc: [0] 16 17 18 19
Kernel command line: virtme_hostname=virtme-ng nr_open=2500000 virtme_link_mods=/home/leit/Devel/upstream/.virtme_mods/lib/modules/0.0.0 console=hvc0 earlyprintk=serial,ttyS0,115200 virtme_console=ttyS0 psmouse.proto=exps "virtme_stty_con=rows 43 cols 235 iutf8" TERM=xterm-256color virtme.dhcp net.ifnames=0 biosdevname=0 virtme_chdir=home/leit/Devel/upstream netconsole=+6666@2401:db00:3120:21a9:face:0000:0270:0000/eth0,1514@2803:6080:a89c:a670::1/02:90:fb:66:aa:e5 init=/home/leit/venv/lib/python3.8/site-packages/virtme/guest/bin/virtme-ng-init
Unknown kernel command line parameters "virtme_hostname=virtme-ng nr_open=2500000 virtme_link_mods=/home/leit/Devel/upstream/.virtme_mods/lib/modules/0.0.0 virtme_console=ttyS0 virtme_stty_con=rows 43 cols 235 iutf8 biosdevname=0 virtme_chdir=home/leit/Devel/upstream", will be passed to user space.
random: crng init done
Dentry cache hash table entries: 2097152 (order: 12, 16777216 bytes, linear)
Inode-cache hash table entries: 1048576 (order: 11, 8388608 bytes, linear)
Fallback order for Node 0: 0
Built 1 zonelists, mobility grouping on. Total pages: 2621310
Policy zone: Normal
mem auto-init: stack:off, heap alloc:off, heap free:off
stackdepot: allocating hash table via alloc_large_system_hash
stackdepot hash table entries: 1048576 (order: 12, 16777216 bytes, linear)
software IO TLB: area num 32.
SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=20, Nodes=1
allocated 20971520 bytes of page_ext
ftrace: allocating 58899 entries in 231 pages
ftrace: allocated 231 pages with 6 groups
Dynamic Preempt: none
Running RCU self tests
Running RCU synchronous self tests
rcu: Preemptible hierarchical RCU implementation.
rcu: RCU event tracing is enabled.
rcu: RCU lockdep checking is enabled.
rcu: RCU restricting CPUs from NR_CPUS=512 to nr_cpu_ids=20.
rcu: RCU callback double-/use-after-free debug is enabled.
rcu: RCU debug extended QS entry/exit.
Trampoline variant of Tasks RCU enabled.
Rude variant of Tasks RCU enabled.
Tracing variant of Tasks RCU enabled.
rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies.
rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=20
Running RCU synchronous self tests
RCU Tasks: Setting shift to 5 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=20.
RCU Tasks Rude: Setting shift to 5 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=20.
RCU Tasks Trace: Setting shift to 5 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=20.
NR_IRQS: 33024, nr_irqs: 584, preallocated irqs: 16
rcu: srcu_init: Setting srcu_struct sizes based on contention.
kfence: initialized - using 2097152 bytes for 255 objects at 0x(____ptrval____)-0x(____ptrval____)
Console: colour *CGA 80x25
Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
... MAX_LOCKDEP_SUBCLASSES: 8
... MAX_LOCK_DEPTH: 48
... MAX_LOCKDEP_KEYS: 8192
... CLASSHASH_SIZE: 4096
... MAX_LOCKDEP_ENTRIES: 1048576
... MAX_LOCKDEP_CHAINS: 1048576
... CHAINHASH_SIZE: 524288
memory used by lock dependency info: 106625 kB
memory used for stack traces: 4224 kB
per task-struct memory footprint: 1920 bytes
ACPI: Core revision 20240827
clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns
APIC: Switch to symmetric I/O mode setup
..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
tsc: Unable to calibrate against PIT
tsc: using HPET reference calibration
tsc: Detected 1199.814 MHz processor
clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x114b6c033ac, max_idle_ns: 440795260201 ns
Calibrating delay loop (skipped), value calculated using timer frequency.. 2399.62 BogoMIPS (lpj=1199814)
x86/cpu: User Mode Instruction Prevention (UMIP) activated
numa_add_cpu cpu 0 node 0: mask now 0
Last level iTLB entries: 4KB 512, 2MB 255, 4MB 127
Last level dTLB entries: 4KB 512, 2MB 255, 4MB 127, 1GB 0
Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization
Spectre V2 : Mitigation: Retpolines
Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch
Spectre V2 : Spectre v2 / SpectreRSB : Filling RSB on VMEXIT
Spectre V2 : Enabling Restricted Speculation for firmware calls
Spectre V2 : mitigation: Enabling conditional Indirect Branch Prediction Barrier
Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl
Speculative Return Stack Overflow: IBPB-extending microcode not applied!
Speculative Return Stack Overflow: WARNING: See https://kernel.org/doc/html/latest/admin-guide/hw-vuln/srso.html for mitigation options.
Speculative Return Stack Overflow: Vulnerable: Safe RET, no microcode
x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
x86/fpu: Supporting XSAVE feature 0x020: 'AVX-512 opmask'
x86/fpu: Supporting XSAVE feature 0x040: 'AVX-512 Hi256'
x86/fpu: Supporting XSAVE feature 0x080: 'AVX-512 ZMM_Hi256'
x86/fpu: Supporting XSAVE feature 0x200: 'Protection Keys User registers'
x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256
x86/fpu: xstate_offset[5]: 832, xstate_sizes[5]: 64
x86/fpu: xstate_offset[6]: 896, xstate_sizes[6]: 512
x86/fpu: xstate_offset[7]: 1408, xstate_sizes[7]: 1024
x86/fpu: xstate_offset[9]: 2432, xstate_sizes[9]: 8
x86/fpu: Enabled xstate features 0x2e7, context size is 2440 bytes, using 'compacted' format.
debug: unmapping init [mem 0xffffffff883ea000-0xffffffff883f6fff]
pid_max: default: 32768 minimum: 301
LSM: initializing lsm=capability,bpf,ima
LSM support for eBPF active
Mount-cache hash table entries: 32768 (order: 6, 262144 bytes, linear)
Mountpoint-cache hash table entries: 32768 (order: 6, 262144 bytes, linear)
Running RCU synchronous self tests
Running RCU synchronous self tests
smpboot: CPU0: AMD EPYC-Milan Processor (family: 0x19, model: 0x1, stepping: 0x1)
psi: inconsistent task state! task=1:swapper/0 cpu=0 psi_flags=4 clear=0 set=4
Running RCU Tasks wait API self tests
Running RCU Tasks Rude wait API self tests
Running RCU Tasks Trace wait API self tests
Performance Events: Fam17h+ core perfctr, AMD PMU driver.
... version: 0
... bit width: 48
... generic registers: 6
... value mask: 0000ffffffffffff
... max period: 00007fffffffffff
... fixed-purpose events: 0
... event mask: 000000000000003f
Callback from call_rcu_tasks_trace() invoked.
signal: max sigframe size: 2976
rcu: Hierarchical SRCU implementation.
rcu: Max phase no-delay instances is 400.
Timer migration: 2 hierarchy levels; 8 children per group; 2 crossnode level
smp: Bringing up secondary CPUs ...
smpboot: x86: Booting SMP configuration:
.... node #0, CPUs: #1 #2 #3 #4 #5 #6 #7 #8 #9 #10 #11 #12 #13 #14 #15 #16
Callback from call_rcu_tasks() invoked.
#17 #18 #19
numa_add_cpu cpu 1 node 0: mask now 0-1
numa_add_cpu cpu 2 node 0: mask now 0-2
numa_add_cpu cpu 3 node 0: mask now 0-3
numa_add_cpu cpu 4 node 0: mask now 0-4
numa_add_cpu cpu 5 node 0: mask now 0-5
numa_add_cpu cpu 6 node 0: mask now 0-6
numa_add_cpu cpu 7 node 0: mask now 0-7
numa_add_cpu cpu 8 node 0: mask now 0-8
numa_add_cpu cpu 9 node 0: mask now 0-9
numa_add_cpu cpu 10 node 0: mask now 0-10
numa_add_cpu cpu 11 node 0: mask now 0-11
numa_add_cpu cpu 12 node 0: mask now 0-12
numa_add_cpu cpu 13 node 0: mask now 0-13
numa_add_cpu cpu 14 node 0: mask now 0-14
numa_add_cpu cpu 15 node 0: mask now 0-15
numa_add_cpu cpu 16 node 0: mask now 0-16
numa_add_cpu cpu 17 node 0: mask now 0-17
numa_add_cpu cpu 18 node 0: mask now 0-18
numa_add_cpu cpu 19 node 0: mask now 0-19
smp: Brought up 1 node, 20 CPUs
smpboot: Total of 20 processors activated (49565.36 BogoMIPS)
Memory: 8470476K/10485240K available (57344K kernel code, 19394K rwdata, 22616K rodata, 7488K init, 167972K bss, 1964852K reserved, 0K cma-reserved)
devtmpfs: initialized
x86/mm: Memory block size: 128MB
Running RCU synchronous self tests
Running RCU synchronous self tests
DMA-API: preallocated 65536 debug entries
DMA-API: debugging enabled by kernel config
clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
futex hash table entries: 8192 (order: 8, 1048576 bytes, linear)
pinctrl core: initialized pinctrl subsystem
NET: Registered PF_NETLINK/PF_ROUTE protocol family
audit: initializing netlink subsys (disabled)
audit: type=2000 audit(1728032147.986:1): state=initialized audit_enabled=0 res=1
thermal_sys: Registered thermal governor 'step_wise'
thermal_sys: Registered thermal governor 'user_space'
cpuidle: using governor menu
PCI: Using configuration type 1 for base access
PCI: Using configuration type 1 for extended access
kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible.
HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages
HugeTLB: 16380 KiB vmemmap can be freed for a 1.00 GiB page
HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages
HugeTLB: 28 KiB vmemmap can be freed for a 2.00 MiB page
cryptd: max_cpu_qlen set to 1000
raid6: avx512x4 gen() 33291 MB/s
raid6: avx512x2 gen() 32437 MB/s
raid6: avx512x1 gen() 25182 MB/s
raid6: avx2x4 gen() 22536 MB/s
raid6: avx2x2 gen() 19688 MB/s
raid6: avx2x1 gen() 15251 MB/s
raid6: using algorithm avx512x4 gen() 33291 MB/s
raid6: .... xor() 6618 MB/s, rmw enabled
raid6: using avx512x2 recovery algorithm
ACPI: Added _OSI(Module Device)
ACPI: Added _OSI(Processor Device)
ACPI: Added _OSI(3.0 _SCP Extensions)
ACPI: Added _OSI(Processor Aggregator Device)
ACPI: 1 ACPI AML tables successfully acquired and loaded
ACPI: Interpreter enabled
ACPI: PM: (supports S0 S3 S5)
ACPI: Using IOAPIC for interrupt routing
PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
PCI: Using E820 reservations for host bridge windows
ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
acpi PNP0A03:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI EDR HPX-Type3]
PCI host bridge to bus 0000:00
pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window]
pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window]
pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window]
pci_bus 0000:00: root bus resource [mem 0xc000000000-0xc07fffffff window]
pci_bus 0000:00: root bus resource [bus 00-ff]
pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 conventional PCI endpoint
pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 conventional PCI endpoint
pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 conventional PCI endpoint
pci 0000:00:01.1: BAR 4 [io 0xc060-0xc06f]
pci 0000:00:01.1: BAR 0 [io 0x01f0-0x01f7]: legacy IDE quirk
pci 0000:00:01.1: BAR 1 [io 0x03f6]: legacy IDE quirk
pci 0000:00:01.1: BAR 2 [io 0x0170-0x0177]: legacy IDE quirk
pci 0000:00:01.1: BAR 3 [io 0x0376]: legacy IDE quirk
pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 conventional PCI endpoint
pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI
pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB
pci 0000:00:02.0: [1af4:105a] type 00 class 0x018000 conventional PCI endpoint
pci 0000:00:02.0: BAR 1 [mem 0xfebc0000-0xfebc0fff]
pci 0000:00:02.0: BAR 4 [mem 0xc000000000-0xc000003fff 64bit pref]
pci 0000:00:03.0: [8086:25ab] type 00 class 0x088000 conventional PCI endpoint
pci 0000:00:03.0: BAR 0 [mem 0xfebc1000-0xfebc100f]
pci 0000:00:04.0: [1af4:1003] type 00 class 0x078000 conventional PCI endpoint
pci 0000:00:04.0: BAR 0 [io 0xc000-0xc03f]
pci 0000:00:04.0: BAR 1 [mem 0xfebc2000-0xfebc2fff]
pci 0000:00:04.0: BAR 4 [mem 0xc000004000-0xc000007fff 64bit pref]
pci 0000:00:05.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint
pci 0000:00:05.0: BAR 0 [io 0xc040-0xc05f]
pci 0000:00:05.0: BAR 1 [mem 0xfebc3000-0xfebc3fff]
pci 0000:00:05.0: BAR 4 [mem 0xc000008000-0xc00000bfff 64bit pref]
pci 0000:00:05.0: ROM [mem 0xfeb80000-0xfebbffff pref]
ACPI: PCI: Interrupt link LNKA configured for IRQ 10
ACPI: PCI: Interrupt link LNKB configured for IRQ 10
ACPI: PCI: Interrupt link LNKC configured for IRQ 11
ACPI: PCI: Interrupt link LNKD configured for IRQ 11
ACPI: PCI: Interrupt link LNKS configured for IRQ 9
iommu: Default domain type: Translated
iommu: DMA domain TLB invalidation policy: lazy mode
SCSI subsystem initialized
libata version 3.00 loaded.
ACPI: bus type USB registered
usbcore: registered new interface driver usbfs
usbcore: registered new interface driver hub
usbcore: registered new device driver usb
pps_core: LinuxPPS API ver. 1 registered
pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
PTP clock support registered
EDAC MC: Ver: 3.0.0
PCI: Using ACPI for IRQ routing
PCI: pci_cache_line_size set to 64 bytes
e820: reserve RAM buffer [mem 0x0009fc00-0x0009ffff]
e820: reserve RAM buffer [mem 0xbffe0000-0xbfffffff]
clocksource: Switched to clocksource tsc-early
VFS: Disk quotas dquot_6.6.0
VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
pnp: PnP ACPI init
pnp 00:02: [dma 2]
pnp: PnP ACPI: found 5 devices
clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
NET: Registered PF_INET protocol family
IP idents hash table entries: 262144 (order: 9, 2097152 bytes, linear)
tcp_listen_portaddr_hash hash table entries: 8192 (order: 7, 589824 bytes, linear)
Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)
TCP established hash table entries: 131072 (order: 8, 1048576 bytes, linear)
TCP bind hash table entries: 65536 (order: 11, 9437184 bytes, vmalloc hugepage)
TCP: Hash tables configured (established 131072 bind 65536)
MPTCP token hash table entries: 16384 (order: 8, 1441792 bytes, linear)
UDP hash table entries: 8192 (order: 8, 1310720 bytes, linear)
UDP-Lite hash table entries: 8192 (order: 8, 1310720 bytes, linear)
NET: Registered PF_UNIX/PF_LOCAL protocol family
NET: Registered PF_XDP protocol family
pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window]
pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window]
pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window]
pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window]
pci_bus 0000:00: resource 8 [mem 0xc000000000-0xc07fffffff window]
pci 0000:00:01.0: PIIX3: Enabling Passive Release
pci 0000:00:00.0: Limiting direct PCI/PCI transfers
PCI: CLS 0 bytes, default 64
PCI-DMA: Using software bounce buffering for IO (SWIOTLB)
software IO TLB: mapped [mem 0x00000000bb218000-0x00000000bf218000] (64MB)
Trying to unpack rootfs image as initramfs...
Initialise system trusted keyrings
workingset: timestamp_bits=40 max_order=22 bucket_order=0
fuse: init (API version 7.41)
SGI XFS with ACLs, security attributes, realtime, verbose warnings, quota, no debug enabled
NET: Registered PF_ALG protocol family
xor: automatically using best checksumming function avx
Key type asymmetric registered
Asymmetric key parser 'x509' registered
Block layer SCSI generic (bsg) driver version 0.4 loaded (major 243)
io scheduler mq-deadline registered
io scheduler kyber registered
debug: unmapping init [mem 0xff110000bf218000-0xff110000bffdffff]
ACPI: _SB_.LNKB: Enabled at IRQ 10
virtiofs virtio0: virtio_fs_setup_dax: No cache capability
ACPI: _SB_.LNKD: Enabled at IRQ 11
ACPI: _SB_.LNKA: Enabled at IRQ 10
Serial: 8250/16550 driver, 16 ports, IRQ sharing enabled
00:03: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
tsc: Refined TSC clocksource calibration: 1199.960 MHz
clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x114bf5f8779, max_idle_ns: 440795246166 ns
clocksource: Switched to clocksource tsc
printk: legacy console [hvc0] enabled
printk: legacy bootconsole [earlyser0] disabled
wireguard: WireGuard 1.0.0 loaded. See www.wireguard.com for information.
wireguard: Copyright (C) 2015-2019 Jason A. Donenfeld <Jason@zx2c4.com>. All Rights Reserved.
igb: Intel(R) Gigabit Ethernet Network Driver
igb: Copyright (c) 2007-2014 Intel Corporation.
ixgbe: Intel(R) 10 Gigabit PCI Express Network Driver
ixgbe: Copyright (c) 1999-2016 Intel Corporation.
usbcore: registered new interface driver ark3116
usbserial: USB Serial support registered for ark3116
usbcore: registered new interface driver pl2303
usbserial: USB Serial support registered for pl2303
i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
serio: i8042 KBD port at 0x60,0x64 irq 1
serio: i8042 AUX port at 0x60,0x64 irq 12
rtc_cmos 00:04: RTC can wake from S4
rtc_cmos 00:04: registered as rtc0
rtc_cmos 00:04: setting system clock to 2024-10-04T08:55:52 UTC (1728032152)
rtc_cmos 00:04: alarms up to one day, y3k, 242 bytes nvram, hpet irqs
input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0
i2c_dev: i2c /dev entries driver
device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log.
device-mapper: ioctl: 4.48.0-ioctl (2023-03-01) initialised: dm-devel@lists.linux.dev
amd_pstate: the _CPC object is not present in SBIOS or ACPI disabled
usbcore: registered new interface driver usbhid
usbhid: USB HID core driver
Initializing XFRM netlink socket
NET: Registered PF_INET6 protocol family
Segment Routing with IPv6
In-situ OAM (IOAM) with IPv6
NET: Registered PF_PACKET protocol family
Key type dns_resolver registered
NET: Registered PF_VSOCK protocol family
start plist test
end plist test
IPI shorthand broadcast: enabled
sched_clock: Marking stable (6385031761, -10224835)->(6687265139, -312458213)
registered taskstats version 1
Loading compiled-in X.509 certificates
virtme initramfs: initramfs does not have module crypto-pkcs1pad(rsa,sha512)
virtme initramfs: initramfs does not have module crypto-pkcs1pad(rsa,sha512)-all
Loaded X.509 cert 'Build time autogenerated kernel key: 1a58da0881b870ef3decd7cf414d45e41b0e363a'
Demotion targets for Node 0: null
kmemleak: Automatic memory scanning thread started
kmemleak: Kernel memory leak detector initialized (mem pool available: 197817)
page_owner is disabled
Btrfs loaded, assert=on, zoned=no, fsverity=yes
ima: No TPM chip found, activating TPM-bypass!
ima: Allocated hash algorithm: sha256
ima: No architecture policies found
netpoll: netconsole: local port 6666
netpoll: netconsole: local IPv6 address 2401:db00:3120:21a9:face:0:270:0
netpoll: netconsole: interface 'eth0'
netpoll: netconsole: remote port 1514
netpoll: netconsole: remote IPv6 address 2803:6080:a89c:a670::1
netpoll: netconsole: remote ethernet address 02:90:fb:66:aa:e5
netpoll: netconsole: device eth0 not up yet, forcing it
printk: legacy console [netcon_ext0] enabled
=====================================================
WARNING: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected
6.12.0-rc1-kbuilder-virtme-00033-gd4ac164bde7a #50 Not tainted
-----------------------------------------------------
swapper/0/1 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire:
ff1100010a260518 (_xmit_ETHER#2){+.-.}-{2:2}, at: virtnet_poll_tx (./include/linux/netdevice.h:4361 drivers/net/virtio_net.c:2969)
and this task is already holding:
ffffffff86f2b5b8 (target_list_lock){....}-{2:2}, at: write_ext_msg (drivers/net/netconsole.c:?)
which would create a new lock dependency:
(target_list_lock){....}-{2:2} -> (_xmit_ETHER#2){+.-.}-{2:2}
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_single (kernel/irq_work.c:222)
irq_work_tick (kernel/irq_work.c:? kernel/irq_work.c:277)
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)
memset (arch/x86/lib/memset_64.S:38)
__unwind_start (arch/x86/kernel/unwind_orc.c:?)
arch_stack_walk (./arch/x86/include/asm/unwind.h:50 arch/x86/kernel/stacktrace.c:24)
stack_trace_save (kernel/stacktrace.c:123)
kasan_save_stack (mm/kasan/common.c:48)
__kasan_record_aux_stack (mm/kasan/generic.c:541)
call_rcu (./arch/x86/include/asm/irqflags.h:26 ./arch/x86/include/asm/irqflags.h:87 ./arch/x86/include/asm/irqflags.h:123 kernel/rcu/tree.c:3087 kernel/rcu/tree.c:3190)
kfree (mm/slub.c:2271 mm/slub.c:4580 mm/slub.c:4728)
__kthread_create_on_node (kernel/kthread.c:479)
__kthread_create_worker (kernel/kthread.c:882)
kthread_create_worker (kernel/kthread.c:919)
wq_cpu_intensive_thresh_init (kernel/workqueue.c:7817)
workqueue_init (kernel/workqueue.c:?)
kernel_init_freeable (init/main.c:1566)
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)
to a HARDIRQ-irq-unsafe lock:
(_xmit_ETHER#2){+.-.}-{2:2}
... 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/netdevice.h:4384 drivers/net/virtio_net.c:2768 drivers/net/virtio_net.c:2821)
__napi_poll (net/core/dev.c:6771)
net_rx_action (net/core/dev.c:6840 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 (./include/linux/bottom_half.h:? drivers/net/virtio_net.c:2619 drivers/net/virtio_net.c:2876 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:1582)
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:
Chain exists of:
console_owner --> target_list_lock --> _xmit_ETHER#2
Possible interrupt unsafe locking scenario:
CPU0 CPU1
---- ----
lock(_xmit_ETHER#2);
local_irq_disable();
lock(console_owner);
lock(target_list_lock);
<Interrupt>
lock(console_owner);
*** DEADLOCK ***
6 locks held by swapper/0/1:
#0: ffffffff861afda8 (console_mutex){+.+.}-{3:3}, at: register_console (kernel/printk/printk.c:113 kernel/printk/printk.c:3933)
#1: ffffffff861b0400 (console_lock){+.+.}-{0:0}, at: _printk (kernel/printk/printk.c:2435)
#2: ffffffff861afe10 (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: ffffffff861b03a0 (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: ffffffff86930cc0 (printk_legacy_map-wait-type-override){....}-{3:3}, at: console_flush_all (./include/linux/rcupdate.h:? ./include/linux/srcu.h:267 kernel/printk/printk.c:288 kernel/printk/printk.c:3157)
#5: ffffffff86f2b5b8 (target_list_lock){....}-{2:2}, at: write_ext_msg (drivers/net/netconsole.c:?)
the dependencies between HARDIRQ-irq-safe lock and the holding lock:
-> (console_owner){-...}-{0:0} ops: 1984 {
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_single (kernel/irq_work.c:222)
irq_work_tick (kernel/irq_work.c:? kernel/irq_work.c:277)
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)
memset (arch/x86/lib/memset_64.S:38)
__unwind_start (arch/x86/kernel/unwind_orc.c:?)
arch_stack_walk (./arch/x86/include/asm/unwind.h:50 arch/x86/kernel/stacktrace.c:24)
stack_trace_save (kernel/stacktrace.c:123)
kasan_save_stack (mm/kasan/common.c:48)
__kasan_record_aux_stack (mm/kasan/generic.c:541)
call_rcu (./arch/x86/include/asm/irqflags.h:26 ./arch/x86/include/asm/irqflags.h:87 ./arch/x86/include/asm/irqflags.h:123 kernel/rcu/tree.c:3087 kernel/rcu/tree.c:3190)
kfree (mm/slub.c:2271 mm/slub.c:4580 mm/slub.c:4728)
__kthread_create_on_node (kernel/kthread.c:479)
__kthread_create_worker (kernel/kthread.c:882)
kthread_create_worker (kernel/kthread.c:919)
wq_cpu_intensive_thresh_init (kernel/workqueue.c:7817)
workqueue_init (kernel/workqueue.c:?)
kernel_init_freeable (init/main.c:1566)
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:
}
... key at: console_owner_dep_map+0x0/0x60
-> (target_list_lock){....}-{2:2} ops: 3 {
INITIAL USE at:
lock_acquire (kernel/locking/lockdep.c:5825)
_raw_spin_lock_irqsave (./include/linux/spinlock_api_smp.h:110 kernel/locking/spinlock.c:162)
init_netconsole (drivers/net/netconsole.c:1327)
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:1582)
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: target_list_lock+0x18/0x60
... acquired at:
lock_acquire (kernel/locking/lockdep.c:5825)
_raw_spin_lock_irqsave (./include/linux/spinlock_api_smp.h:110 kernel/locking/spinlock.c:162)
write_ext_msg (drivers/net/netconsole.c:?)
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:1582)
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)
the dependencies between the lock to be acquired
and HARDIRQ-irq-unsafe lock:
-> (_xmit_ETHER#2){+.-.}-{2:2} ops: 7 {
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/netdevice.h:4384 drivers/net/virtio_net.c:2768 drivers/net/virtio_net.c:2821)
__napi_poll (net/core/dev.c:6771)
net_rx_action (net/core/dev.c:6840 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 (./include/linux/bottom_half.h:? drivers/net/virtio_net.c:2619 drivers/net/virtio_net.c:2876 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:1582)
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 (net/core/dev.c:6771)
net_rx_action (net/core/dev.c:6840 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:2637 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:1582)
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/netdevice.h:4384 drivers/net/virtio_net.c:2768 drivers/net/virtio_net.c:2821)
__napi_poll (net/core/dev.c:6771)
net_rx_action (net/core/dev.c:6840 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 (./include/linux/bottom_half.h:? drivers/net/virtio_net.c:2619 drivers/net/virtio_net.c:2876 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:1582)
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/0x480
... acquired 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)
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:?)
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:1582)
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)
validate_chain (kernel/locking/lockdep.c:? kernel/locking/lockdep.c:2888 kernel/locking/lockdep.c:3165 kernel/locking/lockdep.c:3280 kernel/locking/lockdep.c:3904)
__lock_acquire (kernel/locking/lockdep.c:?)
lock_acquire (kernel/locking/lockdep.c:5825)
? virtnet_poll_tx (./include/linux/netdevice.h:4361 drivers/net/virtio_net.c:2969)
_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)
? srso_alias_return_thunk (arch/x86/lib/retpoline.S:182)
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:?)
? srso_alias_return_thunk (arch/x86/lib/retpoline.S:182)
? 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 (./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:?)
? srso_alias_return_thunk (arch/x86/lib/retpoline.S:182)
_printk (kernel/printk/printk.c:2435)
? srso_alias_return_thunk (arch/x86/lib/retpoline.S:182)
register_console (kernel/printk/printk.c:4070)
? configfs_register_subsystem (./include/linux/instrumented.h:96 ./include/linux/atomic/atomic-arch-fallback.h:2278 ./include/linux/atomic/atomic-instrumented.h:1384 fs/configfs/dir.c:174 fs/configfs/dir.c:1909)
init_netconsole (drivers/net/netconsole.c:1344)
? srso_alias_return_thunk (arch/x86/lib/retpoline.S:182)
do_one_initcall (init/main.c:1269)
? __pfx_init_netconsole (drivers/net/netconsole.c:1301)
? stack_depot_save_flags (lib/stackdepot.c:662)
? srso_alias_return_thunk (arch/x86/lib/retpoline.S:182)
? kasan_save_track (./arch/x86/include/asm/current.h:49 mm/kasan/common.c:60 mm/kasan/common.c:69)
? kasan_save_track (mm/kasan/common.c:48 mm/kasan/common.c:68)
? __kasan_kmalloc (mm/kasan/common.c:398)
? __kmalloc_noprof (./include/linux/kasan.h:257 mm/slub.c:4265 mm/slub.c:4277)
? do_initcalls (init/main.c:1341)
? kernel_init_freeable (init/main.c:1582)
? 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)
? asm_sysvec_apic_timer_interrupt (./arch/x86/include/asm/idtentry.h:702)
? srso_alias_return_thunk (arch/x86/lib/retpoline.S:182)
? lockdep_hardirqs_on (kernel/locking/lockdep.c:4471)
? srso_alias_return_thunk (arch/x86/lib/retpoline.S:182)
? asm_sysvec_apic_timer_interrupt (./arch/x86/include/asm/idtentry.h:702)
? __pfx_ignore_unknown_bootoption (init/main.c:1315)
? srso_alias_return_thunk (arch/x86/lib/retpoline.S:182)
? srso_alias_return_thunk (arch/x86/lib/retpoline.S:182)
? parse_args (kernel/params.c:153 kernel/params.c:186)
? srso_alias_return_thunk (arch/x86/lib/retpoline.S:182)
? rcu_is_watching (./include/linux/context_tracking.h:128 kernel/rcu/tree.c:737)
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:1582)
? __pfx_kernel_init (init/main.c:1461)
kernel_init (init/main.c:1471)
ret_from_fork (arch/x86/kernel/process.c:153)
? __pfx_kernel_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
clk: Disabling unused clocks
Thanks
--breno
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 6.12-rc1: Lockdep regression bissected (virtio-net/console/scheduler)
2024-10-04 9:08 ` Breno Leitao
@ 2024-10-04 10:49 ` Petr Mladek
2024-10-08 15:18 ` John Ogness
0 siblings, 1 reply; 9+ messages in thread
From: Petr Mladek @ 2024-10-04 10:49 UTC (permalink / raw)
To: Breno Leitao
Cc: Peter Zijlstra, gregkh, mst, jasowang, xuanzhuo, kuba,
virtualization, netdev, linux-kernel, vschneid, axboe,
Breno Leitao, Heng Qi
Hi,
I am adding into Cc some people who were involved in a netdev commits
which might be related, see below.
Also adding John Ogness into Cc who was author of the new changes on
the printk side. But it looks to me that the problem is not caused by
the recent printk changes.
Also I keep the entire context for these new people.
On Fri 2024-10-04 02:08:52, Breno Leitao wrote:
> Hello Peter,
>
> On Thu, Oct 03, 2024 at 08:41:53AM -0700, Breno Leitao wrote:
> > > > 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")
> > >
> > > This looks like the normal lockdep splat you get when the scheduler does
> > > printk. I suspect you tripped a WARN, but since you only provided the
> > > lockdep output and not the whole log, I cannot tell.
> >
> > Thanks for the quick answer. I didn't see a warning before the lockdep
> > splat, at least in the usual way I am familiar with. Let me past the
> > full log below.
> >
> > > There is a fix in:
> > >
> > > git://git.kernel.org/pub/scm/linux/kernel/git/peterz/queue.git sched/urgent
> > >
> > > that might, or might not help. I can't tell.
> >
> > Thanks. I will try it soon.
>
> I've just tested your branch "sched/urgent", and the problem is still
> there. I've tested against:
>
> d4ac164bde7a ("sched/eevdf: Fix wakeup-preempt by checking cfs_rq->nr_running")
>
> Here is the full log:
>
> Linux version 6.12.0-rc1-kbuilder-virtme-00033-gd4ac164bde7a (leit@devvm32600.lla0.foo.com) (clang version 20.0.0git (https://github.com/llvm/llvm-project.git d0f67773b213383b6e1c9331fb00f2d4c14bfcb2), LLD 18.0.0) #50 SMP PREEMPT_DYNAMIC Fri Oct 4 01:54:44 PDT 2024
> Command line: virtme_hostname=virtme-ng nr_open=2500000 virtme_link_mods=/home/leit/Devel/upstream/.virtme_mods/lib/modules/0.0.0 console=hvc0 earlyprintk=serial,ttyS0,115200 virtme_console=ttyS0 psmouse.proto=exps "virtme_stty_con=rows 43 cols 235 iutf8" TERM=xterm-256color virtme.dhcp net.ifnames=0 biosdevname=0 virtme_chdir=home/leit/Devel/upstream netconsole=+6666@2401:db00:3120:21a9:face:0000:0270:0000/eth0,1514@2803:6080:a89c:a670::1/02:90:fb:66:aa:e5 init=/home/leit/venv/lib/python3.8/site-packages/virtme/guest/bin/virtme-ng-init
> BIOS-provided physical RAM map:
> BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
> BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
> BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
> BIOS-e820: [mem 0x0000000000100000-0x00000000bffdffff] usable
> BIOS-e820: [mem 0x00000000bffe0000-0x00000000bfffffff] reserved
> BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved
> BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
> BIOS-e820: [mem 0x0000000100000000-0x00000002bfffffff] usable
> BIOS-e820: [mem 0x000000fd00000000-0x000000ffffffffff] reserved
> printk: legacy bootconsole [earlyser0] enabled
> NX (Execute Disable) protection: active
> APIC: Static calls initialized
> SMBIOS 2.8 present.
> DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.16.3-0-ga6ed6b701f0a-prebuilt.qemu.org 04/01/2014
> DMI: Memory slots populated: 1/1
> e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
> e820: remove [mem 0x000a0000-0x000fffff] usable
> last_pfn = 0x2c0000 max_arch_pfn = 0x10000000000
> MTRR map: 4 entries (3 fixed + 1 variable; max 19), built from 8 variable MTRRs
> x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT
> last_pfn = 0xbffe0 max_arch_pfn = 0x10000000000
> found SMP MP-table at [mem 0x000f5470-0x000f547f]
> RAMDISK: [mem 0xbf218000-0xbffdffff]
> ACPI: Early table checksum verification disabled
> ACPI: RSDP 0x00000000000F5270 000014 (v00 BOCHS )
> ACPI: RSDT 0x00000000BFFE2C55 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001)
> ACPI: FACP 0x00000000BFFE2889 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001)
> ACPI: DSDT 0x00000000BFFE0040 002849 (v01 BOCHS BXPC 00000001 BXPC 00000001)
> ACPI: FACS 0x00000000BFFE0000 000040
> ACPI: APIC 0x00000000BFFE28FD 000110 (v03 BOCHS BXPC 00000001 BXPC 00000001)
> ACPI: HPET 0x00000000BFFE2A0D 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001)
> ACPI: SRAT 0x00000000BFFE2A45 0001E8 (v01 BOCHS BXPC 00000001 BXPC 00000001)
> ACPI: WAET 0x00000000BFFE2C2D 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001)
> ACPI: Reserving FACP table memory at [mem 0xbffe2889-0xbffe28fc]
> ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2888]
> ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f]
> ACPI: Reserving APIC table memory at [mem 0xbffe28fd-0xbffe2a0c]
> ACPI: Reserving HPET table memory at [mem 0xbffe2a0d-0xbffe2a44]
> ACPI: Reserving SRAT table memory at [mem 0xbffe2a45-0xbffe2c2c]
> ACPI: Reserving WAET table memory at [mem 0xbffe2c2d-0xbffe2c54]
> ACPI: SRAT: Node 0 PXM 0 [mem 0x00000000-0x0009ffff]
> ACPI: SRAT: Node 0 PXM 0 [mem 0x00100000-0xbfffffff]
> ACPI: SRAT: Node 0 PXM 0 [mem 0x100000000-0x2bfffffff]
> NUMA: Node 0 [mem 0x00001000-0x0009ffff] + [mem 0x00100000-0xbfffffff] -> [mem 0x00001000-0xbfffffff]
> NUMA: Node 0 [mem 0x00001000-0xbfffffff] + [mem 0x100000000-0x2bfffffff] -> [mem 0x00001000-0x2bfffffff]
> NODE_DATA(0) allocated [mem 0x2bebf6ac0-0x2bebfbdff]
> Zone ranges:
> DMA [mem 0x0000000000001000-0x0000000000ffffff]
> DMA32 [mem 0x0000000001000000-0x00000000ffffffff]
> Normal [mem 0x0000000100000000-0x00000002bfffffff]
> Device empty
> Movable zone start for each node
> Early memory node ranges
> node 0: [mem 0x0000000000001000-0x000000000009efff]
> node 0: [mem 0x0000000000100000-0x00000000bffdffff]
> node 0: [mem 0x0000000100000000-0x00000002bfffffff]
> Initmem setup node 0 [mem 0x0000000000001000-0x00000002bfffffff]
> On node 0, zone DMA: 1 pages in unavailable ranges
> On node 0, zone DMA: 97 pages in unavailable ranges
> On node 0, zone Normal: 32 pages in unavailable ranges
> kasan: KernelAddressSanitizer initialized
> ACPI: PM-Timer IO Port: 0x608
> ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
> IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
> ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
> ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
> ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
> ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
> ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
> ACPI: Using ACPI (MADT) for SMP configuration information
> ACPI: HPET id: 0x8086a201 base: 0xfed00000
> TSC deadline timer available
> CPU topo: Max. logical packages: 1
> CPU topo: Max. logical dies: 1
> CPU topo: Max. dies per package: 1
> CPU topo: Max. threads per core: 1
> CPU topo: Num. cores per package: 20
> CPU topo: Num. threads per package: 20
> CPU topo: Allowing 20 present CPUs plus 0 hotplug CPUs
> [mem 0xc0000000-0xfeffbfff] available for PCI devices
> clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
> setup_percpu: NR_CPUS:512 nr_cpumask_bits:20 nr_cpu_ids:20 nr_node_ids:1
> percpu: Embedded 89 pages/cpu s326416 r8192 d29936 u524288
> pcpu-alloc: s326416 r8192 d29936 u524288 alloc=1*2097152
> pcpu-alloc: [0] 00 01 02 03 [0] 04 05 06 07
> pcpu-alloc: [0] 08 09 10 11 [0] 12 13 14 15
> pcpu-alloc: [0] 16 17 18 19
> Kernel command line: virtme_hostname=virtme-ng nr_open=2500000 virtme_link_mods=/home/leit/Devel/upstream/.virtme_mods/lib/modules/0.0.0 console=hvc0 earlyprintk=serial,ttyS0,115200 virtme_console=ttyS0 psmouse.proto=exps "virtme_stty_con=rows 43 cols 235 iutf8" TERM=xterm-256color virtme.dhcp net.ifnames=0 biosdevname=0 virtme_chdir=home/leit/Devel/upstream netconsole=+6666@2401:db00:3120:21a9:face:0000:0270:0000/eth0,1514@2803:6080:a89c:a670::1/02:90:fb:66:aa:e5 init=/home/leit/venv/lib/python3.8/site-packages/virtme/guest/bin/virtme-ng-init
> Unknown kernel command line parameters "virtme_hostname=virtme-ng nr_open=2500000 virtme_link_mods=/home/leit/Devel/upstream/.virtme_mods/lib/modules/0.0.0 virtme_console=ttyS0 virtme_stty_con=rows 43 cols 235 iutf8 biosdevname=0 virtme_chdir=home/leit/Devel/upstream", will be passed to user space.
> random: crng init done
> Dentry cache hash table entries: 2097152 (order: 12, 16777216 bytes, linear)
> Inode-cache hash table entries: 1048576 (order: 11, 8388608 bytes, linear)
> Fallback order for Node 0: 0
> Built 1 zonelists, mobility grouping on. Total pages: 2621310
> Policy zone: Normal
> mem auto-init: stack:off, heap alloc:off, heap free:off
> stackdepot: allocating hash table via alloc_large_system_hash
> stackdepot hash table entries: 1048576 (order: 12, 16777216 bytes, linear)
> software IO TLB: area num 32.
> SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=20, Nodes=1
> allocated 20971520 bytes of page_ext
> ftrace: allocating 58899 entries in 231 pages
> ftrace: allocated 231 pages with 6 groups
> Dynamic Preempt: none
> Running RCU self tests
> Running RCU synchronous self tests
> rcu: Preemptible hierarchical RCU implementation.
> rcu: RCU event tracing is enabled.
> rcu: RCU lockdep checking is enabled.
> rcu: RCU restricting CPUs from NR_CPUS=512 to nr_cpu_ids=20.
> rcu: RCU callback double-/use-after-free debug is enabled.
> rcu: RCU debug extended QS entry/exit.
> Trampoline variant of Tasks RCU enabled.
> Rude variant of Tasks RCU enabled.
> Tracing variant of Tasks RCU enabled.
> rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies.
> rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=20
> Running RCU synchronous self tests
> RCU Tasks: Setting shift to 5 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=20.
> RCU Tasks Rude: Setting shift to 5 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=20.
> RCU Tasks Trace: Setting shift to 5 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=20.
> NR_IRQS: 33024, nr_irqs: 584, preallocated irqs: 16
> rcu: srcu_init: Setting srcu_struct sizes based on contention.
> kfence: initialized - using 2097152 bytes for 255 objects at 0x(____ptrval____)-0x(____ptrval____)
> Console: colour *CGA 80x25
> Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
> ... MAX_LOCKDEP_SUBCLASSES: 8
> ... MAX_LOCK_DEPTH: 48
> ... MAX_LOCKDEP_KEYS: 8192
> ... CLASSHASH_SIZE: 4096
> ... MAX_LOCKDEP_ENTRIES: 1048576
> ... MAX_LOCKDEP_CHAINS: 1048576
> ... CHAINHASH_SIZE: 524288
> memory used by lock dependency info: 106625 kB
> memory used for stack traces: 4224 kB
> per task-struct memory footprint: 1920 bytes
> ACPI: Core revision 20240827
> clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns
> APIC: Switch to symmetric I/O mode setup
> ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
> tsc: Unable to calibrate against PIT
> tsc: using HPET reference calibration
> tsc: Detected 1199.814 MHz processor
> clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x114b6c033ac, max_idle_ns: 440795260201 ns
> Calibrating delay loop (skipped), value calculated using timer frequency.. 2399.62 BogoMIPS (lpj=1199814)
> x86/cpu: User Mode Instruction Prevention (UMIP) activated
> numa_add_cpu cpu 0 node 0: mask now 0
> Last level iTLB entries: 4KB 512, 2MB 255, 4MB 127
> Last level dTLB entries: 4KB 512, 2MB 255, 4MB 127, 1GB 0
> Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization
> Spectre V2 : Mitigation: Retpolines
> Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch
> Spectre V2 : Spectre v2 / SpectreRSB : Filling RSB on VMEXIT
> Spectre V2 : Enabling Restricted Speculation for firmware calls
> Spectre V2 : mitigation: Enabling conditional Indirect Branch Prediction Barrier
> Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl
> Speculative Return Stack Overflow: IBPB-extending microcode not applied!
> Speculative Return Stack Overflow: WARNING: See https://kernel.org/doc/html/latest/admin-guide/hw-vuln/srso.html for mitigation options.
> Speculative Return Stack Overflow: Vulnerable: Safe RET, no microcode
> x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
> x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
> x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
> x86/fpu: Supporting XSAVE feature 0x020: 'AVX-512 opmask'
> x86/fpu: Supporting XSAVE feature 0x040: 'AVX-512 Hi256'
> x86/fpu: Supporting XSAVE feature 0x080: 'AVX-512 ZMM_Hi256'
> x86/fpu: Supporting XSAVE feature 0x200: 'Protection Keys User registers'
> x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256
> x86/fpu: xstate_offset[5]: 832, xstate_sizes[5]: 64
> x86/fpu: xstate_offset[6]: 896, xstate_sizes[6]: 512
> x86/fpu: xstate_offset[7]: 1408, xstate_sizes[7]: 1024
> x86/fpu: xstate_offset[9]: 2432, xstate_sizes[9]: 8
> x86/fpu: Enabled xstate features 0x2e7, context size is 2440 bytes, using 'compacted' format.
> debug: unmapping init [mem 0xffffffff883ea000-0xffffffff883f6fff]
> pid_max: default: 32768 minimum: 301
> LSM: initializing lsm=capability,bpf,ima
> LSM support for eBPF active
> Mount-cache hash table entries: 32768 (order: 6, 262144 bytes, linear)
> Mountpoint-cache hash table entries: 32768 (order: 6, 262144 bytes, linear)
> Running RCU synchronous self tests
> Running RCU synchronous self tests
> smpboot: CPU0: AMD EPYC-Milan Processor (family: 0x19, model: 0x1, stepping: 0x1)
> psi: inconsistent task state! task=1:swapper/0 cpu=0 psi_flags=4 clear=0 set=4
> Running RCU Tasks wait API self tests
> Running RCU Tasks Rude wait API self tests
> Running RCU Tasks Trace wait API self tests
> Performance Events: Fam17h+ core perfctr, AMD PMU driver.
> ... version: 0
> ... bit width: 48
> ... generic registers: 6
> ... value mask: 0000ffffffffffff
> ... max period: 00007fffffffffff
> ... fixed-purpose events: 0
> ... event mask: 000000000000003f
> Callback from call_rcu_tasks_trace() invoked.
> signal: max sigframe size: 2976
> rcu: Hierarchical SRCU implementation.
> rcu: Max phase no-delay instances is 400.
> Timer migration: 2 hierarchy levels; 8 children per group; 2 crossnode level
> smp: Bringing up secondary CPUs ...
> smpboot: x86: Booting SMP configuration:
> .... node #0, CPUs: #1 #2 #3 #4 #5 #6 #7 #8 #9 #10 #11 #12 #13 #14 #15 #16
> Callback from call_rcu_tasks() invoked.
> #17 #18 #19
> numa_add_cpu cpu 1 node 0: mask now 0-1
> numa_add_cpu cpu 2 node 0: mask now 0-2
> numa_add_cpu cpu 3 node 0: mask now 0-3
> numa_add_cpu cpu 4 node 0: mask now 0-4
> numa_add_cpu cpu 5 node 0: mask now 0-5
> numa_add_cpu cpu 6 node 0: mask now 0-6
> numa_add_cpu cpu 7 node 0: mask now 0-7
> numa_add_cpu cpu 8 node 0: mask now 0-8
> numa_add_cpu cpu 9 node 0: mask now 0-9
> numa_add_cpu cpu 10 node 0: mask now 0-10
> numa_add_cpu cpu 11 node 0: mask now 0-11
> numa_add_cpu cpu 12 node 0: mask now 0-12
> numa_add_cpu cpu 13 node 0: mask now 0-13
> numa_add_cpu cpu 14 node 0: mask now 0-14
> numa_add_cpu cpu 15 node 0: mask now 0-15
> numa_add_cpu cpu 16 node 0: mask now 0-16
> numa_add_cpu cpu 17 node 0: mask now 0-17
> numa_add_cpu cpu 18 node 0: mask now 0-18
> numa_add_cpu cpu 19 node 0: mask now 0-19
> smp: Brought up 1 node, 20 CPUs
> smpboot: Total of 20 processors activated (49565.36 BogoMIPS)
> Memory: 8470476K/10485240K available (57344K kernel code, 19394K rwdata, 22616K rodata, 7488K init, 167972K bss, 1964852K reserved, 0K cma-reserved)
> devtmpfs: initialized
> x86/mm: Memory block size: 128MB
> Running RCU synchronous self tests
> Running RCU synchronous self tests
> DMA-API: preallocated 65536 debug entries
> DMA-API: debugging enabled by kernel config
> clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
> futex hash table entries: 8192 (order: 8, 1048576 bytes, linear)
> pinctrl core: initialized pinctrl subsystem
> NET: Registered PF_NETLINK/PF_ROUTE protocol family
> audit: initializing netlink subsys (disabled)
> audit: type=2000 audit(1728032147.986:1): state=initialized audit_enabled=0 res=1
> thermal_sys: Registered thermal governor 'step_wise'
> thermal_sys: Registered thermal governor 'user_space'
> cpuidle: using governor menu
> PCI: Using configuration type 1 for base access
> PCI: Using configuration type 1 for extended access
> kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible.
> HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages
> HugeTLB: 16380 KiB vmemmap can be freed for a 1.00 GiB page
> HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages
> HugeTLB: 28 KiB vmemmap can be freed for a 2.00 MiB page
> cryptd: max_cpu_qlen set to 1000
> raid6: avx512x4 gen() 33291 MB/s
> raid6: avx512x2 gen() 32437 MB/s
> raid6: avx512x1 gen() 25182 MB/s
> raid6: avx2x4 gen() 22536 MB/s
> raid6: avx2x2 gen() 19688 MB/s
> raid6: avx2x1 gen() 15251 MB/s
> raid6: using algorithm avx512x4 gen() 33291 MB/s
> raid6: .... xor() 6618 MB/s, rmw enabled
> raid6: using avx512x2 recovery algorithm
> ACPI: Added _OSI(Module Device)
> ACPI: Added _OSI(Processor Device)
> ACPI: Added _OSI(3.0 _SCP Extensions)
> ACPI: Added _OSI(Processor Aggregator Device)
> ACPI: 1 ACPI AML tables successfully acquired and loaded
> ACPI: Interpreter enabled
> ACPI: PM: (supports S0 S3 S5)
> ACPI: Using IOAPIC for interrupt routing
> PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
> PCI: Using E820 reservations for host bridge windows
> ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
> acpi PNP0A03:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI EDR HPX-Type3]
> PCI host bridge to bus 0000:00
> pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window]
> pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window]
> pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
> pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window]
> pci_bus 0000:00: root bus resource [mem 0xc000000000-0xc07fffffff window]
> pci_bus 0000:00: root bus resource [bus 00-ff]
> pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 conventional PCI endpoint
> pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 conventional PCI endpoint
> pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 conventional PCI endpoint
> pci 0000:00:01.1: BAR 4 [io 0xc060-0xc06f]
> pci 0000:00:01.1: BAR 0 [io 0x01f0-0x01f7]: legacy IDE quirk
> pci 0000:00:01.1: BAR 1 [io 0x03f6]: legacy IDE quirk
> pci 0000:00:01.1: BAR 2 [io 0x0170-0x0177]: legacy IDE quirk
> pci 0000:00:01.1: BAR 3 [io 0x0376]: legacy IDE quirk
> pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 conventional PCI endpoint
> pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI
> pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB
> pci 0000:00:02.0: [1af4:105a] type 00 class 0x018000 conventional PCI endpoint
> pci 0000:00:02.0: BAR 1 [mem 0xfebc0000-0xfebc0fff]
> pci 0000:00:02.0: BAR 4 [mem 0xc000000000-0xc000003fff 64bit pref]
> pci 0000:00:03.0: [8086:25ab] type 00 class 0x088000 conventional PCI endpoint
> pci 0000:00:03.0: BAR 0 [mem 0xfebc1000-0xfebc100f]
> pci 0000:00:04.0: [1af4:1003] type 00 class 0x078000 conventional PCI endpoint
> pci 0000:00:04.0: BAR 0 [io 0xc000-0xc03f]
> pci 0000:00:04.0: BAR 1 [mem 0xfebc2000-0xfebc2fff]
> pci 0000:00:04.0: BAR 4 [mem 0xc000004000-0xc000007fff 64bit pref]
> pci 0000:00:05.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint
> pci 0000:00:05.0: BAR 0 [io 0xc040-0xc05f]
> pci 0000:00:05.0: BAR 1 [mem 0xfebc3000-0xfebc3fff]
> pci 0000:00:05.0: BAR 4 [mem 0xc000008000-0xc00000bfff 64bit pref]
> pci 0000:00:05.0: ROM [mem 0xfeb80000-0xfebbffff pref]
> ACPI: PCI: Interrupt link LNKA configured for IRQ 10
> ACPI: PCI: Interrupt link LNKB configured for IRQ 10
> ACPI: PCI: Interrupt link LNKC configured for IRQ 11
> ACPI: PCI: Interrupt link LNKD configured for IRQ 11
> ACPI: PCI: Interrupt link LNKS configured for IRQ 9
> iommu: Default domain type: Translated
> iommu: DMA domain TLB invalidation policy: lazy mode
> SCSI subsystem initialized
> libata version 3.00 loaded.
> ACPI: bus type USB registered
> usbcore: registered new interface driver usbfs
> usbcore: registered new interface driver hub
> usbcore: registered new device driver usb
> pps_core: LinuxPPS API ver. 1 registered
> pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
> PTP clock support registered
> EDAC MC: Ver: 3.0.0
> PCI: Using ACPI for IRQ routing
> PCI: pci_cache_line_size set to 64 bytes
> e820: reserve RAM buffer [mem 0x0009fc00-0x0009ffff]
> e820: reserve RAM buffer [mem 0xbffe0000-0xbfffffff]
> clocksource: Switched to clocksource tsc-early
> VFS: Disk quotas dquot_6.6.0
> VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
> pnp: PnP ACPI init
> pnp 00:02: [dma 2]
> pnp: PnP ACPI: found 5 devices
> clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
> NET: Registered PF_INET protocol family
> IP idents hash table entries: 262144 (order: 9, 2097152 bytes, linear)
> tcp_listen_portaddr_hash hash table entries: 8192 (order: 7, 589824 bytes, linear)
> Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)
> TCP established hash table entries: 131072 (order: 8, 1048576 bytes, linear)
> TCP bind hash table entries: 65536 (order: 11, 9437184 bytes, vmalloc hugepage)
> TCP: Hash tables configured (established 131072 bind 65536)
> MPTCP token hash table entries: 16384 (order: 8, 1441792 bytes, linear)
> UDP hash table entries: 8192 (order: 8, 1310720 bytes, linear)
> UDP-Lite hash table entries: 8192 (order: 8, 1310720 bytes, linear)
> NET: Registered PF_UNIX/PF_LOCAL protocol family
> NET: Registered PF_XDP protocol family
> pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window]
> pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window]
> pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window]
> pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window]
> pci_bus 0000:00: resource 8 [mem 0xc000000000-0xc07fffffff window]
> pci 0000:00:01.0: PIIX3: Enabling Passive Release
> pci 0000:00:00.0: Limiting direct PCI/PCI transfers
> PCI: CLS 0 bytes, default 64
> PCI-DMA: Using software bounce buffering for IO (SWIOTLB)
> software IO TLB: mapped [mem 0x00000000bb218000-0x00000000bf218000] (64MB)
> Trying to unpack rootfs image as initramfs...
> Initialise system trusted keyrings
> workingset: timestamp_bits=40 max_order=22 bucket_order=0
> fuse: init (API version 7.41)
> SGI XFS with ACLs, security attributes, realtime, verbose warnings, quota, no debug enabled
> NET: Registered PF_ALG protocol family
> xor: automatically using best checksumming function avx
> Key type asymmetric registered
> Asymmetric key parser 'x509' registered
> Block layer SCSI generic (bsg) driver version 0.4 loaded (major 243)
> io scheduler mq-deadline registered
> io scheduler kyber registered
> debug: unmapping init [mem 0xff110000bf218000-0xff110000bffdffff]
> ACPI: _SB_.LNKB: Enabled at IRQ 10
> virtiofs virtio0: virtio_fs_setup_dax: No cache capability
> ACPI: _SB_.LNKD: Enabled at IRQ 11
> ACPI: _SB_.LNKA: Enabled at IRQ 10
> Serial: 8250/16550 driver, 16 ports, IRQ sharing enabled
> 00:03: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
> tsc: Refined TSC clocksource calibration: 1199.960 MHz
> clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x114bf5f8779, max_idle_ns: 440795246166 ns
> clocksource: Switched to clocksource tsc
> printk: legacy console [hvc0] enabled
> printk: legacy bootconsole [earlyser0] disabled
> wireguard: WireGuard 1.0.0 loaded. See www.wireguard.com for information.
> wireguard: Copyright (C) 2015-2019 Jason A. Donenfeld <Jason@zx2c4.com>. All Rights Reserved.
> igb: Intel(R) Gigabit Ethernet Network Driver
> igb: Copyright (c) 2007-2014 Intel Corporation.
> ixgbe: Intel(R) 10 Gigabit PCI Express Network Driver
> ixgbe: Copyright (c) 1999-2016 Intel Corporation.
> usbcore: registered new interface driver ark3116
> usbserial: USB Serial support registered for ark3116
> usbcore: registered new interface driver pl2303
> usbserial: USB Serial support registered for pl2303
> i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
> serio: i8042 KBD port at 0x60,0x64 irq 1
> serio: i8042 AUX port at 0x60,0x64 irq 12
> rtc_cmos 00:04: RTC can wake from S4
> rtc_cmos 00:04: registered as rtc0
> rtc_cmos 00:04: setting system clock to 2024-10-04T08:55:52 UTC (1728032152)
> rtc_cmos 00:04: alarms up to one day, y3k, 242 bytes nvram, hpet irqs
> input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0
> i2c_dev: i2c /dev entries driver
> device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log.
> device-mapper: ioctl: 4.48.0-ioctl (2023-03-01) initialised: dm-devel@lists.linux.dev
> amd_pstate: the _CPC object is not present in SBIOS or ACPI disabled
> usbcore: registered new interface driver usbhid
> usbhid: USB HID core driver
> Initializing XFRM netlink socket
> NET: Registered PF_INET6 protocol family
> Segment Routing with IPv6
> In-situ OAM (IOAM) with IPv6
> NET: Registered PF_PACKET protocol family
> Key type dns_resolver registered
> NET: Registered PF_VSOCK protocol family
> start plist test
> end plist test
> IPI shorthand broadcast: enabled
> sched_clock: Marking stable (6385031761, -10224835)->(6687265139, -312458213)
> registered taskstats version 1
> Loading compiled-in X.509 certificates
> virtme initramfs: initramfs does not have module crypto-pkcs1pad(rsa,sha512)
> virtme initramfs: initramfs does not have module crypto-pkcs1pad(rsa,sha512)-all
> Loaded X.509 cert 'Build time autogenerated kernel key: 1a58da0881b870ef3decd7cf414d45e41b0e363a'
> Demotion targets for Node 0: null
> kmemleak: Automatic memory scanning thread started
> kmemleak: Kernel memory leak detector initialized (mem pool available: 197817)
> page_owner is disabled
> Btrfs loaded, assert=on, zoned=no, fsverity=yes
> ima: No TPM chip found, activating TPM-bypass!
> ima: Allocated hash algorithm: sha256
> ima: No architecture policies found
> netpoll: netconsole: local port 6666
> netpoll: netconsole: local IPv6 address 2401:db00:3120:21a9:face:0:270:0
> netpoll: netconsole: interface 'eth0'
> netpoll: netconsole: remote port 1514
> netpoll: netconsole: remote IPv6 address 2803:6080:a89c:a670::1
> netpoll: netconsole: remote ethernet address 02:90:fb:66:aa:e5
> netpoll: netconsole: device eth0 not up yet, forcing it
> printk: legacy console [netcon_ext0] enabled
This is printed when the "netcon_ext0" console already is registered.
But the lockdep splat is printed later when another "netcon0" has been
registered. I guess that the problem is with this "netcon0".
> =====================================================
> WARNING: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected
> 6.12.0-rc1-kbuilder-virtme-00033-gd4ac164bde7a #50 Not tainted
> -----------------------------------------------------
> swapper/0/1 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire:
> ff1100010a260518 (_xmit_ETHER#2){+.-.}-{2:2}, at: virtnet_poll_tx (./include/linux/netdevice.h:4361 drivers/net/virtio_net.c:2969)
>
> and this task is already holding:
> ffffffff86f2b5b8 (target_list_lock){....}-{2:2}, at: write_ext_msg (drivers/net/netconsole.c:?)
> which would create a new lock dependency:
> (target_list_lock){....}-{2:2} -> (_xmit_ETHER#2){+.-.}-{2:2}
>
> 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_single (kernel/irq_work.c:222)
> irq_work_tick (kernel/irq_work.c:? kernel/irq_work.c:277)
> 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)
> memset (arch/x86/lib/memset_64.S:38)
> __unwind_start (arch/x86/kernel/unwind_orc.c:?)
> arch_stack_walk (./arch/x86/include/asm/unwind.h:50 arch/x86/kernel/stacktrace.c:24)
> stack_trace_save (kernel/stacktrace.c:123)
> kasan_save_stack (mm/kasan/common.c:48)
> __kasan_record_aux_stack (mm/kasan/generic.c:541)
> call_rcu (./arch/x86/include/asm/irqflags.h:26 ./arch/x86/include/asm/irqflags.h:87 ./arch/x86/include/asm/irqflags.h:123 kernel/rcu/tree.c:3087 kernel/rcu/tree.c:3190)
> kfree (mm/slub.c:2271 mm/slub.c:4580 mm/slub.c:4728)
> __kthread_create_on_node (kernel/kthread.c:479)
> __kthread_create_worker (kernel/kthread.c:882)
> kthread_create_worker (kernel/kthread.c:919)
> wq_cpu_intensive_thresh_init (kernel/workqueue.c:7817)
> workqueue_init (kernel/workqueue.c:?)
> kernel_init_freeable (init/main.c:1566)
> 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)
>
> to a HARDIRQ-irq-unsafe lock:
> (_xmit_ETHER#2){+.-.}-{2:2}
>
> ... 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/netdevice.h:4384 drivers/net/virtio_net.c:2768 drivers/net/virtio_net.c:2821)
> __napi_poll (net/core/dev.c:6771)
Note that this napi stuff is handled in softirq context, see below.
> net_rx_action (net/core/dev.c:6840 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 (./include/linux/bottom_half.h:? drivers/net/virtio_net.c:2619 drivers/net/virtio_net.c:2876 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:1582)
> 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:
>
> Chain exists of:
> console_owner --> target_list_lock --> _xmit_ETHER#2
>
> Possible interrupt unsafe locking scenario:
>
> CPU0 CPU1
> ---- ----
> lock(_xmit_ETHER#2);
My understanding is that the fix is to always take "_xmit_ETHER#2"
lock with interrupts disabled.
> local_irq_disable();
> lock(console_owner);
> lock(target_list_lock);
> <Interrupt>
> lock(console_owner);
Just a wild guess. I have looked at changes in
drivers/net/virtio_net.c and noticed a regression caused by the commit
bdacf3e34945 ("net: Use nested-BH locking for napi_alloc_cache.").
There was a followup fix by the commit f8321fa75102246d ("virtio_net:
Fix napi_skb_cache_put warning").
I wonder these changes might be related, see the "napi" call in the softirq
context above.
>
> *** DEADLOCK ***
>
> 6 locks held by swapper/0/1:
> #0: ffffffff861afda8 (console_mutex){+.+.}-{3:3}, at: register_console (kernel/printk/printk.c:113 kernel/printk/printk.c:3933)
> #1: ffffffff861b0400 (console_lock){+.+.}-{0:0}, at: _printk (kernel/printk/printk.c:2435)
> #2: ffffffff861afe10 (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: ffffffff861b03a0 (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: ffffffff86930cc0 (printk_legacy_map-wait-type-override){....}-{3:3}, at: console_flush_all (./include/linux/rcupdate.h:? ./include/linux/srcu.h:267 kernel/printk/printk.c:288 kernel/printk/printk.c:3157)
> #5: ffffffff86f2b5b8 (target_list_lock){....}-{2:2}, at: write_ext_msg (drivers/net/netconsole.c:?)
>
> the dependencies between HARDIRQ-irq-safe lock and the holding lock:
> -> (console_owner){-...}-{0:0} ops: 1984 {
> 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_single (kernel/irq_work.c:222)
> irq_work_tick (kernel/irq_work.c:? kernel/irq_work.c:277)
> 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)
> memset (arch/x86/lib/memset_64.S:38)
> __unwind_start (arch/x86/kernel/unwind_orc.c:?)
> arch_stack_walk (./arch/x86/include/asm/unwind.h:50 arch/x86/kernel/stacktrace.c:24)
> stack_trace_save (kernel/stacktrace.c:123)
> kasan_save_stack (mm/kasan/common.c:48)
> __kasan_record_aux_stack (mm/kasan/generic.c:541)
> call_rcu (./arch/x86/include/asm/irqflags.h:26 ./arch/x86/include/asm/irqflags.h:87 ./arch/x86/include/asm/irqflags.h:123 kernel/rcu/tree.c:3087 kernel/rcu/tree.c:3190)
> kfree (mm/slub.c:2271 mm/slub.c:4580 mm/slub.c:4728)
> __kthread_create_on_node (kernel/kthread.c:479)
> __kthread_create_worker (kernel/kthread.c:882)
> kthread_create_worker (kernel/kthread.c:919)
> wq_cpu_intensive_thresh_init (kernel/workqueue.c:7817)
> workqueue_init (kernel/workqueue.c:?)
> kernel_init_freeable (init/main.c:1566)
> 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:
> }
> ... key at: console_owner_dep_map+0x0/0x60
> -> (target_list_lock){....}-{2:2} ops: 3 {
> INITIAL USE at:
> lock_acquire (kernel/locking/lockdep.c:5825)
> _raw_spin_lock_irqsave (./include/linux/spinlock_api_smp.h:110 kernel/locking/spinlock.c:162)
> init_netconsole (drivers/net/netconsole.c:1327)
> 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:1582)
> 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: target_list_lock+0x18/0x60
> ... acquired at:
> lock_acquire (kernel/locking/lockdep.c:5825)
> _raw_spin_lock_irqsave (./include/linux/spinlock_api_smp.h:110 kernel/locking/spinlock.c:162)
> write_ext_msg (drivers/net/netconsole.c:?)
> 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:1582)
> 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)
>
>
> the dependencies between the lock to be acquired
> and HARDIRQ-irq-unsafe lock:
> -> (_xmit_ETHER#2){+.-.}-{2:2} ops: 7 {
> 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/netdevice.h:4384 drivers/net/virtio_net.c:2768 drivers/net/virtio_net.c:2821)
> __napi_poll (net/core/dev.c:6771)
> net_rx_action (net/core/dev.c:6840 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 (./include/linux/bottom_half.h:? drivers/net/virtio_net.c:2619 drivers/net/virtio_net.c:2876 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:1582)
> 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 (net/core/dev.c:6771)
> net_rx_action (net/core/dev.c:6840 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:2637 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:1582)
> 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/netdevice.h:4384 drivers/net/virtio_net.c:2768 drivers/net/virtio_net.c:2821)
> __napi_poll (net/core/dev.c:6771)
> net_rx_action (net/core/dev.c:6840 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 (./include/linux/bottom_half.h:? drivers/net/virtio_net.c:2619 drivers/net/virtio_net.c:2876 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:1582)
> 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/0x480
> ... acquired 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)
> 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:?)
> 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:1582)
> 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)
> validate_chain (kernel/locking/lockdep.c:? kernel/locking/lockdep.c:2888 kernel/locking/lockdep.c:3165 kernel/locking/lockdep.c:3280 kernel/locking/lockdep.c:3904)
> __lock_acquire (kernel/locking/lockdep.c:?)
> lock_acquire (kernel/locking/lockdep.c:5825)
> ? virtnet_poll_tx (./include/linux/netdevice.h:4361 drivers/net/virtio_net.c:2969)
> _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)
This is where lockdep started yelling. It got the last piece to the
puzzle (deadlock circle).
> ? srso_alias_return_thunk (arch/x86/lib/retpoline.S:182)
> 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:?)
> ? srso_alias_return_thunk (arch/x86/lib/retpoline.S:182)
> ? 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 (./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:?)
> ? srso_alias_return_thunk (arch/x86/lib/retpoline.S:182)
> _printk (kernel/printk/printk.c:2435)
Here the printk() is called from normal context with interrupts
enabled. I am not sure if it is important.
> ? srso_alias_return_thunk (arch/x86/lib/retpoline.S:182)
> register_console (kernel/printk/printk.c:4070)
> ? configfs_register_subsystem (./include/linux/instrumented.h:96 ./include/linux/atomic/atomic-arch-fallback.h:2278 ./include/linux/atomic/atomic-instrumented.h:1384 fs/configfs/dir.c:174 fs/configfs/dir.c:1909)
> init_netconsole (drivers/net/netconsole.c:1344)
> ? srso_alias_return_thunk (arch/x86/lib/retpoline.S:182)
> do_one_initcall (init/main.c:1269)
> ? __pfx_init_netconsole (drivers/net/netconsole.c:1301)
> ? stack_depot_save_flags (lib/stackdepot.c:662)
> ? srso_alias_return_thunk (arch/x86/lib/retpoline.S:182)
> ? kasan_save_track (./arch/x86/include/asm/current.h:49 mm/kasan/common.c:60 mm/kasan/common.c:69)
> ? kasan_save_track (mm/kasan/common.c:48 mm/kasan/common.c:68)
> ? __kasan_kmalloc (mm/kasan/common.c:398)
> ? __kmalloc_noprof (./include/linux/kasan.h:257 mm/slub.c:4265 mm/slub.c:4277)
> ? do_initcalls (init/main.c:1341)
> ? kernel_init_freeable (init/main.c:1582)
> ? 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)
> ? asm_sysvec_apic_timer_interrupt (./arch/x86/include/asm/idtentry.h:702)
> ? srso_alias_return_thunk (arch/x86/lib/retpoline.S:182)
> ? lockdep_hardirqs_on (kernel/locking/lockdep.c:4471)
> ? srso_alias_return_thunk (arch/x86/lib/retpoline.S:182)
> ? asm_sysvec_apic_timer_interrupt (./arch/x86/include/asm/idtentry.h:702)
> ? __pfx_ignore_unknown_bootoption (init/main.c:1315)
> ? srso_alias_return_thunk (arch/x86/lib/retpoline.S:182)
> ? srso_alias_return_thunk (arch/x86/lib/retpoline.S:182)
> ? parse_args (kernel/params.c:153 kernel/params.c:186)
> ? srso_alias_return_thunk (arch/x86/lib/retpoline.S:182)
> ? rcu_is_watching (./include/linux/context_tracking.h:128 kernel/rcu/tree.c:737)
> 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:1582)
> ? __pfx_kernel_init (init/main.c:1461)
> kernel_init (init/main.c:1471)
> ret_from_fork (arch/x86/kernel/process.c:153)
> ? __pfx_kernel_init (init/main.c:1461)
> ret_from_fork_asm (arch/x86/entry/entry_64.S:257)
> </TASK>
> printk: legacy console [netcon0] enabled
I guess that the lockdep splat has been printed when [netcon0]
tried to process this message.
> netconsole: network logging started
> clk: Disabling unused clocks
Best Regards,
Petr
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 6.12-rc1: Lockdep regression bissected (virtio-net/console/scheduler)
2024-10-04 10:49 ` Petr Mladek
@ 2024-10-08 15:18 ` John Ogness
2024-10-09 15:44 ` Pavel Begunkov
0 siblings, 1 reply; 9+ messages in thread
From: John Ogness @ 2024-10-08 15:18 UTC (permalink / raw)
To: Petr Mladek, Breno Leitao
Cc: Peter Zijlstra, gregkh, mst, jasowang, xuanzhuo, kuba,
virtualization, netdev, linux-kernel, vschneid, axboe,
Breno Leitao, Heng Qi
On 2024-10-04, Petr Mladek <pmladek@suse.com> wrote:
> On Fri 2024-10-04 02:08:52, Breno Leitao wrote:
>> =====================================================
>> WARNING: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected
>> 6.12.0-rc1-kbuilder-virtme-00033-gd4ac164bde7a #50 Not tainted
>> -----------------------------------------------------
>> swapper/0/1 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire:
>> ff1100010a260518 (_xmit_ETHER#2){+.-.}-{2:2}, at: virtnet_poll_tx (./include/linux/netdevice.h:4361 drivers/net/virtio_net.c:2969)
>>
>> and this task is already holding:
>> ffffffff86f2b5b8 (target_list_lock){....}-{2:2}, at: write_ext_msg (drivers/net/netconsole.c:?)
>> which would create a new lock dependency:
>> (target_list_lock){....}-{2:2} -> (_xmit_ETHER#2){+.-.}-{2:2}
>>
>> but this new dependency connects a HARDIRQ-irq-safe lock:
>> (console_owner){-...}-{0:0}
...
>> to a HARDIRQ-irq-unsafe lock:
>> (_xmit_ETHER#2){+.-.}-{2:2}
...
>> other info that might help us debug this:
>>
>> Chain exists of:
>> console_owner --> target_list_lock --> _xmit_ETHER#2
>>
>> Possible interrupt unsafe locking scenario:
>>
>> CPU0 CPU1
>> ---- ----
>> lock(_xmit_ETHER#2);
>> local_irq_disable();
>> lock(console_owner);
>> lock(target_list_lock);
>> <Interrupt>
>> lock(console_owner);
I can trigger this lockdep splat on v6.11 as well.
It only requires a printk() call within any interrupt handler, sometime
after the netconsole is initialized and has had at least one run from
softirq context.
> My understanding is that the fix is to always take "_xmit_ETHER#2"
> lock with interrupts disabled.
That seems to be one possible solution. But maybe there is reasoning why
that should not be done. (??) Right now it is clearly a spinlock that is
being taken from both interrupt and softirq contexts and does not
disable interrupts.
I will check if there is some previous kernel release where this problem
does not exist.
John Ogness
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 6.12-rc1: Lockdep regression bissected (virtio-net/console/scheduler)
2024-10-08 15:18 ` John Ogness
@ 2024-10-09 15:44 ` Pavel Begunkov
2024-10-09 17:29 ` Breno Leitao
0 siblings, 1 reply; 9+ messages in thread
From: Pavel Begunkov @ 2024-10-09 15:44 UTC (permalink / raw)
To: John Ogness, Petr Mladek, Breno Leitao
Cc: Peter Zijlstra, gregkh, mst, jasowang, xuanzhuo, kuba,
virtualization, netdev, linux-kernel, vschneid, axboe, Heng Qi
On 10/8/24 16:18, John Ogness wrote:
> On 2024-10-04, Petr Mladek <pmladek@suse.com> wrote:
>> On Fri 2024-10-04 02:08:52, Breno Leitao wrote:
>>> =====================================================
>>> WARNING: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected
>>> 6.12.0-rc1-kbuilder-virtme-00033-gd4ac164bde7a #50 Not tainted
>>> -----------------------------------------------------
>>> swapper/0/1 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire:
>>> ff1100010a260518 (_xmit_ETHER#2){+.-.}-{2:2}, at: virtnet_poll_tx (./include/linux/netdevice.h:4361 drivers/net/virtio_net.c:2969)
>>>
>>> and this task is already holding:
>>> ffffffff86f2b5b8 (target_list_lock){....}-{2:2}, at: write_ext_msg (drivers/net/netconsole.c:?)
>>> which would create a new lock dependency:
>>> (target_list_lock){....}-{2:2} -> (_xmit_ETHER#2){+.-.}-{2:2}
>>>
>>> but this new dependency connects a HARDIRQ-irq-safe lock:
>>> (console_owner){-...}-{0:0}
>
> ...
>
>>> to a HARDIRQ-irq-unsafe lock:
>>> (_xmit_ETHER#2){+.-.}-{2:2}
>
> ...
>
>>> other info that might help us debug this:
>>>
>>> Chain exists of:
>>> console_owner --> target_list_lock --> _xmit_ETHER#2
>>>
>>> Possible interrupt unsafe locking scenario:
>>>
>>> CPU0 CPU1
>>> ---- ----
>>> lock(_xmit_ETHER#2);
>>> local_irq_disable();
>>> lock(console_owner);
>>> lock(target_list_lock);
>>> <Interrupt>
>>> lock(console_owner);
>
> I can trigger this lockdep splat on v6.11 as well.
>
> It only requires a printk() call within any interrupt handler, sometime
> after the netconsole is initialized and has had at least one run from
> softirq context.
>
>> My understanding is that the fix is to always take "_xmit_ETHER#2"
>> lock with interrupts disabled.
>
> That seems to be one possible solution. But maybe there is reasoning why
> that should not be done. (??) Right now it is clearly a spinlock that is
It's expensive, and it's a hot path if I understand correctly which
lock that is. And, IIRC the driver might spend there some time, it's
always nicer to keep irqs enabled if possible.
> being taken from both interrupt and softirq contexts and does not
> disable interrupts.
It rather seems the xmit lock is bh protected, but printk is a one
off case taking it with irqs disabled. I wonder if the printk side
could help with that, e.g. offloading sending from hardirq to softirq?
> I will check if there is some previous kernel release where this problem
> does not exist.
--
Pavel Begunkov
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 6.12-rc1: Lockdep regression bissected (virtio-net/console/scheduler)
2024-10-09 15:44 ` Pavel Begunkov
@ 2024-10-09 17:29 ` Breno Leitao
0 siblings, 0 replies; 9+ messages in thread
From: Breno Leitao @ 2024-10-09 17:29 UTC (permalink / raw)
To: Pavel Begunkov, kuba
Cc: John Ogness, Petr Mladek, Peter Zijlstra, gregkh, mst, jasowang,
xuanzhuo, kuba, virtualization, netdev, linux-kernel, vschneid,
axboe, Heng Qi
On Wed, Oct 09, 2024 at 04:44:24PM +0100, Pavel Begunkov wrote:
> On 10/8/24 16:18, John Ogness wrote:
> > On 2024-10-04, Petr Mladek <pmladek@suse.com> wrote:
> > > On Fri 2024-10-04 02:08:52, Breno Leitao wrote:
> > > > =====================================================
> > > > WARNING: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected
> > > > 6.12.0-rc1-kbuilder-virtme-00033-gd4ac164bde7a #50 Not tainted
> > > > -----------------------------------------------------
> > > > swapper/0/1 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire:
> > > > ff1100010a260518 (_xmit_ETHER#2){+.-.}-{2:2}, at: virtnet_poll_tx (./include/linux/netdevice.h:4361 drivers/net/virtio_net.c:2969)
> > > >
> > > > and this task is already holding:
> > > > ffffffff86f2b5b8 (target_list_lock){....}-{2:2}, at: write_ext_msg (drivers/net/netconsole.c:?)
> > > > which would create a new lock dependency:
> > > > (target_list_lock){....}-{2:2} -> (_xmit_ETHER#2){+.-.}-{2:2}
> > > >
> > > > but this new dependency connects a HARDIRQ-irq-safe lock:
> > > > (console_owner){-...}-{0:0}
> >
> > ...
> >
> > > > to a HARDIRQ-irq-unsafe lock:
> > > > (_xmit_ETHER#2){+.-.}-{2:2}
> >
> > ...
> >
> > > > other info that might help us debug this:
> > > >
> > > > Chain exists of:
> > > > console_owner --> target_list_lock --> _xmit_ETHER#2
> > > >
> > > > Possible interrupt unsafe locking scenario:
> > > >
> > > > CPU0 CPU1
> > > > ---- ----
> > > > lock(_xmit_ETHER#2);
> > > > local_irq_disable();
> > > > lock(console_owner);
> > > > lock(target_list_lock);
> > > > <Interrupt>
> > > > lock(console_owner);
> >
> > I can trigger this lockdep splat on v6.11 as well.
> >
> > It only requires a printk() call within any interrupt handler, sometime
> > after the netconsole is initialized and has had at least one run from
> > softirq context.
> >
> > > My understanding is that the fix is to always take "_xmit_ETHER#2"
> > > lock with interrupts disabled.
> >
> > That seems to be one possible solution. But maybe there is reasoning why
> > that should not be done. (??) Right now it is clearly a spinlock that is
>
> It's expensive, and it's a hot path if I understand correctly which
> lock that is. And, IIRC the driver might spend there some time, it's
> always nicer to keep irqs enabled if possible.
This also seems a broad network lock, which might have so many other
impacts beyond performance.
That said, I am running out of ideas on how to get this fixed,
unfortunately.
--breno
^ permalink raw reply [flat|nested] 9+ messages in thread
end of thread, other threads:[~2024-10-09 17:29 UTC | newest]
Thread overview: 9+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2024-10-03 14:51 6.12-rc1: Lockdep regression bissected (virtio-net/console/scheduler) Breno Leitao
2024-10-03 15:06 ` Breno Leitao
2024-10-03 15:32 ` Peter Zijlstra
2024-10-03 15:41 ` Breno Leitao
2024-10-04 9:08 ` Breno Leitao
2024-10-04 10:49 ` Petr Mladek
2024-10-08 15:18 ` John Ogness
2024-10-09 15:44 ` Pavel Begunkov
2024-10-09 17:29 ` Breno Leitao
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).