Re: Backtrace seen when enabling PREEMPT_RT

[Guenter Roeck <linux@roeck-us.net>]

On 2/11/25 09:22, Steven Rostedt wrote:
> On Tue, 11 Feb 2025 08:12:37 -0800
> Guenter Roeck <linux@roeck-us.net> wrote:
> 
>> Hi,
>>
>> When I tried to enable PREEMPT_RT together with various lock debugging
>> options, I got the attached backtraces.
>>
>> This is with qemu's ne2k_pci Ethernet emulation.
>>
>> Question: If I enable PREEMPT_RT tests at kerneltests.org, should I report
>> such issues or stop testing affected configurations (I understand that
>> ne2k_pci probably isn't used much nowadays).
> 
> Yes, I think you should still report this.
> 
>>
>> Thanks,
>> Guenter
>>
>> ---
>> Build reference: v6.14-rc2-8-g3309945911b8
>> Compiler version: x86_64-linux-gcc (GCC) 13.3.0
>> Qemu version: 9.1.2 (v9.1.2-51-g94825e22f3)
>> ...
>> Starting network: [   13.511263] ip (2707) used greatest stack depth: 11928 bytes left
>> [   13.708177] BUG: sleeping function called from invalid context at kernel/locking/spinlock_rt.c:48
>> [   13.708226] in_atomic(): 0, irqs_disabled(): 1, non_block: 0, pid: 8, name: kworker/0:0
> 
> Interrupts are disabled  while taking a spin_lock() (in RT that's a mutex).
> 
>> [   13.708236] preempt_count: 0, expected: 0
>> [   13.708242] RCU nest depth: 6, expected: 6
>> [   13.708265] 14 locks held by kworker/0:0/8:
>> [   13.708280]  #0: ff4dd8b344e6dd38 ((wq_completion)mld){+.+.}-{0:0}, at: process_one_work+0x590/0x6d0
>> [   13.708568]  #1: ff5a3c8a40057e48 ((work_completion)(&(&idev->mc_ifc_work)->work)){+.+.}-{0:0}, at: process_one_work+0x1df/0x6d0
>> [   13.708582]  #2: ff4dd8b344fbc620 (&idev->mc_lock){+.+.}-{4:4}, at: mld_ifc_work+0x32/0x560
>> [   13.708595]  #3: ffffffff90806f20 (rcu_read_lock){....}-{1:3}, at: mld_sendpack+0x73/0x380
>> [   13.708616]  #4: ffffffff90806f20 (rcu_read_lock){....}-{1:3}, at: ip6_finish_output2+0xe0/0xb80
>> [   13.708629]  #5: ff4dd8b3bf61c818 ((softirq_ctrl.lock)){+.+.}-{3:3}, at: __local_bh_disable_ip+0x94/0x180
>> [   13.708653]  #6: ffffffff90806f20 (rcu_read_lock){....}-{1:3}, at: rt_spin_lock+0xdf/0x170
>> [   13.708669]  #7: ffffffff90806f20 (rcu_read_lock){....}-{1:3}, at: __local_bh_disable_ip+0xab/0x180
>> [   13.708682]  #8: ffffffff90806ee0 (rcu_read_lock_bh){....}-{1:3}, at: __dev_queue_xmit+0x71/0x13b0
>> [   13.708694]  #9: ff4dd8b34566c398 (dev->qdisc_tx_busylock ?: &qdisc_tx_busylock){+...}-{3:3}, at: __dev_queue_xmit+0x1061/0x13b0
>> [   13.708705]  #10: ffffffff90806f20 (rcu_read_lock){....}-{1:3}, at: rt_spin_trylock+0x52/0xc0
>> [   13.708717]  #11: ff4dd8b344c66f58 (_xmit_ETHER#2){+...}-{3:3}, at: sch_direct_xmit+0x113/0x2b0
>> [   13.708737]  #12: ffffffff90806f20 (rcu_read_lock){....}-{1:3}, at: rt_spin_lock+0xdf/0x170
>> [   13.708752]  #13: ff4dd8b344c14e40 (&ei_local->page_lock){+.+.}-{3:3}, at: ei_start_xmit+0xb5/0x470
>> [   13.708793] irq event stamp: 198329
>> [   13.708799] hardirqs last  enabled at (198328): [<ffffffff8fa1fb36>] _raw_spin_unlock_irqrestore+0x46/0x70
>> [   13.708808] hardirqs last disabled at (198329): [<ffffffff8f31d897>] ei_start_xmit+0x2a7/0x470
> 
> Hmm, where is that ei_start_xmit+0x2a7, This would be good to run
> scripts/decode_stacktrace.sh on this.
> 

Does this help ?

[   13.163019] hardirqs last enabled at (52626): _raw_spin_unlock_irqrestore (arch/x86/include/asm/irqflags.h:26 arch/x86/include/asm/irqflags.h:87 arch/x86/include/asm/irqflags.h:147 include/linux/spinlock_api_smp.h:151 kernel/locking/spinlock.c:194)
[   13.163030] hardirqs last disabled at (52627): ei_start_xmit (include/linux/interrupt.h:460 (discriminator 1) drivers/net/ethernet/8390/lib8390.c:333 (discriminator 1) drivers/net/ethernet/8390/8390.c:23 (discriminator 1))
[   13.163038] softirqs last enabled at (52602): __local_bh_enable_ip (kernel/softirq.c:247)
[   13.163046] softirqs last disabled at (52608): __dev_queue_xmit (include/linux/bottom_half.h:20 (discriminator 1) include/linux/rcupdate.h:901 (discriminator 1) net/core/dev.c:4509 (discriminator 1))
[   13.163257] CPU: 2 UID: 0 PID: 59 Comm: kworker/2:1 Tainted: G                 N 6.14.0-rc2-00008-g3309945911b8 #1
[   13.163300] Tainted: [N]=TEST
[   13.163307] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 0.0.0 02/06/2015
[   13.163376] Workqueue: mld mld_ifc_work
[   13.163466] Call Trace:
[   13.163501]  <TASK>
[   13.163544] dump_stack_lvl (lib/dump_stack.c:123)
[   13.163584] __might_resched (kernel/sched/core.c:8767)
[   13.163607] rt_spin_lock (kernel/locking/spinlock_rt.c:40 kernel/locking/spinlock_rt.c:49 kernel/locking/spinlock_rt.c:57)
[   13.163618] ? ei_start_xmit (drivers/net/ethernet/8390/lib8390.c:337 drivers/net/ethernet/8390/8390.c:23)
[   13.163625] ? __disable_irq_nosync (kernel/irq/manage.c:702)
[   13.163638] ei_start_xmit (drivers/net/ethernet/8390/lib8390.c:337 drivers/net/ethernet/8390/8390.c:23)
[   13.163642] ? lock_acquire.part.0 (kernel/locking/lockdep.c:469 (discriminator 4) kernel/locking/lockdep.c:5853 (discriminator 4))
[   13.163685] dev_hard_start_xmit (include/linux/netdevice.h:5144 include/linux/netdevice.h:5153 net/core/dev.c:3735 net/core/dev.c:3751)
[   13.163709] sch_direct_xmit (net/sched/sch_generic.c:343)
[   13.163735] __dev_queue_xmit (net/core/dev.c:3974 (discriminator 1) net/core/dev.c:4550 (discriminator 1))
[   13.163751] ? lock_acquire.part.0 (kernel/locking/lockdep.c:469 (discriminator 4) kernel/locking/lockdep.c:5853 (discriminator 4))
[   13.163760] ? find_held_lock (kernel/locking/lockdep.c:5341 (discriminator 1))
[   13.163778] ? mark_held_locks (kernel/locking/lockdep.c:4323 (discriminator 1))
[   13.163790] ? eth_header (net/ethernet/eth.c:85)
[   13.163819] ip6_finish_output2 (include/net/neighbour.h:539 (discriminator 2) net/ipv6/ip6_output.c:141 (discriminator 2))
[   13.163843] ? ip6_mtu (net/ipv6/route.c:3220)
[   13.163869] mld_sendpack (net/ipv6/mcast.c:1866)
[   13.163918] mld_ifc_work (net/ipv6/mcast.c:2699)
[   13.163940] process_one_work (kernel/workqueue.c:3241)
[   13.163979] worker_thread (kernel/workqueue.c:3311 (discriminator 2) kernel/workqueue.c:3398 (discriminator 2))
[   13.163993] ? __pfx_worker_thread (kernel/workqueue.c:3344)
[   13.164000] kthread (kernel/kthread.c:464)
[   13.164015] ? __pfx_kthread (kernel/kthread.c:413)
[   13.164030] ret_from_fork (arch/x86/kernel/process.c:154)
[   13.164036] ? __pfx_kthread (kernel/kthread.c:413)
[   13.164046] ret_from_fork_asm (arch/x86/entry/entry_64.S:257)

Guenter