[PATCH 0/2] Fix sleeping function called from invalid context

[PATCH 0/2] Fix sleeping function called from invalid context

[Jason-JH.Lin]

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 the mailbox controller driver calls pm_runtime_get_sync() in
mbox_chan_ops->send_data(), it will get this BUG report.
"BUG: sleeping function called from invalid context at drivers/base/power/runtime.c:1164"

Add API to mbox_chan_ops to make mailbox takes into account that a driver
may need PM done.

Jason-JH.Lin (2):
  mailbox: Add power_get/power_put API to mbox_chan_ops
  mailbox: mtk-cmdq: Move pm_runimte_get and put to mbox_chan_ops API

 drivers/mailbox/mailbox.c          | 55 ++++++++++++++++++++++++++++++
 drivers/mailbox/mtk-cmdq-mailbox.c | 37 ++++++++++----------
 include/linux/mailbox_controller.h | 11 ++++++
 3 files changed, 84 insertions(+), 19 deletions(-)

-- 
2.18.0

[PATCH 1/2] mailbox: Add power_get/power_put API to mbox_chan_ops

[Jason-JH.Lin]

To avoid pm_runtime APIs calling sleep in all the atomic context APIs
in mbox_chan_ops, we add power_get/power_put API to let the controllers
implement them with pm_runtime APIs outside the other atomic context APIs
in mbox_chan_ops.

Signed-off-by: Jason-JH.Lin <jason-jh.lin@mediatek.com>
---
 drivers/mailbox/mailbox.c          | 55 ++++++++++++++++++++++++++++++
 include/linux/mailbox_controller.h | 11 ++++++
 2 files changed, 66 insertions(+)

diff --git a/drivers/mailbox/mailbox.c b/drivers/mailbox/mailbox.c
index ebff3baf3045..bafcc7b0c0b8 100644
--- a/drivers/mailbox/mailbox.c
+++ b/drivers/mailbox/mailbox.c
@@ -58,6 +58,12 @@ static void msg_submit(struct mbox_chan *chan)
 	void *data;
 	int err = -EBUSY;
 
+	if (chan->mbox->ops->power_get) {
+		err = chan->mbox->ops->power_get(chan);
+		if (err < 0)
+			return;
+	}
+
 	spin_lock_irqsave(&chan->lock, flags);
 
 	if (!chan->msg_count || chan->active_req)
@@ -89,12 +95,16 @@ static void msg_submit(struct mbox_chan *chan)
 		hrtimer_start(&chan->mbox->poll_hrt, 0, HRTIMER_MODE_REL);
 		spin_unlock_irqrestore(&chan->mbox->poll_hrt_lock, flags);
 	}
+
+	if (chan->mbox->ops->power_put)
+		chan->mbox->ops->power_put(chan);
 }
 
 static void tx_tick(struct mbox_chan *chan, int r)
 {
 	unsigned long flags;
 	void *mssg;
+	int ret;
 
 	spin_lock_irqsave(&chan->lock, flags);
 	mssg = chan->active_req;
@@ -107,10 +117,19 @@ static void tx_tick(struct mbox_chan *chan, int r)
 	if (!mssg)
 		return;
 
+	if (chan->mbox->ops->power_get) {
+		ret = chan->mbox->ops->power_get(chan);
+		if (ret < 0)
+			return;
+	}
+
 	/* Notify the client */
 	if (chan->cl->tx_done)
 		chan->cl->tx_done(chan->cl, mssg, r);
 
+	if (chan->mbox->ops->power_put)
+		chan->mbox->ops->power_put(chan);
+
 	if (r != -ETIME && chan->cl->tx_block)
 		complete(&chan->tx_complete);
 }
@@ -223,9 +242,16 @@ EXPORT_SYMBOL_GPL(mbox_client_txdone);
  */
 bool mbox_client_peek_data(struct mbox_chan *chan)
 {
+	if (chan->mbox->ops->power_get)
+		if (chan->mbox->ops->power_get(chan) < 0)
+			return false;
+
 	if (chan->mbox->ops->peek_data)
 		return chan->mbox->ops->peek_data(chan);
 
+	if (chan->mbox->ops->power_put)
+		chan->mbox->ops->power_put(chan);
+
 	return false;
 }
 EXPORT_SYMBOL_GPL(mbox_client_peek_data);
@@ -310,10 +336,19 @@ int mbox_flush(struct mbox_chan *chan, unsigned long timeout)
 	if (!chan->mbox->ops->flush)
 		return -ENOTSUPP;
 
+	if (chan->mbox->ops->power_get) {
+		ret = chan->mbox->ops->power_get(chan);
+		if (ret < 0)
+			return ret;
+	}
+
 	ret = chan->mbox->ops->flush(chan, timeout);
 	if (ret < 0)
 		tx_tick(chan, ret);
 
+	if (chan->mbox->ops->power_put)
+		chan->mbox->ops->power_put(chan);
+
 	return ret;
 }
 EXPORT_SYMBOL_GPL(mbox_flush);
@@ -341,6 +376,12 @@ static int __mbox_bind_client(struct mbox_chan *chan, struct mbox_client *cl)
 
 	spin_unlock_irqrestore(&chan->lock, flags);
 
+	if (chan->mbox->ops->power_get) {
+		ret = chan->mbox->ops->power_get(chan);
+		if (ret < 0)
+			return ERR_PTR(ret);
+	}
+
 	if (chan->mbox->ops->startup) {
 		ret = chan->mbox->ops->startup(chan);
 
@@ -441,7 +482,11 @@ struct mbox_chan *mbox_request_channel(struct mbox_client *cl, int index)
 	if (ret)
 		chan = ERR_PTR(ret);
 
+	if (chan->mbox->ops->power_put)
+		chan->mbox->ops->power_put(chan);
+
 	mutex_unlock(&con_mutex);
+
 	return chan;
 }
 EXPORT_SYMBOL_GPL(mbox_request_channel);
@@ -485,13 +530,23 @@ EXPORT_SYMBOL_GPL(mbox_request_channel_byname);
 void mbox_free_channel(struct mbox_chan *chan)
 {
 	unsigned long flags;
+	int ret;
 
 	if (!chan || !chan->cl)
 		return;
 
+	if (chan->mbox->ops->power_get) {
+		ret = chan->mbox->ops->power_get(chan);
+		if (ret < 0)
+			return;
+	}
+
 	if (chan->mbox->ops->shutdown)
 		chan->mbox->ops->shutdown(chan);
 
+	if (chan->mbox->ops->power_put)
+		chan->mbox->ops->power_put(chan);
+
 	/* The queued TX requests are simply aborted, no callbacks are made */
 	spin_lock_irqsave(&chan->lock, flags);
 	chan->cl = NULL;
diff --git a/include/linux/mailbox_controller.h b/include/linux/mailbox_controller.h
index 6fee33cb52f5..e8f26e7dabfd 100644
--- a/include/linux/mailbox_controller.h
+++ b/include/linux/mailbox_controller.h
@@ -42,6 +42,15 @@ struct mbox_chan;
  *		  Used only if txdone_poll:=true && txdone_irq:=false
  * @peek_data: Atomic check for any received data. Return true if controller
  *		  has some data to push to the client. False otherwise.
+ * @power_get:	Called when the controller need to get the reference to keep
+ *		the power on for the device of mailbox controller. It is
+ *		optional to implement this function with pm_runtime APIs or
+ *		more complicated operation.
+ *		Return 0 is success, otherwise are fail.
+ * @power_put:	Called when the controller need to put the reference to release
+ *		the power for the device of mailbox controller. It is optional
+ *		to implement this function with pm_runtime APIs or more
+ *		complicated operation.
  */
 struct mbox_chan_ops {
 	int (*send_data)(struct mbox_chan *chan, void *data);
@@ -50,6 +59,8 @@ struct mbox_chan_ops {
 	void (*shutdown)(struct mbox_chan *chan);
 	bool (*last_tx_done)(struct mbox_chan *chan);
 	bool (*peek_data)(struct mbox_chan *chan);
+	int (*power_get)(struct mbox_chan *chan);
+	void (*power_put)(struct mbox_chan *chan);
 };
 
 /**
-- 
2.18.0

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

[Jason-JH.Lin]

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(-)

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,
-- 
2.18.0

Re: [PATCH 1/2] mailbox: Add power_get/power_put API to mbox_chan_ops

[Markus Elfring]

> To avoid pm_runtime APIs calling sleep in all the atomic context APIs

           PM-runtime?


> in mbox_chan_ops, we add power_get/power_put API to let the controllers
> implement them with pm_runtime APIs outside the other atomic context APIs
> in mbox_chan_ops.

* How do you think about to omit the word “we” from such a change description?
  https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/Documentation/process/submitting-patches.rst?h=v6.10-rc3#n94

* Would you like to improve any indications for adjustments of data structures?


> Signed-off-by: Jason-JH.Lin <jason-jh.lin@mediatek.com>

Does a dot really belong to the personal name
(according to the Developer's Certificate of Origin)?
https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/Documentation/process/submitting-patches.rst?h=v6.10-rc3#n438

Regards,
Markus

Re: [PATCH 1/2] mailbox: Add power_get/power_put API to mbox_chan_ops

[kernel test robot]

Hi Jason-JH.Lin,

kernel test robot noticed the following build errors:

[auto build test ERROR on linus/master]
[also build test ERROR on v6.10-rc3 next-20240613]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch#_base_tree_information]

url:    https://github.com/intel-lab-lkp/linux/commits/Jason-JH-Lin/mailbox-Add-power_get-power_put-API-to-mbox_chan_ops/20240614-120412
base:   linus/master
patch link:    https://lore.kernel.org/r/20240614040133.24967-2-jason-jh.lin%40mediatek.com
patch subject: [PATCH 1/2] mailbox: Add power_get/power_put API to mbox_chan_ops
config: riscv-defconfig (https://download.01.org/0day-ci/archive/20240615/202406150022.LXLvvkeI-lkp@intel.com/config)
compiler: clang version 19.0.0git (https://github.com/llvm/llvm-project 78ee473784e5ef6f0b19ce4cb111fb6e4d23c6b2)
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20240615/202406150022.LXLvvkeI-lkp@intel.com/reproduce)

If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Closes: https://lore.kernel.org/oe-kbuild-all/202406150022.LXLvvkeI-lkp@intel.com/

All errors (new ones prefixed by >>):

   In file included from drivers/mailbox/mailbox.c:9:
   In file included from include/linux/interrupt.h:21:
   In file included from arch/riscv/include/asm/sections.h:9:
   In file included from include/linux/mm.h:2253:
   include/linux/vmstat.h:514:36: warning: arithmetic between different enumeration types ('enum node_stat_item' and 'enum lru_list') [-Wenum-enum-conversion]
     514 |         return node_stat_name(NR_LRU_BASE + lru) + 3; // skip "nr_"
         |                               ~~~~~~~~~~~ ^ ~~~
>> drivers/mailbox/mailbox.c:382:11: error: incompatible pointer to integer conversion returning 'void *' from a function with result type 'int' [-Wint-conversion]
     382 |                         return ERR_PTR(ret);
         |                                ^~~~~~~~~~~~
   1 warning and 1 error generated.


vim +382 drivers/mailbox/mailbox.c

   355	
   356	static int __mbox_bind_client(struct mbox_chan *chan, struct mbox_client *cl)
   357	{
   358		struct device *dev = cl->dev;
   359		unsigned long flags;
   360		int ret;
   361	
   362		if (chan->cl || !try_module_get(chan->mbox->dev->driver->owner)) {
   363			dev_dbg(dev, "%s: mailbox not free\n", __func__);
   364			return -EBUSY;
   365		}
   366	
   367		spin_lock_irqsave(&chan->lock, flags);
   368		chan->msg_free = 0;
   369		chan->msg_count = 0;
   370		chan->active_req = NULL;
   371		chan->cl = cl;
   372		init_completion(&chan->tx_complete);
   373	
   374		if (chan->txdone_method	== TXDONE_BY_POLL && cl->knows_txdone)
   375			chan->txdone_method = TXDONE_BY_ACK;
   376	
   377		spin_unlock_irqrestore(&chan->lock, flags);
   378	
   379		if (chan->mbox->ops->power_get) {
   380			ret = chan->mbox->ops->power_get(chan);
   381			if (ret < 0)
 > 382				return ERR_PTR(ret);
   383		}
   384	
   385		if (chan->mbox->ops->startup) {
   386			ret = chan->mbox->ops->startup(chan);
   387	
   388			if (ret) {
   389				dev_err(dev, "Unable to startup the chan (%d)\n", ret);
   390				mbox_free_channel(chan);
   391				return ret;
   392			}
   393		}
   394	
   395		return 0;
   396	}
   397	

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

Re: [PATCH 1/2] mailbox: Add power_get/power_put API to mbox_chan_ops

[kernel test robot]

Hi Jason-JH.Lin,

kernel test robot noticed the following build warnings:

[auto build test WARNING on linus/master]
[also build test WARNING on fujitsu-integration/mailbox-for-next v6.10-rc3 next-20240613]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch#_base_tree_information]

url:    https://github.com/intel-lab-lkp/linux/commits/Jason-JH-Lin/mailbox-Add-power_get-power_put-API-to-mbox_chan_ops/20240614-120412
base:   linus/master
patch link:    https://lore.kernel.org/r/20240614040133.24967-2-jason-jh.lin%40mediatek.com
patch subject: [PATCH 1/2] mailbox: Add power_get/power_put API to mbox_chan_ops
config: arc-randconfig-002-20240614 (https://download.01.org/0day-ci/archive/20240615/202406150041.QTui5Xgq-lkp@intel.com/config)
compiler: arceb-elf-gcc (GCC) 13.2.0
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20240615/202406150041.QTui5Xgq-lkp@intel.com/reproduce)

If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Closes: https://lore.kernel.org/oe-kbuild-all/202406150041.QTui5Xgq-lkp@intel.com/

All warnings (new ones prefixed by >>):

   drivers/mailbox/mailbox.c: In function '__mbox_bind_client':
>> drivers/mailbox/mailbox.c:382:32: warning: returning 'void *' from a function with return type 'int' makes integer from pointer without a cast [-Wint-conversion]
     382 |                         return ERR_PTR(ret);
         |                                ^~~~~~~~~~~~

Kconfig warnings: (for reference only)
   WARNING: unmet direct dependencies detected for REGMAP_SPI
   Depends on [n]: SPI [=n]
   Selected by [y]:
   - AD9739A [=y] && IIO [=y] && (SPI [=n] || COMPILE_TEST [=y])


vim +382 drivers/mailbox/mailbox.c

   355	
   356	static int __mbox_bind_client(struct mbox_chan *chan, struct mbox_client *cl)
   357	{
   358		struct device *dev = cl->dev;
   359		unsigned long flags;
   360		int ret;
   361	
   362		if (chan->cl || !try_module_get(chan->mbox->dev->driver->owner)) {
   363			dev_dbg(dev, "%s: mailbox not free\n", __func__);
   364			return -EBUSY;
   365		}
   366	
   367		spin_lock_irqsave(&chan->lock, flags);
   368		chan->msg_free = 0;
   369		chan->msg_count = 0;
   370		chan->active_req = NULL;
   371		chan->cl = cl;
   372		init_completion(&chan->tx_complete);
   373	
   374		if (chan->txdone_method	== TXDONE_BY_POLL && cl->knows_txdone)
   375			chan->txdone_method = TXDONE_BY_ACK;
   376	
   377		spin_unlock_irqrestore(&chan->lock, flags);
   378	
   379		if (chan->mbox->ops->power_get) {
   380			ret = chan->mbox->ops->power_get(chan);
   381			if (ret < 0)
 > 382				return ERR_PTR(ret);
   383		}
   384	
   385		if (chan->mbox->ops->startup) {
   386			ret = chan->mbox->ops->startup(chan);
   387	
   388			if (ret) {
   389				dev_err(dev, "Unable to startup the chan (%d)\n", ret);
   390				mbox_free_channel(chan);
   391				return ret;
   392			}
   393		}
   394	
   395		return 0;
   396	}
   397	

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

Re: [PATCH 1/2] mailbox: Add power_get/power_put API to mbox_chan_ops

[kernel test robot]

Hi Jason-JH.Lin,

kernel test robot noticed the following build warnings:

[auto build test WARNING on linus/master]
[also build test WARNING on fujitsu-integration/mailbox-for-next v6.10-rc3 next-20240613]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch#_base_tree_information]

url:    https://github.com/intel-lab-lkp/linux/commits/Jason-JH-Lin/mailbox-Add-power_get-power_put-API-to-mbox_chan_ops/20240614-120412
base:   linus/master
patch link:    https://lore.kernel.org/r/20240614040133.24967-2-jason-jh.lin%40mediatek.com
patch subject: [PATCH 1/2] mailbox: Add power_get/power_put API to mbox_chan_ops
config: i386-randconfig-062-20240614 (https://download.01.org/0day-ci/archive/20240615/202406150214.pVxsbllC-lkp@intel.com/config)
compiler: gcc-13 (Ubuntu 13.2.0-4ubuntu3) 13.2.0
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20240615/202406150214.pVxsbllC-lkp@intel.com/reproduce)

If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Closes: https://lore.kernel.org/oe-kbuild-all/202406150214.pVxsbllC-lkp@intel.com/

sparse warnings: (new ones prefixed by >>)
>> drivers/mailbox/mailbox.c:382:39: sparse: sparse: incorrect type in return expression (different base types) @@     expected int @@     got void * @@
   drivers/mailbox/mailbox.c:382:39: sparse:     expected int
   drivers/mailbox/mailbox.c:382:39: sparse:     got void *
   drivers/mailbox/mailbox.c: note: in included file (through include/linux/smp.h, include/linux/alloc_tag.h, include/linux/percpu.h, ...):
   include/linux/list.h:83:21: sparse: sparse: self-comparison always evaluates to true

vim +382 drivers/mailbox/mailbox.c

   355	
   356	static int __mbox_bind_client(struct mbox_chan *chan, struct mbox_client *cl)
   357	{
   358		struct device *dev = cl->dev;
   359		unsigned long flags;
   360		int ret;
   361	
   362		if (chan->cl || !try_module_get(chan->mbox->dev->driver->owner)) {
   363			dev_dbg(dev, "%s: mailbox not free\n", __func__);
   364			return -EBUSY;
   365		}
   366	
   367		spin_lock_irqsave(&chan->lock, flags);
   368		chan->msg_free = 0;
   369		chan->msg_count = 0;
   370		chan->active_req = NULL;
   371		chan->cl = cl;
   372		init_completion(&chan->tx_complete);
   373	
   374		if (chan->txdone_method	== TXDONE_BY_POLL && cl->knows_txdone)
   375			chan->txdone_method = TXDONE_BY_ACK;
   376	
   377		spin_unlock_irqrestore(&chan->lock, flags);
   378	
   379		if (chan->mbox->ops->power_get) {
   380			ret = chan->mbox->ops->power_get(chan);
   381			if (ret < 0)
 > 382				return ERR_PTR(ret);
   383		}
   384	
   385		if (chan->mbox->ops->startup) {
   386			ret = chan->mbox->ops->startup(chan);
   387	
   388			if (ret) {
   389				dev_err(dev, "Unable to startup the chan (%d)\n", ret);
   390				mbox_free_channel(chan);
   391				return ret;
   392			}
   393		}
   394	
   395		return 0;
   396	}
   397	

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

Re: [PATCH 1/2] mailbox: Add power_get/power_put API to mbox_chan_ops

[Dan Carpenter]

Hi Jason-JH.Lin,

kernel test robot noticed the following build warnings:

https://git-scm.com/docs/git-format-patch#_base_tree_information]

url:    https://github.com/intel-lab-lkp/linux/commits/Jason-JH-Lin/mailbox-Add-power_get-power_put-API-to-mbox_chan_ops/20240614-120412
base:   linus/master
patch link:    https://lore.kernel.org/r/20240614040133.24967-2-jason-jh.lin%40mediatek.com
patch subject: [PATCH 1/2] mailbox: Add power_get/power_put API to mbox_chan_ops
config: x86_64-randconfig-161-20240615 (https://download.01.org/0day-ci/archive/20240615/202406151520.TDnOFFbV-lkp@intel.com/config)
compiler: gcc-13 (Ubuntu 13.2.0-4ubuntu3) 13.2.0

If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Reported-by: Dan Carpenter <dan.carpenter@linaro.org>
| Closes: https://lore.kernel.org/r/202406151520.TDnOFFbV-lkp@intel.com/

smatch warnings:
drivers/mailbox/mailbox.c:485 mbox_request_channel() error: 'chan' dereferencing possible ERR_PTR()

vim +/chan +485 drivers/mailbox/mailbox.c

2b6d83e2b8b7de Jassi Brar      2014-06-12  444  struct mbox_chan *mbox_request_channel(struct mbox_client *cl, int index)
2b6d83e2b8b7de Jassi Brar      2014-06-12  445  {
2b6d83e2b8b7de Jassi Brar      2014-06-12  446  	struct device *dev = cl->dev;
2b6d83e2b8b7de Jassi Brar      2014-06-12  447  	struct mbox_controller *mbox;
2b6d83e2b8b7de Jassi Brar      2014-06-12  448  	struct of_phandle_args spec;
2b6d83e2b8b7de Jassi Brar      2014-06-12  449  	struct mbox_chan *chan;
2b6d83e2b8b7de Jassi Brar      2014-06-12  450  	int ret;
2b6d83e2b8b7de Jassi Brar      2014-06-12  451  
2b6d83e2b8b7de Jassi Brar      2014-06-12  452  	if (!dev || !dev->of_node) {
2b6d83e2b8b7de Jassi Brar      2014-06-12  453  		pr_debug("%s: No owner device node\n", __func__);
2b6d83e2b8b7de Jassi Brar      2014-06-12  454  		return ERR_PTR(-ENODEV);
2b6d83e2b8b7de Jassi Brar      2014-06-12  455  	}
2b6d83e2b8b7de Jassi Brar      2014-06-12  456  
2b6d83e2b8b7de Jassi Brar      2014-06-12  457  	mutex_lock(&con_mutex);
2b6d83e2b8b7de Jassi Brar      2014-06-12  458  
2b6d83e2b8b7de Jassi Brar      2014-06-12  459  	if (of_parse_phandle_with_args(dev->of_node, "mboxes",
2b6d83e2b8b7de Jassi Brar      2014-06-12  460  				       "#mbox-cells", index, &spec)) {
b6d83e2b8b7de Jassi Brar      2014-06-12  461  		dev_dbg(dev, "%s: can't parse \"mboxes\" property\n", __func__);
2b6d83e2b8b7de Jassi Brar      2014-06-12  462  		mutex_unlock(&con_mutex);
2b6d83e2b8b7de Jassi Brar      2014-06-12  463  		return ERR_PTR(-ENODEV);
2b6d83e2b8b7de Jassi Brar      2014-06-12  464  	}
2b6d83e2b8b7de Jassi Brar      2014-06-12  465  
2d805fc1c6b2ec Benson Leung    2015-05-04  466  	chan = ERR_PTR(-EPROBE_DEFER);
2b6d83e2b8b7de Jassi Brar      2014-06-12  467  	list_for_each_entry(mbox, &mbox_cons, node)
2b6d83e2b8b7de Jassi Brar      2014-06-12  468  		if (mbox->dev->of_node == spec.np) {
2b6d83e2b8b7de Jassi Brar      2014-06-12  469  			chan = mbox->of_xlate(mbox, &spec);
8ed82e23875e60 Mikko Perttunen 2018-11-28  470  			if (!IS_ERR(chan))
2b6d83e2b8b7de Jassi Brar      2014-06-12  471  				break;
2b6d83e2b8b7de Jassi Brar      2014-06-12  472  		}
2b6d83e2b8b7de Jassi Brar      2014-06-12  473  
2b6d83e2b8b7de Jassi Brar      2014-06-12  474  	of_node_put(spec.np);
2b6d83e2b8b7de Jassi Brar      2014-06-12  475  
2d805fc1c6b2ec Benson Leung    2015-05-04  476  	if (IS_ERR(chan)) {
2d805fc1c6b2ec Benson Leung    2015-05-04  477  		mutex_unlock(&con_mutex);
2d805fc1c6b2ec Benson Leung    2015-05-04  478  		return chan;
2d805fc1c6b2ec Benson Leung    2015-05-04  479  	}
2d805fc1c6b2ec Benson Leung    2015-05-04  480  
85a953806557db Elliot Berman   2023-04-10  481  	ret = __mbox_bind_client(chan, cl);
85a953806557db Elliot Berman   2023-04-10  482  	if (ret)
2b6d83e2b8b7de Jassi Brar      2014-06-12  483  		chan = ERR_PTR(ret);

change is set to error pointer

2b6d83e2b8b7de Jassi Brar      2014-06-12  484  
9c57f48cd805b1 Jason-JH.Lin    2024-06-14 @485  	if (chan->mbox->ops->power_put)
                                                            ^^^^^^
Dereferenced on the next line

9c57f48cd805b1 Jason-JH.Lin    2024-06-14  486  		chan->mbox->ops->power_put(chan);
9c57f48cd805b1 Jason-JH.Lin    2024-06-14  487  
2b6d83e2b8b7de Jassi Brar      2014-06-12  488  	mutex_unlock(&con_mutex);
9c57f48cd805b1 Jason-JH.Lin    2024-06-14  489  
2b6d83e2b8b7de Jassi Brar      2014-06-12  490  	return chan;
2b6d83e2b8b7de Jassi Brar      2014-06-12  491  }

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

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

[Jassi Brar]

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

Re: [PATCH 1/2] mailbox: Add power_get/power_put API to mbox_chan_ops

[Jason-JH Lin (林睿祥)]

On Fri, 2024-06-14 at 13:35 +0200, Markus Elfring wrote:
>  	 
> External email : Please do not click links or open attachments until
> you have verified the sender or the content.
>  > To avoid pm_runtime APIs calling sleep in all the atomic context
> APIs
> 
>            PM-runtime?
> 
OK, I'll change this.

> 
> > in mbox_chan_ops, we add power_get/power_put API to let the
> controllers
> > implement them with pm_runtime APIs outside the other atomic
> context APIs
> > in mbox_chan_ops.
> 
> * How do you think about to omit the word “we” from such a change
> description?
>   
> https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/Documentation/process/submitting-patches.rst?h=v6.10-rc3#n94
> 

OK, I'll remove `we` and change the sentence below:
Add power_get/power_put API into mbox_chan_ops to let controllers
implement them with PM-runtime APIs outside the other atomic context
APIs in mbox_chan_ops to avoid calling sleep in the atomic context.


> * Would you like to improve any indications for adjustments of data
> structures?
> 

You mean the description of power_get and power_put in struct
mbox_chan_ops? Is this better?
@power_get: Called when the controller needs to increase a reference
count to keep power on for the device of mailbox controller. It's
optional to use PM-runtime API or more complex operations to implement
this function.

@power_put: Called when the controller needs to decrease a reference
count to release power for the device of mailbox controller. It's
optional to use PM-runtime API to more complex operations to implement
this function.

> 
> > Signed-off-by: Jason-JH.Lin <jason-jh.lin@mediatek.com>
> 
> Does a dot really belong to the personal name
> (according to the Developer's Certificate of Origin)?
> 
https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/Documentation/process/submitting-patches.rst?h=v6.10-rc3#n438
> 
A dot is not in my name, but I've been using it for a long time.
It's binding to my environment everywhere and it's not easy to change
in a short time. But I'll try to change it before sending upstream
patch. Thanks for your advice.

Regards
Jason-JH Lin


> Regards,
> Markus

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

[Jason-JH Lin (林睿祥)]

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

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

[Jassi Brar]

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

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

[AngeloGioacchino Del Regno]

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

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

[Jassi Brar]

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.

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

[Jason-JH Lin (林睿祥)]

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.
> 

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

[Jassi Brar]

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

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

[AngeloGioacchino Del Regno]

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

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

[Jassi Brar]

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

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

[Jason-JH Lin (林睿祥)]

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

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

[Jassi Brar]

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

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

[Jason-JH Lin (林睿祥)]

[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

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

[Jassi Brar]

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!

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

[Jason-JH Lin (林睿祥)]

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

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

[Jassi Brar]

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

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

[Jason-JH Lin (林睿祥)]

[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

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

[Jassi Brar]

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

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

[Jason-JH Lin (林睿祥)]

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
> 

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

[Jassi Brar]

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.

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

[Jason-JH Lin (林睿祥)]

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.

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

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

[Jassi Brar]

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