Re: [RFC PATCH] serial: core: Use pm_runtime_get_sync() in uart_start()

From: kernel test robot
Date: Tue Nov 28 2023 - 10:12:17 EST

Next message: Maxime Ripard: "Re: [RFC] drm/tests: annotate intentional stack trace in drm_test_rect_calc_hscale()"
Previous message: Jonathan Cameron: "Re: [PATCH RFC 13/22] arm64: setup: Switch over to GENERIC_CPU_DEVICES using arch_register_cpu()"
In reply to: Xuewen Yan: "Re: [RFC PATCH] serial: core: Use pm_runtime_get_sync() in uart_start()"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Hello,

kernel test robot noticed "BUG:sleeping_function_called_from_invalid_context_at_drivers/base/power/runtime.c" on:

commit: 81a787668db066cb86873bd4f8fbf7c36ac8dd5a ("[RFC PATCH] serial: core: Use pm_runtime_get_sync() in uart_start()")
url: https://github.com/intel-lab-lkp/linux/commits/Xuewen-Yan/serial-core-Use-pm_runtime_get_sync-in-uart_start/20231124-202425
base: https://git.kernel.org/cgit/linux/kernel/git/gregkh/tty.git tty-next
patch link: https://lore.kernel.org/all/20231124122258.1050-1-xuewen.yan@xxxxxxxxxx/
patch subject: [RFC PATCH] serial: core: Use pm_runtime_get_sync() in uart_start()

in testcase: boot

compiler: gcc-12
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/202311282251.b5351d99-oliver.sang@xxxxxxxxx

[ 678.716002][ T1] BUG: sleeping function called from invalid context at drivers/base/power/runtime.c:1163
[ 678.716028][ T1]
[ 678.716029][ T1] ======================================================
[ 678.716030][ T1] WARNING: possible circular locking dependency detected
[ 678.716031][ T1] 6.7.0-rc2-00001-g81a787668db0 #3 Tainted: G N
[ 678.716033][ T1] ------------------------------------------------------
[ 678.716033][ T1] init/1 is trying to acquire lock:
[ 678.716035][ T1] c249c82c (console_owner){-.-.}-{0:0}, at: console_flush_all (kernel/printk/printk.c:2894 kernel/printk/printk.c:2967)
[ 678.716047][ T1]
[ 678.716047][ T1] but task is already holding lock:
[ 678.716048][ T1] c3356e90 (&port_lock_key){-.-.}-{2:2}, at: uart_write (drivers/tty/serial/serial_core.c:598)
[ 678.716057][ T1]
[ 678.716057][ T1] which lock already depends on the new lock.
[ 678.716057][ T1]
[ 678.716057][ T1] the existing dependency chain (in reverse order) is:
[ 678.716058][ T1]
[ 678.716058][ T1] -> #1 (&port_lock_key){-.-.}-{2:2}:
[ 678.716062][ T1] __lock_acquire (kernel/locking/lockdep.c:5136)
[ 678.716066][ T1] lock_acquire (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:5755)
[ 678.716069][ T1] _raw_spin_lock_irqsave (include/linux/spinlock_api_smp.h:111 kernel/locking/spinlock.c:162)
[ 678.716073][ T1] serial8250_console_write (drivers/tty/serial/8250/8250_port.c:3396)
[ 678.716076][ T1] univ8250_console_write (drivers/tty/serial/8250/8250_core.c:601)
[ 678.716079][ T1] console_flush_all (kernel/printk/printk.c:2905 kernel/printk/printk.c:2967)
[ 678.716081][ T1] console_unlock (kernel/printk/printk.c:3037)
[ 678.716084][ T1] vprintk_emit (arch/x86/include/asm/preempt.h:85 kernel/printk/printk.c:2304)
[ 678.716086][ T1] vprintk_default (kernel/printk/printk.c:2319)
[ 678.716089][ T1] vprintk (kernel/printk/printk_safe.c:46)
[ 678.716091][ T1] _printk (kernel/printk/printk.c:2332)
[ 678.716093][ T1] register_console (kernel/printk/printk.c:3543)
[ 678.716096][ T1] univ8250_console_init (drivers/tty/serial/8250/8250_core.c:718)
[ 678.716102][ T1] console_init (arch/x86/include/asm/atomic.h:23 include/linux/atomic/atomic-arch-fallback.h:457 include/linux/jump_label.h:260 include/linux/jump_label.h:270 include/trace/events/initcall.h:48 kernel/printk/printk.c:3689)
[ 678.716104][ T1] start_kernel (init/main.c:1009 (discriminator 3))
[ 678.716108][ T1] i386_start_kernel (??:?)
[ 678.716112][ T1] startup_32_smp (arch/x86/kernel/head_32.S:295)
[ 678.716115][ T1]
[ 678.716115][ T1] -> #0 (console_owner){-.-.}-{0:0}:
[ 678.716118][ T1] check_prev_add (kernel/locking/lockdep.c:3135)
[ 678.716121][ T1] validate_chain (kernel/locking/lockdep.c:3254 kernel/locking/lockdep.c:3868)
[ 678.716124][ T1] __lock_acquire (kernel/locking/lockdep.c:5136)
[ 678.716126][ T1] lock_acquire (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:5755)
[ 678.716129][ T1] console_flush_all (kernel/printk/printk.c:2901 kernel/printk/printk.c:2967)
[ 678.716131][ T1] console_unlock (kernel/printk/printk.c:3037)
[ 678.716134][ T1] vprintk_emit (arch/x86/include/asm/preempt.h:85 kernel/printk/printk.c:2304)
[ 678.716136][ T1] vprintk_default (kernel/printk/printk.c:2319)
[ 678.716138][ T1] vprintk (kernel/printk/printk_safe.c:46)
[ 678.716140][ T1] _printk (kernel/printk/printk.c:2332)
[ 678.716142][ T1] __might_resched (kernel/sched/core.c:10130)
[ 678.716145][ T1] __might_sleep (kernel/sched/core.c:10081 (discriminator 17))
[ 678.716147][ T1] __pm_runtime_resume (drivers/base/power/runtime.c:1163 (discriminator 5))
[ 678.716152][ T1] __uart_start (drivers/tty/serial/serial_core.c:149)
[ 678.716156][ T1] uart_write (include/linux/spinlock.h:406 include/linux/serial_core.h:667 drivers/tty/serial/serial_core.c:617)
[ 678.716159][ T1] process_output_block (drivers/tty/n_tty.c:574)
[ 678.716163][ T1] n_tty_write (drivers/tty/n_tty.c:2380)
[ 678.716166][ T1] iterate_tty_write (drivers/tty/tty_io.c:1022)
[ 678.716169][ T1] file_tty_write+0x80/0x10c
[ 678.716172][ T1] redirected_tty_write (drivers/tty/tty_io.c:1137)
[ 678.716175][ T1] vfs_write (fs/read_write.c:492 fs/read_write.c:584)
[ 678.716179][ T1] ksys_write (fs/read_write.c:638)
[ 678.716180][ T1] __ia32_sys_write (fs/read_write.c:646)
[ 678.716182][ T1] do_int80_syscall_32 (arch/x86/entry/common.c:164 arch/x86/entry/common.c:184)
[ 678.716185][ T1] restore_all_switch_stack (arch/x86/entry/entry_32.S:947)
[ 678.716190][ T1]
[ 678.716190][ T1] other info that might help us debug this:
[ 678.716190][ T1]
[ 678.716191][ T1] Possible unsafe locking scenario:
[ 678.716191][ T1]
[ 678.716192][ T1] CPU0 CPU1
[ 678.716193][ T1] ---- ----
[ 678.716193][ T1] lock(&port_lock_key);
[ 678.716195][ T1] lock(console_owner);
[ 678.716196][ T1] lock(&port_lock_key);
[ 678.716198][ T1] lock(console_owner);
[ 678.716199][ T1]
[ 678.716199][ T1] *** DEADLOCK ***
[ 678.716199][ T1]
[ 678.716200][ T1] 7 locks held by init/1:
[ 678.716202][ T1] #0: c3fc5060 (&tty->ldisc_sem){++++}-{0:0}, at: ldsem_down_read (drivers/tty/tty_ldsem.c:341)
[ 678.716211][ T1] #1: c3fc50b8 (&tty->atomic_write_lock){+.+.}-{3:3}, at: iterate_tty_write (drivers/tty/tty_io.c:954 drivers/tty/tty_io.c:973)
[ 678.716217][ T1] #2: c3fc51c4 (&tty->termios_rwsem){++++}-{3:3}, at: n_tty_write (drivers/tty/n_tty.c:2365)
[ 678.716223][ T1] #3: ef4112f0 (&ldata->output_lock){+.+.}-{3:3}, at: process_output_block (drivers/tty/n_tty.c:531)
[ 678.716229][ T1] #4: c3356e90 (&port_lock_key){-.-.}-{2:2}, at: uart_write (drivers/tty/serial/serial_core.c:598)
[ 678.716236][ T1] #5: c27bc9a8 (console_lock){+.+.}-{0:0}, at: vprintk_default (kernel/printk/printk.c:2319)
[ 678.716241][ T1] #6: c27bca58 (console_srcu){....}-{0:0}, at: console_flush_all (include/linux/srcutiny.h:67 include/linux/srcu.h:70 include/linux/srcu.h:231 kernel/printk/printk.c:286 kernel/printk/printk.c:2959)
[ 678.716247][ T1]
[ 678.716247][ T1] stack backtrace:
[ 678.716248][ T1] CPU: 0 PID: 1 Comm: init Tainted: G N 6.7.0-rc2-00001-g81a787668db0 #3 457007a7b9fe78ab16bc9131e3cdb3e013769988
[ 678.716253][ T1] Call Trace:
[ 678.716254][ T1] dump_stack_lvl (lib/dump_stack.c:108)
[ 678.716259][ T1] dump_stack (lib/dump_stack.c:114)
[ 678.716262][ T1] print_circular_bug (kernel/locking/lockdep.c:2061)
[ 678.716266][ T1] check_noncircular (kernel/locking/lockdep.c:2190)
[ 678.716271][ T1] check_prev_add (kernel/locking/lockdep.c:3135)
[ 678.716275][ T1] validate_chain (kernel/locking/lockdep.c:3254 kernel/locking/lockdep.c:3868)
[ 678.716279][ T1] __lock_acquire (kernel/locking/lockdep.c:5136)
[ 678.716282][ T1] ? sched_clock_noinstr (arch/x86/kernel/tsc.c:267)
[ 678.716285][ T1] ? local_clock_noinstr (kernel/sched/clock.c:301)
[ 678.716290][ T1] lock_acquire (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:5755)
[ 678.716293][ T1] ? console_flush_all (kernel/printk/printk.c:2894 kernel/printk/printk.c:2967)
[ 678.716296][ T1] ? console_flush_all (kernel/printk/printk.c:1854 kernel/printk/printk.c:2895 kernel/printk/printk.c:2967)
[ 678.716299][ T1] ? lock_release (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:5775)
[ 678.716303][ T1] console_flush_all (kernel/printk/printk.c:2901 kernel/printk/printk.c:2967)
[ 678.716306][ T1] ? console_flush_all (kernel/printk/printk.c:2894 kernel/printk/printk.c:2967)
[ 678.716310][ T1] console_unlock (kernel/printk/printk.c:3037)
[ 678.716313][ T1] vprintk_emit (arch/x86/include/asm/preempt.h:85 kernel/printk/printk.c:2304)
[ 678.716316][ T1] vprintk_default (kernel/printk/printk.c:2319)
[ 678.716319][ T1] vprintk (kernel/printk/printk_safe.c:46)
[ 678.716322][ T1] _printk (kernel/printk/printk.c:2332)
[ 678.716324][ T1] __might_resched (kernel/sched/core.c:10130)
[ 678.716328][ T1] __might_sleep (kernel/sched/core.c:10081 (discriminator 17))
[ 678.716331][ T1] ? uart_write (drivers/tty/serial/serial_core.c:598)
[ 678.716335][ T1] ? lock_acquired (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:6035)
[ 678.716337][ T1] __pm_runtime_resume (drivers/base/power/runtime.c:1163 (discriminator 5))
[ 678.716341][ T1] ? _raw_spin_lock_irqsave (kernel/locking/spinlock.c:163)
[ 678.716344][ T1] __uart_start (drivers/tty/serial/serial_core.c:149)
[ 678.716348][ T1] uart_write (include/linux/spinlock.h:406 include/linux/serial_core.h:667 drivers/tty/serial/serial_core.c:617)
[ 678.716352][ T1] ? uart_write_room (drivers/tty/serial/serial_core.c:74 drivers/tty/serial/serial_core.c:630)
[ 678.716356][ T1] process_output_block (drivers/tty/n_tty.c:574)
[ 678.716361][ T1] n_tty_write (drivers/tty/n_tty.c:2380)
[ 678.716365][ T1] ? autoremove_wake_function (kernel/sched/wait.c:439)
[ 678.716370][ T1] iterate_tty_write (drivers/tty/tty_io.c:1022)
[ 678.716375][ T1] file_tty_write+0x80/0x10c
[ 678.716378][ T1] ? lock_release (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:5775)
[ 678.716382][ T1] redirected_tty_write (drivers/tty/tty_io.c:1137)
[ 678.716385][ T1] vfs_write (fs/read_write.c:492 fs/read_write.c:584)
[ 678.716389][ T1] ? exit_to_user_mode_prepare (kernel/entry/common.c:212 (discriminator 43))
[ 678.716395][ T1] ksys_write (fs/read_write.c:638)
[ 678.716398][ T1] __ia32_sys_write (fs/read_write.c:646)
[ 678.716400][ T1] do_int80_syscall_32 (arch/x86/entry/common.c:164 arch/x86/entry/common.c:184)
[ 678.716403][ T1] ? syscall_exit_to_user_mode (kernel/entry/common.c:299)
[ 678.716406][ T1] ? do_int80_syscall_32 (arch/x86/entry/common.c:188)
[ 678.716408][ T1] ? irqentry_exit_to_user_mode (kernel/entry/common.c:312)
[ 678.716412][ T1] ? irqentry_exit (kernel/entry/common.c:445)
[ 678.716415][ T1] ? exc_page_fault (arch/x86/mm/fault.c:1565)
[ 678.716417][ T1] ? rest_init (init/main.c:1433)
[ 678.716420][ T1] entry_INT80_32 (arch/x86/entry/entry_32.S:947)
[ 678.716424][ T1] EIP: 0xb7e9b6c2
[ 678.716427][ T1] Code: 90 66 90 66 90 66 90 90 56 53 83 ec 14 8b 5c 24 20 8b 4c 24 24 8b 54 24 28 65 a1 0c 00 00 00 85 c0 75 15 b8 04 00 00 00 cd 80 <3d> 00 f0 ff ff 77 47 83 c4 14 5b 5e c3 90 89 54 24 0c 89 4c 24 08
All code
========
0: 90 nop
1: 66 90 xchg %ax,%ax
3: 66 90 xchg %ax,%ax
5: 66 90 xchg %ax,%ax
7: 90 nop
8: 56 push %rsi
9: 53 push %rbx
a: 83 ec 14 sub $0x14,%esp
d: 8b 5c 24 20 mov 0x20(%rsp),%ebx
11: 8b 4c 24 24 mov 0x24(%rsp),%ecx
15: 8b 54 24 28 mov 0x28(%rsp),%edx
19: 65 a1 0c 00 00 00 85 movabs %gs:0x1575c0850000000c,%eax
20: c0 75 15
23: b8 04 00 00 00 mov $0x4,%eax
28: cd 80 int $0x80

The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20231128/202311282251.b5351d99-oliver.sang@xxxxxxxxx

--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

Next message: Maxime Ripard: "Re: [RFC] drm/tests: annotate intentional stack trace in drm_test_rect_calc_hscale()"
Previous message: Jonathan Cameron: "Re: [PATCH RFC 13/22] arm64: setup: Switch over to GENERIC_CPU_DEVICES using arch_register_cpu()"
In reply to: Xuewen Yan: "Re: [RFC PATCH] serial: core: Use pm_runtime_get_sync() in uart_start()"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]