Hello,
Today it saw sysrq on an UART driven by drivers/tty/serial/imx.c report
a lockdep issue. Bisecting pointed to
fd5f7cde1b85 ("printk: Never set console_may_schedule in
console_trylock()")
When I type <break>t I get:
[ 87.940104] sysrq: SysRq : This sysrq operation is disabled.
[ 87.948752]
[ 87.948772] ======================================================
[ 87.948787] WARNING: possible circular locking dependency detected
[ 87.948798] 4.14.0-12954-gfd5f7cde1b85 #26 Not tainted
[ 87.948813] ------------------------------------------------------
[ 87.948822] swapper/0 is trying to acquire lock:
[ 87.948829] (console_owner){-...}, at: [<c015e438>]
console_unlock+0x110/0x598
[ 87.948861]
[ 87.948869] but task is already holding lock:
[ 87.948874] (&port_lock_key){-.-.}, at: [<c048d5b0>] imx_rxint+0x2c/0x290
[ 87.948902]
[ 87.948911] which lock already depends on the new lock.
[ 87.948917]
[ 87.948923]
[ 87.948932] the existing dependency chain (in reverse order) is:
[ 87.948938]
[ 87.948943] -> #1 (&port_lock_key){-.-.}:
[ 87.948975] _raw_spin_lock_irqsave+0x5c/0x70
[ 87.948983] imx_console_write+0x138/0x15c
[ 87.948991] console_unlock+0x204/0x598
[ 87.949000] register_console+0x21c/0x3e8
[ 87.949008] uart_add_one_port+0x3e4/0x4dc
[ 87.949019] platform_drv_probe+0x3c/0x78
[ 87.949027] driver_probe_device+0x25c/0x47c
[ 87.949035] __driver_attach+0xec/0x114
[ 87.949044] bus_for_each_dev+0x80/0xb0
[ 87.949054] bus_add_driver+0x1d4/0x264
[ 87.949062] driver_register+0x80/0xfc
[ 87.949069] imx_serial_init+0x28/0x48
[ 87.949078] do_one_initcall+0x44/0x18c
[ 87.949087] kernel_init_freeable+0x11c/0x1cc
[ 87.949095] kernel_init+0x10/0x114
[ 87.949103] ret_from_fork+0x14/0x30
[ 87.949108]
[ 87.949113] -> #0 (console_owner){-...}:
[ 87.949145] lock_acquire+0x100/0x23c
[ 87.949154] console_unlock+0x1a4/0x598
[ 87.949162] vprintk_emit+0x1a4/0x45c
[ 87.949171] vprintk_default+0x28/0x30
[ 87.949180] printk+0x28/0x38
[ 87.949189] __handle_sysrq+0x1c4/0x244
[ 87.949196] imx_rxint+0x258/0x290
[ 87.949206] imx_int+0x170/0x178
[ 87.949216] __handle_irq_event_percpu+0x78/0x418
[ 87.949225] handle_irq_event_percpu+0x24/0x6c
[ 87.949233] handle_irq_event+0x40/0x64
[ 87.949242] handle_level_irq+0xb4/0x138
[ 87.949252] generic_handle_irq+0x28/0x3c
[ 87.949261] __handle_domain_irq+0x50/0xb0
[ 87.949269] avic_handle_irq+0x3c/0x5c
[ 87.949277] __irq_svc+0x6c/0xa4
[ 87.949287] arch_cpu_idle+0x30/0x40
[ 87.949297] arch_cpu_idle+0x30/0x40
[ 87.949305] do_idle+0xa0/0x104
[ 87.949313] cpu_startup_entry+0x14/0x18
[ 87.949323] start_kernel+0x30c/0x368
[ 87.949328]
[ 87.949337] other info that might help us debug this:
[ 87.949342]
[ 87.949351] Possible unsafe locking scenario:
[ 87.949356]
[ 87.949364] CPU0 CPU1
[ 87.949372] ---- ----
[ 87.949378] lock(&port_lock_key);
[ 87.949398] lock(console_owner);
[ 87.949423] lock(&port_lock_key);
[ 87.949441] lock(console_owner);
[ 87.949459]
[ 87.949466] *** DEADLOCK ***
[ 87.949471]
[ 87.949478] 3 locks held by swapper/0:
[ 87.949484] #0: (&port_lock_key){-.-.}, at: [<c048d5b0>]
imx_rxint+0x2c/0x290
[ 87.949515] #1: (rcu_read_lock){....}, at: [<c0486ea8>]
__handle_sysrq+0x0/0x244
[ 87.949549] #2: (console_lock){+.+.}, at: [<c015ea58>]
vprintk_emit+0x198/0x45c
[ 87.949581]
[ 87.949588] stack backtrace:
[ 87.949600] CPU: 0 PID: 0 Comm: swapper Not tainted
4.14.0-12954-gfd5f7cde1b85 #26
[ 87.949611] Hardware name: Freescale i.MX25 (Device Tree Support)
[ 87.949623] [<c0108f70>] (unwind_backtrace) from [<c010680c>]
(show_stack+0x18/0x1c)
[ 87.949635] [<c010680c>] (show_stack) from [<c01526ec>]
(print_circular_bug+0x284/0x3c0)
[ 87.949647] [<c01526ec>] (print_circular_bug) from [<c0153714>]
(check_prev_add+0x4ac/0x7cc)
[ 87.949660] [<c0153714>] (check_prev_add) from [<c015561c>]
(__lock_acquire+0x9e8/0x13bc)
[ 87.949671] [<c015561c>] (__lock_acquire) from [<c0156a28>]
(lock_acquire+0x100/0x23c)
[ 87.949683] [<c0156a28>] (lock_acquire) from [<c015e4cc>]
(console_unlock+0x1a4/0x598)
[ 87.949696] [<c015e4cc>] (console_unlock) from [<c015ea64>]
(vprintk_emit+0x1a4/0x45c)
[ 87.949707] [<c015ea64>] (vprintk_emit) from [<c015eec8>]
(vprintk_default+0x28/0x30)
[ 87.949719] [<c015eec8>] (vprintk_default) from [<c015fa80>]
(printk+0x28/0x38)
[ 87.949730] [<c015fa80>] (printk) from [<c048706c>]
(__handle_sysrq+0x1c4/0x244)
[ 87.949742] [<c048706c>] (__handle_sysrq) from [<c048d7dc>]
(imx_rxint+0x258/0x290)
[ 87.949753] [<c048d7dc>] (imx_rxint) from [<c048edd0>] (imx_int+0x170/0x178)
[ 87.949765] [<c048edd0>] (imx_int) from [<c0160ce4>]
(__handle_irq_event_percpu+0x78/0x418)
[ 87.949781] [<c0160ce4>] (__handle_irq_event_percpu) from [<c01610a8>]
(handle_irq_event_percpu+0x24/0x6c)
[ 87.949794] [<c01610a8>] (handle_irq_event_percpu) from [<c0161130>]
(handle_irq_event+0x40/0x64)
[ 87.949808] [<c0161130>] (handle_irq_event) from [<c01642b4>]
(handle_level_irq+0xb4/0x138)
[ 87.949821] [<c01642b4>] (handle_level_irq) from [<c01602dc>]
(generic_handle_irq+0x28/0x3c)
[ 87.949833] [<c01602dc>] (generic_handle_irq) from [<c01608e4>]
(__handle_domain_irq+0x50/0xb0)
[ 87.949846] [<c01608e4>] (__handle_domain_irq) from [<c0101494>]
(avic_handle_irq+0x3c/0x5c)
[ 87.949857] [<c0101494>] (avic_handle_irq) from [<c01075ec>]
(__irq_svc+0x6c/0xa4)
[ 87.949866] Exception stack(0xc0c01f48 to 0xc0c01f90)
[ 87.949879] 1f40: 00000001 00000001 00000000 20000013
ffffe000 c0c078c8
[ 87.949891] 1f60: c0c835aa c094ac0c c7eeca40 c0b3a920 00053177 00000000
00000000 c0c01f98
[ 87.949900] 1f80: c01548b4 c01033bc 20000013 ffffffff
[ 87.949911] [<c01075ec>] (__irq_svc) from [<c01033bc>]
(arch_cpu_idle+0x30/0x40)
[ 87.949922] [<c01033bc>] (arch_cpu_idle) from [<c014f09c>]
(do_idle+0xa0/0x104)
[ 87.949934] [<c014f09c>] (do_idle) from [<c014f448>]
(cpu_startup_entry+0x14/0x18)
[ 87.949946] [<c014f448>] (cpu_startup_entry) from [<c0b00c78>]
(start_kernel+0x30c/0x368)
I didn't even try to understand that change, so for now you just get the
lockdep splat :-)
Best regards
Uwe
--
Pengutronix e.K. | Uwe Kleine-König |
Industrial Linux Solutions | http://www.pengutronix.de/ |
