[0/2] Fix BUG: Invalid wait context in hrtimer_interrupt()
mbox series

Message ID 20210123233741.3614408-1-qais.yousef@arm.com
Headers show
Series
  • Fix BUG: Invalid wait context in hrtimer_interrupt()
Related show

Message

Qais Yousef Jan. 23, 2021, 11:37 p.m. UTC
I hit a pr_warn() inside hrtimer_interrupt() which lead to a BUG: Invalid wait
context splat.

The problem wasn't reproducible but I think the cause is obvious, printk can't
be called from interrupt context.

AFAICU printk_deferred() is safe from NMI, so I assumed it is safe to be called
from hrtimer_interrupt() too. Adding a pr_warn_once() inside
hrtimer_interrupt() in a location where it is always hit produces the BUG
splat. Replacing it with pr_warn_deferred_once() generates the printk warning
without any splat.

I added a new pr_*_deferred_once() variants to avoid open coding; but the name
ended not much shorter and I'm not sure if the wrappers are a win overall.
Since I've already done it, I'm sticking to it in this post. But will be happy
to drop it and just open code the printk_deferred_once(KERN_WARN, ...) in
hrtimer_interrupt() instead.

Thanks

Qais Yousef (2):
  printk: Add new pr_*_deferred_once() variants
  hrtimer: Use pr_warn_deferred_once() in hrtimer_interrupt()

 include/linux/printk.h | 24 ++++++++++++++++++++++++
 kernel/time/hrtimer.c  |  3 ++-
 2 files changed, 26 insertions(+), 1 deletion(-)

Comments

Sergey Senozhatsky Jan. 26, 2021, 4:46 a.m. UTC | #1
On (21/01/23 23:37), Qais Yousef wrote:
> 
> I hit a pr_warn() inside hrtimer_interrupt() which lead to a BUG: Invalid wait
> context splat.
> 
> The problem wasn't reproducible but I think the cause is obvious, printk can't
> be called from interrupt context.
> 
> AFAICU printk_deferred() is safe from NMI, so I assumed it is safe to be called
> from hrtimer_interrupt() too. Adding a pr_warn_once() inside
> hrtimer_interrupt() in a location where it is always hit produces the BUG
> splat. Replacing it with pr_warn_deferred_once() generates the printk warning
> without any splat.

Could you please post the lockdep splat?
Why is it invalid? Is this... -rt kernel, perhaps?

	-ss
Qais Yousef Jan. 26, 2021, 2:59 p.m. UTC | #2
On 01/26/21 13:46, Sergey Senozhatsky wrote:
> On (21/01/23 23:37), Qais Yousef wrote:
> > 
> > I hit a pr_warn() inside hrtimer_interrupt() which lead to a BUG: Invalid wait
> > context splat.
> > 
> > The problem wasn't reproducible but I think the cause is obvious, printk can't
> > be called from interrupt context.
> > 
> > AFAICU printk_deferred() is safe from NMI, so I assumed it is safe to be called
> > from hrtimer_interrupt() too. Adding a pr_warn_once() inside
> > hrtimer_interrupt() in a location where it is always hit produces the BUG
> > splat. Replacing it with pr_warn_deferred_once() generates the printk warning
> > without any splat.
> 
> Could you please post the lockdep splat?

Sorry I should have done that. I thought printk() in interrupt is not allowed
and obvious.

I reported it here: https://lore.kernel.org/lkml/20210114124512.mg3vexudfmoadef5@e107158-lin/

	# [67628.388606] hrtimer: interrupt took 304720 ns
	[67628.393546]
	[67628.393550] =============================
	[67628.393554] [ BUG: Invalid wait context ]
	[67628.393557] 5.11.0-rc3-00019-g86be331946f7 #37 Not tainted
	[67628.393560] -----------------------------
	[67628.393563] sugov:0/192 is trying to lock:
	[67628.393566] ffff000800b1d898 (&port_lock_key){-.-.}-{3:3}, at: pl011_console_write+0x138/0x218
	[67628.393581] other info that might help us debug this:
	[67628.393584] context-{2:2}
	[67628.393586] 4 locks held by sugov:0/192:
	[67628.393589]  #0: ffff0008059cb720 (&sg_policy->work_lock){+.+.}-{4:4}, at: sugov_work+0x58/0x88
	[67628.393603]  #1: ffff800015446f20 (prepare_lock){+.+.}-{4:4}, at: clk_prepare_lock+0x34/0xb0
	[67628.393618]  #2: ffff8000152aaa60 (console_lock){+.+.}-{0:0}, at: vprintk_emit+0x12c/0x310
	[67628.393632]  #3: ffff8000152aab88 (console_owner){-.-.}-{0:0}, at: console_unlock+0x190/0x6d8
	[67628.393646] stack backtrace:
	[67628.393649] CPU: 0 PID: 192 Comm: sugov:0 Not tainted 5.11.0-rc3-00019-g86be331946f7 #37
	[67628.393653] Hardware name: ARM Juno development board (r2) (DT)
	[67628.393656] Call trace:
	[67628.393659]  dump_backtrace+0x0/0x1b0
	[67628.393661]  show_stack+0x20/0x70
	[67628.393664]  dump_stack+0xf8/0x168
	[67628.393666]  __lock_acquire+0x964/0x1c88
	[67628.393669]  lock_acquire+0x26c/0x500
	[67628.393671]  _raw_spin_lock+0x64/0x88
	[67628.393674]  pl011_console_write+0x138/0x218
	[67628.393677]  console_unlock+0x2c4/0x6d8
	[67628.393680]  vprintk_emit+0x134/0x310
	[67628.393682]  vprintk_default+0x40/0x50
	[67628.393685]  vprintk_func+0xfc/0x2b0
	[67628.393687]  printk+0x68/0x90
	[67628.393690]  hrtimer_interrupt+0x24c/0x250
	[67628.393693]  arch_timer_handler_phys+0x3c/0x50
	[67628.393695]  handle_percpu_devid_irq+0xd8/0x460
	[67628.393698]  generic_handle_irq+0x38/0x50
	[67628.393701]  __handle_domain_irq+0x6c/0xc8
	[67628.393704]  gic_handle_irq+0xb0/0xf0
	[67628.393706]  el1_irq+0xb4/0x180
	[67628.393709]  _raw_spin_unlock_irqrestore+0x58/0xa8
	[67628.393712]  hrtimer_start_range_ns+0x1b0/0x420
	[67628.393715]  msg_submit+0x100/0x108
	[67628.393717]  mbox_send_message+0x84/0x128
	[67628.393720]  scpi_send_message+0x11c/0x2a8
	[67628.393723]  scpi_dvfs_set_idx+0x48/0x70
	[67628.393726]  scpi_dvfs_set_rate+0x60/0x78
	[67628.393728]  clk_change_rate+0x184/0x8a8
	[67628.393731]  clk_core_set_rate_nolock+0x1c0/0x280
	[67628.393734]  clk_set_rate+0x40/0x98
	[67628.393736]  scpi_cpufreq_set_target+0x40/0x68
	[67628.393739]  __cpufreq_driver_target+0x1a0/0x5d0

> Why is it invalid? Is this... -rt kernel, perhaps?

No I was running on Linus master at the time.

AFAIU printk will hold the console lock which could sleep in interrupt context.

Did I miss something?

Thanks

--
Qais Yousef
John Ogness Jan. 26, 2021, 3:22 p.m. UTC | #3
On 2021-01-26, Qais Yousef <qais.yousef@arm.com> wrote:
> 	[67628.393550] =============================
> 	[67628.393554] [ BUG: Invalid wait context ]
> 	[67628.393557] 5.11.0-rc3-00019-g86be331946f7 #37 Not tainted
> 	[67628.393560] -----------------------------
> 	[67628.393563] sugov:0/192 is trying to lock:
> 	[67628.393566] ffff000800b1d898 (&port_lock_key){-.-.}-{3:3}, at: pl011_console_write+0x138/0x218
> 	[67628.393581] other info that might help us debug this:
> 	[67628.393584] context-{2:2}
> 	[67628.393586] 4 locks held by sugov:0/192:
> 	[67628.393589]  #0: ffff0008059cb720 (&sg_policy->work_lock){+.+.}-{4:4}, at: sugov_work+0x58/0x88
> 	[67628.393603]  #1: ffff800015446f20 (prepare_lock){+.+.}-{4:4}, at: clk_prepare_lock+0x34/0xb0
> 	[67628.393618]  #2: ffff8000152aaa60 (console_lock){+.+.}-{0:0}, at: vprintk_emit+0x12c/0x310
> 	[67628.393632]  #3: ffff8000152aab88 (console_owner){-.-.}-{0:0}, at: console_unlock+0x190/0x6d8
> 	[67628.393646] stack backtrace:
> 	[67628.393649] CPU: 0 PID: 192 Comm: sugov:0 Not tainted 5.11.0-rc3-00019-g86be331946f7 #37
> 	[67628.393653] Hardware name: ARM Juno development board (r2) (DT)
> 	[67628.393656] Call trace:
> 	[67628.393659]  dump_backtrace+0x0/0x1b0
> 	[67628.393661]  show_stack+0x20/0x70
> 	[67628.393664]  dump_stack+0xf8/0x168
> 	[67628.393666]  __lock_acquire+0x964/0x1c88
> 	[67628.393669]  lock_acquire+0x26c/0x500
> 	[67628.393671]  _raw_spin_lock+0x64/0x88
> 	[67628.393674]  pl011_console_write+0x138/0x218
> 	[67628.393677]  console_unlock+0x2c4/0x6d8
> 	[67628.393680]  vprintk_emit+0x134/0x310
> 	[67628.393682]  vprintk_default+0x40/0x50
> 	[67628.393685]  vprintk_func+0xfc/0x2b0
> 	[67628.393687]  printk+0x68/0x90
> 	[67628.393690]  hrtimer_interrupt+0x24c/0x250
> 	[67628.393693]  arch_timer_handler_phys+0x3c/0x50
> 	[67628.393695]  handle_percpu_devid_irq+0xd8/0x460
> 	[67628.393698]  generic_handle_irq+0x38/0x50
> 	[67628.393701]  __handle_domain_irq+0x6c/0xc8
> 	[67628.393704]  gic_handle_irq+0xb0/0xf0
> 	[67628.393706]  el1_irq+0xb4/0x180
> 	[67628.393709]  _raw_spin_unlock_irqrestore+0x58/0xa8
> 	[67628.393712]  hrtimer_start_range_ns+0x1b0/0x420
> 	[67628.393715]  msg_submit+0x100/0x108
> 	[67628.393717]  mbox_send_message+0x84/0x128
> 	[67628.393720]  scpi_send_message+0x11c/0x2a8
> 	[67628.393723]  scpi_dvfs_set_idx+0x48/0x70
> 	[67628.393726]  scpi_dvfs_set_rate+0x60/0x78
> 	[67628.393728]  clk_change_rate+0x184/0x8a8
> 	[67628.393731]  clk_core_set_rate_nolock+0x1c0/0x280
> 	[67628.393734]  clk_set_rate+0x40/0x98
> 	[67628.393736]  scpi_cpufreq_set_target+0x40/0x68
> 	[67628.393739]  __cpufreq_driver_target+0x1a0/0x5d0

pl011_console_write() does:

    local_irq_save(flags);
    spin_lock(&uap->port.lock);

This needs to be:

    spin_lock_irqsave(&uap->port.lock, flags);

Of course, it will be a trickier than that because of the
@oops_in_progress madness. This bug has been around for quite a while.

John Ogness
Sergey Senozhatsky Jan. 26, 2021, 3:58 p.m. UTC | #4
On (21/01/26 14:59), Qais Yousef wrote:
> On 01/26/21 13:46, Sergey Senozhatsky wrote:
> > On (21/01/23 23:37), Qais Yousef wrote:

[..]

> I reported it here: https://lore.kernel.org/lkml/20210114124512.mg3vexudfmoadef5@e107158-lin/
>
> 	# [67628.388606] hrtimer: interrupt took 304720 ns
> 	[67628.393546]
> 	[67628.393550] =============================
> 	[67628.393554] [ BUG: Invalid wait context ]
> 	[67628.393557] 5.11.0-rc3-00019-g86be331946f7 #37 Not tainted
> 	[67628.393560] -----------------------------
> 	[67628.393563] sugov:0/192 is trying to lock:
> 	[67628.393566] ffff000800b1d898 (&port_lock_key){-.-.}-{3:3}, at: pl011_console_write+0x138/0x218
> 	[67628.393581] other info that might help us debug this:
> 	[67628.393584] context-{2:2}
> 	[67628.393586] 4 locks held by sugov:0/192:
> 	[67628.393589]  #0: ffff0008059cb720 (&sg_policy->work_lock){+.+.}-{4:4}, at: sugov_work+0x58/0x88
> 	[67628.393603]  #1: ffff800015446f20 (prepare_lock){+.+.}-{4:4}, at: clk_prepare_lock+0x34/0xb0
> 	[67628.393618]  #2: ffff8000152aaa60 (console_lock){+.+.}-{0:0}, at: vprintk_emit+0x12c/0x310
> 	[67628.393632]  #3: ffff8000152aab88 (console_owner){-.-.}-{0:0}, at: console_unlock+0x190/0x6d8
> 	[67628.393646] stack backtrace:
> 	[67628.393649] CPU: 0 PID: 192 Comm: sugov:0 Not tainted 5.11.0-rc3-00019-g86be331946f7 #37
> 	[67628.393653] Hardware name: ARM Juno development board (r2) (DT)
> 	[67628.393656] Call trace:
> 	[67628.393659]  dump_backtrace+0x0/0x1b0
> 	[67628.393661]  show_stack+0x20/0x70
> 	[67628.393664]  dump_stack+0xf8/0x168
> 	[67628.393666]  __lock_acquire+0x964/0x1c88
> 	[67628.393669]  lock_acquire+0x26c/0x500
> 	[67628.393671]  _raw_spin_lock+0x64/0x88
> 	[67628.393674]  pl011_console_write+0x138/0x218
> 	[67628.393677]  console_unlock+0x2c4/0x6d8
> 	[67628.393680]  vprintk_emit+0x134/0x310
> 	[67628.393682]  vprintk_default+0x40/0x50
> 	[67628.393685]  vprintk_func+0xfc/0x2b0
> 	[67628.393687]  printk+0x68/0x90
> 	[67628.393690]  hrtimer_interrupt+0x24c/0x250
> 	[67628.393693]  arch_timer_handler_phys+0x3c/0x50
> 	[67628.393695]  handle_percpu_devid_irq+0xd8/0x460
> 	[67628.393698]  generic_handle_irq+0x38/0x50
> 	[67628.393701]  __handle_domain_irq+0x6c/0xc8
> 	[67628.393704]  gic_handle_irq+0xb0/0xf0
> 	[67628.393706]  el1_irq+0xb4/0x180
> 	[67628.393709]  _raw_spin_unlock_irqrestore+0x58/0xa8
> 	[67628.393712]  hrtimer_start_range_ns+0x1b0/0x420
> 	[67628.393715]  msg_submit+0x100/0x108
> 	[67628.393717]  mbox_send_message+0x84/0x128
> 	[67628.393720]  scpi_send_message+0x11c/0x2a8
> 	[67628.393723]  scpi_dvfs_set_idx+0x48/0x70
> 	[67628.393726]  scpi_dvfs_set_rate+0x60/0x78
> 	[67628.393728]  clk_change_rate+0x184/0x8a8
> 	[67628.393731]  clk_core_set_rate_nolock+0x1c0/0x280
> 	[67628.393734]  clk_set_rate+0x40/0x98
> 	[67628.393736]  scpi_cpufreq_set_target+0x40/0x68
> 	[67628.393739]  __cpufreq_driver_target+0x1a0/0x5d0

Thanks.

> > Why is it invalid? Is this... -rt kernel, perhaps?
> 
> No I was running on Linus master at the time.
> 
> AFAIU printk will hold the console lock which could sleep in interrupt context.
> 
> Did I miss something?

printk() is not permitted to sleep/schedule/etc and it never does.
Generally it should be OK to call it from IRQ (module recursion paths).

	-ss
Peter Zijlstra Jan. 26, 2021, 4:18 p.m. UTC | #5
On Tue, Jan 26, 2021 at 04:28:42PM +0106, John Ogness wrote:
> On 2021-01-26, Qais Yousef <qais.yousef@arm.com> wrote:
> > 	[67628.393550] =============================
> > 	[67628.393554] [ BUG: Invalid wait context ]
> > 	[67628.393557] 5.11.0-rc3-00019-g86be331946f7 #37 Not tainted
> > 	[67628.393560] -----------------------------
> > 	[67628.393563] sugov:0/192 is trying to lock:
> > 	[67628.393566] ffff000800b1d898 (&port_lock_key){-.-.}-{3:3}, at: pl011_console_write+0x138/0x218
> > 	[67628.393581] other info that might help us debug this:
> > 	[67628.393584] context-{2:2}
> > 	[67628.393586] 4 locks held by sugov:0/192:
> > 	[67628.393589]  #0: ffff0008059cb720 (&sg_policy->work_lock){+.+.}-{4:4}, at: sugov_work+0x58/0x88
> > 	[67628.393603]  #1: ffff800015446f20 (prepare_lock){+.+.}-{4:4}, at: clk_prepare_lock+0x34/0xb0


> pl011_console_write() does:
> 
>     local_irq_save(flags);
>     spin_lock(&uap->port.lock);
> 
> This needs to be:
> 
>     spin_lock_irqsave(&uap->port.lock, flags);
> 
> Of course, it will be a trickier than that because of the
> @oops_in_progress madness. This bug has been around for quite a while.

Well yes, but that's not going to be fixing anything.

The problem is that sugov_work() is holding a raw_spin_lock, and you're
trying to acquire a spin_lock.

That's an invalid lock nesting.
Peter Zijlstra Jan. 26, 2021, 4:23 p.m. UTC | #6
On Wed, Jan 27, 2021 at 12:58:33AM +0900, Sergey Senozhatsky wrote:
> On (21/01/26 14:59), Qais Yousef wrote:

> > 	# [67628.388606] hrtimer: interrupt took 304720 ns
> > 	[67628.393546]
> > 	[67628.393550] =============================
> > 	[67628.393554] [ BUG: Invalid wait context ]
> > 	[67628.393557] 5.11.0-rc3-00019-g86be331946f7 #37 Not tainted
> > 	[67628.393560] -----------------------------
> > 	[67628.393563] sugov:0/192 is trying to lock:
> > 	[67628.393566] ffff000800b1d898 (&port_lock_key){-.-.}-{3:3}, at: pl011_console_write+0x138/0x218
> > 	[67628.393581] other info that might help us debug this:
> > 	[67628.393584] context-{2:2}
> > 	[67628.393586] 4 locks held by sugov:0/192:
> > 	[67628.393589]  #0: ffff0008059cb720 (&sg_policy->work_lock){+.+.}-{4:4}, at: sugov_work+0x58/0x88
> > 	[67628.393603]  #1: ffff800015446f20 (prepare_lock){+.+.}-{4:4}, at: clk_prepare_lock+0x34/0xb0
> > 	[67628.393618]  #2: ffff8000152aaa60 (console_lock){+.+.}-{0:0}, at: vprintk_emit+0x12c/0x310
> > 	[67628.393632]  #3: ffff8000152aab88 (console_owner){-.-.}-{0:0}, at: console_unlock+0x190/0x6d8

> > Did I miss something?
> 
> printk() is not permitted to sleep/schedule/etc and it never does.
> Generally it should be OK to call it from IRQ (module recursion paths).

The report is that it is trying to acquire spin_lock() while holding
raw_spin_lock(), which is an invalid lock nesting.

Note that this is CONFIG_PROVE_RAW_LOCK_NESTING=y which specifically
checks for this.

On current (mainline) kernel configs this is not yet a problem, but the
moment we do land PREEMPT_RT this order will be problematic.
Petr Mladek Jan. 26, 2021, 4:58 p.m. UTC | #7
On Wed 2021-01-27 00:58:33, Sergey Senozhatsky wrote:
> On (21/01/26 14:59), Qais Yousef wrote:
> > On 01/26/21 13:46, Sergey Senozhatsky wrote:
> > > On (21/01/23 23:37), Qais Yousef wrote:
> 
> [..]
> 
> > I reported it here: https://lore.kernel.org/lkml/20210114124512.mg3vexudfmoadef5@e107158-lin/
> >
> > 	# [67628.388606] hrtimer: interrupt took 304720 ns
> > 	[67628.393546]
> > 	[67628.393550] =============================
> > 	[67628.393554] [ BUG: Invalid wait context ]
> > 	[67628.393557] 5.11.0-rc3-00019-g86be331946f7 #37 Not tainted
> > 	[67628.393560] -----------------------------
> > 	[67628.393563] sugov:0/192 is trying to lock:
> > 	[67628.393566] ffff000800b1d898 (&port_lock_key){-.-.}-{3:3}, at: pl011_console_write+0x138/0x218
> > 	[67628.393581] other info that might help us debug this:
> > 	[67628.393584] context-{2:2}
> > 	[67628.393586] 4 locks held by sugov:0/192:
> > 	[67628.393589]  #0: ffff0008059cb720 (&sg_policy->work_lock){+.+.}-{4:4}, at: sugov_work+0x58/0x88
> > 	[67628.393603]  #1: ffff800015446f20 (prepare_lock){+.+.}-{4:4}, at: clk_prepare_lock+0x34/0xb0
> > 	[67628.393618]  #2: ffff8000152aaa60 (console_lock){+.+.}-{0:0}, at: vprintk_emit+0x12c/0x310
> > 	[67628.393632]  #3: ffff8000152aab88 (console_owner){-.-.}-{0:0}, at: console_unlock+0x190/0x6d8
> > 	[67628.393646] stack backtrace:
> > 	[67628.393649] CPU: 0 PID: 192 Comm: sugov:0 Not tainted 5.11.0-rc3-00019-g86be331946f7 #37
> > 	[67628.393653] Hardware name: ARM Juno development board (r2) (DT)
> > 	[67628.393656] Call trace:
> > 	[67628.393659]  dump_backtrace+0x0/0x1b0
> > 	[67628.393661]  show_stack+0x20/0x70
> > 	[67628.393664]  dump_stack+0xf8/0x168
> > 	[67628.393666]  __lock_acquire+0x964/0x1c88
> > 	[67628.393669]  lock_acquire+0x26c/0x500
> > 	[67628.393671]  _raw_spin_lock+0x64/0x88
> > 	[67628.393674]  pl011_console_write+0x138/0x218
> > 	[67628.393677]  console_unlock+0x2c4/0x6d8
> > 	[67628.393680]  vprintk_emit+0x134/0x310
> > 	[67628.393682]  vprintk_default+0x40/0x50
> > 	[67628.393685]  vprintk_func+0xfc/0x2b0
> > 	[67628.393687]  printk+0x68/0x90
> > 	[67628.393690]  hrtimer_interrupt+0x24c/0x250
> > 	[67628.393693]  arch_timer_handler_phys+0x3c/0x50
> > 	[67628.393695]  handle_percpu_devid_irq+0xd8/0x460
> > 	[67628.393698]  generic_handle_irq+0x38/0x50
> > 	[67628.393701]  __handle_domain_irq+0x6c/0xc8
> > 	[67628.393704]  gic_handle_irq+0xb0/0xf0
> > 	[67628.393706]  el1_irq+0xb4/0x180
> > 	[67628.393709]  _raw_spin_unlock_irqrestore+0x58/0xa8
> > 	[67628.393712]  hrtimer_start_range_ns+0x1b0/0x420
> > 	[67628.393715]  msg_submit+0x100/0x108
> > 	[67628.393717]  mbox_send_message+0x84/0x128
> > 	[67628.393720]  scpi_send_message+0x11c/0x2a8
> > 	[67628.393723]  scpi_dvfs_set_idx+0x48/0x70
> > 	[67628.393726]  scpi_dvfs_set_rate+0x60/0x78
> > 	[67628.393728]  clk_change_rate+0x184/0x8a8
> > 	[67628.393731]  clk_core_set_rate_nolock+0x1c0/0x280
> > 	[67628.393734]  clk_set_rate+0x40/0x98
> > 	[67628.393736]  scpi_cpufreq_set_target+0x40/0x68
> > 	[67628.393739]  __cpufreq_driver_target+0x1a0/0x5d0
> 
> Thanks.
> 
> > > Why is it invalid? Is this... -rt kernel, perhaps?
> > 
> > No I was running on Linus master at the time.
> > 
> > AFAIU printk will hold the console lock which could sleep in interrupt context.
> > 
> > Did I miss something?
> 
> printk() is not permitted to sleep/schedule/etc and it never does.
> Generally it should be OK to call it from IRQ (module recursion paths).

To make it clear. printk() takes the mutex via console_trylock().
It does not sleep when the lock is not available. But lockdep should
be aware of this.

Honestly, I am not sure what the lockdep complains about here.
IMHO, the key is that we try to take lock

     (&port_lock_key){-.-.}-{3:3}

in context

     context-{2:2}

where {-.-.} looks fine. Both dots and dashes looks safe, see
      get_usage_char()

So, it is likely the {3:3} vs. {2:2}. I have never seen this.
It has been added by the commit de8f5e4f2dc1f032 ("lockdep: Introduce
wait-type checks").

Might it be that we take normal mutex under a raw one?

It would be safe in normal kernel. But it would be bad
in RT one. But lockep should complain about it even in
the normal kernel.

Best Regards,
Petr
Qais Yousef Jan. 26, 2021, 6:08 p.m. UTC | #8
On 01/26/21 17:23, Peter Zijlstra wrote:
> On Wed, Jan 27, 2021 at 12:58:33AM +0900, Sergey Senozhatsky wrote:
> > On (21/01/26 14:59), Qais Yousef wrote:
> 
> > > 	# [67628.388606] hrtimer: interrupt took 304720 ns
> > > 	[67628.393546]
> > > 	[67628.393550] =============================
> > > 	[67628.393554] [ BUG: Invalid wait context ]
> > > 	[67628.393557] 5.11.0-rc3-00019-g86be331946f7 #37 Not tainted
> > > 	[67628.393560] -----------------------------
> > > 	[67628.393563] sugov:0/192 is trying to lock:
> > > 	[67628.393566] ffff000800b1d898 (&port_lock_key){-.-.}-{3:3}, at: pl011_console_write+0x138/0x218
> > > 	[67628.393581] other info that might help us debug this:
> > > 	[67628.393584] context-{2:2}
> > > 	[67628.393586] 4 locks held by sugov:0/192:
> > > 	[67628.393589]  #0: ffff0008059cb720 (&sg_policy->work_lock){+.+.}-{4:4}, at: sugov_work+0x58/0x88
> > > 	[67628.393603]  #1: ffff800015446f20 (prepare_lock){+.+.}-{4:4}, at: clk_prepare_lock+0x34/0xb0
> > > 	[67628.393618]  #2: ffff8000152aaa60 (console_lock){+.+.}-{0:0}, at: vprintk_emit+0x12c/0x310
> > > 	[67628.393632]  #3: ffff8000152aab88 (console_owner){-.-.}-{0:0}, at: console_unlock+0x190/0x6d8
> 
> > > Did I miss something?
> > 
> > printk() is not permitted to sleep/schedule/etc and it never does.
> > Generally it should be OK to call it from IRQ (module recursion paths).
> 
> The report is that it is trying to acquire spin_lock() while holding
> raw_spin_lock(), which is an invalid lock nesting.
> 
> Note that this is CONFIG_PROVE_RAW_LOCK_NESTING=y which specifically
> checks for this.
> 
> On current (mainline) kernel configs this is not yet a problem, but the
> moment we do land PREEMPT_RT this order will be problematic.

I should have dug more into the history of printk() and the meaning of the
splat. Sorry for the noise.

Looking at v5.10.8-rt24 the following fix is applied in RT

	https://git.kernel.org/pub/scm/linux/kernel/git/rt/linux-rt-devel.git/commit/drivers/tty/serial/amba-pl011.c?h=linux-5.10.y-rt&id=008cc77aff249e830e5eb90b7ae3a6784597b8cf

which is what John suggested.

Looking at the locks held

> > > 	[67628.393589]  #0: ffff0008059cb720 (&sg_policy->work_lock){+.+.}-{4:4}, at: sugov_work+0x58/0x88
> > > 	[67628.393603]  #1: ffff800015446f20 (prepare_lock){+.+.}-{4:4}, at: clk_prepare_lock+0x34/0xb0

These two are mutexes.

> > > 	[67628.393618]  #2: ffff8000152aaa60 (console_lock){+.+.}-{0:0}, at: vprintk_emit+0x12c/0x310

This is a semaphore.

> > > 	[67628.393632]  #3: ffff8000152aab88 (console_owner){-.-.}-{0:0}, at: console_unlock+0x190/0x6d8

I think this is acquired by console_lock_spinning_enable() which has acquiring
syntax I'm not familiar with. console_owner_lock is defined as RAW_SPINLOCK, so
regardless of how it is acquired, it must be the problem.

Looks like John has reworked this code in RT too. So maybe this is just a red
herring after all..

	https://git.kernel.org/pub/scm/linux/kernel/git/rt/linux-rt-devel.git/commit/kernel/printk/printk.c?h=linux-5.10.y-rt&id=0097798fd99948d3ffea535005eee7eb3b14fd06

Thanks

--
Qais Yousef