Bug 211575
Created attachment 295073 [details]
kernel .config (kernel 5.11-rc6, Shuttle XPC FS51, Pentium 4)
Created attachment 295579 [details]
dmesg (kernel 5.12-rc1, Shuttle XPC FS51, Pentium 4)
Same for 5.12-rc1.
================================
WARNING: inconsistent lock state
5.12.0-rc1-Pentium4 #2 Not tainted
--------------------------------
inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.
swapper/0/0 [HC0[0]:SC1[1]:HE1:SE0] takes:
c113c804 (&syncp->seq#2){?.-.}-{0:0}, at: rtl8139_poll+0x251/0x350
{IN-HARDIRQ-W} state was registered at:
lock_acquire+0x239/0x2c5
do_write_seqcount_begin_nested.constprop.0+0x1a/0x1f
rtl8139_interrupt+0x346/0x3cb
__handle_irq_event_percpu+0xe5/0x20c
handle_irq_event_percpu+0x17/0x3d
handle_irq_event+0x29/0x42
handle_fasteoi_irq+0x67/0xd7
__handle_irq+0x7d/0x9c
__common_interrupt+0x68/0xc3
common_interrupt+0x22/0x35
asm_common_interrupt+0x106/0x180
_raw_spin_unlock_irqrestore+0x41/0x45
__mod_timer+0x1cd/0x1d8
mod_timer+0xa/0xc
mld_ifc_start_timer+0x24/0x37
mld_ifc_timer_expire+0x1b0/0x1c0
call_timer_fn+0xfe/0x201
__run_timers+0x134/0x159
run_timer_softirq+0x14/0x27
__do_softirq+0x15f/0x307
call_on_stack+0x40/0x46
do_softirq_own_stack+0x1c/0x1e
__irq_exit_rcu+0x4f/0x85
irq_exit_rcu+0x8/0x11
sysvec_apic_timer_interrupt+0x20/0x2e
handle_exception_return+0x0/0xaf
default_idle+0xa/0xc
arch_cpu_idle+0xd/0xf
default_idle_call+0x48/0x74
do_idle+0xb7/0x1c3
cpu_startup_entry+0x19/0x1b
rest_init+0x11d/0x120
arch_call_rest_init+0x8/0xb
start_kernel+0x417/0x425
i386_start_kernel+0x43/0x45
startup_32_smp+0x164/0x168
irq event stamp: 26328
hardirqs last enabled at (26328): [<c4362e64>] __slab_alloc.constprop.0+0x3e/0x59
hardirqs last disabled at (26327): [<c4362e47>] __slab_alloc.constprop.0+0x21/0x59
softirqs last enabled at (26314): [<c4789f1f>] __do_softirq+0x2d7/0x307
softirqs last disabled at (26321): [<c420fecb>] call_on_stack+0x40/0x46
other info that might help us debug this:
Possible unsafe locking scenario:
CPU0
----
lock(&syncp->seq#2);
<Interrupt>
lock(&syncp->seq#2);
*** DEADLOCK ***
1 lock held by swapper/0/0:
#0: c113c8a4 (&tp->rx_lock){+.-.}-{2:2}, at: rtl8139_poll+0x31/0x350
stack backtrace:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.12.0-rc1-Pentium4 #2
Hardware name: /FS51, BIOS 6.00 PG 12/02/2003
Call Trace:
<SOFTIRQ>
dump_stack+0x78/0xa5
print_usage_bug+0x17d/0x188
mark_lock.part.0+0xfd/0x27a
? hlock_class+0x18/0x58
? mark_lock.part.0+0x33/0x27a
? ___slab_alloc.constprop.0+0x2b7/0x2d1
__lock_acquire+0x458/0x1488
? rcu_read_lock_sched_held+0x23/0x4a
? trace_kmalloc+0x8c/0xb9
? __kmalloc_track_caller+0x130/0x143
lock_acquire+0x239/0x2c5
? rtl8139_poll+0x251/0x350
? __alloc_skb+0xb7/0x102
do_write_seqcount_begin_nested.constprop.0+0x1a/0x1f
? rtl8139_poll+0x251/0x350
rtl8139_poll+0x251/0x350
__napi_poll+0x24/0xf1
net_rx_action+0xbb/0x177
__do_softirq+0x15f/0x307
? __entry_text_end+0x5/0x5
call_on_stack+0x40/0x46
</SOFTIRQ>
? __irq_exit_rcu+0x4f/0x85
? irq_exit_rcu+0x8/0x11
? common_interrupt+0x27/0x35
? asm_common_interrupt+0x106/0x180
? ldsem_down_write+0x1f/0x1f
? newidle_balance+0x1d0/0x3ab
? default_idle+0xa/0xc
? __pci_setup_bridge+0x4e/0x64
? default_idle+0xa/0xc
? arch_cpu_idle+0xd/0xf
? default_idle_call+0x48/0x74
? do_idle+0xb7/0x1c3
? cpu_startup_entry+0x19/0x1b
? rest_init+0x11d/0x120
? arch_call_rest_init+0x8/0xb
? start_kernel+0x417/0x425
? i386_start_kernel+0x43/0x45
? startup_32_smp+0x164/0x168
Thank you for the report! Are you able to apply patches and build the kernel to test? I think this would be the fix: diff --git a/drivers/net/ethernet/realtek/8139too.c b/drivers/net/ethernet/realtek/8139too.c index 1e5a453dea14..e5c333eacc11 100644 --- a/drivers/net/ethernet/realtek/8139too.c +++ b/drivers/net/ethernet/realtek/8139too.c @@ -2222,9 +2222,12 @@ static void rtl8139_poll_controller(struct net_device *dev) { struct rtl8139_private *tp = netdev_priv(dev); const int irq = tp->pci_dev->irq; + unsigned long flags; disable_irq_nosync(irq); + local_irq_save(flags); rtl8139_interrupt(irq, dev); + local_irq_restore(flags); enable_irq(irq); } #endif With the patch applied I still get almost the same backtrace: [...] ================================ WARNING: inconsistent lock state 5.12.0-rc1-Pentium4+ #3 Not tainted -------------------------------- inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage. swapper/0/0 [HC0[0]:SC1[1]:HE1:SE0] takes: c113c804 (&syncp->seq#2){?.-.}-{0:0}, at: rtl8139_poll+0x251/0x350 {IN-HARDIRQ-W} state was registered at: lock_acquire+0x239/0x2c5 do_write_seqcount_begin_nested.constprop.0+0x1a/0x1f rtl8139_interrupt+0x346/0x3cb __handle_irq_event_percpu+0xe5/0x20c handle_irq_event_percpu+0x17/0x3d handle_irq_event+0x29/0x42 handle_fasteoi_irq+0x67/0xd7 __handle_irq+0x7d/0x9c __common_interrupt+0x68/0xc3 common_interrupt+0x22/0x35 asm_common_interrupt+0x106/0x180 _raw_spin_unlock_irqrestore+0x41/0x45 __mod_timer+0x1cd/0x1d8 mod_timer+0xa/0xc mld_ifc_start_timer+0x24/0x37 mld_ifc_timer_expire+0x1b0/0x1c0 call_timer_fn+0xfe/0x201 __run_timers+0x134/0x159 run_timer_softirq+0x14/0x27 __do_softirq+0x15f/0x307 call_on_stack+0x40/0x46 do_softirq_own_stack+0x1c/0x1e __irq_exit_rcu+0x4f/0x85 irq_exit_rcu+0x8/0x11 sysvec_apic_timer_interrupt+0x20/0x2e handle_exception_return+0x0/0xaf default_idle+0xa/0xc arch_cpu_idle+0xd/0xf default_idle_call+0x48/0x74 do_idle+0xb7/0x1c3 cpu_startup_entry+0x19/0x1b rest_init+0x11d/0x120 arch_call_rest_init+0x8/0xb start_kernel+0x417/0x425 i386_start_kernel+0x43/0x45 startup_32_smp+0x164/0x168 irq event stamp: 23566 hardirqs last enabled at (23566): [<dad62e64>] __slab_alloc.constprop.0+0x3e/0x59 hardirqs last disabled at (23565): [<dad62e47>] __slab_alloc.constprop.0+0x21/0x59 softirqs last enabled at (23552): [<db189f1f>] __do_softirq+0x2d7/0x307 softirqs last disabled at (23559): [<dac0fecb>] call_on_stack+0x40/0x46 other info that might help us debug this: Possible unsafe locking scenario: CPU0 ---- lock(&syncp->seq#2); <Interrupt> lock(&syncp->seq#2); *** DEADLOCK *** 1 lock held by swapper/0/0: #0: c113c8a4 (&tp->rx_lock){+.-.}-{2:2}, at: rtl8139_poll+0x31/0x350 stack backtrace: CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.12.0-rc1-Pentium4+ #3 Hardware name: /FS51, BIOS 6.00 PG 12/02/2003 Call Trace: <SOFTIRQ> dump_stack+0x78/0xa5 print_usage_bug+0x17d/0x188 mark_lock.part.0+0xfd/0x27a ? hlock_class+0x18/0x58 ? mark_lock.part.0+0x33/0x27a ? ___slab_alloc.constprop.0+0x2b7/0x2d1 __lock_acquire+0x458/0x1488 ? rcu_read_lock_sched_held+0x23/0x4a ? trace_kmalloc+0x8c/0xb9 ? __kmalloc_track_caller+0x130/0x143 lock_acquire+0x239/0x2c5 ? rtl8139_poll+0x251/0x350 ? __alloc_skb+0xb7/0x102 do_write_seqcount_begin_nested.constprop.0+0x1a/0x1f ? rtl8139_poll+0x251/0x350 rtl8139_poll+0x251/0x350 __napi_poll+0x24/0xf1 net_rx_action+0xbb/0x177 __do_softirq+0x15f/0x307 ? __entry_text_end+0x5/0x5 call_on_stack+0x40/0x46 </SOFTIRQ> ? __irq_exit_rcu+0x4f/0x85 ? irq_exit_rcu+0x8/0x11 ? common_interrupt+0x27/0x35 ? asm_common_interrupt+0x106/0x180 ? ldsem_down_write+0x1f/0x1f ? pci_subsys_init+0x41/0x5c ? default_idle+0xa/0xc ? __pci_setup_bridge+0x25/0x64 ? default_idle+0xa/0xc ? arch_cpu_idle+0xd/0xf ? default_idle_call+0x48/0x74 ? do_idle+0xb7/0x1c3 ? cpu_startup_entry+0x19/0x1b ? rest_init+0x11d/0x120 ? arch_call_rest_init+0x8/0xb ? start_kernel+0x417/0x425 ? i386_start_kernel+0x43/0x45 ? startup_32_smp+0x164/0x168 Strange, I don't see the same syncp being taken both in RX and TX paths. Would you be able to translate the offsets into lines of code? For common builds you'd need to do something like: ./scripts/decode_stacktrace.sh vmlinux ./ ./ And then paste in the stack trace. The script will respond with line numbers. In particular I wonder what's at: rtl8139_poll+0x251/0x350 and: rtl8139_interrupt+0x346/0x3cb Pasted the stuff after "{IN-HARDIRQ-W} state was registered at:" from v5.12-rc1 + patch and got: lock_acquire (/usr/src/linux-stable/kernel/locking/lockdep.c:437) startup_32_smp+0x164/0x168lock_acquire (/usr/src/linux-stable/kernel/locking/lockdep.c:437) do_write_seqcount_begin_nested.constprop.0 (/usr/src/linux-stable/./include/linux/seqlock.h:520) rtl8139_interrupt (/usr/src/linux-stable/drivers/net/ethernet/realtek/8139too.c:1806) __handle_irq_event_percpu (/usr/src/linux-stable/kernel/irq/handle.c:156) handle_irq_event_percpu (/usr/src/linux-stable/kernel/irq/handle.c:196) handle_irq_event (/usr/src/linux-stable/kernel/irq/handle.c:213) handle_fasteoi_irq (/usr/src/linux-stable/kernel/irq/chip.c:662) __handle_irq (/usr/src/linux-stable/arch/x86/kernel/irq_32.c:100) __common_interrupt (/usr/src/linux-stable/arch/x86/kernel/irq.c:234) common_interrupt (/usr/src/linux-stable/arch/x86/kernel/irq.c:240) asm_common_interrupt (/usr/src/linux-stable/./arch/x86/include/asm/idtentry.h:623) _raw_spin_unlock_irqrestore (/usr/src/linux-stable/kernel/locking/spinlock.c:192) __mod_timer (/usr/src/linux-stable/kernel/time/timer.c:1066) mod_timer (/usr/src/linux-stable/kernel/time/timer.c:1107) mld_ifc_start_timer (/usr/src/linux-stable/net/ipv6/mcast.c:1050) mld_ifc_timer_expire (/usr/src/linux-stable/net/ipv6/mcast.c:2481) call_timer_fn (/usr/src/linux-stable/./arch/x86/include/asm/jump_label.h:25) __run_timers (/usr/src/linux-stable/kernel/time/timer.c:1477) run_timer_softirq (/usr/src/linux-stable/kernel/time/timer.c:1760) __do_softirq (/usr/src/linux-stable/./arch/x86/include/asm/jump_label.h:25) call_on_stack (/usr/src/linux-stable/arch/x86/kernel/irq_32.c:60) do_softirq_own_stack (/usr/src/linux-stable/arch/x86/kernel/irq_32.c:150) __irq_exit_rcu (/usr/src/linux-stable/kernel/softirq.c:228) irq_exit_rcu (/usr/src/linux-stable/kernel/softirq.c:436) sysvec_apic_timer_interrupt (/usr/src/linux-stable/arch/x86/kernel/apic/apic.c:1100) handle_exception_return (/usr/src/linux-stable/arch/x86/entry/entry_32.S:1179) default_idle (/usr/src/linux-stable/arch/x86/kernel/process.c:689) arch_cpu_idle (/usr/src/linux-stable/arch/x86/kernel/process.c:681) default_idle_call (/usr/src/linux-stable/./arch/x86/include/asm/irqflags.h:40) do_idle (/usr/src/linux-stable/kernel/sched/idle.c:195) cpu_startup_entry (/usr/src/linux-stable/kernel/sched/idle.c:396 (discriminator 1)) rest_init (/usr/src/linux-stable/init/main.c:722) arch_call_rest_init+0x8/0xb start_kernel (/usr/src/linux-stable/init/main.c:1066) i386_start_kernel (/usr/src/linux-stable/arch/x86/kernel/head32.c:57) Pasted the stuff after "Call Trace: <SOFTIRQ>" from v5.12-rc1 + patch and got: dump_stack (/usr/src/linux-stable/lib/dump_stack.c:122) print_usage_bug (/usr/src/linux-stable/kernel/locking/lockdep.c:3806) mark_lock.part.0 (/usr/src/linux-stable/kernel/locking/lockdep.c:3818) ? hlock_class (/usr/src/linux-stable/kernel/locking/lockdep.c:198) ? mark_lock.part.0 (/usr/src/linux-stable/kernel/locking/lockdep.c:4456) ? ___slab_alloc.constprop.0 (/usr/src/linux-stable/mm/slub.c:2767) __lock_acquire (/usr/src/linux-stable/kernel/locking/lockdep.c:4387) ? rcu_read_lock_sched_held (/usr/src/linux-stable/./include/linux/lockdep.h:278) ? trace_kmalloc (/usr/src/linux-stable/./include/trace/events/kmem.h:46) ? __kmalloc_track_caller (/usr/src/linux-stable/mm/slub.c:4566) lock_acquire (/usr/src/linux-stable/kernel/locking/lockdep.c:437) ? rtl8139_poll (/usr/src/linux-stable/drivers/net/ethernet/realtek/8139too.c:2051) ? __alloc_skb (/usr/src/linux-stable/net/core/skbuff.c:441) do_write_seqcount_begin_nested.constprop.0 (/usr/src/linux-stable/./include/linux/seqlock.h:520) ? rtl8139_poll (/usr/src/linux-stable/drivers/net/ethernet/realtek/8139too.c:2051) rtl8139_poll (/usr/src/linux-stable/drivers/net/ethernet/realtek/8139too.c:2051) __napi_poll (/usr/src/linux-stable/net/core/dev.c:6892) net_rx_action (/usr/src/linux-stable/net/core/dev.c:6959) __do_softirq (/usr/src/linux-stable/./arch/x86/include/asm/jump_label.h:25) ? __entry_text_end (/usr/src/linux-stable/kernel/softirq.c:303) call_on_stack (/usr/src/linux-stable/arch/x86/kernel/irq_32.c:60) </SOFTIRQ> ? __irq_exit_rcu (/usr/src/linux-stable/kernel/softirq.c:228) ? irq_exit_rcu (/usr/src/linux-stable/kernel/softirq.c:436) ? common_interrupt (/usr/src/linux-stable/arch/x86/kernel/irq.c:240) ? asm_common_interrupt (/usr/src/linux-stable/./arch/x86/include/asm/idtentry.h:623) ? ldsem_down_write (/usr/src/linux-stable/arch/x86/kernel/process.c:687) ? pci_subsys_init (/usr/src/linux-stable/arch/x86/pci/legacy.c:23) ? default_idle (/usr/src/linux-stable/arch/x86/kernel/process.c:689) ? __pci_setup_bridge (/usr/src/linux-stable/drivers/pci/setup-bus.c:672) ? default_idle (/usr/src/linux-stable/arch/x86/kernel/process.c:689) ? arch_cpu_idle (/usr/src/linux-stable/arch/x86/kernel/process.c:681) ? default_idle_call (/usr/src/linux-stable/./arch/x86/include/asm/irqflags.h:40) ? do_idle (/usr/src/linux-stable/kernel/sched/idle.c:195) ? cpu_startup_entry (/usr/src/linux-stable/kernel/sched/idle.c:396 (discriminator 1)) ? rest_init (/usr/src/linux-stable/init/main.c:722) ? arch_call_rest_init+0x8/0xb ? start_kernel (/usr/src/linux-stable/init/main.c:1066) ? i386_start_kernel (/usr/src/linux-stable/arch/x86/kernel/head32.c:57) Probably bug #208097 is relevant too? Same machine, also IRQ related problems. Makes no sense, these are separate locks, let me ask Ahmed on the mailing list. Created attachment 296653 [details]
dmesg (kernel 5.12.1, Shuttle XPC FS51, Pentium 4)
Looks like 5.12.x is still affected. Though the trace looks a bit different compared to 5.11-rc6 and 5.12-rc1:
[...]
printk: console [netcon0] enabled
================================
WARNING: inconsistent lock state
5.12.1-gentoo-Pentium4 #2 Not tainted
--------------------------------
inconsistent {HARDIRQ-ON-W} -> {IN-HARDIRQ-W} usage.
swapper/0/0 [HC1[1]:SC0[0]:HE0:SE1] takes:
c108c8a4 (&tp->rx_lock){?.-.}-{2:2}, at: rtl8139_poll+0x31/0x350
{HARDIRQ-ON-W} state was registered at:
lock_acquire+0x239/0x2c5
_raw_spin_lock+0x22/0x31
rtl8139_poll+0x31/0x350
__napi_poll+0x24/0xf1
net_rx_action+0xbb/0x177
__do_softirq+0x15f/0x307
call_on_stack+0x40/0x46
do_softirq_own_stack+0x1c/0x1e
__irq_exit_rcu+0x4f/0x85
irq_exit_rcu+0x8/0x11
common_interrupt+0x27/0x35
asm_common_interrupt+0x106/0x180
default_idle+0xa/0xc
arch_cpu_idle+0xd/0xf
default_idle_call+0x48/0x74
do_idle+0xb7/0x1c3
cpu_startup_entry+0x19/0x1b
rest_init+0x11d/0x120
arch_call_rest_init+0x8/0xb
start_kernel+0x417/0x425
i386_start_kernel+0x43/0x45
startup_32_smp+0x164/0x168
irq event stamp: 23068
hardirqs last enabled at (23067): [<ced8c8c8>] default_idle_call+0x39/0x74
hardirqs last disabled at (23068): [<ced86781>] common_interrupt+0xf/0x35
softirqs last enabled at (22798): [<ced8e59f>] __do_softirq+0x2d7/0x307
softirqs last disabled at (22785): [<ce80fee0>] call_on_stack+0x40/0x46
other info that might help us debug this:
Possible unsafe locking scenario:
CPU0
----
lock(&tp->rx_lock);
<Interrupt>
lock(&tp->rx_lock);
*** DEADLOCK ***
3 locks held by swapper/0/0:
#0: cf038eb4 (console_lock){+.+.}-{0:0}, at: vprintk_emit+0x192/0x1cc
#1: cf006dc4 (console_owner){-...}-{0:0}, at: console_unlock+0x260/0x475
#2: cf09b6f0 (target_list_lock){-...}-{2:2}, at: write_msg+0x37/0xa5
stack backtrace:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.12.1-gentoo-Pentium4 #2
Hardware name: /FS51, BIOS 6.00 PG 12/02/2003
Call Trace:
<IRQ>
dump_stack+0x78/0xa5
print_usage_bug+0x17d/0x188
mark_lock.part.0+0xfd/0x27a
? mark_lock.part.0+0x33/0x27a
? check_chain_key+0xea/0x142
__lock_acquire+0x3fb/0x1488
? __lock_acquire+0x9f6/0x1488
? __lock_acquire+0x9f6/0x1488
lock_acquire+0x239/0x2c5
? rtl8139_poll+0x31/0x350
? check_chain_key+0xea/0x142
_raw_spin_lock+0x22/0x31
? rtl8139_poll+0x31/0x350
rtl8139_poll+0x31/0x350
? enable_irq+0x45/0x53
netpoll_poll_dev+0xd7/0x1c1
netpoll_send_skb+0x12d/0x256
netpoll_send_udp+0x384/0x38c
write_msg+0x87/0xa5
? netconsole_netdev_event+0x13f/0x13f
console_unlock+0x38a/0x475
vprintk_emit+0x1b6/0x1cc
vprintk_default+0x10/0x12
vprintk_func+0x96/0xa1
printk+0xe/0x10
crng_fast_load+0xdf/0xea
add_interrupt_randomness+0xec/0x14a
handle_irq_event_percpu+0x24/0x3d
handle_irq_event+0x29/0x42
handle_fasteoi_irq+0x67/0xd7
? handle_level_irq+0x83/0x83
__handle_irq+0x7d/0x9c
</IRQ>
__common_interrupt+0x68/0xc3
common_interrupt+0x22/0x35
asm_common_interrupt+0x106/0x180
EIP: default_idle+0xa/0xc
Code: 51 89 c3 89 55 f8 e8 60 de ff ff 8b 4d f8 31 d2 89 d8 e8 e2 a1 e7 ff 5b 5b 5d c3 cc cc cc cc cc 55 89 e5 e8 cc 7e a8 ff fb f4 <5d> c3 55 89 e5 64 a1 d4 97 14 cf f0 80 48 02 20 8b 10 80 e2 08 75
EAX: ced8c720 EBX: 00000000 ECX: 00000000 EDX: ffffffff
ESI: ceff2800 EDI: 00000000 EBP: cefebf2c ESP: cefebf2c
DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 EFLAGS: 00200202
? __sched_text_end+0x5/0x5
? print_irq_lock_scenario.isra.0+0x7a/0x10c
? default_idle+0xa/0xc
arch_cpu_idle+0xd/0xf
default_idle_call+0x48/0x74
do_idle+0xb7/0x1c3
cpu_startup_entry+0x19/0x1b
rest_init+0x11d/0x120
arch_call_rest_init+0x8/0xb
start_kernel+0x417/0x425
i386_start_kernel+0x43/0x45
startup_32_smp+0x164/0x168
netconsole: network logging started
[...]
Created attachment 296655 [details]
kernel .config (kernel 5.12.1, Shuttle XPC FS51, Pentium 4)
Created attachment 297931 [details]
dmesg (kernel 5.14-rc2, Shuttle XPC FS51, Pentium 4)
Looks like it's still in... kernel v5.14-rc2:
[...]
printk: console [netcon0] enabled
================================
WARNING: inconsistent lock state
5.14.0-rc2-Pentium4 #5 Not tainted
--------------------------------
inconsistent {HARDIRQ-ON-W} -> {IN-HARDIRQ-W} usage.
swapper/0/0 [HC1[1]:SC0[0]:HE0:SE1] takes:
c10ac8a4 (&tp->rx_lock){?.-.}-{2:2}, at: rtl8139_poll+0x31/0x350
{HARDIRQ-ON-W} state was registered at:
lock_acquire+0x1f2/0x22a
_raw_spin_lock+0x22/0x31
rtl8139_poll+0x31/0x350
__napi_poll+0x24/0xf1
net_rx_action+0x118/0x28a
__do_softirq+0x155/0x2f3
call_on_stack+0x40/0x46
do_softirq_own_stack+0x1c/0x1e
__irq_exit_rcu+0x59/0x8f
irq_exit_rcu+0x8/0x11
common_interrupt+0x27/0x35
asm_common_interrupt+0xff/0x180
default_idle+0xa/0xc
arch_cpu_idle+0xd/0xf
default_idle_call+0x48/0x74
do_idle+0xbe/0x1ca
cpu_startup_entry+0x19/0x1b
rest_init+0x121/0x124
arch_call_rest_init+0x11/0x45
start_kernel+0x6b3/0x6d1
i386_start_kernel+0x5d/0x73
startup_32_smp+0x161/0x164
irq event stamp: 14738
hardirqs last enabled at (14737): [<de353855>] default_idle_call+0x39/0x74
hardirqs last disabled at (14738): [<de34c6ea>] common_interrupt+0xf/0x35
softirqs last enabled at (13838): [<de3554e3>] __do_softirq+0x2c3/0x2f3
softirqs last disabled at (13827): [<dde10de7>] call_on_stack+0x40/0x46
other info that might help us debug this:
Possible unsafe locking scenario:
CPU0
----
lock(&tp->rx_lock);
<Interrupt>
lock(&tp->rx_lock);
*** DEADLOCK ***
3 locks held by swapper/0/0:
#0: de5f17d4 (console_lock){+.+.}-{0:0}, at: vprintk_emit+0x192/0x1cc
#1: de5bf6a4 (console_owner){-...}-{0:0}, at: console_unlock+0x251/0x441
#2: de644850 (target_list_lock){-...}-{2:2}, at: write_msg+0x37/0xa5
stack backtrace:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.14.0-rc2-Pentium4 #5
Hardware name: /FS51, BIOS 6.00 PG 12/02/2003
Call Trace:
<IRQ>
dump_stack_lvl+0x53/0x76
dump_stack+0xd/0x10
print_usage_bug+0x17d/0x188
mark_lock.part.0+0xfd/0x27a
? mark_lock.part.0+0x33/0x27a
? check_chain_key+0xea/0x142
__lock_acquire+0x404/0x14a6
? __lock_acquire+0xa03/0x14a6
? __lock_acquire+0xa03/0x14a6
? rtl8139_poll+0x31/0x350
lock_acquire+0x1f2/0x22a
? rtl8139_poll+0x31/0x350
? check_chain_key+0xea/0x142
_raw_spin_lock+0x22/0x31
? rtl8139_poll+0x31/0x350
rtl8139_poll+0x31/0x350
? enable_irq+0x45/0x53
netpoll_poll_dev+0xd7/0x1c1
netpoll_send_skb+0x12d/0x256
netpoll_send_udp+0x384/0x38c
write_msg+0x87/0xa5
? netconsole_netdev_event+0x13f/0x13f
console_unlock+0x37b/0x441
vprintk_emit+0x1b6/0x1cc
vprintk_default+0x10/0x12
vprintk+0xbf/0xcb
printk+0xf/0x11
crng_fast_load+0xdf/0xea
add_interrupt_randomness+0x157/0x20a
handle_irq_event_percpu+0x24/0x3a
handle_irq_event+0x29/0x42
handle_fasteoi_irq+0x67/0xd7
? handle_level_irq+0x83/0x83
__handle_irq+0x7d/0x9c
</IRQ>
__common_interrupt+0x68/0xc3
common_interrupt+0x22/0x35
asm_common_interrupt+0xff/0x180
EIP: default_idle+0xa/0xc
Code: e5 53 51 89 c3 89 55 f8 e8 31 d2 ff ff 8b 4d f8 31 d2 89 d8 e8 b5 b9 e6 ff 5b 5b 5d c3 cc cc cc 55 89 e5 e8 60 1f ac ff fb f4 <5d> c3 55 89 e5 64 a1 d8 c7 70 de f0 80 48 02 20 8b 10 80 e2 08 75
EAX: de3536b0 EBX: 00000000 ECX: 00000000 EDX: ffffffff
ESI: de5aa800 EDI: 00000000 EBP: de5a3f1c ESP: de5a3f1c
DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 EFLAGS: 00200202
? __sched_text_end+0x3/0x3
? __schedule+0x390/0xb0e
? default_idle+0xa/0xc
arch_cpu_idle+0xd/0xf
default_idle_call+0x48/0x74
do_idle+0xbe/0x1ca
cpu_startup_entry+0x19/0x1b
rest_init+0x121/0x124
arch_call_rest_init+0x11/0x45
start_kernel+0x6b3/0x6d1
i386_start_kernel+0x5d/0x73
startup_32_smp+0x161/0x164
netconsole: network logging started
Created attachment 297933 [details]
kernel .config (kernel 5.14-rc2, Shuttle XPC FS51, Pentium 4)
Created attachment 299247 [details]
dmesg (kernel 5.15-rc6, Shuttle XPC FS51, Pentium 4)
[...]
printk: console [netcon0] enabled
================================
WARNING: inconsistent lock state
5.15.0-rc6-Pentium4 #2 Not tainted
--------------------------------
inconsistent {HARDIRQ-ON-W} -> {IN-HARDIRQ-W} usage.
swapper/0/0 [HC1[1]:SC0[0]:HE0:SE1] takes:
c12298a4 (&tp->rx_lock){?.-.}-{2:2}, at: rtl8139_poll+0x31/0x34e
{HARDIRQ-ON-W} state was registered at:
lock_acquire+0x1f2/0x230
_raw_spin_lock+0x22/0x37
rtl8139_poll+0x31/0x34e
__napi_poll.constprop.0+0x24/0xf5
net_rx_action+0x118/0x28c
__do_softirq+0x155/0x2f9
call_on_stack+0x40/0x4c
do_softirq_own_stack+0x1c/0x22
__irq_exit_rcu+0x57/0x8f
irq_exit_rcu+0x8/0x11
common_interrupt+0x27/0x39
asm_common_interrupt+0xff/0x180
default_idle+0xa/0xc
arch_cpu_idle+0xd/0x11
default_idle_call+0x48/0x78
do_idle+0xbe/0x1d0
cpu_startup_entry+0x19/0x1b
rest_init+0x121/0x12a
arch_call_rest_init+0x11/0x4b
start_kernel+0x6a2/0x6c6
i386_start_kernel+0x5d/0x75
startup_32_smp+0x161/0x164
irq event stamp: 35934
hardirqs last enabled at (35933): [<d59e1054>] default_idle_call+0x39/0x78
hardirqs last disabled at (35934): [<d59d9bad>] common_interrupt+0xf/0x39
softirqs last enabled at (35832): [<d59e2d63>] __do_softirq+0x2c3/0x2f9
softirqs last disabled at (35821): [<d5411715>] call_on_stack+0x40/0x4c
other info that might help us debug this:
Possible unsafe locking scenario:
CPU0
----
lock(&tp->rx_lock);
<Interrupt>
lock(&tp->rx_lock);
*** DEADLOCK ***
3 locks held by swapper/0/0:
#0: d5ca38dc (console_lock){+.+.}-{0:0}, at: vprintk_emit+0x15e/0x19c
#1: d5c71784 (console_owner){-...}-{0:0}, at: console_unlock+0x1c5/0x400
#2: d5d07530 (target_list_lock){-...}-{2:2}, at: write_msg+0x37/0xa7
stack backtrace:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.15.0-rc6-Pentium4 #2
Hardware name: /FS51, BIOS 6.00 PG 12/02/2003
Call Trace:
<IRQ>
dump_stack_lvl+0x53/0x7c
dump_stack+0xd/0x12
print_usage_bug+0x17d/0x18e
mark_lock.part.0+0xfb/0x27c
? mark_lock.part.0+0x33/0x27c
? check_chain_key+0xea/0x148
__lock_acquire+0x400/0x1472
? __lock_acquire+0x9ee/0x1472
? __lock_acquire+0x9ee/0x1472
? rtl8139_poll+0x31/0x34e
lock_acquire+0x1f2/0x230
? rtl8139_poll+0x31/0x34e
? check_chain_key+0xea/0x148
_raw_spin_lock+0x22/0x37
? rtl8139_poll+0x31/0x34e
rtl8139_poll+0x31/0x34e
? enable_irq+0x45/0x59
netpoll_poll_dev+0xd7/0x1c7
netpoll_send_skb+0x12d/0x25a
netpoll_send_udp+0x386/0x394
write_msg+0x83/0xa7
? netconsole_netdev_event+0x14d/0x14d
console_unlock+0x333/0x400
vprintk_emit+0x182/0x19c
vprintk_default+0x10/0x14
vprintk+0x46/0x4c
_printk+0xf/0x11
crng_fast_load+0xdf/0xee
add_interrupt_randomness+0x159/0x221
handle_irq_event_percpu+0x24/0x3e
handle_irq_event+0x29/0x42
handle_fasteoi_irq+0x69/0xdf
? handle_level_irq+0x89/0x89
__handle_irq+0x7d/0xa2
</IRQ>
__common_interrupt+0x68/0xc9
common_interrupt+0x22/0x39
asm_common_interrupt+0xff/0x180
EIP: default_idle+0xa/0xc
Code: 89 c3 89 55 f8 e8 fb cf ff ff 8b 4d f8 31 d2 89 d8 e8 b7 d3 e5 ff 5b 5b 5d 31 d2 89 d1 c3 cc cc 55 89 e5 e8 14 53 a3 ff fb f4 <5d> c3 55 89 e5 64 a1 f8 77 dd d5 f0 80 48 02 20 8b 10 80 e2 08 75
EAX: d59e0ea0 EBX: 00000000 ECX: 00000000 EDX: 00000000
ESI: d5c5c800 EDI: 00000000 EBP: d5c55f1c ESP: d5c55f1c
DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 EFLAGS: 00200246
? __sched_text_end+0x2/0x2
? task_blocks_on_rt_mutex.constprop.0.isra.0+0x254/0x283
? default_idle+0xa/0xc
arch_cpu_idle+0xd/0x11
default_idle_call+0x48/0x78
do_idle+0xbe/0x1d0
cpu_startup_entry+0x19/0x1b
rest_init+0x121/0x12a
arch_call_rest_init+0x11/0x4b
start_kernel+0x6a2/0x6c6
i386_start_kernel+0x5d/0x75
startup_32_smp+0x161/0x164
netconsole: network logging started
Created attachment 299249 [details]
kernel .config (kernel 5.15-rc6, Shuttle XPC FS51, Pentium 4)
Created attachment 300418 [details]
dmesg (kernel 5.17-rc3, Shuttle XPC FS51, Pentium 4)
Still in 5.17-rc3.
[...]
printk: console [netcon0] enabled
================================
WARNING: inconsistent lock state
5.17.0-rc3-P4 #2 Not tainted
--------------------------------
inconsistent {HARDIRQ-ON-W} -> {IN-HARDIRQ-W} usage.
swapper/0/0 [HC1[1]:SC0[0]:HE0:SE1] takes:
c12d98a4 (&tp->rx_lock){?.-.}-{2:2}, at: rtl8139_poll+0x2b/0x404
{HARDIRQ-ON-W} state was registered at:
lock_acquire+0xa7/0x165
_raw_spin_lock+0x23/0x31
rtl8139_poll+0x2b/0x404
__napi_poll+0x26/0x13d
net_rx_action+0xf0/0x213
__do_softirq+0x136/0x27f
do_softirq_own_stack+0x50/0x56
irq_exit_rcu+0x96/0xa9
common_interrupt+0x29/0x3c
asm_common_interrupt+0xff/0x180
default_idle+0xe/0x10
arch_cpu_idle+0xd/0xf
default_idle_call+0x48/0x7c
do_idle+0xc7/0x1f2
cpu_startup_entry+0x17/0x19
rest_init+0x1af/0x1b2
arch_call_rest_init+0x8/0xa
start_kernel+0x2c6/0x33e
i386_start_kernel+0x94/0x97
startup_32_smp+0x161/0x164
irq event stamp: 23324
hardirqs last enabled at (23323): [<d8555e47>] default_idle_call+0x39/0x7c
hardirqs last disabled at (23324): [<d854dbed>] common_interrupt+0x10/0x3c
softirqs last enabled at (23194): [<d8557d00>] __do_softirq+0x250/0x27f
softirqs last disabled at (23189): [<d7e170f1>] do_softirq_own_stack+0x50/0x56
other info that might help us debug this:
Possible unsafe locking scenario:
CPU0
----
lock(&tp->rx_lock);
<Interrupt>
lock(&tp->rx_lock);
*** DEADLOCK ***
[...]
Created attachment 300419 [details]
kernel .config (kernel 5.17-rc3, Shuttle XPC FS51, Pentium 4)
Have not seen this on 5.18.x, 5.19.x nor on 6.0-rc. I think it's safe to close here. |
Created attachment 295071 [details] dmesg (kernel 5.11-rc6, Shuttle XPC FS51, Pentium 4) Happens every time at booting since I got netconsole enabled. [...] netpoll: netconsole: local port 6666 netpoll: netconsole: local IPv4 address 192.168.2.7 netpoll: netconsole: interface 'eth0' netpoll: netconsole: remote port 6666 netpoll: netconsole: remote IPv4 address 192.168.2.3 netpoll: netconsole: remote ethernet address xx:xx:xx:xx:xx:xx netpoll: netconsole: device eth0 not up yet, forcing it 8139too 0000:00:0f.0 eth0: link up, 100Mbps, full-duplex, lpa 0xC5E1 netpoll: netconsole: carrier detect appears untrustworthy, waiting 4 seconds ================================ WARNING: inconsistent lock state 5.11.0-rc6-Pentium4 #4 Not tainted -------------------------------- inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage. swapper/0/0 [HC0[0]:SC1[1]:HE1:SE0] takes: c1081800 (&syncp->seq#2){?.-.}-{0:0}, at: rtl8139_poll+0x24b/0x34a {IN-HARDIRQ-W} state was registered at: lock_acquire+0x236/0x2b4 do_write_seqcount_begin_nested.constprop.0+0x1a/0x1f rtl8139_interrupt+0x346/0x3cb __handle_irq_event_percpu+0xe5/0x20c handle_irq_event_percpu+0x17/0x3d handle_irq_event+0x29/0x42 handle_fasteoi_irq+0x67/0xd7 __handle_irq+0x7d/0x9c common_interrupt+0x7b/0xe5 asm_common_interrupt+0x106/0x180 _raw_spin_unlock_irqrestore+0x28/0x33 __mod_timer+0x1cd/0x1d8 mod_timer+0xa/0xc mld_ifc_start_timer+0x24/0x37 mld_ifc_timer_expire+0x1b0/0x1c0 call_timer_fn+0xfe/0x201 __run_timers+0x134/0x159 run_timer_softirq+0x14/0x27 __do_softirq+0x15f/0x307 call_on_stack+0x40/0x46 do_softirq_own_stack+0x1c/0x1e __irq_exit_rcu+0x4f/0x85 irq_exit_rcu+0x8/0x11 sysvec_apic_timer_interrupt+0x3e/0x4b handle_exception_return+0x0/0xaf default_idle+0xa/0xc arch_cpu_idle+0xd/0xf default_idle_call+0x48/0x74 do_idle+0xb7/0x1c3 cpu_startup_entry+0x19/0x1b rest_init+0x11d/0x120 arch_call_rest_init+0x8/0xb start_kernel+0x412/0x420 i386_start_kernel+0x43/0x45 startup_32_smp+0x164/0x168 irq event stamp: 8782 hardirqs last enabled at (8782): [<dd8929e2>] net_rx_action+0x75/0x250 hardirqs last disabled at (8781): [<dd8929bf>] net_rx_action+0x52/0x250 softirqs last enabled at (8772): [<dd99221f>] __do_softirq+0x2d7/0x307 softirqs last disabled at (8779): [<dd40fc2e>] call_on_stack+0x40/0x46 other info that might help us debug this: Possible unsafe locking scenario: CPU0 ---- lock(&syncp->seq#2); <Interrupt> lock(&syncp->seq#2); *** DEADLOCK *** 1 lock held by swapper/0/0: #0: c10818a0 (&tp->rx_lock){+.-.}-{2:2}, at: rtl8139_poll+0x31/0x34a stack backtrace: CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.11.0-rc6-Pentium4 #4 Hardware name: /FS51, BIOS 6.00 PG 12/02/2003 Call Trace: <SOFTIRQ> dump_stack+0x6b/0x89 print_usage_bug+0x17d/0x188 mark_lock.part.0+0xf8/0x272 ? check_chain_key+0xea/0x142 __lock_acquire+0x459/0x147f ? rcu_read_lock_sched_held+0x23/0x4a ? trace_kmalloc+0x8c/0xb9 ? __kmalloc_track_caller+0x113/0x126 lock_acquire+0x236/0x2b4 ? rtl8139_poll+0x24b/0x34a ? ksize+0xd/0x12 ? __alloc_skb+0x84/0x133 do_write_seqcount_begin_nested.constprop.0+0x1a/0x1f ? rtl8139_poll+0x24b/0x34a rtl8139_poll+0x24b/0x34a net_rx_action+0xd2/0x250 __do_softirq+0x15f/0x307 ? __entry_text_end+0x5/0x5 call_on_stack+0x40/0x46 </SOFTIRQ> ? __irq_exit_rcu+0x4f/0x85 ? irq_exit_rcu+0x8/0x11 ? common_interrupt+0xd3/0xe5 ? asm_common_interrupt+0x106/0x180 ? ldsem_down_write+0x1f/0x1f ? default_idle+0xa/0xc ? schedule_timeout+0x41/0x97 ? default_idle+0xa/0xc ? arch_cpu_idle+0xd/0xf ? default_idle_call+0x48/0x74 ? do_idle+0xb7/0x1c3 ? cpu_startup_entry+0x19/0x1b ? rest_init+0x11d/0x120 ? arch_call_rest_init+0x8/0xb ? start_kernel+0x412/0x420 ? i386_start_kernel+0x43/0x45 ? startup_32_smp+0x164/0x168 random: fast init done printk: console [netcon0] enabled netconsole: network logging started [...] # lspci 00:00.0 Host bridge: Silicon Integrated Systems [SiS] 651 Host (rev 02) 00:01.0 PCI bridge: Silicon Integrated Systems [SiS] AGP Port (virtual PCI-to-PCI bridge) 00:02.0 ISA bridge: Silicon Integrated Systems [SiS] SiS962 [MuTIOL Media IO] LPC Controller (rev 14) 00:02.1 SMBus: Silicon Integrated Systems [SiS] SiS961/2/3 SMBus controller 00:02.5 IDE interface: Silicon Integrated Systems [SiS] 5513 IDE Controller 00:02.7 Multimedia audio controller: Silicon Integrated Systems [SiS] SiS7012 AC'97 Sound Controller (rev a0) 00:03.0 USB controller: Silicon Integrated Systems [SiS] USB 1.1 Controller (rev 0f) 00:03.1 USB controller: Silicon Integrated Systems [SiS] USB 1.1 Controller (rev 0f) 00:03.2 USB controller: Silicon Integrated Systems [SiS] USB 1.1 Controller (rev 0f) 00:03.3 USB controller: Silicon Integrated Systems [SiS] USB 2.0 Controller 00:0a.0 Network controller: Ralink corp. RT2500 Wireless 802.11bg (rev 01) 00:0f.0 Ethernet controller: Realtek Semiconductor Co., Ltd. RTL-8100/8101L/8139 PCI Fast Ethernet Adapter (rev 10) 00:10.0 FireWire (IEEE 1394): VIA Technologies, Inc. VT6306/7/8 [Fire II(M)] IEEE 1394 OHCI Controller (rev 46) 01:00.0 VGA compatible controller: Advanced Micro Devices, Inc. [AMD/ATI] RV350 [Radeon 9550/9600/X1050 Series] 01:00.1 Display controller: Advanced Micro Devices, Inc. [AMD/ATI] RV350 [Radeon 9550/9600/X1050 Series] (Secondary) # LC_ALL=C lscpu Architecture: i686 CPU op-mode(s): 32-bit Byte Order: Little Endian Address sizes: 36 bits physical, 32 bits virtual CPU(s): 1 On-line CPU(s) list: 0 Thread(s) per core: 1 Core(s) per socket: 1 Socket(s): 1 Vendor ID: GenuineIntel CPU family: 15 Model: 2 Model name: Intel(R) Pentium(R) 4 CPU 3.06GHz Stepping: 7 CPU MHz: 3062.724 BogoMIPS: 6127.67 Vulnerability Itlb multihit: Processor vulnerable Vulnerability L1tf: Vulnerable Vulnerability Mds: Vulnerable: Clear CPU buffers attempted, no microcode; SMT disabled Vulnerability Meltdown: Vulnerable Vulnerability Spec store bypass: Vulnerable Vulnerability Spectre v1: Mitigation; usercopy/swapgs barriers and __user pointer sanitization Vulnerability Spectre v2: Mitigation; Full generic retpoline, STIBP disabled, RSB filling Vulnerability Srbds: Not affected Vulnerability Tsx async abort: Not affected Flags: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe pebs bts cpuid cid xtpr