Hello,
kernel test robot noticed "INFO:rcu_sched_detected_stalls_on_CPUs/tasks" on:
commit: 2e4f53117a649fdb8ccae2df5a4eb76b87c01ed6 ("serial: 8250: implement non-BKL console")
https://git.kernel.org/cgit/linux/kernel/git/rt/linux-rt-devel.git linux-6.5.y-rt-rebase
in testcase: boot
compiler: clang-16
test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
(please refer to attached dmesg/kmsg for entire log/backtrace)
If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <oliver.sang@xxxxxxxxx>
| Closes: https://lore.kernel.org/oe-lkp/202309102359.47ac0da8-oliver.sang@xxxxxxxxx
[ 167.273569][ C0] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
[ 167.273679][ C0] rcu: 1-...!: (0 ticks this GP) idle=1a34/1/0x40000000 softirq=11586/11586 fqs=0
[ 167.273715][ C0] rcu: (detected by 0, t=105002 jiffies, g=6757, q=16 ncpus=2)
[ 167.273724][ C0] Sending NMI from CPU 0 to CPUs 1:
[ 167.273757][ C1] NMI backtrace for cpu 1
[ 167.273760][ C1]
[ 167.273762][ C1] ================================
[ 167.273763][ C1] WARNING: inconsistent lock state
[ 167.273765][ C1] 6.5.2-00053-g2e4f53117a64 #1 Tainted: G S W T
[ 167.273767][ C1] --------------------------------
[ 167.273768][ C1] inconsistent {INITIAL USE} -> {IN-NMI} usage.
[ 167.273770][ C1] swapper/0/1 [HC1[1]:SC0[0]:HE0:SE1] takes:
[ 167.273773][ C1] c34fcd9c (console_srcu){....}-{0:0}, at: rcu_lock_acquire (include/linux/rcupdate.h:302)
[ 167.273787][ C1] {INITIAL USE} state was registered at:
[ 167.273789][ C1] lock_sync (kernel/locking/lockdep.c:5800)
[ 167.273795][ C1] srcu_lock_sync (include/linux/srcu.h:128)
[ 167.273800][ C1] __synchronize_srcu (kernel/rcu/srcutree.c:1347)
[ 167.273804][ C1] synchronize_srcu (kernel/rcu/srcutree.c:1442)
[ 167.273806][ C1] unregister_console_locked (kernel/printk/printk.c:3739)
[ 167.273810][ C1] register_console (kernel/printk/printk.c:3681)
[ 167.273814][ C1] univ8250_console_init (drivers/tty/serial/8250/8250_core.c:?)
[ 167.273819][ C1] console_init (include/linux/jump_label.h:270 include/trace/events/initcall.h:48 kernel/printk/printk.c:3837)
[ 167.273822][ C1] start_kernel (init/main.c:1005)
[ 167.273828][ C1] i386_start_kernel (arch/x86/kernel/head32.c:56)
[ 167.273831][ C1] startup_32_smp (??:?)
[ 167.273834][ C1] irq event stamp: 19150472
[ 167.273836][ C1] hardirqs last enabled at (19150471): _raw_spin_unlock_irqrestore (arch/x86/include/asm/irqflags.h:19 arch/x86/include/asm/irqflags.h:67 arch/x86/include/asm/irqflags.h:127 include/linux/spinlock_api_smp.h:151 kernel/locking/spinlock.c:194)
[ 167.273841][ C1] hardirqs last disabled at (19150472): _raw_spin_lock_irqsave (arch/x86/include/asm/preempt.h:80 include/linux/spinlock_api_smp.h:109 kernel/locking/spinlock.c:162)
[ 167.273846][ C1] softirqs last enabled at (19149630): do_softirq_own_stack (arch/x86/kernel/irq_32.c:57 arch/x86/kernel/irq_32.c:147)
[ 167.273852][ C1] softirqs last disabled at (19149623): do_softirq_own_stack (arch/x86/kernel/irq_32.c:57 arch/x86/kernel/irq_32.c:147)
[ 167.273857][ C1]
[ 167.273857][ C1] other info that might help us debug this:
[ 167.273858][ C1] Possible unsafe locking scenario:
[ 167.273858][ C1]
[ 167.273859][ C1] CPU0
[ 167.273860][ C1] ----
[ 167.273861][ C1] lock(console_srcu);
[ 167.273864][ C1] <Interrupt>
[ 167.273865][ C1] lock(console_srcu);
[ 167.273867][ C1]
[ 167.273867][ C1] *** DEADLOCK ***
[ 167.273867][ C1]
[ 167.273868][ C1] 4 locks held by swapper/0/1:
[ 167.273870][ C1] #0: c6a11af8 (&tty->legacy_mutex){+.+.}-{3:3}, at: tty_lock (drivers/tty/tty_mutex.c:19)
[ 167.273880][ C1] #1: eea4317c (&port->mutex){+.+.}-{3:3}, at: tty_port_open (arch/x86/include/asm/bitops.h:207 arch/x86/include/asm/bitops.h:239 include/asm-generic/bitops/instrumented-non-atomic.h:142 include/linux/tty_port.h:213 drivers/tty/tty_port.c:781)
[ 167.273889][ C1] #2: c450ca9c (&port_lock_key){....}-{2:2}, at: serial8250_do_startup (drivers/tty/serial/8250/8250_port.c:?)
[ 167.273899][ C1] #3: c34fcd9c (console_srcu){....}-{0:0}, at: rcu_lock_acquire (include/linux/rcupdate.h:302)
[ 167.273907][ C1]
[ 167.273907][ C1] stack backtrace:
[ 167.273910][ C1] CPU: 1 PID: 1 Comm: swapper/0 Tainted: G S W T 6.5.2-00053-g2e4f53117a64 #1
[ 167.273913][ C1] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
[ 167.273916][ C1] Call Trace:
[ 167.273919][ C1] dump_stack_lvl (lib/dump_stack.c:107)
[ 167.273924][ C1] ? vprintk (kernel/printk/printk_safe.c:69)
[ 167.273929][ C1] dump_stack (lib/dump_stack.c:113)
[ 167.273933][ C1] print_usage_bug (kernel/locking/lockdep.c:?)
[ 167.273938][ C1] verify_lock_unused (kernel/locking/lockdep.c:5685)
[ 167.273943][ C1] lock_acquire (kernel/locking/lockdep.c:5744)
[ 167.273948][ C1] ? trace_raw_output_console (include/linux/rcupdate.h:302)
[ 167.273953][ C1] rcu_lock_acquire (include/linux/rcupdate.h:303)
[ 167.273958][ C1] ? trace_raw_output_console (include/linux/rcupdate.h:302)
[ 167.273961][ C1] console_srcu_read_lock (kernel/printk/printk.c:292)
[ 167.273965][ C1] cons_atomic_flush (kernel/printk/printk_nobkl.c:?)
[ 167.273970][ C1] vprintk_emit (kernel/printk/printk.c:2306)
[ 167.273976][ C1] vprintk_deferred (kernel/printk/printk.c:4100)
[ 167.273981][ C1] vprintk (kernel/printk/printk_safe.c:69)
[ 167.273986][ C1] _printk (kernel/printk/printk.c:2370)
[ 167.273989][ C1] nmi_cpu_backtrace (lib/nmi_backtrace.c:109)
[ 167.273995][ C1] ? cons_read_seq (kernel/printk/printk_nobkl.c:938)
[ 167.273999][ C1] nmi_cpu_backtrace_handler (arch/x86/kernel/apic/hw_nmi.c:?)
[ 167.274003][ C1] nmi_handle (arch/x86/kernel/nmi.c:?)
[ 167.274007][ C1] ? ct_nmi_enter (kernel/context_tracking.c:297)
[ 167.274011][ C1] ? cons_read_seq (kernel/printk/printk_nobkl.c:938)
[ 167.274015][ C1] default_do_nmi (arch/x86/kernel/nmi.c:347)
[ 167.274021][ C1] exc_nmi (arch/x86/kernel/nmi.c:538)
[ 167.274026][ C1] asm_exc_nmi (??:?)
[ 167.274030][ C1] EIP: console_try_acquire (kernel/printk/printk_nobkl.c:938)
[ 167.274035][ C1] Code: 5d 31 c0 31 d2 c3 0f 1f 40 00 55 89 e5 56 8b 70 5c a1 18 ce 4f c3 e8 1f 2e 00 00 89 c1 29 f1 29 c8 83 da 00 5e 5d 31 c9 c3 90 <55> 89 e5 89 c1 e8 06 00 00 00 5d 31 c9 c3 66 90 55 89 e5 53 57 56
All code
========
0: 5d pop %rbp
1: 31 c0 xor %eax,%eax
3: 31 d2 xor %edx,%edx
5: c3 retq
6: 0f 1f 40 00 nopl 0x0(%rax)
a: 55 push %rbp
b: 89 e5 mov %esp,%ebp
d: 56 push %rsi
e: 8b 70 5c mov 0x5c(%rax),%esi
11: a1 18 ce 4f c3 e8 1f movabs 0x2e1fe8c34fce18,%eax
18: 2e 00
1a: 00 89 c1 29 f1 29 add %cl,0x29f129c1(%rcx)
20: c8 83 da 00 enterq $0xda83,$0x0
24: 5e pop %rsi
25: 5d pop %rbp
26: 31 c9 xor %ecx,%ecx
28: c3 retq
29: 90 nop
2a:* 55 push %rbp <-- trapping instruction
2b: 89 e5 mov %esp,%ebp
2d: 89 c1 mov %eax,%ecx
2f: e8 06 00 00 00 callq 0x3a
34: 5d pop %rbp
35: 31 c9 xor %ecx,%ecx
37: c3 retq
38: 66 90 xchg %ax,%ax
3a: 55 push %rbp
3b: 89 e5 mov %esp,%ebp
3d: 53 push %rbx
3e: 57 push %rdi
3f: 56 push %rsi
Code starting with the faulting instruction
===========================================
0: 55 push %rbp
1: 89 e5 mov %esp,%ebp
3: 89 c1 mov %eax,%ecx
5: e8 06 00 00 00 callq 0x10
a: 5d pop %rbp
b: 31 c9 xor %ecx,%ecx
d: c3 retq
e: 66 90 xchg %ax,%ax
10: 55 push %rbp
11: 89 e5 mov %esp,%ebp
13: 53 push %rbx
14: 57 push %rdi
15: 56 push %rsi
The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20230910/202309102359.47ac0da8-oliver.sang@xxxxxxxxx
--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki
