Hello,
kernel test robot noticed "INFO:rcu_preempt_detected_stalls_on_CPUs/tasks" on:
commit: bbed94a61d7be55a64c9d87e0c5d55faef924f57 ("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: gcc-7
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/202308312242.eb909be8-oliver.sang@xxxxxxxxx
[ 148.995863][ C1] NMI backtrace for cpu 1
[ 148.995867][ C1]
[ 148.995868][ C1] ================================
[ 148.995870][ C1] WARNING: inconsistent lock state
[ 148.995871][ C1] 6.5.0-00051-gbbed94a61d7b #1 Tainted: G W N
[ 148.995873][ C1] --------------------------------
[ 148.995874][ C1] inconsistent {INITIAL USE} -> {IN-NMI} usage.
[ 148.995876][ C1] swapper/0/1 [HC1[1]:SC0[0]:HE0:SE1] takes:
[ 148.995878][ C1] 828529a8 (console_srcu){....}-{0:0}, at: rcu_lock_acquire (include/linux/rcupdate.h:302)
[ 148.995889][ C1] {INITIAL USE} state was registered at:
[ 148.995890][ C1] lock_sync (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:5811)
[ 148.995893][ C1] __synchronize_srcu (kernel/rcu/srcutree.c:1347)
[ 148.995897][ C1] synchronize_srcu_expedited (kernel/rcu/srcutree.c:1386)
[ 148.995900][ C1] synchronize_srcu (kernel/rcu/srcutree.c:1439)
[ 148.995902][ C1] unregister_console_locked (kernel/printk/printk.c:3739)
[ 148.995905][ C1] register_console (kernel/printk/printk.c:3681)
[ 148.995908][ C1] univ8250_console_init (drivers/tty/serial/8250/8250_core.c:754)
[ 148.995911][ C1] console_init (kernel/printk/printk.c:3836)
[ 148.995913][ C1] start_kernel (init/main.c:1005 (discriminator 3))
[ 148.995917][ C1] mk_early_pgtbl_32 (arch/x86/kernel/head32.c:74)
[ 148.995919][ C1] startup_32_smp (arch/x86/kernel/head_32.S:305)
[ 148.995921][ C1] irq event stamp: 3902978
[ 148.995922][ C1] hardirqs last enabled at (3902977): _raw_spin_unlock_irqrestore (arch/x86/include/asm/irqflags.h:26 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)
[ 148.995926][ C1] hardirqs last disabled at (3902978): _raw_spin_lock_irqsave (arch/x86/include/asm/preempt.h:80 include/linux/spinlock_api_smp.h:109 kernel/locking/spinlock.c:162)
[ 148.995929][ C1] softirqs last enabled at (3902962): __do_softirq (arch/x86/include/asm/preempt.h:27 kernel/softirq.c:413 kernel/softirq.c:595)
[ 148.995932][ C1] softirqs last disabled at (3902951): call_on_stack (arch/x86/kernel/irq_32.c:57)
[ 148.995936][ C1]
[ 148.995936][ C1] other info that might help us debug this:
[ 148.995937][ C1] Possible unsafe locking scenario:
[ 148.995937][ C1]
[ 148.995938][ C1] CPU0
[ 148.995938][ C1] ----
[ 148.995939][ C1] lock(console_srcu);
[ 148.995941][ C1] <Interrupt>
[ 148.995941][ C1] lock(console_srcu);
[ 148.995943][ C1]
[ 148.995943][ C1] *** DEADLOCK ***
[ 148.995943][ C1]
[ 148.995943][ C1] 4 locks held by swapper/0/1:
[ 148.995945][ C1] #0: ed98f914 (&tty->legacy_mutex){+.+.}-{3:3}, at: tty_lock (drivers/tty/tty_mutex.c:19)
[ 148.995952][ C1] #1: 868f51b4 (&port->mutex){+.+.}-{3:3}, at: tty_port_open (drivers/tty/tty_port.c:781)
[ 148.995957][ C1] #2: 8365b8d0 (&port_lock_key){....}-{2:2}, at: serial8250_do_startup (drivers/tty/serial/8250/8250_port.c:2366)
[ 148.995964][ C1] #3: 828529a8 (console_srcu){....}-{0:0}, at: rcu_lock_acquire (include/linux/rcupdate.h:302)
[ 148.995970][ C1]
[ 148.995970][ C1] stack backtrace:
[ 148.995971][ C1] CPU: 1 PID: 1 Comm: swapper/0 Tainted: G W N 6.5.0-00051-gbbed94a61d7b #1
[ 148.995975][ C1] Call Trace:
[ 148.995979][ C1] dump_stack_lvl (lib/dump_stack.c:107)
[ 148.995982][ C1] dump_stack (lib/dump_stack.c:114)
[ 148.995985][ C1] print_usage_bug (kernel/locking/lockdep.c:4008)
[ 148.995988][ C1] ? console_list_unlock (include/linux/rcupdate.h:302)
[ 148.995991][ C1] lock_acquire (kernel/locking/lockdep.c:5693 kernel/locking/lockdep.c:5752)
[ 148.995994][ C1] ? console_list_unlock (include/linux/rcupdate.h:302)
[ 148.995997][ C1] ? prb_final_commit (kernel/printk/printk_ringbuffer.c:1671)
[ 148.996000][ C1] rcu_lock_acquire (include/linux/rcupdate.h:304)
[ 148.996002][ C1] ? console_list_unlock (include/linux/rcupdate.h:302)
[ 148.996005][ C1] console_srcu_read_lock (kernel/printk/printk.c:293)
[ 148.996007][ C1] cons_atomic_flush (kernel/printk/printk_nobkl.c:1587)
[ 148.996012][ C1] vprintk_emit (kernel/printk/printk.c:2333)
[ 148.996017][ C1] vprintk_deferred (kernel/printk/printk.c:4101)
[ 148.996021][ C1] vprintk (kernel/printk/printk_safe.c:65)
[ 148.996023][ C1] _printk (kernel/printk/printk.c:2371)
[ 148.996026][ C1] nmi_cpu_backtrace (lib/nmi_backtrace.c:110)
[ 148.996029][ C1] nmi_cpu_backtrace_handler (arch/x86/kernel/apic/hw_nmi.c:46)
[ 148.996033][ C1] nmi_handle (arch/x86/kernel/nmi.c:150 (discriminator 7))
[ 148.996037][ C1] default_do_nmi (arch/x86/kernel/nmi.c:347)
[ 148.996041][ C1] exc_nmi (arch/x86/kernel/nmi.c:543)
[ 148.996043][ C1] asm_exc_nmi (arch/x86/entry/entry_32.S:1149)
[ 148.996046][ C1] EIP: cons_try_acquire (kernel/printk/printk_nobkl.c:736 kernel/printk/printk_nobkl.c:836)
[ 148.996049][ C1] Code: 34 8d 00 00 00 00 83 e0 e3 89 55 e8 83 e7 03 c1 e7 03 09 f0 09 f8 83 e0 9f 88 45 e8 8b 45 e8 25 7f 00 00 fe 0b 45 d0 89 45 e8 <8a> 45 e4 a8 01 75 1f 8d 45 e8 8d 4d e4 31 d2 50 8b 45 e0 e8 60 fd
All code
========
0: 34 8d xor $0x8d,%al
2: 00 00 add %al,(%rax)
4: 00 00 add %al,(%rax)
6: 83 e0 e3 and $0xffffffe3,%eax
9: 89 55 e8 mov %edx,-0x18(%rbp)
c: 83 e7 03 and $0x3,%edi
f: c1 e7 03 shl $0x3,%edi
12: 09 f0 or %esi,%eax
14: 09 f8 or %edi,%eax
16: 83 e0 9f and $0xffffff9f,%eax
19: 88 45 e8 mov %al,-0x18(%rbp)
1c: 8b 45 e8 mov -0x18(%rbp),%eax
1f: 25 7f 00 00 fe and $0xfe00007f,%eax
24: 0b 45 d0 or -0x30(%rbp),%eax
27: 89 45 e8 mov %eax,-0x18(%rbp)
2a:* 8a 45 e4 mov -0x1c(%rbp),%al <-- trapping instruction
2d: a8 01 test $0x1,%al
2f: 75 1f jne 0x50
31: 8d 45 e8 lea -0x18(%rbp),%eax
34: 8d 4d e4 lea -0x1c(%rbp),%ecx
37: 31 d2 xor %edx,%edx
39: 50 push %rax
3a: 8b 45 e0 mov -0x20(%rbp),%eax
3d: e8 .byte 0xe8
3e: 60 (bad)
3f: fd std
Code starting with the faulting instruction
===========================================
0: 8a 45 e4 mov -0x1c(%rbp),%al
3: a8 01 test $0x1,%al
5: 75 1f jne 0x26
7: 8d 45 e8 lea -0x18(%rbp),%eax
a: 8d 4d e4 lea -0x1c(%rbp),%ecx
d: 31 d2 xor %edx,%edx
f: 50 push %rax
10: 8b 45 e0 mov -0x20(%rbp),%eax
13: e8 .byte 0xe8
14: 60 (bad)
15: fd std
[ 148.996052][ C1] EAX: 00000089 EBX: 8365bb40 ECX: 00000000 EDX: 0000000d
[ 148.996054][ C1] ESI: 00000000 EDI: 00000008 EBP: 865f5d30 ESP: 865f5d00
[ 148.996055][ C1] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 EFLAGS: 00000002
[ 148.996059][ C1] ? build_sched_domains (kernel/sched/topology.c:2268 kernel/sched/topology.c:1467 kernel/sched/topology.c:2494)
[ 148.996064][ C1] ? build_sched_domains (kernel/sched/topology.c:2268 kernel/sched/topology.c:1467 kernel/sched/topology.c:2494)
[ 148.996067][ C1] ? cons_try_acquire (kernel/printk/printk_nobkl.c:736 kernel/printk/printk_nobkl.c:836)
[ 148.996071][ C1] console_try_acquire (kernel/printk/printk_nobkl.c:942)
[ 148.996074][ C1] serial8250_enter_unsafe (drivers/tty/serial/8250/8250.h:222 drivers/tty/serial/8250/8250.h:250)
[ 148.996077][ C1] serial8250_do_startup (drivers/tty/serial/8250/8250_port.c:2369)
[ 148.996081][ C1] serial8250_startup (drivers/tty/serial/8250/8250_port.c:2513)
[ 148.996084][ C1] uart_startup (drivers/tty/serial/serial_core.c:290 drivers/tty/serial/serial_core.c:332)
[ 148.996086][ C1] uart_port_activate (drivers/tty/serial/serial_core.c:1967)
[ 148.996089][ C1] tty_port_open (drivers/tty/tty_port.c:786)
[ 148.996092][ C1] uart_open (drivers/tty/serial/serial_core.c:1950)
[ 148.996095][ C1] tty_open (drivers/tty/tty_io.c:2154)
[ 148.996100][ C1] chrdev_open (fs/char_dev.c:415)
[ 148.996105][ C1] do_dentry_open (fs/open.c:915)
[ 148.996107][ C1] ? cdev_put (fs/char_dev.c:374)
[ 148.996110][ C1] vfs_open (fs/open.c:1049)
[ 148.996112][ C1] path_openat (fs/namei.c:3636 fs/namei.c:3793)
[ 148.996117][ C1] do_filp_open (fs/namei.c:3821)
[ 148.996122][ C1] ? kmemleak_alloc (mm/kmemleak.c:724 mm/kmemleak.c:976)
[ 148.996126][ C1] ? slab_post_alloc_hook+0x7e/0x8d
[ 148.996132][ C1] file_open_name (fs/open.c:1353)
[ 148.996136][ C1] filp_open (fs/open.c:1372)
[ 148.996138][ C1] console_on_rootfs (init/main.c:1508)
[ 148.996141][ C1] kernel_init_freeable (init/main.c:1557)
[ 148.996144][ C1] ? rest_init (init/main.c:1429)
[ 148.996146][ C1] kernel_init (init/main.c:1439)
[ 148.996148][ C1] ret_from_fork (arch/x86/kernel/process.c:151)
[ 148.996151][ C1] ? rest_init (init/main.c:1429)
[ 148.996154][ C1] ret_from_fork_asm (arch/x86/entry/entry_32.S:741)
[ 148.996156][ C1] entry_INT80_32 (arch/x86/entry/entry_32.S:947)
[ 148.996161][ C1] CPU: 1 PID: 1 Comm: swapper/0 Tainted: G W N 6.5.0-00051-gbbed94a61d7b #1
[ 148.996163][ C1] EIP: cons_try_acquire (kernel/printk/printk_nobkl.c:736 kernel/printk/printk_nobkl.c:836)
[ 148.996165][ C1] Code: 34 8d 00 00 00 00 83 e0 e3 89 55 e8 83 e7 03 c1 e7 03 09 f0 09 f8 83 e0 9f 88 45 e8 8b 45 e8 25 7f 00 00 fe 0b 45 d0 89 45 e8 <8a> 45 e4 a8 01 75 1f 8d 45 e8 8d 4d e4 31 d2 50 8b 45 e0 e8 60 fd
All code
========
0: 34 8d xor $0x8d,%al
2: 00 00 add %al,(%rax)
4: 00 00 add %al,(%rax)
6: 83 e0 e3 and $0xffffffe3,%eax
The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20230831/202308312242.eb909be8-oliver.sang@xxxxxxxxx
--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki
