| Message ID | 20240614040133.24967-3-jason-jh.lin@mediatek.com (mailing list archive) |
|---|---|
| State | New |
| Headers | show |
| Series | Fix sleeping function called from invalid context | expand |
On Thu, Jun 13, 2024 at 11:01 PM Jason-JH.Lin <jason-jh.lin@mediatek.com> wrote: > > When we run kernel with lockdebug option, we will get the BUG below: > BUG: sleeping function called from invalid context at drivers/base/power/runtime.c:1164 > in_atomic(): 1, irqs_disabled(): 128, non_block: 0, pid: 3616, name: kworker/u17:3 > preempt_count: 1, expected: 0 > RCU nest depth: 0, expected: 0 > INFO: lockdep is turned off. > irq event stamp: 0 > CPU: 1 PID: 3616 Comm: kworker/u17:3 Not tainted 6.1.87-lockdep-14133-g26e933aca785 #1 > Hardware name: Google Ciri sku0/unprovisioned board (DT) > Workqueue: imgsys_runner imgsys_runner_func > Call trace: > dump_backtrace+0x100/0x120 > show_stack+0x20/0x2c > dump_stack_lvl+0x84/0xb4 > dump_stack+0x18/0x48 > __might_resched+0x354/0x4c0 > __might_sleep+0x98/0xe4 > __pm_runtime_resume+0x70/0x124 > cmdq_mbox_send_data+0xe4/0xb1c > msg_submit+0x194/0x2dc > mbox_send_message+0x190/0x330 > imgsys_cmdq_sendtask+0x1618/0x2224 > imgsys_runner_func+0xac/0x11c > process_one_work+0x638/0xf84 > worker_thread+0x808/0xcd0 > kthread+0x24c/0x324 > ret_from_fork+0x10/0x20 > > We found that there is a spin_lock_irqsave protection in msg_submit() > of mailbox.c and it is in the atomic context. > So when cmdq driver calls pm_runtime_get_sync() in cmdq_mbox_send_data(), > it will get this BUG report. > > To avoid using sleep in atomic context, move pm_runtime_get_sync to > mbox_chan_ops->power_get and also move pm_runtime_put_autosuspend to > mbox_chan_ops->power_put. > > Fixes: 8afe816b0c99 ("mailbox: mtk-cmdq-mailbox: Implement Runtime PM with autosuspend") Can you please share the pattern of mailbox transfers on your platform? As in, how often and long are the "channel idle" periods? And when active, how many transfers/sec ? I see every TX is acked by one RX packet. How long is the typical gap between a TX and its ack? Thanks
Hi Jassi, On Mon, 2024-06-17 at 13:18 -0500, Jassi Brar wrote: > > External email : Please do not click links or open attachments until > you have verified the sender or the content. > On Thu, Jun 13, 2024 at 11:01 PM Jason-JH.Lin < > jason-jh.lin@mediatek.com> wrote: > > > > When we run kernel with lockdebug option, we will get the BUG > below: > > BUG: sleeping function called from invalid context at > drivers/base/power/runtime.c:1164 > > in_atomic(): 1, irqs_disabled(): 128, non_block: 0, pid: 3616, > name: kworker/u17:3 > > preempt_count: 1, expected: 0 > > RCU nest depth: 0, expected: 0 > > INFO: lockdep is turned off. > > irq event stamp: 0 > > CPU: 1 PID: 3616 Comm: kworker/u17:3 Not tainted 6.1.87- > lockdep-14133-g26e933aca785 #1 > > Hardware name: Google Ciri sku0/unprovisioned board (DT) > > Workqueue: imgsys_runner imgsys_runner_func > > Call trace: > > dump_backtrace+0x100/0x120 > > show_stack+0x20/0x2c > > dump_stack_lvl+0x84/0xb4 > > dump_stack+0x18/0x48 > > __might_resched+0x354/0x4c0 > > __might_sleep+0x98/0xe4 > > __pm_runtime_resume+0x70/0x124 > > cmdq_mbox_send_data+0xe4/0xb1c > > msg_submit+0x194/0x2dc > > mbox_send_message+0x190/0x330 > > imgsys_cmdq_sendtask+0x1618/0x2224 > > imgsys_runner_func+0xac/0x11c > > process_one_work+0x638/0xf84 > > worker_thread+0x808/0xcd0 > > kthread+0x24c/0x324 > > ret_from_fork+0x10/0x20 > > > > We found that there is a spin_lock_irqsave protection in > msg_submit() > > of mailbox.c and it is in the atomic context. > > So when cmdq driver calls pm_runtime_get_sync() in > cmdq_mbox_send_data(), > > it will get this BUG report. > > > > To avoid using sleep in atomic context, move pm_runtime_get_sync to > > mbox_chan_ops->power_get and also move pm_runtime_put_autosuspend > to > > mbox_chan_ops->power_put. > > > > Fixes: 8afe816b0c99 ("mailbox: mtk-cmdq-mailbox: Implement Runtime > PM with autosuspend") > > Can you please share the pattern of mailbox transfers on your > platform? I'm not familiar with imgsys driver, so I provide the mbox transfer pattern of DRM driver in this scenario: 1. mbox_request_channel() in mtk_crtc.c: mtk_crtc_create() mtk_crtc->cmdq_client.client.dev = mtk_crtc->mmsys_dev; mtk_crtc->cmdq_client.client.tx_block = false; mtk_crtc->cmdq_client.client.knows_txdone = true; mtk_crtc->cmdq_client.client.rx_callback = ddp_cmdq_cb; mtk_crtc->cmdq_client.chan = mbox_request_channel(&client, i); 2. mbox_send_message() in mtk_crtc.c: mtk_crtc_update_config() mbox_flush(cmdq_client.chan, 2000); // prepare cmd to a buffer in cmdq_handle structure mbox_send_message(cmdq_client.chan, cmdq_handle); mbox_client_txdone(cmdq_client.chan, 0); 3. mbox_chan_received_data() in mtk-cmdq-mailbox.c: cmdq_task_done() // When CMDQ driver get an GCE IRQ from hardware means all cmd in cmd buffer are executed > As in, how often and long are the "channel idle" periods? And when > active, how many transfers/sec ? Is there any debug logs in mailbox can measure this? This mailbox channel is use to configure display hardware in every VSYNC, so the channel idle periods may be less than 16.66ms. It should call rx_callback() before VACTIVE, but sometimes it will be dropped by mbox_flush() if the new message is coming. > I see every TX is acked by one RX packet. How long is the typical gap > between a TX and its ack? Typical gap between a TX and its ack is less than 16.66ms. I'll address to imgsys part after confirming with imgsys owner. Regards, Jason-JH Lin > > Thanks
On Tue, Jun 18, 2024 at 3:42 AM Jason-JH Lin (林睿祥) <Jason-JH.Lin@mediatek.com> wrote: > > On Mon, 2024-06-17 at 13:18 -0500, Jassi Brar wrote: > > ...... > > As in, how often and long are the "channel idle" periods? And when > > active, how many transfers/sec ? > Is there any debug logs in mailbox can measure this? > > This mailbox channel is use to configure display hardware in every > VSYNC, so the channel idle periods may be less than 16.66ms. > > It should call rx_callback() before VACTIVE, but sometimes it will be > dropped by mbox_flush() if the new message is coming. > > > I see every TX is acked by one RX packet. How long is the typical gap > > between a TX and its ack? > > Typical gap between a TX and its ack is less than 16.66ms. > So basically the usecase is driving some display at 60Hz. And I believe the display is driven continuously for at least some minutes ? If so, RPM between xfers is not really in effect because the autosuspend delay is 100ms while you get() it every 16.66ms. So all that is happening is some variables changed under a spinlock. I think you should consider get/put RPM in cmdq_mbox_startup() and cmdq_mbox_shutdown(). Thanks
Il 18/06/24 17:59, Jassi Brar ha scritto: > On Tue, Jun 18, 2024 at 3:42 AM Jason-JH Lin (林睿祥) > <Jason-JH.Lin@mediatek.com> wrote: >> >> On Mon, 2024-06-17 at 13:18 -0500, Jassi Brar wrote: >>> > ...... > >>> As in, how often and long are the "channel idle" periods? And when >>> active, how many transfers/sec ? >> Is there any debug logs in mailbox can measure this? >> >> This mailbox channel is use to configure display hardware in every >> VSYNC, so the channel idle periods may be less than 16.66ms. >> >> It should call rx_callback() before VACTIVE, but sometimes it will be >> dropped by mbox_flush() if the new message is coming. >> >>> I see every TX is acked by one RX packet. How long is the typical gap >>> between a TX and its ack? >> >> Typical gap between a TX and its ack is less than 16.66ms. >> > So basically the usecase is driving some display at 60Hz. And I > believe the display is driven > continuously for at least some minutes ? > If so, RPM between xfers is not really in effect because the > autosuspend delay is 100ms while you > get() it every 16.66ms. So all that is happening is some variables > changed under a spinlock. > I think you should consider get/put RPM in cmdq_mbox_startup() and > cmdq_mbox_shutdown(). > > Thanks With at least MediaTek (but surely more than just mtk), a system that is idling while having display ON doesn't mean that the display is continuously refreshed by the CPU and with CMDQ messaging. For example, when static content is displayed on screen, the CMDQ mailbox never gets shut down, but no communication happens for a relatively long time; the overhead of actually shutting down the mailbox and setting it back up would be increasing latency in an unacceptable manner. This is why I opted for autosuspend - it's only bringing down certain clocks for the CMDQ HW, adding up a bit of power saving to the mix which, for some use cases such as mobile devices with relatively small batteries, is definitely important. I'll also briefly (and only briefly) mention that 120Hz displays are already a common thing and in this case the gap between TX and ACK is ~8.33ms instead, let alone that displays with a framerate of more than 120Hz also do exist even though they're less common. All of the above describes a few of the reasons why autosuspend is a good choice here, instead of a shutdown->startup flow. And again - I can place some bets that PM would also be applicable to SoCs from other vendors as well, with most probably different benefits (but still with some power related benefits!) compared to MediaTek. ....And that's the reason why I think that implementing a way to cleanly perform this kind-of-aggressive power management in mailboxes is something that needs to be done. Cheers, Angelo
On Wed, Jun 19, 2024 at 3:18 AM AngeloGioacchino Del Regno <angelogioacchino.delregno@collabora.com> wrote: > Il 18/06/24 17:59, Jassi Brar ha scritto: ..... > For example, when static content is displayed on screen, the CMDQ mailbox never > gets shut down, but no communication happens for a relatively long time; the > overhead of actually shutting down the mailbox and setting it back up would be > increasing latency in an unacceptable manner. > Hmm... in your driver, startup() is _empty_ and shutdown() is all under a spin-lock with irqs disabled, so that too shouldn't be expensive. Right? Then what causes unacceptable latencies? > This is why I opted for autosuspend - it's only bringing down certain clocks for > the CMDQ HW, adding up a bit of power saving to the mix which, for some use cases > such as mobile devices with relatively small batteries, is definitely important. > > I'll also briefly (and only briefly) mention that 120Hz displays are already a > common thing and in this case the gap between TX and ACK is ~8.33ms instead, let > alone that displays with a framerate of more than 120Hz also do exist even though > they're less common. > I don't know how even busier channels help your point. > All of the above describes a few of the reasons why autosuspend is a good choice > here, instead of a shutdown->startup flow. > And again - I can place some bets that PM would also be applicable to SoCs from > other vendors as well, with most probably different benefits (but still with some > power related benefits!) compared to MediaTek. > Sure, if some platform _actually_ has a high channel startup()/shutdown() cost, it may need finer PM control. And I have a way for that, but even with that I am sure someone from MTK will realize they didn't need that. Thanks.
On Wed, 2024-06-19 at 10:38 -0500, Jassi Brar wrote: > > External email : Please do not click links or open attachments until > you have verified the sender or the content. > On Wed, Jun 19, 2024 at 3:18 AM AngeloGioacchino Del Regno > <angelogioacchino.delregno@collabora.com> wrote: > > Il 18/06/24 17:59, Jassi Brar ha scritto: > ..... > > > For example, when static content is displayed on screen, the CMDQ > mailbox never > > gets shut down, but no communication happens for a relatively long > time; the > > overhead of actually shutting down the mailbox and setting it back > up would be > > increasing latency in an unacceptable manner. > > > Hmm... in your driver, startup() is _empty_ and shutdown() is > all > under a spin-lock with irqs disabled, so that too shouldn't be > expensive. Right? > Then what causes unacceptable latencies? > I found that the BUG report only occurred when opening the camera APP. Maybe something in imgsys_cmdq_sendtask() is too expensive or somewhere else in imgsys driver. I'm wondering why this BUG report is not occurred in display use case which is more frequent than imgsys use case. Does this mean sleep() is not always called in pm_runtime_get_sync() and if we can guarantee this sleep() won't be called, then using pm_runtime_get_sync() in atomic context is OK? > > This is why I opted for autosuspend - it's only bringing down > certain clocks for > > the CMDQ HW, adding up a bit of power saving to the mix which, for > some use cases > > such as mobile devices with relatively small batteries, is > definitely important. > > > > I'll also briefly (and only briefly) mention that 120Hz displays > are already a > > common thing and in this case the gap between TX and ACK is ~8.33ms > instead, let > > alone that displays with a framerate of more than 120Hz also do > exist even though > > they're less common. > > > I don't know how even busier channels help your point. > > > All of the above describes a few of the reasons why autosuspend is > a good choice > > here, instead of a shutdown->startup flow. > > And again - I can place some bets that PM would also be applicable > to SoCs from > > other vendors as well, with most probably different benefits (but > still with some > > power related benefits!) compared to MediaTek. I agree with Angelo's point! Regard, Jason-JH Lin > > > Sure, if some platform _actually_ has a high channel > startup()/shutdown() cost, it may need finer PM control. And I have a > way for that, but even with that I am sure someone from MTK will > realize they didn't need that. > > Thanks. >
On Thu, Jun 20, 2024 at 1:33 AM Jason-JH Lin (林睿祥) <Jason-JH.Lin@mediatek.com> wrote: > > On Wed, 2024-06-19 at 10:38 -0500, Jassi Brar wrote: > > > > External email : Please do not click links or open attachments until > > you have verified the sender or the content. > > On Wed, Jun 19, 2024 at 3:18 AM AngeloGioacchino Del Regno > > <angelogioacchino.delregno@collabora.com> wrote: > > > Il 18/06/24 17:59, Jassi Brar ha scritto: > > ..... > > > > > For example, when static content is displayed on screen, the CMDQ > > mailbox never > > > gets shut down, but no communication happens for a relatively long > > time; the > > > overhead of actually shutting down the mailbox and setting it back > > up would be > > > increasing latency in an unacceptable manner. > > > > > Hmm... in your driver, startup() is _empty_ and shutdown() is > > all > > under a spin-lock with irqs disabled, so that too shouldn't be > > expensive. Right? > > Then what causes unacceptable latencies? > > > > I found that the BUG report only occurred when opening the camera APP. > Maybe something in imgsys_cmdq_sendtask() is too expensive or somewhere > else in imgsys driver. > If you move anything from submit() into startup(), which is once per lifetime of a channel, it will only make imgsys_cmdq_sendtask() cheaper. Btw, the imgsys code is not public, I don't know how it looks. > I'm wondering why this BUG report is not occurred in display use case > which is more frequent than imgsys use case. > Does this mean sleep() is not always called in pm_runtime_get_sync() > and if we can guarantee this sleep() won't be called, then using > pm_runtime_get_sync() in atomic context is OK? > Instead of hacking around, maybe try using startup() and shutdown() which is for such uses? Maybe request/release channel as part of RPM in your client driver if you are worried about the noise? > > > This is why I opted for autosuspend - it's only bringing down > > certain clocks for > > > the CMDQ HW, adding up a bit of power saving to the mix which, for > > some use cases > > > such as mobile devices with relatively small batteries, is > > definitely important. > > > > > > I'll also briefly (and only briefly) mention that 120Hz displays > > are already a > > > common thing and in this case the gap between TX and ACK is ~8.33ms > > instead, let > > > alone that displays with a framerate of more than 120Hz also do > > exist even though > > > they're less common. > > > > > I don't know how even busier channels help your point. > > > > > All of the above describes a few of the reasons why autosuspend is > > a good choice > > > here, instead of a shutdown->startup flow. > > > And again - I can place some bets that PM would also be applicable > > to SoCs from > > > other vendors as well, with most probably different benefits (but > > still with some > > > power related benefits!) compared to MediaTek. > > I agree with Angelo's point! > Ok, but you or Angelo still don't explain "unacceptable latencies" when your startup() and shutdown() are empty. You just want api changed, which we can but at least do you part and tell me where the bottleneck (unexpected latency) comes from. Thanks
diff --git a/drivers/mailbox/mtk-cmdq-mailbox.c b/drivers/mailbox/mtk-cmdq-mailbox.c index 4aa394e91109..02cef3eee35a 100644 --- a/drivers/mailbox/mtk-cmdq-mailbox.c +++ b/drivers/mailbox/mtk-cmdq-mailbox.c @@ -387,20 +387,13 @@ static int cmdq_mbox_send_data(struct mbox_chan *chan, void *data) struct cmdq *cmdq = dev_get_drvdata(chan->mbox->dev); struct cmdq_task *task; unsigned long curr_pa, end_pa; - int ret; /* Client should not flush new tasks if suspended. */ WARN_ON(cmdq->suspended); - ret = pm_runtime_get_sync(cmdq->mbox.dev); - if (ret < 0) - return ret; - task = kzalloc(sizeof(*task), GFP_ATOMIC); - if (!task) { - pm_runtime_put_autosuspend(cmdq->mbox.dev); + if (!task) return -ENOMEM; - } task->cmdq = cmdq; INIT_LIST_HEAD(&task->list_entry); @@ -448,7 +441,6 @@ static int cmdq_mbox_send_data(struct mbox_chan *chan, void *data) list_move_tail(&task->list_entry, &thread->task_busy_list); pm_runtime_mark_last_busy(cmdq->mbox.dev); - pm_runtime_put_autosuspend(cmdq->mbox.dev); return 0; } @@ -465,8 +457,6 @@ static void cmdq_mbox_shutdown(struct mbox_chan *chan) struct cmdq_task *task, *tmp; unsigned long flags; - WARN_ON(pm_runtime_get_sync(cmdq->mbox.dev) < 0); - spin_lock_irqsave(&thread->chan->lock, flags); if (list_empty(&thread->task_busy_list)) goto done; @@ -496,7 +486,6 @@ static void cmdq_mbox_shutdown(struct mbox_chan *chan) spin_unlock_irqrestore(&thread->chan->lock, flags); pm_runtime_mark_last_busy(cmdq->mbox.dev); - pm_runtime_put_autosuspend(cmdq->mbox.dev); } static int cmdq_mbox_flush(struct mbox_chan *chan, unsigned long timeout) @@ -507,11 +496,6 @@ static int cmdq_mbox_flush(struct mbox_chan *chan, unsigned long timeout) struct cmdq_task *task, *tmp; unsigned long flags; u32 enable; - int ret; - - ret = pm_runtime_get_sync(cmdq->mbox.dev); - if (ret < 0) - return ret; spin_lock_irqsave(&thread->chan->lock, flags); if (list_empty(&thread->task_busy_list)) @@ -536,7 +520,6 @@ static int cmdq_mbox_flush(struct mbox_chan *chan, unsigned long timeout) out: spin_unlock_irqrestore(&thread->chan->lock, flags); pm_runtime_mark_last_busy(cmdq->mbox.dev); - pm_runtime_put_autosuspend(cmdq->mbox.dev); return 0; @@ -551,15 +534,31 @@ static int cmdq_mbox_flush(struct mbox_chan *chan, unsigned long timeout) return -EFAULT; } pm_runtime_mark_last_busy(cmdq->mbox.dev); - pm_runtime_put_autosuspend(cmdq->mbox.dev); + return 0; } +static int cmdq_mbox_pm_resume(struct mbox_chan *chan) +{ + struct cmdq *cmdq = dev_get_drvdata(chan->mbox->dev); + + return pm_runtime_get_sync(cmdq->mbox.dev); +} + +static void cmdq_mbox_pm_susepnd(struct mbox_chan *chan) +{ + struct cmdq *cmdq = dev_get_drvdata(chan->mbox->dev); + + pm_runtime_put_autosuspend(cmdq->mbox.dev); +} + static const struct mbox_chan_ops cmdq_mbox_chan_ops = { .send_data = cmdq_mbox_send_data, .startup = cmdq_mbox_startup, .shutdown = cmdq_mbox_shutdown, .flush = cmdq_mbox_flush, + .power_get = cmdq_mbox_pm_resume, + .power_put = cmdq_mbox_pm_susepnd, }; static struct mbox_chan *cmdq_xlate(struct mbox_controller *mbox,
When we run kernel with lockdebug option, we will get the BUG below: BUG: sleeping function called from invalid context at drivers/base/power/runtime.c:1164 in_atomic(): 1, irqs_disabled(): 128, non_block: 0, pid: 3616, name: kworker/u17:3 preempt_count: 1, expected: 0 RCU nest depth: 0, expected: 0 INFO: lockdep is turned off. irq event stamp: 0 CPU: 1 PID: 3616 Comm: kworker/u17:3 Not tainted 6.1.87-lockdep-14133-g26e933aca785 #1 Hardware name: Google Ciri sku0/unprovisioned board (DT) Workqueue: imgsys_runner imgsys_runner_func Call trace: dump_backtrace+0x100/0x120 show_stack+0x20/0x2c dump_stack_lvl+0x84/0xb4 dump_stack+0x18/0x48 __might_resched+0x354/0x4c0 __might_sleep+0x98/0xe4 __pm_runtime_resume+0x70/0x124 cmdq_mbox_send_data+0xe4/0xb1c msg_submit+0x194/0x2dc mbox_send_message+0x190/0x330 imgsys_cmdq_sendtask+0x1618/0x2224 imgsys_runner_func+0xac/0x11c process_one_work+0x638/0xf84 worker_thread+0x808/0xcd0 kthread+0x24c/0x324 ret_from_fork+0x10/0x20 We found that there is a spin_lock_irqsave protection in msg_submit() of mailbox.c and it is in the atomic context. So when cmdq driver calls pm_runtime_get_sync() in cmdq_mbox_send_data(), it will get this BUG report. To avoid using sleep in atomic context, move pm_runtime_get_sync to mbox_chan_ops->power_get and also move pm_runtime_put_autosuspend to mbox_chan_ops->power_put. Fixes: 8afe816b0c99 ("mailbox: mtk-cmdq-mailbox: Implement Runtime PM with autosuspend") Signed-off-by: Jason-JH.Lin <jason-jh.lin@mediatek.com> --- drivers/mailbox/mtk-cmdq-mailbox.c | 37 +++++++++++++++--------------- 1 file changed, 18 insertions(+), 19 deletions(-)