Re: [PATCH 0/2] Fix BUG: Invalid wait context in hrtimer_interrupt()
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] 000800b1d898 (&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: 0008059cb720
> > (&sg_policy->work_lock){+.+.}-{4:4}, at: sugov_work+0x58/0x88
> > [67628.393603] #1: 800015446f20 (prepare_lock){+.+.}-{4:4}, at:
> > clk_prepare_lock+0x34/0xb0
> > [67628.393618] #2: 8000152aaa60 (console_lock){+.+.}-{0:0}, at:
> > vprintk_emit+0x12c/0x310
> > [67628.393632] #3: 8000152aab88 (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
Re: [PATCH 0/2] Fix BUG: Invalid wait context in hrtimer_interrupt()
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
Re: [PATCH 0/2] Fix BUG: Invalid wait context in hrtimer_interrupt()
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] 000800b1d898 (&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: 0008059cb720
> > > (&sg_policy->work_lock){+.+.}-{4:4}, at: sugov_work+0x58/0x88
> > > [67628.393603] #1: 800015446f20 (prepare_lock){+.+.}-{4:4}, at:
> > > clk_prepare_lock+0x34/0xb0
> > > [67628.393618] #2: 8000152aaa60 (console_lock){+.+.}-{0:0}, at:
> > > vprintk_emit+0x12c/0x310
> > > [67628.393632] #3: 8000152aab88 (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: 0008059cb720
> > > (&sg_policy->work_lock){+.+.}-{4:4}, at: sugov_work+0x58/0x88
> > > [67628.393603] #1: 800015446f20 (prepare_lock){+.+.}-{4:4}, at:
> > > clk_prepare_lock+0x34/0xb0
These two are mutexes.
> > > [67628.393618] #2: 8000152aaa60 (console_lock){+.+.}-{0:0}, at:
> > > vprintk_emit+0x12c/0x310
This is a semaphore.
> > > [67628.393632] #3: 8000152aab88 (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
Re: [PATCH 0/2] Fix BUG: Invalid wait context in hrtimer_interrupt()
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] 000800b1d898 (&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: 0008059cb720
> > (&sg_policy->work_lock){+.+.}-{4:4}, at: sugov_work+0x58/0x88
> > [67628.393603] #1: 800015446f20 (prepare_lock){+.+.}-{4:4}, at:
> > clk_prepare_lock+0x34/0xb0
> > [67628.393618] #2: 8000152aaa60 (console_lock){+.+.}-{0:0}, at:
> > vprintk_emit+0x12c/0x310
> > [67628.393632] #3: 8000152aab88 (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.
Re: [PATCH 0/2] Fix BUG: Invalid wait context in hrtimer_interrupt()
On Tue, Jan 26, 2021 at 04:28:42PM +0106, John Ogness wrote:
> On 2021-01-26, Qais Yousef 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] 000800b1d898 (&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: 0008059cb720
> > (&sg_policy->work_lock){+.+.}-{4:4}, at: sugov_work+0x58/0x88
> > [67628.393603] #1: 800015446f20 (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.
Re: [PATCH 0/2] Fix BUG: Invalid wait context in hrtimer_interrupt()
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] 000800b1d898 (&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: 0008059cb720
> (&sg_policy->work_lock){+.+.}-{4:4}, at: sugov_work+0x58/0x88
> [67628.393603] #1: 800015446f20 (prepare_lock){+.+.}-{4:4}, at:
> clk_prepare_lock+0x34/0xb0
> [67628.393618] #2: 8000152aaa60 (console_lock){+.+.}-{0:0}, at:
> vprintk_emit+0x12c/0x310
> [67628.393632] #3: 8000152aab88 (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
Re: [PATCH 0/2] Fix BUG: Invalid wait context in hrtimer_interrupt()
On 2021-01-26, Qais Yousef 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] 000800b1d898 (&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: 0008059cb720
> (&sg_policy->work_lock){+.+.}-{4:4}, at: sugov_work+0x58/0x88
> [67628.393603] #1: 800015446f20 (prepare_lock){+.+.}-{4:4}, at:
> clk_prepare_lock+0x34/0xb0
> [67628.393618] #2: 8000152aaa60 (console_lock){+.+.}-{0:0}, at:
> vprintk_emit+0x12c/0x310
> [67628.393632] #3: 8000152aab88 (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
Re: [PATCH 0/2] Fix BUG: Invalid wait context in hrtimer_interrupt()
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] 000800b1d898 (&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: 0008059cb720
(&sg_policy->work_lock){+.+.}-{4:4}, at: sugov_work+0x58/0x88
[67628.393603] #1: 800015446f20 (prepare_lock){+.+.}-{4:4}, at:
clk_prepare_lock+0x34/0xb0
[67628.393618] #2: 8000152aaa60 (console_lock){+.+.}-{0:0}, at:
vprintk_emit+0x12c/0x310
[67628.393632] #3: 8000152aab88 (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
[PATCH 0/2] Fix BUG: Invalid wait context in hrtimer_interrupt()
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(-) -- 2.25.1
