Stopping/Pausing a CHAIN_DMA stream takes 100ms

@ujfalusi

Adding a Linux issue based on thesofproject/sof-test#1126 comments

"ChainDMA enabled PCMs where the time to stop the stream takes more than 100ms (from trigger stop to PCM close)."

this needs to be root-caused, 100ms is not an acceptable response time.

@ujfalusi @lgirdwood we might transfer this issue to SOF at some point.

@plbossart

@plbossart, this is a firmware feature. The roundtrip of the message alone is ~100ms:

[ 1097.670709] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0xe050000|0x0: GLB_CHAIN_DMA
[ 1097.771134] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x2e000000|0x0: GLB_CHAIN_DMA
[ 1097.771171] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx done : 0xe050000|0x0: GLB_CHAIN_DMA

and this is not random, but constant.
CC: @jsarha,@makarukp

the firmware log:

[    5.089171] <inf> ipc: ipc_cmd: rx   : 0xe050000|0x0
[    5.089185] <inf> chain_dma: chain_host_stop: comp:128 0x80 chain_host_stop(): dma_stop() host chan_index = 0
[    5.089191] <inf> chain_dma: chain_link_stop: comp:128 0x80 chain_link_stop(): dma_stop() link chan_index = 0
[    5.089446] <inf> ll_schedule: zephyr_ll_task_done: task complete 0xbe097310 0x204b0U
[    5.089450] <inf> ll_schedule: zephyr_ll_task_done: num_tasks 1 total_num_tasks 1
[    5.089461] <inf> ll_schedule: zephyr_domain_unregister: zephyr_domain_unregister domain->type 1 domain->clk 4
[    5.189238] <inf> ipc: ipc_cmd: tx-reply     : 0x2e000000|0x0

this is the call that takes ~100ms:
https://github.com/thesofproject/sof/blob/main/src/audio/chain_dma.c#L383

schedule_task_free(&cd->chain_task);

@plbossart

@plbossart, and to be precise, pausing ChainDMA also takes 100ms, the 0xe050000 is a pause command

@lyakh

this is what is going on:
chain_task_pause() -> schedule_task_free() ->zephyr_ll_task_free() -> k_sem_take(&pdata->sem, K_USEC(LL_TIMER_PERIOD_US * 100));
On zephyr_ll_run() pdata->freeing is true for the ChainDMA:

		if (pdata->freeing) {
			/*
			 * zephyr_ll_task_free() is trying to free this task.
			 * complete it and signal the semaphore to let the
			 * function proceed
			 */
			zephyr_ll_task_done(sch, task);
			k_sem_give(&pdata->sem);
		} else if (state == SOF_TASK_STATE_COMPLETED) {

and we have this in zephyr_ll_task_done():

	/*
	 * If this is the last task, domain_unregister() won't return. It is
	 * important to decrement the task counter last before aborting the
	 * thread.
	 */
	domain_unregister(sch->ll_domain, task, --sch->n_tasks);

With a single HDMI playback we have one task and that is what we are stopping, domain_unregister() will not return and we are not going to call k_sem_give(&pdata->sem) which means that zephyr_ll_task_free() will wait the maximum of 100ms before continuing.

If we have two ChainDMA playbacks and we only pause/stop one of them then the domain_unregister() will return and the k_sem_give() is called -> we don't have the 100ms time to pause/stop ChainDMA stream:

[   12.773428] <inf> ipc: ipc_cmd: rx   : 0xe050101|0x0
[   12.773440] <inf> chain_dma: chain_task_pause: comp:129 0x81 chain_task_pause() - ENTER
[   12.773446] <inf> chain_dma: chain_host_stop: comp:129 0x81 chain_host_stop(): dma_stop() host chan_index = 1
[   12.773453] <inf> chain_dma: chain_link_stop: comp:129 0x81 chain_link_stop(): dma_stop() link chan_index = 1
[   12.774340] <inf> ll_schedule: zephyr_ll_task_done: task complete 0xbe097d90 0x204b0U
[   12.774350] <inf> ll_schedule: zephyr_ll_task_done: num_tasks 2 total_num_tasks 2
[   12.774376] <inf> chain_dma: chain_task_pause: comp:129 0x81 chain_task_pause() - LEAVE

I'm not familiar with the scheduling, @lyakh, @kv2019i FYI

Moving to firmware

@ujfalusi

nice work @ujfalusi. The response time should not depend on the number of active CHAIN_DMA streams, that's a code flow problem clearly.

chain-dma: cancel a task before freeing it

schedule: cancel a task before freeing it

There was one failure in daily tests with commit 1bd9e0d, right before the #8451 fix was merged:
34373?model=TGLU_UP_HDA-ipc4&testcase=multiple-pause-resume-50

This failure was extremely rare. Rather than letting GitHub's auto-close this issue (anti--feature https://github.com/orgs/community/discussions/23476), let's make sure it does not happen for about a week and only then close it.

@marc-hb

@marc-hb @kv2019i I don't think this issue should remain open, no one has reported any updated in 8+ months.

Navigation Menu

Repository navigation

Stopping/Pausing a CHAIN_DMA stream takes 100ms #8445

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Stopping/Pausing a CHAIN_DMA stream takes 100ms #8445

Description

Activity

ujfalusi commented on Nov 6, 2023

ujfalusi commented on Nov 6, 2023

ujfalusi commented on Nov 6, 2023

ujfalusi commented on Nov 6, 2023

ujfalusi commented on Nov 6, 2023

ujfalusi commented on Nov 6, 2023

plbossart commented on Nov 6, 2023

marc-hb commented on Nov 10, 2023

plbossart commented on Jul 23, 2024

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions