Message-ID: <CABb+yY1EZOsKUR7WUX0Ni0Ukbqz0+yRHswiu07tNXtY1A1gNUQ@mail.gmail.com>
Date: Mon, 24 Jun 2024 23:21:25 -0500
From: Jassi Brar <jassisinghbrar@...il.com>
To: Jason-JH Lin (林睿祥) <Jason-JH.Lin@...iatek.com>
Cc: "angelogioacchino.delregno@...labora.com" <angelogioacchino.delregno@...labora.com>, 
	"linux-kernel@...r.kernel.org" <linux-kernel@...r.kernel.org>, 
	"linux-mediatek@...ts.infradead.org" <linux-mediatek@...ts.infradead.org>, 
	Singo Chang (張興國) <Singo.Chang@...iatek.com>, 
	"chunkuang.hu@...nel.org" <chunkuang.hu@...nel.org>, Nancy Lin (林欣螢) <Nancy.Lin@...iatek.com>, 
	Project_Global_Chrome_Upstream_Group <Project_Global_Chrome_Upstream_Group@...iatek.com>, 
	"linux-arm-kernel@...ts.infradead.org" <linux-arm-kernel@...ts.infradead.org>, 
	"matthias.bgg@...il.com" <matthias.bgg@...il.com>
Subject: Re: [PATCH 2/2] mailbox: mtk-cmdq: Move pm_runimte_get and put to
 mbox_chan_ops API

On Mon, Jun 24, 2024 at 10:41 PM Jason-JH Lin (林睿祥)
<Jason-JH.Lin@...iatek.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@...labora.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@...iatek.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@...labora.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

Powered by blists - more mailing lists