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

[Jason-JH Lin (林睿祥)]

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