diff mbox series

[2/2] mailbox: mtk-cmdq: Move pm_runimte_get and put to mbox_chan_ops API

Message ID 20240614040133.24967-3-jason-jh.lin@mediatek.com (mailing list archive)
State New, archived
Headers show
Series Fix sleeping function called from invalid context | expand

Commit Message

Jason-JH.Lin June 14, 2024, 4:01 a.m. UTC
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(-)

Comments

Jassi Brar June 17, 2024, 6:18 p.m. UTC | #1
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
Jason-JH.Lin June 18, 2024, 8:42 a.m. UTC | #2
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
Jassi Brar June 18, 2024, 3:59 p.m. UTC | #3
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
AngeloGioacchino Del Regno June 19, 2024, 8:18 a.m. UTC | #4
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
Jassi Brar June 19, 2024, 3:38 p.m. UTC | #5
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.
Jason-JH.Lin June 20, 2024, 6:32 a.m. UTC | #6
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.
>
Jassi Brar June 20, 2024, 2:39 p.m. UTC | #7
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
AngeloGioacchino Del Regno June 24, 2024, 11:29 a.m. UTC | #8
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
Jassi Brar June 24, 2024, 5:45 p.m. UTC | #9
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
Jason-JH.Lin June 25, 2024, 3:40 a.m. UTC | #10
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
Jassi Brar June 25, 2024, 4:21 a.m. UTC | #11
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
Jason-JH.Lin June 26, 2024, 9:32 a.m. UTC | #12
[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
Jassi Brar June 28, 2024, 3:40 a.m. UTC | #13
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!
Jason-JH.Lin July 3, 2024, 4:41 p.m. UTC | #14
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
Jassi Brar July 3, 2024, 7:06 p.m. UTC | #15
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
Jason-JH.Lin July 5, 2024, 6:11 a.m. UTC | #16
[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
Jassi Brar July 5, 2024, 4:43 p.m. UTC | #17
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
Jason-JH.Lin July 11, 2024, 2 a.m. UTC | #18
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
>
Jassi Brar July 11, 2024, 3:47 a.m. UTC | #19
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.
Jason-JH.Lin July 12, 2024, 7:23 a.m. UTC | #20
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.
Jason-JH.Lin July 15, 2024, 9:45 a.m. UTC | #21
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
Jassi Brar July 17, 2024, 4:17 p.m. UTC | #22
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 mbox series

Patch

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,