| 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
Il 20/06/24 16:39, Jassi Brar ha scritto: > 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. > "I want numbers" is a sensible request, honestly I would do the same so I totally understand that. Jason, can you please perform latency measurements on 60Hz and *especially* ISP/cam cases while "continuously" calling startup() and shutdown() for every power saving operation? Thanks, Angelo
On Mon, Jun 24, 2024 at 6:29 AM AngeloGioacchino Del Regno <angelogioacchino.delregno@collabora.com> wrote: > > Il 20/06/24 16:39, Jassi Brar ha scritto: > > 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. > > > > "I want numbers" is a sensible request, honestly I would do the same so I totally > understand that. > > Jason, can you please perform latency measurements on 60Hz and *especially* ISP/cam > cases while "continuously" calling startup() and shutdown() for every power saving > operation? > To be clear, do with the mailbox channel that you do with the clocks now, because your startup() is literally and shutdown() is practically empty. Call shutdown() when no request has come in for a while, so you know the client has quiesced likely. So try putting request/release in higher level RPM with autosuspend. thanks
On Mon, 2024-06-24 at 12:45 -0500, Jassi Brar wrote: > > External email : Please do not click links or open attachments until > you have verified the sender or the content. > On Mon, Jun 24, 2024 at 6:29 AM AngeloGioacchino Del Regno > <angelogioacchino.delregno@collabora.com> wrote: > > > > Il 20/06/24 16:39, Jassi Brar ha scritto: > > > 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. > > > It'll be upstreamed in the future, so I can only test it locally to find the information we want. > > > > > >> 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. > > > > > > > "I want numbers" is a sensible request, honestly I would do the > same so I totally > > understand that. > > > > Jason, can you please perform latency measurements on 60Hz and > *especially* ISP/cam > > cases while "continuously" calling startup() and shutdown() for > every power saving > > operation? You mean moving clk_builk_enable() and clk_bulk_disable() to startup() and shutdown(), and then calling startup() in cmdq_runtime_resume() and calling shutdown() in cmdq_runtime_suspend()? If we do that, I think GCE clocks will never be closed because mbox_request_channel() and mbox_free_channel() will call startup() and shutdown() already. I found that display thread:0 will call mbox_send_message() every 16ms when I moving UI continuously: [ 61.503604] thread_id:0, send_diff:16 ms [ 61.520266] thread_id:0, send_diff:16 ms [ 61.537143] thread_id:0, send_diff:16 ms [ 61.553609] thread_id:0, send_diff:16 ms [ 61.570811] thread_id:0, send_diff:17 ms [ 61.587075] thread_id:0, send_diff:16 ms [ 61.603527] thread_id:0, send_diff:16 ms [ 61.620082] thread_id:0, send_diff:16 ms [ 61.637496] thread_id:0, send_diff:17 ms [ 61.653876] thread_id:0, send_diff:16 ms [ 61.670162] thread_id:0, send_diff:16 ms [ 61.687318] thread_id:0, send_diff:17 ms [ 61.703747] thread_id:0, send_diff:16 ms [ 61.720656] thread_id:0, send_diff:16 ms If I didn't do anything to UI, I won't see any mbox_send_message() logs. It means mbox_send_message() will only be called when the display is updated: [ 782.777205] thread_id:0, send_diff:20072 ms [ 820.296738] thread_id:0, send_diff:37519 ms [ 863.034270] thread_id:0, send_diff:42737 ms [ 880.297759] thread_id:0, send_diff:17263 ms [ 917.795432] thread_id:0, send_diff:37497 ms When opening camera APP, it seems to become 30fps: [ 120.551778] BUG: sleeping function called from invalid context at drivers/base/power/runtime.c:1164 [ 120.560844] in_atomic(): 1, irqs_disabled(): 128, non_block: 0, pid: 201, name: kworker/u17:1 [ 120.569363] preempt_count: 1, expected: 0 [ 120.573367] RCU nest depth: 0, expected: 0 [ 120.577457] INFO: lockdep is turned off. [ 120.581372] irq event stamp: 0 [ 120.584420] hardirqs last enabled at (0): [<0000000000000000>] 0x0 [ 120.590687] hardirqs last disabled at (0): [<ffffffd3624a86e0>] copy_process+0x578/0xf10 [ 120.598780] softirqs last enabled at (0): [<ffffffd3624a86ec>] copy_process+0x584/0xf10 [ 120.606865] softirqs last disabled at (0): [<0000000000000000>] 0x0 [ 120.613128] CPU: 0 PID: 201 Comm: kworker/u17:1 Not tainted 6.1.92- lockdep-14419-g8c5f20e56598-dirty #1 e971112e83e796239a41e46e8747794c737fb18c [ 120.626073] Hardware name: Google Ciri sku0/unprovisioned board (DT) [ 120.632420] Workqueue: imgsys_runner imgsys_runner_func [ 120.637647] Call trace: [ 120.640086] dump_backtrace+0x100/0x120 [ 120.643919] show_stack+0x20/0x2c [ 120.647230] dump_stack_lvl+0x84/0xb4 [ 120.650891] dump_stack+0x18/0x44 [ 120.654203] __might_resched+0x204/0x214 [ 120.658123] __might_sleep+0x50/0x80 [ 120.661692] __pm_runtime_resume+0x48/0xbc [ 120.665786] cmdq_mbox_send_data+0x8c/0x434 [ 120.669966] msg_submit+0x84/0x104 [ 120.673362] mbox_send_message+0xb8/0x124 [ 120.677365] imgsys_cmdq_sendtask+0x688/0x928 [ 120.681717] imgsys_runner_func+0x44/0x78 [ 120.685722] process_one_work+0x274/0x574 [ 120.689731] worker_thread+0x240/0x3f0 [ 120.693475] kthread+0xfc/0x11c [ 120.696612] ret_from_fork+0x10/0x20 [ 120.710570] mtk-cam raw 16030000.cam-raw-a: [SOF] frame done reading lost frames. req(7),ts(120697780083) [ 120.720352] mtk-cam raw 16030000.cam-raw-a: [SOF] SCQ_DELAY state:4 ts:120697780083 [ 120.990091] thread_id:0, send_diff:1470 ms [ 121.007210] thread_id:0, send_diff:17 ms [ 121.016484] thread_id:0, send_diff:9 ms [ 121.032652] thread_id:0, send_diff:16 ms [ 121.049366] thread_id:0, send_diff:16 ms [ 121.066880] thread_id:0, send_diff:17 ms [ 121.087023] thread_id:0, send_diff:20 ms [ 121.099325] thread_id:0, send_diff:12 ms [ 121.135286] thread_id:0, send_diff:35 ms [ 121.149349] thread_id:0, send_diff:14 ms [ 121.179259] thread_id:0, send_diff:29 ms [ 121.203183] thread_id:0, send_diff:23 ms [ 121.242234] thread_id:0, send_diff:39 ms [ 121.280645] thread_id:0, send_diff:38 ms [ 121.318651] thread_id:0, send_diff:38 ms [ 121.356366] thread_id:0, send_diff:37 ms [ 121.394484] thread_id:0, send_diff:38 ms The cmdq_runtime_suspend() will only be called when I disabled camera APP: [ 468.137530] pm_on ts:465259, pm_off ts:4681375, diff:2877 ms and the diff is the duration from opening the camera APP to closing the camera APP. From booting to seeing the UI and any operation of UI, I didn't see any cmdq_runtime_suspend() logs from display mbox channel. So cmdq_runtime_resume() and cmdq_runtime_suspend() are never called by display mbox channel. This can tell why only opening the camera APP can see this BUG report. > > > To be clear, do with the mailbox channel that you do with the clocks > now, because your startup() is literally and shutdown() is > practically > empty. > Call shutdown() when no request has come in for a while, so you know > the client has quiesced likely. So try putting request/release in > higher level RPM with autosuspend. I'm not quit sure how to modify this from current usage. Do you mean: 1. Move pm_runtime_get_sync() from cmdq_mbox_semd_data() to startup() and keep pm_runtime_put_autosuspend() in cmdq_mbox_semd_data()? 2. Call shutdown() in cmdq_runtime_suspend()? Regards, Jason-JH.Lin > > thanks
On Mon, Jun 24, 2024 at 10:41 PM Jason-JH Lin (林睿祥) <Jason-JH.Lin@mediatek.com> wrote: > > On Mon, 2024-06-24 at 12:45 -0500, Jassi Brar wrote: > > > > External email : Please do not click links or open attachments until > > you have verified the sender or the content. > > On Mon, Jun 24, 2024 at 6:29 AM AngeloGioacchino Del Regno > > <angelogioacchino.delregno@collabora.com> wrote: > > > > > > Il 20/06/24 16:39, Jassi Brar ha scritto: > > > > 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. > > > > > > It'll be upstreamed in the future, so I can only test it locally to > find the information we want. > > > > > > > > >> 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. > > > > > > > > > > "I want numbers" is a sensible request, honestly I would do the > > same so I totally > > > understand that. > > > > > > Jason, can you please perform latency measurements on 60Hz and > > *especially* ISP/cam > > > cases while "continuously" calling startup() and shutdown() for > > every power saving > > > operation? > > You mean moving clk_builk_enable() and clk_bulk_disable() to startup() > and shutdown(), and then calling startup() in cmdq_runtime_resume() and > calling shutdown() in cmdq_runtime_suspend()? > If we do that, I think GCE clocks will never be closed because > mbox_request_channel() and mbox_free_channel() will call startup() and > shutdown() already. > > I found that display thread:0 will call mbox_send_message() every 16ms > when I moving UI continuously: > [ 61.503604] thread_id:0, send_diff:16 ms > [ 61.520266] thread_id:0, send_diff:16 ms > [ 61.537143] thread_id:0, send_diff:16 ms > [ 61.553609] thread_id:0, send_diff:16 ms > [ 61.570811] thread_id:0, send_diff:17 ms > [ 61.587075] thread_id:0, send_diff:16 ms > [ 61.603527] thread_id:0, send_diff:16 ms > [ 61.620082] thread_id:0, send_diff:16 ms > [ 61.637496] thread_id:0, send_diff:17 ms > [ 61.653876] thread_id:0, send_diff:16 ms > [ 61.670162] thread_id:0, send_diff:16 ms > [ 61.687318] thread_id:0, send_diff:17 ms > [ 61.703747] thread_id:0, send_diff:16 ms > [ 61.720656] thread_id:0, send_diff:16 ms > If I didn't do anything to UI, I won't see any mbox_send_message() > logs. > > It means mbox_send_message() will only be called when the display is > updated: > [ 782.777205] thread_id:0, send_diff:20072 ms > [ 820.296738] thread_id:0, send_diff:37519 ms > [ 863.034270] thread_id:0, send_diff:42737 ms > [ 880.297759] thread_id:0, send_diff:17263 ms > [ 917.795432] thread_id:0, send_diff:37497 ms > > > When opening camera APP, it seems to become 30fps: > [ 120.551778] BUG: sleeping function called from invalid context at > drivers/base/power/runtime.c:1164 > [ 120.560844] in_atomic(): 1, irqs_disabled(): 128, non_block: 0, pid: > 201, name: kworker/u17:1 > [ 120.569363] preempt_count: 1, expected: 0 > [ 120.573367] RCU nest depth: 0, expected: 0 > [ 120.577457] INFO: lockdep is turned off. > [ 120.581372] irq event stamp: 0 > [ 120.584420] hardirqs last enabled at (0): [<0000000000000000>] 0x0 > [ 120.590687] hardirqs last disabled at (0): [<ffffffd3624a86e0>] > copy_process+0x578/0xf10 > [ 120.598780] softirqs last enabled at (0): [<ffffffd3624a86ec>] > copy_process+0x584/0xf10 > [ 120.606865] softirqs last disabled at (0): [<0000000000000000>] 0x0 > [ 120.613128] CPU: 0 PID: 201 Comm: kworker/u17:1 Not tainted 6.1.92- > lockdep-14419-g8c5f20e56598-dirty #1 > e971112e83e796239a41e46e8747794c737fb18c > [ 120.626073] Hardware name: Google Ciri sku0/unprovisioned board (DT) > [ 120.632420] Workqueue: imgsys_runner imgsys_runner_func > [ 120.637647] Call trace: > [ 120.640086] dump_backtrace+0x100/0x120 > [ 120.643919] show_stack+0x20/0x2c > [ 120.647230] dump_stack_lvl+0x84/0xb4 > [ 120.650891] dump_stack+0x18/0x44 > [ 120.654203] __might_resched+0x204/0x214 > [ 120.658123] __might_sleep+0x50/0x80 > [ 120.661692] __pm_runtime_resume+0x48/0xbc > [ 120.665786] cmdq_mbox_send_data+0x8c/0x434 > [ 120.669966] msg_submit+0x84/0x104 > [ 120.673362] mbox_send_message+0xb8/0x124 > [ 120.677365] imgsys_cmdq_sendtask+0x688/0x928 > [ 120.681717] imgsys_runner_func+0x44/0x78 > [ 120.685722] process_one_work+0x274/0x574 > [ 120.689731] worker_thread+0x240/0x3f0 > [ 120.693475] kthread+0xfc/0x11c > [ 120.696612] ret_from_fork+0x10/0x20 > [ 120.710570] mtk-cam raw 16030000.cam-raw-a: [SOF] frame done reading > lost frames. req(7),ts(120697780083) > [ 120.720352] mtk-cam raw 16030000.cam-raw-a: [SOF] SCQ_DELAY state:4 > ts:120697780083 > [ 120.990091] thread_id:0, send_diff:1470 ms > [ 121.007210] thread_id:0, send_diff:17 ms > [ 121.016484] thread_id:0, send_diff:9 ms > [ 121.032652] thread_id:0, send_diff:16 ms > [ 121.049366] thread_id:0, send_diff:16 ms > [ 121.066880] thread_id:0, send_diff:17 ms > [ 121.087023] thread_id:0, send_diff:20 ms > [ 121.099325] thread_id:0, send_diff:12 ms > [ 121.135286] thread_id:0, send_diff:35 ms > [ 121.149349] thread_id:0, send_diff:14 ms > [ 121.179259] thread_id:0, send_diff:29 ms > [ 121.203183] thread_id:0, send_diff:23 ms > [ 121.242234] thread_id:0, send_diff:39 ms > [ 121.280645] thread_id:0, send_diff:38 ms > [ 121.318651] thread_id:0, send_diff:38 ms > [ 121.356366] thread_id:0, send_diff:37 ms > [ 121.394484] thread_id:0, send_diff:38 ms > > The cmdq_runtime_suspend() will only be called when I disabled camera > APP: > [ 468.137530] pm_on ts:465259, pm_off ts:4681375, diff:2877 ms > and the diff is the duration from opening the camera APP to closing the > camera APP. > > From booting to seeing the UI and any operation of UI, I didn't see > any cmdq_runtime_suspend() logs from display mbox channel. > So cmdq_runtime_resume() and cmdq_runtime_suspend() are never called by > display mbox channel. > This can tell why only opening the camera APP can see this BUG report. > > > > > > To be clear, do with the mailbox channel that you do with the clocks > > now, because your startup() is literally and shutdown() is > > practically > > empty. > > Call shutdown() when no request has come in for a while, so you know > > the client has quiesced likely. So try putting request/release in > > higher level RPM with autosuspend. > > I'm not quit sure how to modify this from current usage. > Do you mean: > 1. Move pm_runtime_get_sync() from cmdq_mbox_semd_data() to startup() > and keep pm_runtime_put_autosuspend() in cmdq_mbox_semd_data()? > > 2. Call shutdown() in cmdq_runtime_suspend()? > No shutdown() is called from channel release. Maybe release the channel from suspend() of user driver (imgsys). The idea is that 1) If the gap between transfers on a busy channel is ~10ms or more. And .. 2) The silence on the mailbox channel is multiple of 100ms. And ... 3) startup() and shutdown() are empty (as in your driver) ... then you could afford to release/suspend and resume/request during the silence period because the _api_ cost of request/release should not even be 1ms. Your stack may be designed to make doing that difficult but numbers wise it should work. Thanks
[snip] > > > > "I want numbers" is a sensible request, honestly I would do the > > > same so I totally > > > > understand that. > > > > > > > > Jason, can you please perform latency measurements on 60Hz and > > > *especially* ISP/cam > > > > cases while "continuously" calling startup() and shutdown() for > > > every power saving > > > > operation? > > > > You mean moving clk_builk_enable() and clk_bulk_disable() to > startup() > > and shutdown(), and then calling startup() in cmdq_runtime_resume() > and > > calling shutdown() in cmdq_runtime_suspend()? > > If we do that, I think GCE clocks will never be closed because > > mbox_request_channel() and mbox_free_channel() will call startup() > and > > shutdown() already. > > > > I found that display thread:0 will call mbox_send_message() every > 16ms > > when I moving UI continuously: > > [ 61.503604] thread_id:0, send_diff:16 ms > > [ 61.520266] thread_id:0, send_diff:16 ms > > [ 61.537143] thread_id:0, send_diff:16 ms > > [ 61.553609] thread_id:0, send_diff:16 ms > > [ 61.570811] thread_id:0, send_diff:17 ms > > [ 61.587075] thread_id:0, send_diff:16 ms > > [ 61.603527] thread_id:0, send_diff:16 ms > > [ 61.620082] thread_id:0, send_diff:16 ms > > [ 61.637496] thread_id:0, send_diff:17 ms > > [ 61.653876] thread_id:0, send_diff:16 ms > > [ 61.670162] thread_id:0, send_diff:16 ms > > [ 61.687318] thread_id:0, send_diff:17 ms > > [ 61.703747] thread_id:0, send_diff:16 ms > > [ 61.720656] thread_id:0, send_diff:16 ms > > If I didn't do anything to UI, I won't see any mbox_send_message() > > logs. > > > > It means mbox_send_message() will only be called when the display > is > > updated: > > [ 782.777205] thread_id:0, send_diff:20072 ms > > [ 820.296738] thread_id:0, send_diff:37519 ms > > [ 863.034270] thread_id:0, send_diff:42737 ms > > [ 880.297759] thread_id:0, send_diff:17263 ms > > [ 917.795432] thread_id:0, send_diff:37497 ms > > > > > > When opening camera APP, it seems to become 30fps: > > [ 120.551778] BUG: sleeping function called from invalid context > at > > drivers/base/power/runtime.c:1164 > > [ 120.560844] in_atomic(): 1, irqs_disabled(): 128, non_block: 0, > pid: > > 201, name: kworker/u17:1 > > [ 120.569363] preempt_count: 1, expected: 0 > > [ 120.573367] RCU nest depth: 0, expected: 0 > > [ 120.577457] INFO: lockdep is turned off. > > [ 120.581372] irq event stamp: 0 > > [ 120.584420] hardirqs last enabled at (0): [<0000000000000000>] > 0x0 > > [ 120.590687] hardirqs last disabled at (0): [<ffffffd3624a86e0>] > > copy_process+0x578/0xf10 > > [ 120.598780] softirqs last enabled at (0): [<ffffffd3624a86ec>] > > copy_process+0x584/0xf10 > > [ 120.606865] softirqs last disabled at (0): [<0000000000000000>] > 0x0 > > [ 120.613128] CPU: 0 PID: 201 Comm: kworker/u17:1 Not tainted > 6.1.92- > > lockdep-14419-g8c5f20e56598-dirty #1 > > e971112e83e796239a41e46e8747794c737fb18c > > [ 120.626073] Hardware name: Google Ciri sku0/unprovisioned board > (DT) > > [ 120.632420] Workqueue: imgsys_runner imgsys_runner_func > > [ 120.637647] Call trace: > > [ 120.640086] dump_backtrace+0x100/0x120 > > [ 120.643919] show_stack+0x20/0x2c > > [ 120.647230] dump_stack_lvl+0x84/0xb4 > > [ 120.650891] dump_stack+0x18/0x44 > > [ 120.654203] __might_resched+0x204/0x214 > > [ 120.658123] __might_sleep+0x50/0x80 > > [ 120.661692] __pm_runtime_resume+0x48/0xbc > > [ 120.665786] cmdq_mbox_send_data+0x8c/0x434 > > [ 120.669966] msg_submit+0x84/0x104 > > [ 120.673362] mbox_send_message+0xb8/0x124 > > [ 120.677365] imgsys_cmdq_sendtask+0x688/0x928 > > [ 120.681717] imgsys_runner_func+0x44/0x78 > > [ 120.685722] process_one_work+0x274/0x574 > > [ 120.689731] worker_thread+0x240/0x3f0 > > [ 120.693475] kthread+0xfc/0x11c > > [ 120.696612] ret_from_fork+0x10/0x20 > > [ 120.710570] mtk-cam raw 16030000.cam-raw-a: [SOF] frame done > reading > > lost frames. req(7),ts(120697780083) > > [ 120.720352] mtk-cam raw 16030000.cam-raw-a: [SOF] SCQ_DELAY > state:4 > > ts:120697780083 > > [ 120.990091] thread_id:0, send_diff:1470 ms > > [ 121.007210] thread_id:0, send_diff:17 ms > > [ 121.016484] thread_id:0, send_diff:9 ms > > [ 121.032652] thread_id:0, send_diff:16 ms > > [ 121.049366] thread_id:0, send_diff:16 ms > > [ 121.066880] thread_id:0, send_diff:17 ms > > [ 121.087023] thread_id:0, send_diff:20 ms > > [ 121.099325] thread_id:0, send_diff:12 ms > > [ 121.135286] thread_id:0, send_diff:35 ms > > [ 121.149349] thread_id:0, send_diff:14 ms > > [ 121.179259] thread_id:0, send_diff:29 ms > > [ 121.203183] thread_id:0, send_diff:23 ms > > [ 121.242234] thread_id:0, send_diff:39 ms > > [ 121.280645] thread_id:0, send_diff:38 ms > > [ 121.318651] thread_id:0, send_diff:38 ms > > [ 121.356366] thread_id:0, send_diff:37 ms > > [ 121.394484] thread_id:0, send_diff:38 ms > > > > The cmdq_runtime_suspend() will only be called when I disabled > camera > > APP: > > [ 468.137530] pm_on ts:465259, pm_off ts:4681375, diff:2877 ms > > and the diff is the duration from opening the camera APP to closing > the > > camera APP. > > > > From booting to seeing the UI and any operation of UI, I didn't see > > any cmdq_runtime_suspend() logs from display mbox channel. > > So cmdq_runtime_resume() and cmdq_runtime_suspend() are never > called by > > display mbox channel. > > This can tell why only opening the camera APP can see this BUG > report. > > > > > > > > > To be clear, do with the mailbox channel that you do with the > clocks > > > now, because your startup() is literally and shutdown() is > > > practically > > > empty. > > > Call shutdown() when no request has come in for a while, so you > know > > > the client has quiesced likely. So try putting request/release in > > > higher level RPM with autosuspend. > > > > I'm not quit sure how to modify this from current usage. > > Do you mean: > > 1. Move pm_runtime_get_sync() from cmdq_mbox_semd_data() to > startup() > > and keep pm_runtime_put_autosuspend() in cmdq_mbox_semd_data()? > > > > 2. Call shutdown() in cmdq_runtime_suspend()? > > > No shutdown() is called from channel release. Maybe release the > channel from suspend() of user driver (imgsys). When users call mbox_channel_request(), there is nothing to do with HW, so CMDQ driver leaves startup() empty. When users call mbox_sned_message(), users want to use HW to execute some instruction, so CMDQ driver needs to enable the power/clocks in this function. When users call mbox_free_channel() or mbox_flush(), CMDQ driver needs to check the HW executing status and clears all the executing tasks, so it also needs to enable power/clocks in shutdown() and flush() to control the HW. The power saving goal is to disable the power/clk more than the configurable timeout (100ms currently) after enabling it. So I think calling suspend() of user driver can not achieve this. Please correct me if I'm wrong :) > > The idea is that > 1) If the gap between transfers on a busy channel is ~10ms or > more. And .. > 2) The silence on the mailbox channel is multiple of 100ms. And ... The mailbox channel would not be always busy and the gap is not consistent as well. For example, display driver calls mbox_send_message() every ~16ms while UI is updating in 60fps. If UI dose not update, display driver won't call mbox_send_message(), so user may not has the gap and the silence like this. > 3) startup() and shutdown() are empty (as in your driver) > ... then you could afford to release/suspend and resume/request > during the silence period because the _api_ cost of request/release > should not even be 1ms. Your stack may be designed to make doing that > difficult but numbers wise it should work. Yes, that's true, but I think we can not achieve the goal during the suspend/resume stage. Currently, we use the pm_runtime_get_sync() and pm_runtime_auto_suspend() to achieve this. So I think adding the PM function hook in mailbox driver is much better for users driver and also more flexible for the controller driver. Please correct me if there is something I misunderstood :) Regards, Jason-JH.Lin > > Thanks
On Wed, Jun 26, 2024 at 4:32 AM Jason-JH Lin (林睿祥) <Jason-JH.Lin@mediatek.com> wrote: > > > > The idea is that > > 1) If the gap between transfers on a busy channel is ~10ms or > > more. And .. > > 2) The silence on the mailbox channel is multiple of 100ms. And ... > > The mailbox channel would not be always busy and the gap is not > consistent as well. > For example, display driver calls mbox_send_message() every ~16ms while > UI is updating in 60fps. > If UI dose not update, display driver won't call mbox_send_message(), > so user may not has the gap and the silence like this. > From your logs, send_diff only increases from 16ms if the UI is not updating. Which makes it more prudent to release the channel. The user needs the channel for mbox_send_message, while actual power saving comes from cmdq_runtime_suspend/resume. So for your target usage pattern, trace mbox_send_message() , cmdq_runtime_resume() and cmdq_runtime_suspend() and compare the timestamped logs with and without this patchset. > > 3) startup() and shutdown() are empty (as in your driver) > > ... then you could afford to release/suspend and resume/request > > during the silence period because the _api_ cost of request/release > > should not even be 1ms. Your stack may be designed to make doing that > > difficult but numbers wise it should work. > > Yes, that's true, but I think we can not achieve the goal during the > suspend/resume stage. > > Currently, we use the pm_runtime_get_sync() and > pm_runtime_auto_suspend() to achieve this. > So I think adding the PM function hook in mailbox driver is much better > for users driver and also more flexible for the controller driver. > > Please correct me if there is something I misunderstood :) > I have a gut feeling the logs above will make it clear :) Cheers!
On Thu, 2024-06-27 at 22:40 -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 26, 2024 at 4:32 AM Jason-JH Lin (林睿祥) > <Jason-JH.Lin@mediatek.com> wrote: > > > > > > The idea is that > > > 1) If the gap between transfers on a busy channel is ~10ms or > > > more. And .. > > > 2) The silence on the mailbox channel is multiple of 100ms. And > ... > > > > The mailbox channel would not be always busy and the gap is not > > consistent as well. > > For example, display driver calls mbox_send_message() every ~16ms > while > > UI is updating in 60fps. > > If UI dose not update, display driver won't call > mbox_send_message(), > > so user may not has the gap and the silence like this. > > > From your logs, send_diff only increases from 16ms if the UI is not > updating. Which makes it more prudent to release the channel. > > The user needs the channel for mbox_send_message, while actual power > saving comes from cmdq_runtime_suspend/resume. > So for your target usage pattern, trace mbox_send_message() , > cmdq_runtime_resume() and cmdq_runtime_suspend() and compare the > timestamped logs with and without this patchset. > [snip] I realized that we have 2 cmdq drivers: display uses 10320000.mailbox and imgsys uses 10330000.mailbox I added diff logs in cmdq_runtime_resume(), cmdq_runtime_suspend() and cmdq_mbox_send_data(). Here is the log of 10320000.mailbox: // CMDQ probe [ 4.288408] mtk_cmdq 10320000.mailbox: IRQ=279++++++++++++++ // Show boot logo [ 9.177741] cmdq_runtime_resume: resume_diff=9177 ms [ 9.698045] cmdq_mbox_send_data: send_diff=14 ms // Show UI [ 15.620525] cmdq_mbox_send_data: send_diff=5922 ms [ 15.652041] cmdq_mbox_send_data: send_diff=31 ms [ 15.681308] cmdq_mbox_send_data: send_diff=29 ms [ 16.276090] cmdq_mbox_send_data: send_diff=594 ms [ 16.355256] cmdq_mbox_send_data: send_diff=79 ms ... [ 35.013395] cmdq_mbox_send_data: send_diff=16 ms [ 35.030301] cmdq_mbox_send_data: send_diff=16 ms [ 35.047002] cmdq_mbox_send_data: send_diff=16 ms [ 35.068360] cmdq_mbox_send_data: send_diff=21 ms // Open camera APP [ 37.291937] cmdq_mbox_send_data: send_diff=2223 ms [ 37.884435] cmdq_mbox_send_data: send_diff=592 ms [ 37.905703] cmdq_mbox_send_data: send_diff=21 ms [ 37.928599] cmdq_mbox_send_data: send_diff=22 ms ... [ 41.396577] cmdq_mbox_send_data: send_diff=16 ms [ 41.413107] cmdq_mbox_send_data: send_diff=16 ms [ 42.440862] cmdq_mbox_send_data: send_diff=1027 ms [ 42.647045] cmdq_mbox_send_data: send_diff=206 ms // Close camera APP [ 89.940631] cmdq_mbox_send_data: send_diff=47293 ms [ 106.704928] cmdq_mbox_send_data: send_diff=16764 ms ... [ 113.130841] cmdq_mbox_send_data: send_diff=211 ms // push power key to disable panel [ 113.281999] cmdq_runtime_suspend: R/S_diff=104104 ms // push power key to enable panel [ 131.287190] cmdq_runtime_resume: resume_diff=122109 ms Here is the log of 10330000.mailbox: // CMDQ probe [ 4.290404] mtk_cmdq 10330000.mailbox: IRQ=280++++++++++++++ // Open camera APP [ 36.174867] BUG: sleeping function called from invalid context at drivers/base/power/runtime.c:1164 [ 36.183942] in_atomic(): 1, irqs_disabled(): 128, non_block: 0, pid: 95, name: kworker/u17:0 [ 36.192383] preempt_count: 1, expected: 0 [ 36.196395] RCU nest depth: 0, expected: 0 [ 36.200489] INFO: lockdep is turned off. [ 36.204405] irq event stamp: 16 [ 36.238636] CPU: 2 PID: 95 Comm: kworker/u17:0 Not tainted [ 36.251508] Hardware name: Google Ciri sku0/unprovisioned board (DT) [ 36.257864] Workqueue: imgsys_runner imgsys_runner_func [ 36.263107] Call trace: [ 36.265555] dump_backtrace+0x100/0x120 [ 36.269400] show_stack+0x20/0x2c [ 36.272722] dump_stack_lvl+0x84/0xb4 [ 36.276390] dump_stack+0x18/0x44 [ 36.279706] __might_resched+0x204/0x214 [ 36.283631] __might_sleep+0x50/0x80 [ 36.287209] __pm_runtime_resume+0x48/0xbc [ 36.291316] cmdq_mbox_send_data+0x84/0x43c [ 36.295510] msg_submit+0x84/0x104 [ 36.298919] mbox_send_message+0xb8/0x124 [ 36.302934] imgsys_cmdq_sendtask+0x6b0/0x990 [ 36.307300] imgsys_runner_func+0x44/0x78 [ 36.311318] process_one_work+0x274/0x574 [ 36.315336] worker_thread+0x240/0x3f0 [ 36.319093] kthread+0xfc/0x11c [ 36.322242] ret_from_fork+0x10/0x20 [ 36.325989] cmdq_runtime_resume: resume_diff=36325 ms [ 36.342235] cmdq_mbox_send_data: send_diff=167 ms [ 36.366714] cmdq_mbox_send_data: send_diff=24 ms [ 36.382882] cmdq_mbox_send_data: send_diff=16 ms [ 36.399512] cmdq_mbox_send_data: send_diff=16 ms ... [ 42.817244] cmdq_mbox_send_data: send_diff=16 ms [ 42.844891] cmdq_mbox_send_data: send_diff=27 ms [ 42.856340] cmdq_mbox_send_data: send_diff=11 ms [ 42.856364] cmdq_mbox_send_data: send_diff=0 ms [ 42.856384] cmdq_mbox_send_data: send_diff=0 ms [ 42.856410] cmdq_mbox_send_data: send_diff=0 ms [ 42.856431] cmdq_mbox_send_data: send_diff=0 ms [ 42.856458] cmdq_mbox_send_data: send_diff=0 ms [ 42.856482] cmdq_mbox_send_data: send_diff=0 ms [ 42.985695] cmdq_mbox_send_data: send_diff=129 ms [ 42.992017] cmdq_runtime_suspend: R/S_diff=6666 ms Regards, Jason-JH.Lin
On Wed, Jul 3, 2024 at 11:41 AM Jason-JH Lin (林睿祥) <Jason-JH.Lin@mediatek.com> wrote: > > On Thu, 2024-06-27 at 22:40 -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 26, 2024 at 4:32 AM Jason-JH Lin (林睿祥) > > <Jason-JH.Lin@mediatek.com> wrote: > > > > > > > > The idea is that > > > > 1) If the gap between transfers on a busy channel is ~10ms or > > > > more. And .. > > > > 2) The silence on the mailbox channel is multiple of 100ms. And > > ... > > > > > > The mailbox channel would not be always busy and the gap is not > > > consistent as well. > > > For example, display driver calls mbox_send_message() every ~16ms > > while > > > UI is updating in 60fps. > > > If UI dose not update, display driver won't call > > mbox_send_message(), > > > so user may not has the gap and the silence like this. > > > > > From your logs, send_diff only increases from 16ms if the UI is not > > updating. Which makes it more prudent to release the channel. > > > > The user needs the channel for mbox_send_message, while actual power > > saving comes from cmdq_runtime_suspend/resume. > > So for your target usage pattern, trace mbox_send_message() , > > cmdq_runtime_resume() and cmdq_runtime_suspend() and compare the > > timestamped logs with and without this patchset. > > > [snip] > > I realized that we have 2 cmdq drivers: > display uses 10320000.mailbox and imgsys uses 10330000.mailbox > You may disable one to make it easy to capture. Make sure your kernel prints have timestamps. Over your patchset, apply the following diff and execute your usecase. Then share $ dmesg | grep Jason diff --git a/drivers/mailbox/mailbox.c b/drivers/mailbox/mailbox.c index bafcc7b0c0b8d..90c0620c0ae63 100644 --- a/drivers/mailbox/mailbox.c +++ b/drivers/mailbox/mailbox.c @@ -284,6 +284,7 @@ int mbox_send_message(struct mbox_chan *chan, void *mssg) { int t; + printk("Jason %s: %p\n", __func__, (void *)chan); if (!chan || !chan->cl) return -EINVAL; diff --git a/drivers/mailbox/mtk-cmdq-mailbox.c b/drivers/mailbox/mtk-cmdq-mailbox.c index 02cef3eee35a5..6436e1b22f353 100644 --- a/drivers/mailbox/mtk-cmdq-mailbox.c +++ b/drivers/mailbox/mtk-cmdq-mailbox.c @@ -317,6 +317,7 @@ static int cmdq_runtime_resume(struct device *dev) { struct cmdq *cmdq = dev_get_drvdata(dev); + printk("Jason %s: %p\n", __func__, (void *)dev); return clk_bulk_enable(cmdq->pdata->gce_num, cmdq->clocks); } @@ -324,6 +325,7 @@ static int cmdq_runtime_suspend(struct device *dev) { struct cmdq *cmdq = dev_get_drvdata(dev); + printk("Jason %s: %p\n", __func__, (void *)dev); clk_bulk_disable(cmdq->pdata->gce_num, cmdq->clocks); return 0; } Thanks
[snip] > You may disable one to make it easy to capture. > Make sure your kernel prints have timestamps. > Over your patchset, apply the following diff and execute your > usecase. > Then share > $ dmesg | grep Jason > > diff --git a/drivers/mailbox/mailbox.c b/drivers/mailbox/mailbox.c > index bafcc7b0c0b8d..90c0620c0ae63 100644 > --- a/drivers/mailbox/mailbox.c > +++ b/drivers/mailbox/mailbox.c > @@ -284,6 +284,7 @@ int mbox_send_message(struct mbox_chan *chan, > void *mssg) > { > int t; > > + printk("Jason %s: %p\n", __func__, (void *)chan); > if (!chan || !chan->cl) > return -EINVAL; > > diff --git a/drivers/mailbox/mtk-cmdq-mailbox.c > b/drivers/mailbox/mtk-cmdq-mailbox.c > index 02cef3eee35a5..6436e1b22f353 100644 > --- a/drivers/mailbox/mtk-cmdq-mailbox.c > +++ b/drivers/mailbox/mtk-cmdq-mailbox.c > @@ -317,6 +317,7 @@ static int cmdq_runtime_resume(struct device > *dev) > { > struct cmdq *cmdq = dev_get_drvdata(dev); > > + printk("Jason %s: %p\n", __func__, (void *)dev); > return clk_bulk_enable(cmdq->pdata->gce_num, cmdq->clocks); > } > > @@ -324,6 +325,7 @@ static int cmdq_runtime_suspend(struct device > *dev) > { > struct cmdq *cmdq = dev_get_drvdata(dev); > > + printk("Jason %s: %p\n", __func__, (void *)dev); > clk_bulk_disable(cmdq->pdata->gce_num, cmdq->clocks); > return 0; > } > > Thanks It seems CMDQ driver is not suspend over 100ms. Here is the log with your diff over my log path: // Show boot logo [ 9.293001] Jason cmdq_runtime_resume: dev:00000000f85c3b60, resume_diff=9293 ms [ 9.300401] Jason cmdq_runtime_resume 00000000f85c3b60 [ 9.803409] Jason mbox_send_message 000000000a4d37b5 [ 9.818483] Jason mbox_send_message 000000000a4d37b5 [ 9.823449] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=10 ms // Show UI [ 15.814500] Jason mbox_send_message 000000000a4d37b5 [ 15.828538] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=6005 ms [ 15.872734] Jason mbox_send_message 000000000a4d37b5 [ 15.881172] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=52 ms [ 15.945682] Jason mbox_send_message 000000000a4d37b5 [ 15.966191] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=85 ms [ 16.265901] Jason mbox_send_message 000000000a4d37b5 [ 16.270896] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=304 ms [ 16.324910] Jason mbox_send_message 000000000a4d37b5 [ 16.330092] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=59 ms [ 16.352114] Jason mbox_send_message 000000000a4d37b5 [ 16.357636] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=27 ms [ 16.510801] Jason mbox_send_message 000000008bc5af0a [ 16.555246] Jason mbox_send_message 000000000a4d37b5 [ 16.560754] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=203 ms [ 16.585409] Jason mbox_send_message 000000000a4d37b5 [ 16.590662] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=29 ms [ 16.610080] Jason mbox_send_message 000000000a4d37b5 [ 16.615094] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=24 ms [ 16.635150] Jason mbox_send_message 000000000a4d37b5 [ 16.640134] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=25 ms [ 16.669825] Jason mbox_send_message 000000000a4d37b5 [ 16.678863] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=38 ms [ 16.704411] Jason mbox_send_message 000000000a4d37b5 [ 16.712306] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=33 ms [ 16.736412] Jason mbox_send_message 000000000a4d37b5 [ 16.769828] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=57 ms [ 16.799703] Jason mbox_send_message 000000000a4d37b5 [ 16.804738] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=34 ms [ 16.819595] Jason mbox_send_message 000000000a4d37b5 [ 16.824785] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=20 ms [ 16.843220] Jason mbox_send_message 0000000093b3576f [ 16.853728] Jason mbox_send_message 0000000093b3576f [ 16.855027] Jason mbox_send_message 000000000a4d37b5 [ 16.858791] Jason mbox_send_message 0000000093b3576f [ 16.866244] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=41 ms [ 16.868773] Jason mbox_send_message 0000000093b3576f [ 16.882623] Jason mbox_send_message 0000000093b3576f [ 16.885841] Jason mbox_send_message 000000000a4d37b5 [ 16.887749] Jason mbox_send_message 0000000093b3576f [ 16.894291] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=28 ms [ 16.908402] Jason mbox_send_message 0000000093b3576f [ 16.913893] Jason mbox_send_message 0000000093b3576f [ 16.919574] Jason mbox_send_message 0000000093b3576f [ 16.922340] Jason mbox_send_message 000000000a4d37b5 [ 16.926164] Jason mbox_send_message 0000000093b3576f [ 16.930373] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=36 ms [ 16.934538] Jason mbox_send_message 0000000093b3576f [ 16.959472] Jason mbox_send_message 0000000093b3576f [ 16.966214] Jason mbox_send_message 0000000093b3576f [ 16.969024] Jason mbox_send_message 000000000a4d37b5 [ 16.972936] Jason mbox_send_message 0000000093b3576f [ 16.979286] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=48 ms [ 16.981247] Jason mbox_send_message 0000000093b3576f [ 17.001737] Jason mbox_send_message 0000000093b3576f [ 17.006783] Jason mbox_send_message 0000000093b3576f [ 17.016727] Jason mbox_send_message 0000000093b3576f [ 17.036242] Jason mbox_send_message 000000000a4d37b5 [ 17.050531] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=71 ms [ 17.054402] Jason mbox_send_message 0000000093b3576f [ 17.068355] Jason mbox_send_message 0000000093b3576f [ 17.073592] Jason mbox_send_message 0000000093b3576f [ 17.073703] Jason mbox_send_message 000000000a4d37b5 [ 17.078707] Jason mbox_send_message 0000000093b3576f [ 17.085946] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=35 ms [ 17.088615] Jason mbox_send_message 0000000093b3576f [ 17.101791] Jason mbox_send_message 000000000a4d37b5 [ 17.102450] Jason mbox_send_message 0000000093b3576f [ 17.107405] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=21 ms [ 17.112472] Jason mbox_send_message 0000000093b3576f [ 17.126709] Jason mbox_send_message 0000000093b3576f [ 17.132703] Jason mbox_send_message 0000000093b3576f [ 17.140598] Jason mbox_send_message 000000000a4d37b5 [ 17.152516] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=45 ms [ 17.163510] Jason mbox_send_message 0000000093b3576f [ 17.175405] Jason mbox_send_message 0000000093b3576f [ 17.180439] Jason mbox_send_message 0000000093b3576f [ 17.193267] Jason mbox_send_message 0000000093b3576f [ 17.193720] Jason mbox_send_message 000000000a4d37b5 [ 17.198670] Jason mbox_send_message 0000000093b3576f [ 17.204419] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=51 ms [ 17.209114] Jason mbox_send_message 0000000093b3576f [ 17.218999] Jason mbox_send_message 000000000a4d37b5 [ 17.222142] Jason mbox_send_message 0000000093b3576f [ 17.227067] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=22 ms [ 17.232104] Jason mbox_send_message 0000000093b3576f [ 17.246065] Jason mbox_send_message 0000000093b3576f [ 17.246858] Jason mbox_send_message 000000000a4d37b5 [ 17.251078] Jason mbox_send_message 0000000093b3576f [ 17.257316] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=30 ms [ 17.261236] Jason mbox_send_message 0000000093b3576f [ 17.276316] Jason mbox_send_message 0000000093b3576f [ 17.281395] Jason mbox_send_message 0000000093b3576f [ 17.294176] Jason mbox_send_message 0000000093b3576f [ 17.294471] Jason mbox_send_message 000000000a4d37b5 [ 17.299247] Jason mbox_send_message 0000000093b3576f [ 17.304112] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=46 ms [ 17.309142] Jason mbox_send_message 0000000093b3576f [ 17.323022] Jason mbox_send_message 0000000093b3576f [ 17.343009] Jason mbox_send_message 000000000a4d37b5 [ 17.350301] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=46 ms [ 17.368514] Jason mbox_send_message 000000000a4d37b5 [ 17.373829] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=23 ms [ 17.385069] Jason mbox_send_message 000000000a4d37b5 [ 17.390199] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=16 ms [ 17.402151] Jason mbox_send_message 000000000a4d37b5 [ 17.407187] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=16 ms [ 17.418912] Jason mbox_send_message 000000000a4d37b5 [ 17.423921] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=16 ms [ 17.434945] Jason mbox_send_message 000000000a4d37b5 [ 17.440628] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=16 ms [ 17.452001] Jason mbox_send_message 000000000a4d37b5 [ 17.457019] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=16 ms [ 17.469020] Jason mbox_send_message 000000000a4d37b5 [ 17.474283] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=17 ms [ 17.486596] Jason mbox_send_message 000000000a4d37b5 [ 17.492076] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=17 ms [ 17.518716] Jason mbox_send_message 000000000a4d37b5 [ 17.523807] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=31 ms [ 17.534869] Jason mbox_send_message 000000000a4d37b5 [ 17.539898] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=16 ms [ 17.553383] Jason mbox_send_message 000000000a4d37b5 [ 17.559155] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=19 ms [ 17.585307] Jason mbox_send_message 000000000a4d37b5 [ 17.590335] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=31 ms [ 17.601689] Jason mbox_send_message 000000000a4d37b5 [ 17.606803] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=16 ms [ 17.618302] Jason mbox_send_message 000000000a4d37b5 [ 17.623352] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=16 ms [ 17.635423] Jason mbox_send_message 000000000a4d37b5 [ 17.640405] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=17 ms [ 17.651805] Jason mbox_send_message 000000000a4d37b5 [ 17.656956] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=16 ms [ 17.668379] Jason mbox_send_message 000000000a4d37b5 [ 17.673937] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=16 ms [ 17.685543] Jason mbox_send_message 000000000a4d37b5 [ 17.690698] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=16 ms [ 17.718262] Jason mbox_send_message 000000000a4d37b5 [ 17.723248] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=32 ms [ 17.735378] Jason mbox_send_message 000000000a4d37b5 [ 17.740686] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=17 ms [ 17.766828] Jason mbox_send_message 000000000a4d37b5 [ 17.773126] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=32 ms [ 17.785113] Jason mbox_send_message 000000000a4d37b5 [ 17.790131] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=17 ms [ 17.814729] Jason mbox_send_message 000000000a4d37b5 [ 17.820786] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=30 ms [ 17.836325] Jason mbox_send_message 000000000a4d37b5 [ 17.841818] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=21 ms [ 17.852743] Jason mbox_send_message 000000000a4d37b5 [ 17.858573] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=16 ms [ 17.885626] Jason mbox_send_message 000000000a4d37b5 [ 17.890644] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=32 ms [ 17.903622] Jason mbox_send_message 000000000a4d37b5 [ 17.909311] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=18 ms [ 17.935129] Jason mbox_send_message 000000000a4d37b5 [ 17.940219] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=30 ms [ 17.952121] Jason mbox_send_message 000000000a4d37b5 [ 17.968309] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=28 ms [ 17.988969] Jason mbox_send_message 000000000a4d37b5 [ 17.994230] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=25 ms [ 18.018778] Jason mbox_send_message 000000000a4d37b5 [ 18.023881] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=29 ms [ 18.037807] Jason mbox_send_message 000000000a4d37b5 [ 18.047959] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=24 ms [ 18.069339] Jason mbox_send_message 000000000a4d37b5 [ 18.079722] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=31 ms [ 18.101570] Jason mbox_send_message 000000000a4d37b5 [ 18.107038] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=27 ms [ 18.118478] Jason mbox_send_message 000000000a4d37b5 [ 18.123506] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=16 ms [ 18.135656] Jason mbox_send_message 000000000a4d37b5 [ 18.140719] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=17 ms [ 18.154624] Jason mbox_send_message 000000000a4d37b5 [ 18.159945] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=19 ms [ 18.188673] Jason mbox_send_message 000000000a4d37b5 [ 18.194535] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=34 ms [ 18.220118] Jason mbox_send_message 000000000a4d37b5 [ 18.225142] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=30 ms [ 18.235616] Jason mbox_send_message 000000000a4d37b5 [ 18.240595] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=15 ms [ 18.269325] Jason mbox_send_message 000000000a4d37b5 [ 18.274345] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=33 ms [ 18.285281] Jason mbox_send_message 000000000a4d37b5 [ 18.290395] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=16 ms [ 18.318692] Jason mbox_send_message 000000000a4d37b5 [ 18.325465] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=35 ms [ 18.352060] Jason mbox_send_message 000000000a4d37b5 [ 18.360611] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=35 ms [ 18.385190] Jason mbox_send_message 000000000a4d37b5 [ 18.390299] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=29 ms [ 18.402937] Jason mbox_send_message 000000000a4d37b5 [ 18.408895] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=18 ms [ 18.434931] Jason mbox_send_message 000000000a4d37b5 [ 18.439988] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=31 ms [ 18.451612] Jason mbox_send_message 000000000a4d37b5 [ 18.456803] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=16 ms [ 18.468397] Jason mbox_send_message 000000000a4d37b5 [ 18.473516] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=16 ms [ 18.485023] Jason mbox_send_message 000000000a4d37b5 [ 18.490090] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=16 ms [ 18.502056] Jason mbox_send_message 000000000a4d37b5 [ 18.507035] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=16 ms [ 18.518382] Jason mbox_send_message 000000000a4d37b5 [ 18.524306] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=17 ms [ 18.552373] Jason mbox_send_message 000000000a4d37b5 [ 18.557351] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=33 ms [ 18.585566] Jason mbox_send_message 000000000a4d37b5 [ 18.592584] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=35 ms [ 18.620910] Jason mbox_send_message 000000000a4d37b5 [ 18.626032] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=33 ms [ 18.655541] Jason mbox_send_message 000000000a4d37b5 [ 18.665194] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=39 ms [ 18.671288] Jason mbox_send_message 000000000a4d37b5 [ 18.685323] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=20 ms [ 18.701606] Jason mbox_send_message 000000000a4d37b5 [ 18.706742] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=21 ms [ 18.720827] Jason mbox_send_message 000000000a4d37b5 [ 18.720839] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=14 ms [ 18.736966] Jason mbox_send_message 000000000a4d37b5 [ 18.755545] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=34 ms [ 18.786233] Jason mbox_send_message 000000000a4d37b5 [ 18.805378] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=49 ms [ 18.819349] Jason mbox_send_message 000000000a4d37b5 [ 18.827441] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=22 ms [ 18.855612] Jason mbox_send_message 000000000a4d37b5 [ 18.870140] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=42 ms [ 18.886660] Jason mbox_send_message 000000000a4d37b5 [ 18.902180] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=32 ms [ 18.903280] Jason mbox_send_message 000000000a4d37b5 [ 18.915842] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=13 ms [ 18.923847] Jason mbox_send_message 000000000a4d37b5 [ 18.937416] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=21 ms [ 18.938528] Jason mbox_send_message 000000000a4d37b5 [ 18.961883] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=24 ms [ 18.971554] Jason mbox_send_message 000000000a4d37b5 [ 18.971562] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=9 ms [ 19.097018] Jason mbox_send_message 000000000a4d37b5 [ 19.102015] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=130 ms [ 19.120098] Jason mbox_send_message 000000000a4d37b5 [ 19.120194] Jason mbox_send_message 000000009537aba7 [ 19.125098] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=23 ms [ 19.151700] Jason mbox_send_message 000000000a4d37b5 [ 19.157271] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=32 ms [ 19.184952] Jason mbox_send_message 000000000a4d37b5 [ 19.193168] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=35 ms [ 19.219379] Jason mbox_send_message 000000000a4d37b5 [ 19.224375] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=31 ms [ 19.251631] Jason mbox_send_message 000000000a4d37b5 [ 19.256642] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=32 ms [ 19.268119] Jason mbox_send_message 000000000a4d37b5 [ 19.273100] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=16 ms [ 19.286170] Jason mbox_send_message 000000000a4d37b5 [ 19.291757] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=18 ms [ 19.318481] Jason mbox_send_message 000000000a4d37b5 [ 19.323504] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=31 ms [ 19.350567] Jason mbox_send_message 000000000a4d37b5 [ 19.360345] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=36 ms [ 19.392657] Jason mbox_send_message 000000000a4d37b5 [ 19.398211] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=37 ms [ 19.418254] Jason mbox_send_message 000000000a4d37b5 [ 19.424851] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=26 ms [ 19.434780] Jason mbox_send_message 000000000a4d37b5 [ 19.439754] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=14 ms [ 19.503384] Jason mbox_send_message 000000000a4d37b5 [ 19.508352] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=68 ms [ 19.534682] Jason mbox_send_message 000000009537aba7 [ 19.552997] Jason mbox_send_message 000000009537aba7 [ 19.559209] Jason mbox_send_message 000000009537aba7 [ 19.565295] Jason mbox_send_message 000000009537aba7 [ 19.574511] Jason mbox_send_message 000000009537aba7 [ 19.577693] Jason mbox_send_message 000000000a4d37b5 [ 19.580977] Jason mbox_send_message 000000009537aba7 [ 19.584434] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=76 ms [ 19.599437] Jason mbox_send_message 000000009537aba7 [ 19.604655] Jason mbox_send_message 000000009537aba7 [ 19.689977] Jason mbox_send_message 000000000a4d37b5 [ 19.695656] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=111 ms [ 20.205749] Jason mbox_send_message 000000000a4d37b5 [ 20.210966] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=515 ms [ 20.255058] Jason mbox_send_message 0000000093b3576f [ 20.260149] Jason mbox_send_message 0000000093b3576f [ 20.265705] Jason mbox_send_message 0000000093b3576f [ 20.271294] Jason mbox_send_message 0000000093b3576f [ 20.277265] Jason mbox_send_message 0000000093b3576f [ 20.282923] Jason mbox_send_message 0000000093b3576f [ 20.289006] Jason mbox_send_message 0000000093b3576f [ 20.294559] Jason mbox_send_message 0000000093b3576f [ 20.301648] Jason mbox_send_message 0000000093b3576f [ 20.306704] Jason mbox_send_message 0000000093b3576f [ 20.317623] Jason mbox_send_message 0000000093b3576f [ 20.325003] Jason mbox_send_message 0000000093b3576f [ 20.332405] Jason mbox_send_message 0000000093b3576f [ 20.338029] Jason mbox_send_message 0000000093b3576f [ 20.343322] Jason mbox_send_message 0000000093b3576f [ 20.348369] Jason mbox_send_message 0000000093b3576f [ 20.353427] Jason mbox_send_message 0000000093b3576f [ 20.358476] Jason mbox_send_message 0000000093b3576f [ 20.363632] Jason mbox_send_message 0000000093b3576f [ 20.369123] Jason mbox_send_message 0000000093b3576f [ 20.375329] Jason mbox_send_message 0000000093b3576f [ 20.393828] Jason mbox_send_message 0000000093b3576f [ 20.406408] Jason mbox_send_message 0000000093b3576f [ 20.414704] Jason mbox_send_message 0000000093b3576f [ 20.428184] Jason mbox_send_message 0000000093b3576f [ 20.436659] Jason mbox_send_message 0000000093b3576f [ 20.441891] Jason mbox_send_message 0000000093b3576f [ 20.450576] Jason mbox_send_message 0000000093b3576f [ 20.455883] Jason mbox_send_message 0000000093b3576f [ 20.462483] Jason mbox_send_message 0000000093b3576f [ 20.473945] Jason mbox_send_message 0000000093b3576f [ 20.479672] Jason mbox_send_message 0000000093b3576f [ 20.491036] Jason mbox_send_message 0000000093b3576f [ 20.497658] Jason mbox_send_message 0000000093b3576f [ 20.504420] Jason mbox_send_message 0000000093b3576f [ 20.516844] Jason mbox_send_message 0000000093b3576f [ 20.522241] Jason mbox_send_message 0000000093b3576f [ 20.547393] Jason mbox_send_message 0000000093b3576f [ 20.553109] Jason mbox_send_message 0000000093b3576f [ 20.558177] Jason mbox_send_message 0000000093b3576f [ 20.574998] Jason mbox_send_message 0000000093b3576f [ 20.580061] Jason mbox_send_message 0000000093b3576f [ 20.657984] Jason mbox_send_message 000000000a4d37b5 [ 20.663743] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=452 ms [ 20.713887] Jason mbox_send_message 000000000a4d37b5 [ 20.728350] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=64 ms [ 20.922020] Jason mbox_send_message 0000000093b3576f [ 20.978140] Jason mbox_send_message 0000000093b3576f [ 21.004172] Jason mbox_send_message 000000008bc5af0a [ 21.025495] Jason mbox_send_message 000000008bc5af0a [ 21.046129] Jason mbox_send_message 000000008bc5af0a [ 21.068132] Jason mbox_send_message 000000008bc5af0a [ 21.089124] Jason mbox_send_message 000000008bc5af0a [ 21.110163] Jason mbox_send_message 000000008bc5af0a [ 21.132130] Jason mbox_send_message 000000008bc5af0a [ 21.153162] Jason mbox_send_message 000000008bc5af0a [ 21.174136] Jason mbox_send_message 000000008bc5af0a [ 21.196189] Jason mbox_send_message 000000008bc5af0a [ 21.207513] Jason mbox_send_message 000000000a4d37b5 [ 21.213265] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=484 ms [ 21.217166] Jason mbox_send_message 000000008bc5af0a [ 21.238212] Jason mbox_send_message 000000008bc5af0a [ 21.260651] Jason mbox_send_message 000000008bc5af0a [ 21.281147] Jason mbox_send_message 000000008bc5af0a [ 21.307792] Jason mbox_send_message 000000008bc5af0a [ 21.324118] Jason mbox_send_message 000000008bc5af0a [ 21.345607] Jason mbox_send_message 000000008bc5af0a [ 21.366121] Jason mbox_send_message 000000008bc5af0a [ 21.388126] Jason mbox_send_message 000000008bc5af0a [ 21.409134] Jason mbox_send_message 000000008bc5af0a [ 21.430193] Jason mbox_send_message 000000008bc5af0a [ 21.452182] Jason mbox_send_message 000000008bc5af0a [ 21.473118] Jason mbox_send_message 000000008bc5af0a [ 21.494721] Jason mbox_send_message 000000008bc5af0a [ 21.516119] Jason mbox_send_message 000000008bc5af0a [ 21.537127] Jason mbox_send_message 000000008bc5af0a [ 21.558127] Jason mbox_send_message 000000008bc5af0a [ 21.580125] Jason mbox_send_message 000000008bc5af0a [ 21.601651] Jason mbox_send_message 000000008bc5af0a [ 21.622661] Jason mbox_send_message 000000008bc5af0a [ 21.644124] Jason mbox_send_message 000000008bc5af0a [ 21.665525] Jason mbox_send_message 000000008bc5af0a [ 21.686410] Jason mbox_send_message 000000008bc5af0a [ 21.696131] Jason mbox_send_message 000000000a4d37b5 [ 21.701136] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=487 ms [ 21.708127] Jason mbox_send_message 000000008bc5af0a [ 21.729126] Jason mbox_send_message 000000008bc5af0a [ 21.750136] Jason mbox_send_message 000000008bc5af0a [ 21.772130] Jason mbox_send_message 000000008bc5af0a [ 21.793134] Jason mbox_send_message 000000008bc5af0a [ 21.814151] Jason mbox_send_message 000000008bc5af0a [ 21.836402] Jason mbox_send_message 000000008bc5af0a [ 21.857569] Jason mbox_send_message 000000008bc5af0a [ 21.863183] Jason mbox_send_message 000000009537aba7 [ 21.878428] Jason mbox_send_message 000000008bc5af0a [ 21.900149] Jason mbox_send_message 000000008bc5af0a [ 21.921186] Jason mbox_send_message 000000008bc5af0a [ 21.942166] Jason mbox_send_message 000000008bc5af0a [ 21.964538] Jason mbox_send_message 000000008bc5af0a [ 21.985131] Jason mbox_send_message 000000008bc5af0a [ 22.006144] Jason mbox_send_message 000000008bc5af0a [ 22.028142] Jason mbox_send_message 000000008bc5af0a [ 22.049143] Jason mbox_send_message 000000008bc5af0a [ 22.070135] Jason mbox_send_message 000000008bc5af0a [ 22.092114] Jason mbox_send_message 000000008bc5af0a [ 22.113135] Jason mbox_send_message 000000008bc5af0a [ 22.134130] Jason mbox_send_message 000000008bc5af0a [ 22.156144] Jason mbox_send_message 000000008bc5af0a [ 22.177128] Jason mbox_send_message 000000008bc5af0a [ 22.193169] Jason mbox_send_message 000000000a4d37b5 [ 22.198120] Jason mbox_send_message 000000008bc5af0a [ 22.198183] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=497 ms [ 22.220125] Jason mbox_send_message 000000008bc5af0a [ 22.241136] Jason mbox_send_message 000000008bc5af0a [ 22.262139] Jason mbox_send_message 000000008bc5af0a [ 22.284126] Jason mbox_send_message 000000008bc5af0a [ 22.305123] Jason mbox_send_message 000000008bc5af0a [ 22.326133] Jason mbox_send_message 000000008bc5af0a [ 22.348125] Jason mbox_send_message 000000008bc5af0a [ 22.369125] Jason mbox_send_message 000000008bc5af0a [ 22.390148] Jason mbox_send_message 000000008bc5af0a [ 22.412123] Jason mbox_send_message 000000008bc5af0a [ 22.433128] Jason mbox_send_message 000000008bc5af0a [ 22.454122] Jason mbox_send_message 000000008bc5af0a [ 22.476128] Jason mbox_send_message 000000008bc5af0a [ 22.497144] Jason mbox_send_message 000000008bc5af0a [ 22.518164] Jason mbox_send_message 000000008bc5af0a [ 22.540149] Jason mbox_send_message 000000008bc5af0a [ 22.561141] Jason mbox_send_message 000000008bc5af0a [ 22.582132] Jason mbox_send_message 000000008bc5af0a [ 22.604123] Jason mbox_send_message 000000008bc5af0a [ 22.625145] Jason mbox_send_message 000000008bc5af0a [ 22.646158] Jason mbox_send_message 000000008bc5af0a [ 22.668133] Jason mbox_send_message 000000008bc5af0a [ 22.689204] Jason mbox_send_message 000000008bc5af0a [ 22.694449] Jason mbox_send_message 000000000a4d37b5 [ 22.699950] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=501 ms [ 22.710131] Jason mbox_send_message 000000008bc5af0a [ 22.732178] Jason mbox_send_message 000000008bc5af0a [ 22.753135] Jason mbox_send_message 000000008bc5af0a [ 22.774125] Jason mbox_send_message 000000008bc5af0a [ 22.796131] Jason mbox_send_message 000000008bc5af0a [ 22.817140] Jason mbox_send_message 000000008bc5af0a [ 22.838129] Jason mbox_send_message 000000008bc5af0a [ 22.860129] Jason mbox_send_message 000000008bc5af0a [ 22.881128] Jason mbox_send_message 000000008bc5af0a [ 22.902156] Jason mbox_send_message 000000008bc5af0a [ 22.924149] Jason mbox_send_message 000000008bc5af0a [ 22.945170] Jason mbox_send_message 000000008bc5af0a [ 22.966129] Jason mbox_send_message 000000008bc5af0a [ 22.988131] Jason mbox_send_message 000000008bc5af0a [ 23.009145] Jason mbox_send_message 000000008bc5af0a [ 23.030236] Jason mbox_send_message 000000008bc5af0a [ 23.052137] Jason mbox_send_message 000000008bc5af0a [ 23.073139] Jason mbox_send_message 000000008bc5af0a [ 23.094122] Jason mbox_send_message 000000008bc5af0a [ 23.116127] Jason mbox_send_message 000000008bc5af0a [ 23.137187] Jason mbox_send_message 000000008bc5af0a [ 23.158130] Jason mbox_send_message 000000008bc5af0a [ 23.180145] Jason mbox_send_message 000000008bc5af0a [ 23.197399] Jason mbox_send_message 000000000a4d37b5 [ 23.202581] Jason mbox_send_message 000000008bc5af0a [ 23.207796] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=507 ms [ 23.222126] Jason mbox_send_message 000000008bc5af0a [ 23.244164] Jason mbox_send_message 000000008bc5af0a [ 23.265151] Jason mbox_send_message 000000008bc5af0a [ 23.286137] Jason mbox_send_message 000000008bc5af0a [ 23.308123] Jason mbox_send_message 000000008bc5af0a [ 23.329124] Jason mbox_send_message 000000008bc5af0a [ 23.350129] Jason mbox_send_message 000000008bc5af0a [ 23.361071] Jason mbox_send_message 000000000a4d37b5 [ 23.369353] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=161 ms [ 23.372137] Jason mbox_send_message 000000008bc5af0a [ 23.393129] Jason mbox_send_message 000000008bc5af0a [ 23.414135] Jason mbox_send_message 000000008bc5af0a [ 23.436147] Jason mbox_send_message 000000008bc5af0a [ 23.457397] Jason mbox_send_message 000000008bc5af0a [ 23.478128] Jason mbox_send_message 000000008bc5af0a [ 23.500161] Jason mbox_send_message 000000008bc5af0a [ 23.521133] Jason mbox_send_message 000000008bc5af0a [ 23.542141] Jason mbox_send_message 000000008bc5af0a [ 23.564128] Jason mbox_send_message 000000008bc5af0a [ 23.585126] Jason mbox_send_message 000000008bc5af0a [ 23.606133] Jason mbox_send_message 000000008bc5af0a [ 23.628165] Jason mbox_send_message 000000008bc5af0a [ 23.649131] Jason mbox_send_message 000000008bc5af0a [ 23.670133] Jason mbox_send_message 000000008bc5af0a [ 23.692127] Jason mbox_send_message 000000008bc5af0a [ 23.700563] Jason mbox_send_message 000000000a4d37b5 [ 23.705570] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=336 ms [ 23.713131] Jason mbox_send_message 000000008bc5af0a [ 23.734131] Jason mbox_send_message 000000008bc5af0a [ 23.756129] Jason mbox_send_message 000000008bc5af0a [ 23.777138] Jason mbox_send_message 000000008bc5af0a [ 23.798122] Jason mbox_send_message 000000008bc5af0a [ 23.820137] Jason mbox_send_message 000000008bc5af0a [ 23.841126] Jason mbox_send_message 000000008bc5af0a [ 23.862144] Jason mbox_send_message 000000008bc5af0a [ 23.884126] Jason mbox_send_message 000000008bc5af0a [ 23.905144] Jason mbox_send_message 000000008bc5af0a [ 23.926130] Jason mbox_send_message 000000008bc5af0a [ 23.948126] Jason mbox_send_message 000000008bc5af0a [ 23.969158] Jason mbox_send_message 000000008bc5af0a [ 23.990155] Jason mbox_send_message 000000008bc5af0a [ 24.012149] Jason mbox_send_message 000000008bc5af0a [ 24.033154] Jason mbox_send_message 000000008bc5af0a [ 24.054127] Jason mbox_send_message 000000008bc5af0a [ 24.076137] Jason mbox_send_message 000000008bc5af0a [ 24.097158] Jason mbox_send_message 000000008bc5af0a [ 24.118122] Jason mbox_send_message 000000008bc5af0a [ 24.140139] Jason mbox_send_message 000000008bc5af0a [ 24.161122] Jason mbox_send_message 000000008bc5af0a [ 24.182152] Jason mbox_send_message 000000008bc5af0a [ 24.204136] Jason mbox_send_message 000000008bc5af0a [ 24.217230] Jason mbox_send_message 000000000a4d37b5 [ 24.222317] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=516 ms [ 24.225124] Jason mbox_send_message 000000008bc5af0a [ 24.246130] Jason mbox_send_message 000000008bc5af0a [ 24.268133] Jason mbox_send_message 000000008bc5af0a [ 24.289133] Jason mbox_send_message 000000008bc5af0a [ 24.310154] Jason mbox_send_message 000000008bc5af0a [ 24.332128] Jason mbox_send_message 000000008bc5af0a [ 24.353126] Jason mbox_send_message 000000008bc5af0a [ 24.374172] Jason mbox_send_message 000000008bc5af0a [ 24.396127] Jason mbox_send_message 000000008bc5af0a [ 24.417142] Jason mbox_send_message 000000008bc5af0a [ 24.438131] Jason mbox_send_message 000000008bc5af0a [ 24.460129] Jason mbox_send_message 000000008bc5af0a [ 24.481124] Jason mbox_send_message 000000008bc5af0a [ 24.502124] Jason mbox_send_message 000000008bc5af0a [ 24.524117] Jason mbox_send_message 000000008bc5af0a [ 24.545133] Jason mbox_send_message 000000008bc5af0a [ 24.566143] Jason mbox_send_message 000000008bc5af0a [ 24.588128] Jason mbox_send_message 000000008bc5af0a [ 24.609180] Jason mbox_send_message 000000008bc5af0a [ 24.630148] Jason mbox_send_message 000000008bc5af0a [ 24.652157] Jason mbox_send_message 000000008bc5af0a [ 24.673122] Jason mbox_send_message 000000008bc5af0a [ 24.694139] Jason mbox_send_message 000000008bc5af0a [ 24.704155] Jason mbox_send_message 000000000a4d37b5 [ 24.709219] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=486 ms [ 24.716196] Jason mbox_send_message 000000008bc5af0a [ 24.737136] Jason mbox_send_message 000000008bc5af0a [ 24.758142] Jason mbox_send_message 000000008bc5af0a [ 24.780124] Jason mbox_send_message 000000008bc5af0a [ 24.801124] Jason mbox_send_message 000000008bc5af0a [ 24.822151] Jason mbox_send_message 000000008bc5af0a [ 24.844126] Jason mbox_send_message 000000008bc5af0a [ 24.860272] Jason mbox_send_message 000000009537aba7 [ 24.865653] Jason mbox_send_message 000000008bc5af0a [ 24.886126] Jason mbox_send_message 000000008bc5af0a [ 24.908144] Jason mbox_send_message 000000008bc5af0a [ 24.929256] Jason mbox_send_message 000000008bc5af0a [ 24.950171] Jason mbox_send_message 000000008bc5af0a [ 24.972149] Jason mbox_send_message 000000008bc5af0a [ 24.993132] Jason mbox_send_message 000000008bc5af0a [ 25.014138] Jason mbox_send_message 000000008bc5af0a [ 25.036125] Jason mbox_send_message 000000008bc5af0a [ 25.057133] Jason mbox_send_message 000000008bc5af0a [ 25.078124] Jason mbox_send_message 000000008bc5af0a [ 25.100171] Jason mbox_send_message 000000008bc5af0a [ 25.121133] Jason mbox_send_message 000000008bc5af0a [ 25.142136] Jason mbox_send_message 000000008bc5af0a [ 25.164247] Jason mbox_send_message 000000008bc5af0a [ 25.185124] Jason mbox_send_message 000000008bc5af0a [ 25.200100] Jason mbox_send_message 000000000a4d37b5 [ 25.205118] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=495 ms [ 25.206128] Jason mbox_send_message 000000008bc5af0a [ 25.228129] Jason mbox_send_message 000000008bc5af0a [ 25.249170] Jason mbox_send_message 000000008bc5af0a [ 25.270148] Jason mbox_send_message 000000008bc5af0a [ 25.292150] Jason mbox_send_message 000000008bc5af0a [ 25.313133] Jason mbox_send_message 000000008bc5af0a [ 25.334128] Jason mbox_send_message 000000008bc5af0a [ 25.356131] Jason mbox_send_message 000000008bc5af0a [ 25.377155] Jason mbox_send_message 000000008bc5af0a [ 25.398134] Jason mbox_send_message 000000008bc5af0a [ 25.420134] Jason mbox_send_message 000000008bc5af0a [ 25.441145] Jason mbox_send_message 000000008bc5af0a [ 25.462208] Jason mbox_send_message 000000008bc5af0a [ 25.484118] Jason mbox_send_message 000000008bc5af0a [ 25.505139] Jason mbox_send_message 000000008bc5af0a [ 25.526159] Jason mbox_send_message 000000008bc5af0a [ 25.548117] Jason mbox_send_message 000000008bc5af0a [ 25.569129] Jason mbox_send_message 000000008bc5af0a [ 25.590179] Jason mbox_send_message 000000008bc5af0a [ 25.612171] Jason mbox_send_message 000000008bc5af0a [ 25.633311] Jason mbox_send_message 000000008bc5af0a [ 25.654148] Jason mbox_send_message 000000008bc5af0a [ 25.676142] Jason mbox_send_message 000000008bc5af0a [ 25.697160] Jason mbox_send_message 000000008bc5af0a [ 25.705082] Jason mbox_send_message 000000000a4d37b5 [ 25.710111] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=504 ms [ 25.718140] Jason mbox_send_message 000000008bc5af0a [ 25.740133] Jason mbox_send_message 000000008bc5af0a [ 25.761129] Jason mbox_send_message 000000008bc5af0a [ 25.782133] Jason mbox_send_message 000000008bc5af0a [ 25.804130] Jason mbox_send_message 000000008bc5af0a [ 25.825183] Jason mbox_send_message 000000008bc5af0a [ 25.846144] Jason mbox_send_message 000000008bc5af0a [ 25.865324] Jason mbox_send_message 000000009537aba7 [ 25.870426] Jason mbox_send_message 000000008bc5af0a [ 25.875463] Jason mbox_send_message 000000009537aba7 [ 25.889132] Jason mbox_send_message 000000008bc5af0a [ 25.910144] Jason mbox_send_message 000000008bc5af0a [ 25.932156] Jason mbox_send_message 000000008bc5af0a [ 25.953119] Jason mbox_send_message 000000008bc5af0a [ 25.974113] Jason mbox_send_message 000000008bc5af0a [ 25.996109] Jason mbox_send_message 000000008bc5af0a [ 26.017114] Jason mbox_send_message 000000008bc5af0a [ 26.038113] Jason mbox_send_message 000000008bc5af0a [ 26.060110] Jason mbox_send_message 000000008bc5af0a [ 26.081111] Jason mbox_send_message 000000008bc5af0a [ 26.102109] Jason mbox_send_message 000000008bc5af0a [ 26.124107] Jason mbox_send_message 000000008bc5af0a [ 26.145114] Jason mbox_send_message 000000008bc5af0a [ 26.166125] Jason mbox_send_message 000000008bc5af0a [ 26.188111] Jason mbox_send_message 000000008bc5af0a [ 26.200283] Jason mbox_send_message 000000000a4d37b5 [ 26.205355] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=495 ms [ 26.209280] Jason mbox_send_message 000000008bc5af0a [ 26.230157] Jason mbox_send_message 000000008bc5af0a [ 26.252130] Jason mbox_send_message 000000008bc5af0a [ 26.273138] Jason mbox_send_message 000000008bc5af0a [ 26.294124] Jason mbox_send_message 000000008bc5af0a [ 26.316129] Jason mbox_send_message 000000008bc5af0a [ 26.337143] Jason mbox_send_message 000000008bc5af0a [ 26.358181] Jason mbox_send_message 000000008bc5af0a [ 26.380122] Jason mbox_send_message 000000008bc5af0a [ 26.401121] Jason mbox_send_message 000000008bc5af0a [ 26.422119] Jason mbox_send_message 000000008bc5af0a [ 26.444128] Jason mbox_send_message 000000008bc5af0a [ 26.465188] Jason mbox_send_message 000000008bc5af0a [ 26.486180] Jason mbox_send_message 000000008bc5af0a [ 26.508121] Jason mbox_send_message 000000008bc5af0a [ 26.529118] Jason mbox_send_message 000000008bc5af0a [ 26.550128] Jason mbox_send_message 000000008bc5af0a [ 26.572117] Jason mbox_send_message 000000008bc5af0a [ 26.593127] Jason mbox_send_message 000000008bc5af0a [ 26.614180] Jason mbox_send_message 000000008bc5af0a [ 26.636122] Jason mbox_send_message 000000008bc5af0a [ 26.657141] Jason mbox_send_message 000000008bc5af0a [ 26.678124] Jason mbox_send_message 000000008bc5af0a [ 26.700141] Jason mbox_send_message 000000008bc5af0a [ 26.705241] Jason mbox_send_message 000000000a4d37b5 [ 26.710229] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=504 ms [ 26.721140] Jason mbox_send_message 000000008bc5af0a [ 26.742146] Jason mbox_send_message 000000008bc5af0a [ 26.764132] Jason mbox_send_message 000000008bc5af0a [ 26.785134] Jason mbox_send_message 000000008bc5af0a [ 26.806138] Jason mbox_send_message 000000008bc5af0a [ 26.828116] Jason mbox_send_message 000000008bc5af0a [ 26.849127] Jason mbox_send_message 000000008bc5af0a [ 26.870122] Jason mbox_send_message 000000008bc5af0a [ 26.892119] Jason mbox_send_message 000000008bc5af0a [ 26.913119] Jason mbox_send_message 000000008bc5af0a [ 26.934127] Jason mbox_send_message 000000008bc5af0a [ 26.956128] Jason mbox_send_message 000000008bc5af0a [ 26.977136] Jason mbox_send_message 000000008bc5af0a [ 26.998138] Jason mbox_send_message 000000008bc5af0a [ 27.020120] Jason mbox_send_message 000000008bc5af0a [ 27.041139] Jason mbox_send_message 000000008bc5af0a [ 27.062130] Jason mbox_send_message 000000008bc5af0a [ 27.084112] Jason mbox_send_message 000000008bc5af0a [ 27.105188] Jason mbox_send_message 000000008bc5af0a [ 27.126251] Jason mbox_send_message 000000008bc5af0a [ 27.148148] Jason mbox_send_message 000000008bc5af0a [ 27.169146] Jason mbox_send_message 000000008bc5af0a [ 27.190133] Jason mbox_send_message 000000008bc5af0a [ 27.206793] Jason mbox_send_message 000000000a4d37b5 [ 27.211861] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=501 ms [ 27.212169] Jason mbox_send_message 000000008bc5af0a [ 27.233156] Jason mbox_send_message 000000008bc5af0a [ 27.254161] Jason mbox_send_message 000000008bc5af0a [ 27.276178] Jason mbox_send_message 000000008bc5af0a [ 27.297167] Jason mbox_send_message 000000008bc5af0a [ 27.318247] Jason mbox_send_message 000000008bc5af0a [ 27.340151] Jason mbox_send_message 000000008bc5af0a [ 27.361194] Jason mbox_send_message 000000008bc5af0a [ 27.382160] Jason mbox_send_message 000000008bc5af0a [ 27.404119] Jason mbox_send_message 000000008bc5af0a [ 27.425156] Jason mbox_send_message 000000008bc5af0a [ 27.446158] Jason mbox_send_message 000000008bc5af0a [ 27.468244] Jason mbox_send_message 000000008bc5af0a [ 27.489156] Jason mbox_send_message 000000008bc5af0a [ 27.510158] Jason mbox_send_message 000000008bc5af0a [ 27.532149] Jason mbox_send_message 000000008bc5af0a [ 27.553115] Jason mbox_send_message 000000008bc5af0a [ 27.574149] Jason mbox_send_message 000000008bc5af0a [ 27.596152] Jason mbox_send_message 000000008bc5af0a [ 27.617190] Jason mbox_send_message 000000008bc5af0a [ 27.638150] Jason mbox_send_message 000000008bc5af0a [ 27.660145] Jason mbox_send_message 000000008bc5af0a [ 27.681154] Jason mbox_send_message 000000008bc5af0a [ 27.702134] Jason mbox_send_message 000000008bc5af0a [ 27.707250] Jason mbox_send_message 000000000a4d37b5 [ 27.712325] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=500 ms [ 27.724126] Jason mbox_send_message 000000008bc5af0a [ 27.745246] Jason mbox_send_message 000000008bc5af0a [ 27.766172] Jason mbox_send_message 000000008bc5af0a [ 27.788123] Jason mbox_send_message 000000008bc5af0a [ 27.809132] Jason mbox_send_message 000000008bc5af0a [ 27.830132] Jason mbox_send_message 000000008bc5af0a [ 27.852133] Jason mbox_send_message 000000008bc5af0a [ 27.873116] Jason mbox_send_message 000000008bc5af0a [ 27.894117] Jason mbox_send_message 000000008bc5af0a [ 27.916117] Jason mbox_send_message 000000008bc5af0a [ 27.937115] Jason mbox_send_message 000000008bc5af0a [ 27.958112] Jason mbox_send_message 000000008bc5af0a [ 27.980114] Jason mbox_send_message 000000008bc5af0a [ 28.001119] Jason mbox_send_message 000000008bc5af0a [ 28.022168] Jason mbox_send_message 000000008bc5af0a [ 28.044123] Jason mbox_send_message 000000008bc5af0a [ 28.065126] Jason mbox_send_message 000000008bc5af0a [ 28.086128] Jason mbox_send_message 000000008bc5af0a [ 28.108111] Jason mbox_send_message 000000008bc5af0a [ 28.129118] Jason mbox_send_message 000000008bc5af0a [ 28.150121] Jason mbox_send_message 000000008bc5af0a [ 28.172115] Jason mbox_send_message 000000008bc5af0a [ 28.193116] Jason mbox_send_message 000000008bc5af0a [ 28.203238] Jason mbox_send_message 000000000a4d37b5 [ 28.208268] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=495 ms [ 28.214125] Jason mbox_send_message 000000008bc5af0a [ 28.236148] Jason mbox_send_message 000000008bc5af0a [ 28.257133] Jason mbox_send_message 000000008bc5af0a [ 28.278112] Jason mbox_send_message 000000008bc5af0a [ 28.300113] Jason mbox_send_message 000000008bc5af0a [ 28.321110] Jason mbox_send_message 000000008bc5af0a [ 28.342117] Jason mbox_send_message 000000008bc5af0a [ 28.364113] Jason mbox_send_message 000000008bc5af0a [ 28.385109] Jason mbox_send_message 000000008bc5af0a [ 28.406108] Jason mbox_send_message 000000008bc5af0a [ 28.428110] Jason mbox_send_message 000000008bc5af0a [ 28.449116] Jason mbox_send_message 000000008bc5af0a [ 28.470117] Jason mbox_send_message 000000008bc5af0a [ 28.492112] Jason mbox_send_message 000000008bc5af0a [ 28.513108] Jason mbox_send_message 000000008bc5af0a [ 28.534112] Jason mbox_send_message 000000008bc5af0a [ 28.556157] Jason mbox_send_message 000000008bc5af0a [ 28.577105] Jason mbox_send_message 000000008bc5af0a [ 28.598114] Jason mbox_send_message 000000008bc5af0a [ 28.620126] Jason mbox_send_message 000000008bc5af0a [ 28.641113] Jason mbox_send_message 000000008bc5af0a [ 28.662108] Jason mbox_send_message 000000008bc5af0a [ 28.684105] Jason mbox_send_message 000000008bc5af0a [ 28.705133] Jason mbox_send_message 000000008bc5af0a [ 28.710291] Jason mbox_send_message 000000000a4d37b5 [ 28.715299] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=507 ms [ 28.726123] Jason mbox_send_message 000000008bc5af0a [ 28.748117] Jason mbox_send_message 000000008bc5af0a [ 28.769115] Jason mbox_send_message 000000008bc5af0a [ 28.790113] Jason mbox_send_message 000000008bc5af0a [ 28.812159] Jason mbox_send_message 000000008bc5af0a [ 28.833108] Jason mbox_send_message 000000008bc5af0a [ 28.854114] Jason mbox_send_message 000000008bc5af0a [ 28.876115] Jason mbox_send_message 000000008bc5af0a [ 28.897106] Jason mbox_send_message 000000008bc5af0a [ 28.918115] Jason mbox_send_message 000000008bc5af0a [ 28.940114] Jason mbox_send_message 000000008bc5af0a [ 28.961110] Jason mbox_send_message 000000008bc5af0a [ 28.982145] Jason mbox_send_message 000000008bc5af0a [ 29.004111] Jason mbox_send_message 000000008bc5af0a [ 29.025124] Jason mbox_send_message 000000008bc5af0a [ 29.046159] Jason mbox_send_message 000000008bc5af0a [ 29.068111] Jason mbox_send_message 000000008bc5af0a [ 29.089136] Jason mbox_send_message 000000008bc5af0a [ 29.110112] Jason mbox_send_message 000000008bc5af0a [ 29.132110] Jason mbox_send_message 000000008bc5af0a [ 29.153112] Jason mbox_send_message 000000008bc5af0a [ 29.174159] Jason mbox_send_message 000000008bc5af0a [ 29.196116] Jason mbox_send_message 000000008bc5af0a [ 29.206066] Jason mbox_send_message 000000000a4d37b5 [ 29.211082] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=495 ms [ 29.217126] Jason mbox_send_message 000000008bc5af0a [ 29.238164] Jason mbox_send_message 000000008bc5af0a [ 29.260119] Jason mbox_send_message 000000008bc5af0a [ 29.281116] Jason mbox_send_message 000000008bc5af0a [ 29.302118] Jason mbox_send_message 000000008bc5af0a [ 29.324119] Jason mbox_send_message 000000008bc5af0a [ 29.345118] Jason mbox_send_message 000000008bc5af0a [ 29.366123] Jason mbox_send_message 000000008bc5af0a [ 29.388111] Jason mbox_send_message 000000008bc5af0a [ 29.409119] Jason mbox_send_message 000000008bc5af0a [ 29.430154] Jason mbox_send_message 000000008bc5af0a [ 29.452146] Jason mbox_send_message 000000008bc5af0a [ 29.473114] Jason mbox_send_message 000000008bc5af0a [ 29.494127] Jason mbox_send_message 000000008bc5af0a [ 29.516166] Jason mbox_send_message 000000008bc5af0a [ 29.537172] Jason mbox_send_message 000000008bc5af0a [ 29.558159] Jason mbox_send_message 000000008bc5af0a [ 29.580179] Jason mbox_send_message 000000008bc5af0a [ 29.601174] Jason mbox_send_message 000000008bc5af0a [ 29.622123] Jason mbox_send_message 000000008bc5af0a [ 29.644119] Jason mbox_send_message 000000008bc5af0a [ 29.665177] Jason mbox_send_message 000000008bc5af0a [ 29.686142] Jason mbox_send_message 000000008bc5af0a [ 29.705430] Jason mbox_send_message 000000000a4d37b5 [ 29.708138] Jason mbox_send_message 000000008bc5af0a [ 29.710456] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=499 ms [ 29.729122] Jason mbox_send_message 000000008bc5af0a [ 29.750180] Jason mbox_send_message 000000008bc5af0a [ 29.772160] Jason mbox_send_message 000000008bc5af0a [ 29.793170] Jason mbox_send_message 000000008bc5af0a [ 29.814137] Jason mbox_send_message 000000008bc5af0a [ 29.836162] Jason mbox_send_message 000000008bc5af0a [ 29.857118] Jason mbox_send_message 000000008bc5af0a [ 29.878157] Jason mbox_send_message 000000008bc5af0a [ 29.900160] Jason mbox_send_message 000000008bc5af0a [ 29.921161] Jason mbox_send_message 000000008bc5af0a [ 29.942161] Jason mbox_send_message 000000008bc5af0a [ 29.964135] Jason mbox_send_message 000000008bc5af0a [ 29.985177] Jason mbox_send_message 000000008bc5af0a [ 30.006164] Jason mbox_send_message 000000008bc5af0a [ 30.028170] Jason mbox_send_message 000000008bc5af0a [ 30.049162] Jason mbox_send_message 000000008bc5af0a [ 30.070121] Jason mbox_send_message 000000008bc5af0a [ 30.092163] Jason mbox_send_message 000000008bc5af0a [ 30.113109] Jason mbox_send_message 000000008bc5af0a [ 30.134110] Jason mbox_send_message 000000008bc5af0a [ 30.156165] Jason mbox_send_message 000000008bc5af0a [ 30.177131] Jason mbox_send_message 000000008bc5af0a [ 30.198143] Jason mbox_send_message 000000008bc5af0a [ 30.210837] Jason mbox_send_message 000000000a4d37b5 [ 30.215873] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=505 ms [ 30.220130] Jason mbox_send_message 000000008bc5af0a [ 30.241137] Jason mbox_send_message 000000008bc5af0a [ 30.262108] Jason mbox_send_message 000000008bc5af0a [ 30.284109] Jason mbox_send_message 000000008bc5af0a [ 30.305131] Jason mbox_send_message 000000008bc5af0a [ 30.326106] Jason mbox_send_message 000000008bc5af0a [ 30.348104] Jason mbox_send_message 000000008bc5af0a [ 30.369123] Jason mbox_send_message 000000008bc5af0a [ 30.390106] Jason mbox_send_message 000000008bc5af0a [ 30.412126] Jason mbox_send_message 000000008bc5af0a [ 30.433106] Jason mbox_send_message 000000008bc5af0a [ 30.454138] Jason mbox_send_message 000000008bc5af0a [ 30.476103] Jason mbox_send_message 000000008bc5af0a [ 30.497126] Jason mbox_send_message 000000008bc5af0a [ 30.518107] Jason mbox_send_message 000000008bc5af0a [ 30.540190] Jason mbox_send_message 000000008bc5af0a [ 30.561103] Jason mbox_send_message 000000008bc5af0a [ 30.582106] Jason mbox_send_message 000000008bc5af0a [ 30.604149] Jason mbox_send_message 000000008bc5af0a [ 30.625105] Jason mbox_send_message 000000008bc5af0a [ 30.646107] Jason mbox_send_message 000000008bc5af0a [ 30.668127] Jason mbox_send_message 000000008bc5af0a [ 30.689129] Jason mbox_send_message 000000008bc5af0a [ 30.707454] Jason mbox_send_message 000000000a4d37b5 [ 30.710162] Jason mbox_send_message 000000008bc5af0a [ 30.712457] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=496 ms [ 30.732125] Jason mbox_send_message 000000008bc5af0a [ 30.753117] Jason mbox_send_message 000000008bc5af0a [ 30.774130] Jason mbox_send_message 000000008bc5af0a [ 30.796175] Jason mbox_send_message 000000008bc5af0a [ 30.817124] Jason mbox_send_message 000000008bc5af0a [ 30.838120] Jason mbox_send_message 000000008bc5af0a [ 30.860131] Jason mbox_send_message 000000008bc5af0a [ 30.881152] Jason mbox_send_message 000000008bc5af0a [ 30.902132] Jason mbox_send_message 000000008bc5af0a [ 30.924123] Jason mbox_send_message 000000008bc5af0a [ 30.945150] Jason mbox_send_message 000000008bc5af0a [ 30.966157] Jason mbox_send_message 000000008bc5af0a [ 30.988201] Jason mbox_send_message 000000008bc5af0a [ 31.009122] Jason mbox_send_message 000000008bc5af0a [ 31.030139] Jason mbox_send_message 000000008bc5af0a [ 31.052133] Jason mbox_send_message 000000008bc5af0a [ 31.073103] Jason mbox_send_message 000000008bc5af0a [ 31.094106] Jason mbox_send_message 000000008bc5af0a [ 31.116126] Jason mbox_send_message 000000008bc5af0a [ 31.137118] Jason mbox_send_message 000000008bc5af0a [ 31.158128] Jason mbox_send_message 000000008bc5af0a [ 31.180104] Jason mbox_send_message 000000008bc5af0a [ 31.201119] Jason mbox_send_message 000000008bc5af0a [ 31.210404] Jason mbox_send_message 000000000a4d37b5 [ 31.215439] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=502 ms [ 31.222120] Jason mbox_send_message 000000008bc5af0a [ 31.244115] Jason mbox_send_message 000000008bc5af0a [ 31.265113] Jason mbox_send_message 000000008bc5af0a [ 31.286111] Jason mbox_send_message 000000008bc5af0a [ 31.308180] Jason mbox_send_message 000000008bc5af0a [ 31.329115] Jason mbox_send_message 000000008bc5af0a [ 31.342481] Jason mbox_send_message 0000000093b3576f [ 31.347991] Jason mbox_send_message 0000000093b3576f [ 31.711552] Jason mbox_send_message 000000000a4d37b5 [ 31.716556] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=501 ms [ 32.214294] Jason mbox_send_message 000000000a4d37b5 [ 32.219318] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=502 ms [ 32.714511] Jason mbox_send_message 000000000a4d37b5 [ 32.719580] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=500 ms [ 33.209874] Jason mbox_send_message 000000000a4d37b5 [ 33.214884] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=495 ms [ 33.710970] Jason mbox_send_message 000000000a4d37b5 [ 33.716006] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=501 ms [ 34.218290] Jason mbox_send_message 000000000a4d37b5 [ 34.223353] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=507 ms [ 34.717553] Jason mbox_send_message 000000000a4d37b5 [ 34.722569] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=499 ms [ 35.217235] Jason mbox_send_message 000000000a4d37b5 [ 35.222247] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=499 ms [ 35.713409] Jason mbox_send_message 000000000a4d37b5 [ 35.718424] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=496 ms [ 36.219710] Jason mbox_send_message 000000000a4d37b5 [ 36.224734] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=506 ms [ 36.721449] Jason mbox_send_message 000000000a4d37b5 [ 36.726489] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=501 ms [ 37.219857] Jason mbox_send_message 000000000a4d37b5 [ 37.224898] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=498 ms [ 37.727349] Jason mbox_send_message 000000000a4d37b5 [ 37.732368] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=507 ms [ 38.217418] Jason mbox_send_message 000000000a4d37b5 [ 38.222427] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=490 ms [ 38.722077] Jason mbox_send_message 000000000a4d37b5 [ 38.727097] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=504 ms [ 39.218165] Jason mbox_send_message 000000000a4d37b5 [ 39.223174] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=496 ms [ 39.719430] Jason mbox_send_message 000000000a4d37b5 [ 39.724441] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=501 ms [ 40.225886] Jason mbox_send_message 000000000a4d37b5 [ 40.230939] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=506 ms [ 40.639082] Jason mbox_send_message 000000000a4d37b5 [ 40.644128] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=413 ms [ 40.667785] Jason mbox_send_message 000000000a4d37b5 [ 40.672819] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=28 ms [ 40.874922] Jason mbox_send_message 000000000a4d37b5 [ 40.879890] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=207 ms // Push power key to enable panel [ 41.024381] Jason cmdq_runtime_suspend: dev:00000000f85c3b60, R/S_diff=31731 ms [ 41.031749] Jason cmdq_runtime_suspend 00000000f85c3b60 // Push power key to enable panel [ 43.843514] Jason cmdq_runtime_resume: dev:00000000f85c3b60, resume_diff=34550 ms [ 43.851050] Jason cmdq_runtime_resume 00000000f85c3b60 [ 44.659633] Jason mbox_send_message 000000000a4d37b5 [ 44.664647] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=3784 ms [ 44.688990] Jason mbox_send_message 000000000a4d37b5 [ 44.694683] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=30 ms [ 44.712686] Jason mbox_send_message 000000000a4d37b5 [ 44.717707] Jason cmdq_mbox_send_data: chan:000000000a4d37b5 dev:00000000f85c3b60, send_diff=23 ms ... Regards, Jason-JH.Lin
On Fri, Jul 5, 2024 at 1:11 AM Jason-JH Lin (林睿祥) <Jason-JH.Lin@mediatek.com> wrote: > > [snip] > > > You may disable one to make it easy to capture. > > Make sure your kernel prints have timestamps. > > Over your patchset, apply the following diff and execute your > > usecase. > > Then share > > $ dmesg | grep Jason > > > > diff --git a/drivers/mailbox/mailbox.c b/drivers/mailbox/mailbox.c > > index bafcc7b0c0b8d..90c0620c0ae63 100644 > > --- a/drivers/mailbox/mailbox.c > > +++ b/drivers/mailbox/mailbox.c > > @@ -284,6 +284,7 @@ int mbox_send_message(struct mbox_chan *chan, > > void *mssg) > > { > > int t; > > > > + printk("Jason %s: %p\n", __func__, (void *)chan); > > if (!chan || !chan->cl) > > return -EINVAL; > > > > diff --git a/drivers/mailbox/mtk-cmdq-mailbox.c > > b/drivers/mailbox/mtk-cmdq-mailbox.c > > index 02cef3eee35a5..6436e1b22f353 100644 > > --- a/drivers/mailbox/mtk-cmdq-mailbox.c > > +++ b/drivers/mailbox/mtk-cmdq-mailbox.c > > @@ -317,6 +317,7 @@ static int cmdq_runtime_resume(struct device > > *dev) > > { > > struct cmdq *cmdq = dev_get_drvdata(dev); > > > > + printk("Jason %s: %p\n", __func__, (void *)dev); > > return clk_bulk_enable(cmdq->pdata->gce_num, cmdq->clocks); > > } > > > > @@ -324,6 +325,7 @@ static int cmdq_runtime_suspend(struct device > > *dev) > > { > > struct cmdq *cmdq = dev_get_drvdata(dev); > > > > + printk("Jason %s: %p\n", __func__, (void *)dev); > > clk_bulk_disable(cmdq->pdata->gce_num, cmdq->clocks); > > return 0; > > } > > > > Thanks > > It seems CMDQ driver is not suspend over 100ms. > here are the time deltas in milli-seconds 10 6005 52 85 304 59 27 203 29 24 25 38 33 57 34 20 41 28 36 48 71 35 21 45 51 22 30 46 46 23 16 16 16 16 16 17 17 31 16 19 31 16 16 17 16 16 16 32 17 32 17 30 21 16 32 18 30 28 25 29 24 31 27 16 17 19 34 30 15 33 16 35 35 29 18 31 16 16 16 16 17 33 35 33 39 20 21 14 34 49 22 42 32 13 21 24 9 130 23 32 35 31 32 16 18 31 36 37 26 14 68 76 111 515 452 64 484 487 497 501 507 161 336 516 486 495 504 495 504 501 500 495 507 495 499 505 496 502 501 502 500 495 501 507 499 499 496 506 501 498 507 490 504 496 501 506 413 28 207 31731 34550 3784 30 23 For detlas <100 we don't expect suspend because your set autosuspend_delay to 100ms. For deltas >100 you should have seen suspend. Apparently the changes you want in the api still don't help you. Also I see messages are being submitted on 4 channels, but only for the '000000000a4d37b5' channel cmdq_mbox_send_data is ever called. Unless you selectively printk only for that channel, your driver has some even fundamental problems. Maybe trace without your patch and with pm_runtime_xxx commented out (to avoid stack dump). -jassi
On Fri, 2024-07-05 at 11:43 -0500, Jassi Brar wrote: > > External email : Please do not click links or open attachments until > you have verified the sender or the content. > On Fri, Jul 5, 2024 at 1:11 AM Jason-JH Lin (林睿祥) > <Jason-JH.Lin@mediatek.com> wrote: > > > > [snip] > > > > > You may disable one to make it easy to capture. > > > Make sure your kernel prints have timestamps. > > > Over your patchset, apply the following diff and execute your > > > usecase. > > > Then share > > > $ dmesg | grep Jason > > > > > > diff --git a/drivers/mailbox/mailbox.c > b/drivers/mailbox/mailbox.c > > > index bafcc7b0c0b8d..90c0620c0ae63 100644 > > > --- a/drivers/mailbox/mailbox.c > > > +++ b/drivers/mailbox/mailbox.c > > > @@ -284,6 +284,7 @@ int mbox_send_message(struct mbox_chan *chan, > > > void *mssg) > > > { > > > int t; > > > > > > + printk("Jason %s: %p\n", __func__, (void *)chan); > > > if (!chan || !chan->cl) > > > return -EINVAL; > > > > > > diff --git a/drivers/mailbox/mtk-cmdq-mailbox.c > > > b/drivers/mailbox/mtk-cmdq-mailbox.c > > > index 02cef3eee35a5..6436e1b22f353 100644 > > > --- a/drivers/mailbox/mtk-cmdq-mailbox.c > > > +++ b/drivers/mailbox/mtk-cmdq-mailbox.c > > > @@ -317,6 +317,7 @@ static int cmdq_runtime_resume(struct device > > > *dev) > > > { > > > struct cmdq *cmdq = dev_get_drvdata(dev); > > > > > > + printk("Jason %s: %p\n", __func__, (void *)dev); > > > return clk_bulk_enable(cmdq->pdata->gce_num, cmdq->clocks); > > > } > > > > > > @@ -324,6 +325,7 @@ static int cmdq_runtime_suspend(struct device > > > *dev) > > > { > > > struct cmdq *cmdq = dev_get_drvdata(dev); > > > > > > + printk("Jason %s: %p\n", __func__, (void *)dev); > > > clk_bulk_disable(cmdq->pdata->gce_num, cmdq->clocks); > > > return 0; > > > } > > > > > > Thanks > > > > It seems CMDQ driver is not suspend over 100ms. > > > here are the time deltas in milli-seconds > 10 6005 52 85 304 59 27 203 29 24 25 38 33 57 34 20 41 28 36 48 71 35 > 21 45 51 22 30 46 46 23 16 16 16 16 16 17 17 31 16 19 31 16 16 17 16 > 16 16 32 17 32 17 30 21 16 32 18 30 28 25 29 24 31 27 16 17 19 34 30 > 15 33 16 35 35 29 18 31 16 16 16 16 17 33 35 33 39 20 21 14 34 49 22 > 42 32 13 21 24 9 130 23 32 35 31 32 16 18 31 36 37 26 14 68 76 111 > 515 > 452 64 484 487 497 501 507 161 336 516 486 495 504 495 504 501 500 > 495 > 507 495 499 505 496 502 501 502 500 495 501 507 499 499 496 506 501 > 498 507 490 504 496 501 506 413 28 207 31731 34550 3784 30 23 > > For detlas <100 we don't expect suspend because your set > autosuspend_delay to 100ms. > For deltas >100 you should have seen suspend. Apparently the changes > you want in the api still don't help you. I think "deltas > 100 ms not autosuspend" and "calling pm_runtime_get_sync() in atomic context" are 2 different problems. > > Also I see messages are being submitted on 4 channels, but only for > the '000000000a4d37b5' channel cmdq_mbox_send_data is ever called. > Unless you selectively printk only for that channel, your driver has > some even fundamental problems. Maybe trace without your patch and > with pm_runtime_xxx commented out (to avoid stack dump). I've confirmed that autosuspend didn't work without these API patches. I'll find out why it won't call cmdq_runtime_suspend() > 100ms. Regards, Jason-JH.Lin > > -jassi >
On Wed, Jul 10, 2024 at 9:00 PM Jason-JH Lin (林睿祥) <Jason-JH.Lin@mediatek.com> wrote: > > On Fri, 2024-07-05 at 11:43 -0500, Jassi Brar wrote: > > > > External email : Please do not click links or open attachments until > > you have verified the sender or the content. > > On Fri, Jul 5, 2024 at 1:11 AM Jason-JH Lin (林睿祥) > > <Jason-JH.Lin@mediatek.com> wrote: > > > > > > [snip] > > > > > > > You may disable one to make it easy to capture. > > > > Make sure your kernel prints have timestamps. > > > > Over your patchset, apply the following diff and execute your > > > > usecase. > > > > Then share > > > > $ dmesg | grep Jason > > > > > > > > diff --git a/drivers/mailbox/mailbox.c > > b/drivers/mailbox/mailbox.c > > > > index bafcc7b0c0b8d..90c0620c0ae63 100644 > > > > --- a/drivers/mailbox/mailbox.c > > > > +++ b/drivers/mailbox/mailbox.c > > > > @@ -284,6 +284,7 @@ int mbox_send_message(struct mbox_chan *chan, > > > > void *mssg) > > > > { > > > > int t; > > > > > > > > + printk("Jason %s: %p\n", __func__, (void *)chan); > > > > if (!chan || !chan->cl) > > > > return -EINVAL; > > > > > > > > diff --git a/drivers/mailbox/mtk-cmdq-mailbox.c > > > > b/drivers/mailbox/mtk-cmdq-mailbox.c > > > > index 02cef3eee35a5..6436e1b22f353 100644 > > > > --- a/drivers/mailbox/mtk-cmdq-mailbox.c > > > > +++ b/drivers/mailbox/mtk-cmdq-mailbox.c > > > > @@ -317,6 +317,7 @@ static int cmdq_runtime_resume(struct device > > > > *dev) > > > > { > > > > struct cmdq *cmdq = dev_get_drvdata(dev); > > > > > > > > + printk("Jason %s: %p\n", __func__, (void *)dev); > > > > return clk_bulk_enable(cmdq->pdata->gce_num, cmdq->clocks); > > > > } > > > > > > > > @@ -324,6 +325,7 @@ static int cmdq_runtime_suspend(struct device > > > > *dev) > > > > { > > > > struct cmdq *cmdq = dev_get_drvdata(dev); > > > > > > > > + printk("Jason %s: %p\n", __func__, (void *)dev); > > > > clk_bulk_disable(cmdq->pdata->gce_num, cmdq->clocks); > > > > return 0; > > > > } > > > > > > > > Thanks > > > > > > It seems CMDQ driver is not suspend over 100ms. > > > > > here are the time deltas in milli-seconds > > 10 6005 52 85 304 59 27 203 29 24 25 38 33 57 34 20 41 28 36 48 71 35 > > 21 45 51 22 30 46 46 23 16 16 16 16 16 17 17 31 16 19 31 16 16 17 16 > > 16 16 32 17 32 17 30 21 16 32 18 30 28 25 29 24 31 27 16 17 19 34 30 > > 15 33 16 35 35 29 18 31 16 16 16 16 17 33 35 33 39 20 21 14 34 49 22 > > 42 32 13 21 24 9 130 23 32 35 31 32 16 18 31 36 37 26 14 68 76 111 > > 515 > > 452 64 484 487 497 501 507 161 336 516 486 495 504 495 504 501 500 > > 495 > > 507 495 499 505 496 502 501 502 500 495 501 507 499 499 496 506 501 > > 498 507 490 504 496 501 506 413 28 207 31731 34550 3784 30 23 > > > > For detlas <100 we don't expect suspend because your set > > autosuspend_delay to 100ms. > > For deltas >100 you should have seen suspend. Apparently the changes > > you want in the api still don't help you. > > I think "deltas > 100 ms not autosuspend" and "calling > pm_runtime_get_sync() in atomic context" are 2 different problems. > Fixing the first may avoid the need of the second on your platform. > > > > Also I see messages are being submitted on 4 channels, but only for > > the '000000000a4d37b5' channel cmdq_mbox_send_data is ever called. > > Unless you selectively printk only for that channel, your driver has > > some even fundamental problems. Maybe trace without your patch and > > with pm_runtime_xxx commented out (to avoid stack dump). > > I've confirmed that autosuspend didn't work without these API patches. > You mean _with_ the api patches. right? Because I had suggested "Over your patchset, apply the following diff ..." cheers.
On Wed, 2024-07-10 at 22:47 -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, Jul 10, 2024 at 9:00 PM Jason-JH Lin (林睿祥) > <Jason-JH.Lin@mediatek.com> wrote: > > > > On Fri, 2024-07-05 at 11:43 -0500, Jassi Brar wrote: > > > > > > External email : Please do not click links or open attachments > until > > > you have verified the sender or the content. > > > On Fri, Jul 5, 2024 at 1:11 AM Jason-JH Lin (林睿祥) > > > <Jason-JH.Lin@mediatek.com> wrote: > > > > > > > > [snip] > > > > > > > > > You may disable one to make it easy to capture. > > > > > Make sure your kernel prints have timestamps. > > > > > Over your patchset, apply the following diff and execute your > > > > > usecase. > > > > > Then share > > > > > $ dmesg | grep Jason > > > > > > > > > > diff --git a/drivers/mailbox/mailbox.c > > > b/drivers/mailbox/mailbox.c > > > > > index bafcc7b0c0b8d..90c0620c0ae63 100644 > > > > > --- a/drivers/mailbox/mailbox.c > > > > > +++ b/drivers/mailbox/mailbox.c > > > > > @@ -284,6 +284,7 @@ int mbox_send_message(struct mbox_chan > *chan, > > > > > void *mssg) > > > > > { > > > > > int t; > > > > > > > > > > + printk("Jason %s: %p\n", __func__, (void *)chan); > > > > > if (!chan || !chan->cl) > > > > > return -EINVAL; > > > > > > > > > > diff --git a/drivers/mailbox/mtk-cmdq-mailbox.c > > > > > b/drivers/mailbox/mtk-cmdq-mailbox.c > > > > > index 02cef3eee35a5..6436e1b22f353 100644 > > > > > --- a/drivers/mailbox/mtk-cmdq-mailbox.c > > > > > +++ b/drivers/mailbox/mtk-cmdq-mailbox.c > > > > > @@ -317,6 +317,7 @@ static int cmdq_runtime_resume(struct > device > > > > > *dev) > > > > > { > > > > > struct cmdq *cmdq = dev_get_drvdata(dev); > > > > > > > > > > + printk("Jason %s: %p\n", __func__, (void *)dev); > > > > > return clk_bulk_enable(cmdq->pdata->gce_num, cmdq->clocks); > > > > > } > > > > > > > > > > @@ -324,6 +325,7 @@ static int cmdq_runtime_suspend(struct > device > > > > > *dev) > > > > > { > > > > > struct cmdq *cmdq = dev_get_drvdata(dev); > > > > > > > > > > + printk("Jason %s: %p\n", __func__, (void *)dev); > > > > > clk_bulk_disable(cmdq->pdata->gce_num, cmdq->clocks); > > > > > return 0; > > > > > } > > > > > > > > > > Thanks > > > > > > > > It seems CMDQ driver is not suspend over 100ms. > > > > > > > here are the time deltas in milli-seconds > > > 10 6005 52 85 304 59 27 203 29 24 25 38 33 57 34 20 41 28 36 48 > 71 35 > > > 21 45 51 22 30 46 46 23 16 16 16 16 16 17 17 31 16 19 31 16 16 17 > 16 > > > 16 16 32 17 32 17 30 21 16 32 18 30 28 25 29 24 31 27 16 17 19 34 > 30 > > > 15 33 16 35 35 29 18 31 16 16 16 16 17 33 35 33 39 20 21 14 34 49 > 22 > > > 42 32 13 21 24 9 130 23 32 35 31 32 16 18 31 36 37 26 14 68 76 > 111 > > > 515 > > > 452 64 484 487 497 501 507 161 336 516 486 495 504 495 504 501 > 500 > > > 495 > > > 507 495 499 505 496 502 501 502 500 495 501 507 499 499 496 506 > 501 > > > 498 507 490 504 496 501 506 413 28 207 31731 34550 3784 30 23 > > > > > > For detlas <100 we don't expect suspend because your set > > > autosuspend_delay to 100ms. > > > For deltas >100 you should have seen suspend. Apparently the > changes > > > you want in the api still don't help you. > > > > I think "deltas > 100 ms not autosuspend" and "calling > > pm_runtime_get_sync() in atomic context" are 2 different problems. > > > Fixing the first may avoid the need of the second on your platform. > > > > > > > Also I see messages are being submitted on 4 channels, but only > for > > > the '000000000a4d37b5' channel cmdq_mbox_send_data is ever > called. > > > Unless you selectively printk only for that channel, your driver > has > > > some even fundamental problems. Maybe trace without your patch > and > > > with pm_runtime_xxx commented out (to avoid stack dump). > > > > I've confirmed that autosuspend didn't work without these API > patches. > > > You mean _with_ the api patches. right? Because I had suggested "Over > your patchset, apply the following diff ..." No matter __with__ or __without__ the api patches, autosuspend didn't work... We have to find out the reason __without__ the api patches, then see if we still need the api patches to fix "calling sleep in atomic context" problem. Regards, Jason-JH.Lin > > cheers.
Hi Jassi, > > You mean _with_ the api patches. right? Because I had suggested > > "Over > > your patchset, apply the following diff ..." > > No matter __with__ or __without__ the api patches, autosuspend didn't > work... > > We have to find out the reason __without__ the api patches, then see > if > we still need the api patches to fix "calling sleep in atomic > context" > problem. > I found that the reason autosuspend didn't work was that I added the devece_add_link() locally between the drm device and the mbox device. After removing that change, the mailbox device of display can autosuspend as expected. So the current autosuspend function is fine. And the mailbox device of display has the same BUG report like imgsys. Here is the log after removing the local change of device link and without the PM api patches: // CMDQ probe [ 4.230063] mtk_cmdq 10320000.mailbox: IRQ=279++++++++++++++ // Show boot logo [ 9.465625] mtk_cmdq 10320000.mailbox: cmdq_runtime_resume: resume_diff=9465 ms [ 9.472940] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 588: pm_runtime_get_sync(), ret:0, thread:0 [ 9.481896] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 619: pm_runtime_mark_last_busy(), thread:0 [ 9.481898] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 [ 9.499359] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 621: pm_runtime_put_autosuspend(), ret:0, thread:0 [ 9.499367] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 418: pm_runtime_get_sync(), ret:1, thread:0 [ 9.532364] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 496: pm_runtime_mark_last_busy(), thread:0 [ 9.541567] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 [ 9.547818] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 498: pm_runtime_put_autosuspend(), ret:0, thread:0 [ 9.565408] mtk_cmdq 10320000.mailbox: cmdq_irq_handler 306: pm_runtime_mark_last_busy() [ 9.565496] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 588: pm_runtime_get_sync(), ret:1, thread:0 [ 9.582455] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 619: pm_runtime_mark_last_busy(), thread:0 [ 9.591324] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 [ 9.603487] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 621: pm_runtime_put_autosuspend(), ret:0, thread:0 [ 9.613039] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 [ 9.619301] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 418: pm_runtime_get_sync(), ret:1, thread:0 [ 9.628592] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data: send_diff=119 ms [ 9.635629] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 496: pm_runtime_mark_last_busy(), thread:0 [ 9.644831] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 [ 9.651084] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 498: pm_runtime_put_autosuspend(), ret:0, thread:0 [ 9.660988] mtk_cmdq 10320000.mailbox: cmdq_irq_handler 306: pm_runtime_mark_last_busy() [ 9.706660] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 [ 9.786011] mtk_cmdq 10320000.mailbox: cmdq_runtime_suspend: R/S_diff=320 ms // Show UI [ 15.262644] mtk_cmdq 10320000.mailbox: cmdq_runtime_resume: resume_diff=5797 ms [ 15.272870] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 588: pm_runtime_get_sync(), ret:0, thread:0 [ 15.283065] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 619: pm_runtime_mark_last_busy(), thread:0 [ 15.294136] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 [ 15.300473] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 621: pm_runtime_put_autosuspend(), ret:0, thread:0 [ 15.310471] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 418: pm_runtime_get_sync(), ret:1, thread:0 [ 15.319774] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data: send_diff=5691 ms [ 15.326899] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 496: pm_runtime_mark_last_busy(), thread:0 [ 15.336103] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 [ 15.336105] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 498: pm_runtime_put_autosuspend(), ret:0, thread:0 [ 15.336114] mtk_cmdq 10320000.mailbox: cmdq_irq_handler 306: pm_runtime_mark_last_busy() [ 15.382279] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 588: pm_runtime_get_sync(), ret:1, thread:0 [ 15.391682] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 619: pm_runtime_mark_last_busy(), thread:0 [ 15.401735] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 [ 15.408015] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 [ 15.409114] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 621: pm_runtime_put_autosuspend(), ret:0, thread:0 [ 15.433697] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 418: pm_runtime_get_sync(), ret:1, thread:0 [ 15.443019] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data: send_diff=123 ms [ 15.450070] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 496: pm_runtime_mark_last_busy(), thread:0 [ 15.459288] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 [ 15.465552] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 498: pm_runtime_put_autosuspend(), ret:0, thread:0 [ 15.475464] mtk_cmdq 10320000.mailbox: cmdq_irq_handler 306: pm_runtime_mark_last_busy() [ 15.496091] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 588: pm_runtime_get_sync(), ret:1, thread:0 [ 15.505117] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 619: pm_runtime_mark_last_busy(), thread:0 [ 15.514261] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 [ 15.520531] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 [ 15.520695] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 621: pm_runtime_put_autosuspend(), ret:0, thread:0 [ 15.537347] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 418: pm_runtime_get_sync(), ret:1, thread:0 [ 15.546653] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data: send_diff=103 ms [ 15.553692] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 496: pm_runtime_mark_last_busy(), thread:0 [ 15.562896] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 [ 15.569151] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 498: pm_runtime_put_autosuspend(), ret:0, thread:0 [ 15.579057] mtk_cmdq 10320000.mailbox: cmdq_irq_handler 306: pm_runtime_mark_last_busy() [ 15.629590] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 [ 15.703612] mtk_cmdq 10320000.mailbox: cmdq_runtime_suspend: R/S_diff=440 ms [ 15.802705] mtk_cmdq 10320000.mailbox: cmdq_runtime_resume: resume_diff=540 ms [ 15.812716] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 588: pm_runtime_get_sync(), ret:0, thread:0 [ 15.821820] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 619: pm_runtime_mark_last_busy(), thread:0 [ 15.846161] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 [ 15.852900] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 621: pm_runtime_put_autosuspend(), ret:0, thread:0 [ 15.862779] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 418: pm_runtime_get_sync(), ret:1, thread:0 ... [ 161.875995] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 418: pm_runtime_get_sync(), ret:1, thread:0 [ 161.885289] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data: send_diff=84 ms [ 161.892240] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 496: pm_runtime_mark_last_busy(), thread:0 [ 161.901444] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 [ 161.907698] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 498: pm_runtime_put_autosuspend(), ret:0, thread:0 [ 161.917603] mtk_cmdq 10320000.mailbox: cmdq_irq_handler 306: pm_runtime_mark_last_busy() [ 161.969595] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 // Open camera APP [ 162.025947] mtk_cmdq 10320000.mailbox: cmdq_runtime_suspend: R/S_diff=2148 ms [ 162.952349] BUG: sleeping function called from invalid context at drivers/base/power/runtime.c:1166 [ 162.961422] in_atomic(): 1, irqs_disabled(): 128, non_block: 0, pid: 96, name: kworker/u17:0 [ 162.969874] preempt_count: 1, expected: 0 [ 162.973892] RCU nest depth: 0, expected: 0 [ 162.977988] INFO: lockdep is turned off. [ 162.981902] irq event stamp: 16 [ 162.985037] hardirqs last enabled at (15): [<ffffffee13802564>] _raw_spin_unlock_irq+0x44/0x8c [ 162.993743] hardirqs last disabled at (16): [<ffffffee137f7ec4>] __schedule+0x164/0xa50 [ 163.001758] softirqs last enabled at (0): [<ffffffee12aa86ec>] copy_process+0x584/0xf10 [ 163.009860] softirqs last disabled at (0): [<0000000000000000>] 0x0 [ 163.016146] CPU: 2 PID: 96 Comm: kworker/u17:0 Not tainted [ 163.029026] Hardware name: Google Ciri sku0/unprovisioned board (DT) [ 163.035388] Workqueue: imgsys_runner imgsys_runner_func [ 163.040638] Call trace: [ 163.043085] dump_backtrace+0x100/0x120 [ 163.046921] show_stack+0x20/0x2c [ 163.050235] dump_stack_lvl+0x84/0xb4 [ 163.053895] dump_stack+0x18/0x44 [ 163.057205] __might_resched+0x204/0x214 [ 163.061123] __might_sleep+0x50/0x80 [ 163.064692] __pm_runtime_resume+0x48/0xbc [ 163.068786] cmdq_mbox_send_data+0x70/0x3f4 [ 163.072965] msg_submit+0x84/0x104 [ 163.076361] mbox_send_message+0xb8/0x124 [ 163.080365] imgsys_cmdq_sendtask+0x6b0/0x990 [ 163.084718] imgsys_runner_func+0x44/0x78 [ 163.088722] process_one_work+0x274/0x574 [ 163.092728] worker_thread+0x240/0x3f0 [ 163.096471] kthread+0xfc/0x11c [ 163.099608] ret_from_fork+0x10/0x20 [ 163.627262] mtk_cmdq 10320000.mailbox: cmdq_runtime_resume: resume_diff=3749 ms [ 163.641479] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 588: pm_runtime_get_sync(), ret:0, thread:0 [ 163.657722] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 619: pm_runtime_mark_last_busy(), thread:0 [ 163.670587] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 [ 163.689235] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 621: pm_runtime_put_autosuspend(), ret:0, thread:0 [ 163.705474] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 418: pm_runtime_get_sync(), ret:1, thread:0 [ 163.719426] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data: send_diff=1835 ms [ 163.734969] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 496: pm_runtime_mark_last_busy(), thread:0 [ 163.749554] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 [ 163.749556] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 498: pm_runtime_put_autosuspend(), ret:0, thread:0 [ 163.759028] mtk_cmdq 10320000.mailbox: cmdq_irq_handler 306: pm_runtime_mark_last_busy() [ 163.782829] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 [ 163.883590] mtk_cmdq 10320000.mailbox: cmdq_runtime_suspend: R/S_diff=256 ms [ 164.224638] mtk_cmdq 10320000.mailbox: cmdq_runtime_resume: resume_diff=597 ms [ 164.242516] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 588: pm_runtime_get_sync(), ret:0, thread:0 [ 164.258784] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 619: pm_runtime_mark_last_busy(), thread:0 ... [ 167.252326] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 418: pm_runtime_get_sync(), ret:1, thread:0 [ 167.252331] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data: send_diff=32 ms [ 167.252338] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 496: pm_runtime_mark_last_busy(), thread:0 [ 167.252343] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 [ 167.252347] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 498: pm_runtime_put_autosuspend(), ret:0, thread:0 [ 167.252486] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 [ 167.310359] mtk_cmdq 10320000.mailbox: cmdq_irq_handler 306: pm_runtime_mark_last_busy() [ 167.325274] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 588: pm_runtime_get_sync(), ret:1, thread:0 [ 167.340312] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 619: pm_runtime_mark_last_busy(), thread:0 [ 169.050498] mtk_cmdq 10320000.mailbox: cmdq_runtime_suspend: R/S_diff=4825 ms [ 169.052718] mtk_cmdq 10320000.mailbox: cmdq_mbox_flush 621: pm_runtime_put_autosuspend(), ret:0, thread:0 [ 169.067398] BUG: sleeping function called from invalid context at drivers/base/power/runtime.c:1166 [ 169.076435] in_atomic(): 1, irqs_disabled(): 128, non_block: 0, pid: 86, name: kworker/u16:5 [ 169.084858] preempt_count: 1, expected: 0 [ 169.088854] RCU nest depth: 0, expected: 0 [ 169.092939] INFO: lockdep is turned off. [ 169.096848] irq event stamp: 364 [ 169.100064] hardirqs last enabled at (363): [<ffffffee13802564>] _raw_spin_unlock_irq+0x44/0x8c [ 169.108840] hardirqs last disabled at (364): [<ffffffee137f7ec4>] __schedule+0x164/0xa50 [ 169.124557] softirqs last enabled at (0): [<ffffffee12aa86ec>] copy_process+0x584/0xf10 [ 169.132635] softirqs last disabled at (0): [<0000000000000000>] 0x0 [ 169.138892] CPU: 6 PID: 86 Comm: kworker/u16:5 Tainted: G [ 169.153217] Hardware name: Google Ciri sku0/unprovisioned board (DT) [ 169.159557] Workqueue: events_unbound commit_work [ 169.164253] Call trace: [ 169.166686] dump_backtrace+0x100/0x120 [ 169.170511] show_stack+0x20/0x2c [ 169.173814] dump_stack_lvl+0x84/0xb4 [ 169.177465] dump_stack+0x18/0x44 [ 169.180768] __might_resched+0x204/0x214 [ 169.184680] __might_sleep+0x50/0x80 [ 169.188243] __pm_runtime_resume+0x48/0xbc [ 169.192328] cmdq_mbox_send_data+0x70/0x3f4 [ 169.196501] msg_submit+0x84/0x104 [ 169.199892] mbox_send_message+0xb8/0x124 [ 169.203888] mtk_crtc_update_config+0x1cc/0x22c [ 169.208408] mtk_crtc_atomic_flush+0xa4/0xb4 [ 169.212666] drm_atomic_helper_commit_planes+0x1fc/0x280 [ 169.217964] drm_atomic_helper_commit_tail_rpm+0x44/0x78 [ 169.223262] commit_tail+0xb0/0x15c [ 169.226738] commit_work+0x1c/0x28 [ 169.230128] process_one_work+0x274/0x574 [ 169.234126] worker_thread+0x240/0x3f0 [ 169.237864] kthread+0xfc/0x11c [ 169.240993] ret_from_fork+0x10/0x20 [ 169.244603] mtk_cmdq 10320000.mailbox: cmdq_runtime_resume: resume_diff=5019 ms [ 169.251922] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 418: pm_runtime_get_sync(), ret:0, thread:0 [ 169.261214] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data: send_diff=1815 ms [ 169.268337] mtk_cmdq 10320000.mailbox: cmdq_mbox_send_data 496: pm_runtime_mark_last_busy(), thread:0 [ 169.277542] mtk_cmdq 10320000.mailbox: expire autosuspend delay:100 ... And after adding the PM api patches, that BUG report can be fixed. So I think PM api patches for mailbox are required. Regards, Jason-JH.Lin
On Mon, Jul 15, 2024 at 4:45 AM Jason-JH Lin (林睿祥) <Jason-JH.Lin@mediatek.com> wrote: > > Hi Jassi, > > > > You mean _with_ the api patches. right? Because I had suggested > > > "Over > > > your patchset, apply the following diff ..." > > > > No matter __with__ or __without__ the api patches, autosuspend didn't > > work... > > > > We have to find out the reason __without__ the api patches, then see > > if > > we still need the api patches to fix "calling sleep in atomic > > context" > > problem. > > > > I found that the reason autosuspend didn't work was that I added the > devece_add_link() locally between the drm device and the mbox device. > > After removing that change, the mailbox device of display can > autosuspend as expected. So the current autosuspend function is fine. > > And the mailbox device of display has the same BUG report like imgsys. > > > Here is the log after removing the local change of device link and > without the PM api patches: > .... That is the log of your some w.i.p code... it does not trace mbox_send_message() which is where users call the api. You trace cmdq_mbox_send_data() , i.e, the api calls the driver. Even here, the minimum send_diff (time between two cmdq_mbox_send_data calls) is 32ms. The minimum resume_diff is 540ms, which means you suspend for at least 540ms. Also you don't expect these times to change even with the changed api, do you? At these timescales, you could very well release-acquire the channel resource because that cost is ~0ms for your driver. That will not only be the right thing to do but also avoid opening another can of worms by adding some ad-hoc api that works only on your platform. Thanks Jassi
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(-)