[BUG] DMIC capture failed to start

Describe the bug

Launch arecord on DMIC Raw, and observe error returned immediately.

To Reproduce
Steps to reproduce the behavior: (e.g. list commands or actions used to reproduce the bug)

arecord -Dhw:0,99 /tmp/test.wav -c4 -r48000 -fs32_le -d10

Reproduction Rate
100%

Environment

Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
- Kernel: {https://chromium.googlesource.com/chromiumos/third_party/kernel/+log/refs/heads/chromeos-6.1/sound}
- SOF: {a8db157b9a2dee8}
Name of the topology file
- Topology: {sof-mtl-max98357a-rt5682-ssp2-ssp0.tplg}
Name of the platform(s) on which the bug is observed.
- Platform: {MTL/Rex}

Screenshots or console output
If applicable, add a screenshot (drag-and-drop an image), or console logs

mtrace-main-dmic.txt
dmesg-dmic-err.txt

@singalsu

@singalsu can you check this on main, any thoughts ?

@yongzhi1

@yongzhi1 can you confirm if stereo is working with your device, i.e. is issue only with 4 channels and 32bit data ? Thanks

Seems there's no data coming to host. Do you know if this is a regression?

The <err> dai_intel_dmic_nhlt: seen in mtrace from DMIC is not an error but wrong log function usage. I will create a PR to change it to LOG_INF().

@ujfalusi

Reverting this PR can help in this scenario:
#8084

@ujfalusi can you take a quick look if we are missing something obvious?

@yongzhi1

@yongzhi1 can you confirm if stereo is working with your device, i.e. is issue only with 4 channels and 32bit data ? Thanks

To confirm, stereo playback works fine, 2xch raw capture (with modified tplg from 4ch -> 2ch, with or without GOOGLE_RTC_AEC_SUPPORT) fails for same reason. AEC mock capture is also broken when tested with LL and on core0.

@abonislawski

@abonislawski @ujfalusi "-61" is -ENODATA and this is only returned in very specific cases, notably for echo reference stream when the associated playback is not running at all. So I wonder if we have a regression in pipeline-stream.c:pipeline_should_report_enodata_on_trigger() that triggers in this specific case?

@kv2019i

Based on the kernel log:
1st we move the pipelines to RUNNING state, which involves two steps:
PAUSED state

[   45.079369] sof-audio-pci-intel-mtl 0000:00:1f.3: trigger cmd: 1 state: 4
[   45.079375] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x13000003|0x1 [data size: 12]
[   45.079753] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x33000000|0x1
[   45.079781] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x13000003|0x1 [data size: 12]
[   45.079789] Message payload: 00000000: 00000002 00000000 00000001

Success
Followed by RUNNING state:

[   45.079793] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x13000004|0x1 [data size: 12]
[   45.090475] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x330000a4|0x1
[   45.090486] sof-audio-pci-intel-mtl 0000:00:1f.3: FW reported error: 164 - Unknown
[   45.090796] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc error for msg 0x13000004|0x1
[   45.090814] Message payload: 00000000: 00000002 00000000 00000001

This fails with -ENODATA as @kv2019i pointed out.
Since the pipelines failed to start the kernel is trying to stop the stream:
Set the pipelines to RESET state:

[   45.091007] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x13000002|0x1 [data size: 12]
[   45.091454] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x33000007|0x1
[   45.091467] sof-audio-pci-intel-mtl 0000:00:1f.3: FW reported error: 7 - Unsupported operation requested
[   45.091566] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc error for msg 0x13000002|0x1
[   45.091581] Message payload: 00000000: 00000002 00000001 00000000

This fails as the failed pipeline remained in PREPARED state, from which taking the RESET state is not allowed by the state machine.

I don't know why reverting #8084 helps, we should be failing in a same way?

@abonislawski

@abonislawski and note, if we revert 8084, we'll get a known issue back -> #8084 (comment)

I think the AEC is in the pipeline is somehow breaking the ENODATA logic. The ENODATA condition should not be returned for this pipeline, so something goes wrong. I don't see immediate connection to 8084, it might be the problem has been masked before (not confirmed yet though). I recreated a similar branched raw dmic pipeline tplg, and the bug does not occur with latest SOF main.

@abonislawski

@abonislawski and note, if we revert 8084, we'll get a known issue back -> #8084 (comment)

We want to only unlock AEC DP work on MTL branch with revert, on main it needs to be properly fixed. Hopefully your fix will work, @yongzhi1 please verify PR 8504

audio: pipeline: do not propagate pipeline triggers for IPC4

ipc4: handler: maintain IPC set_pipeline_state order

audio: pipeline: do not propagate pipeline triggers for IPC4

ipc4: handler: maintain IPC set_pipeline_state order

@kv2019i

Thanks @kv2019i @abonislawski @ujfalusi @singalsu @lgirdwood for the quick root-causing and action, really appreciated, close with fix.

ipc4: handler: maintain IPC set_pipeline_state order

@kv2019i

Sorry for reviving this old issue.

The fix for this issue (#8504) has an unfortunate side effect: starting multiple pipelines using the multi-pipeline-set-state IPC now takes 1 ms per pipeline, e.g., 5 ms for 5 pipelines. It would be nice if the multi-pipeline-set-state could start multiple pipelines as simultaneously as possible (that might be a requirement, not sure).

I looked through the firmware code that starts pipelines, and it seems the LL scheduler always executes pipelines in the order they were added to its task list. Pipelines are added to the list in the order they are specified in the multi-pipeline-set-state IPC, but also taking into account pipeline priorities. For the firmware, pipelines with a LOWER priority number are executed BEFORE pipelines with a HIGHER priority number.

For convenience, I've copy-pasted below the log from Kai's comment in the same thread above. Here, pipeline 0 has priority 1, and pipeline 1 has priority 0. So, for the firmware, pipeline 1 has higher execution priority and has to be executed before pipeline 0. And that's exactly what happened. However, Kai's comment says
# KV: here the unexpected thing happens, pipe-id 1 is triggered first (i.e. just opposite of what host asked)

# KV: setting to state 3 is as expected
[    0.140966] <inf> ipc: ipc_cmd: rx   : 0x13000003|0x1
[    0.140978] <err> ipc: ipc4_set_pipeline_state: ipc: prep on pipe-id 0
[    0.140991] <err> ipc: ipc4_set_pipeline_state: ipc: prep on pipe-id 1
[    0.141003] <wrn> ipc: ipc_pipeline_complete: ipc_pipeline_complete(): no scheduling component specified, use comp 131076
[    0.141008] <err> ipc: ipc4_set_pipeline_state: ipc: trig on pipe-id 0
[    0.141020] <err> ipc: ipc4_set_pipeline_state: ipc: trig on pipe-id 1
[    0.141025] <err> ipc: ipc4_set_pipeline_state: ipc: set_pipeline done
# KV: then we started setting to state 4
[    0.141430] <inf> ipc: ipc_cmd: rx   : 0x13000004|0x1
[    0.141435] <err> ipc: ipc4_set_pipeline_state: ipc: prep on pipe-id 0
[    0.141468] <inf> copier: copier_prepare: comp:0 0x10004 copier_prepare()
[    0.141485] <inf> eq_iir: eq_iir_prepare: comp:0 0x10 eq_iir_prepare(), source_format=2, sink_format=2
[    0.141488] <inf> eq_iir: eq_iir_init_coef: comp:0 0x10 eq_iir_init_coef(): 1 responses, 2 channels, stream 4 channels
[    0.141491] <inf> eq_iir: eq_iir_init_coef: comp:0 0x10 eq_iir_init_coef(), ch 0 is set to response 0
[    0.141495] <inf> eq_iir: eq_iir_init_coef: comp:0 0x10 eq_iir_init_coef(), ch 1 is set to response 0
[    0.141498] <inf> eq_iir: eq_iir_init_coef: comp:0 0x10 eq_iir_init_coef(), ch 2 is set to response 0
[    0.141501] <inf> eq_iir: eq_iir_init_coef: comp:0 0x10 eq_iir_init_coef(), ch 3 is set to response 0
[    0.141545] <inf> copier: copier_prepare: comp:0 0x4 copier_prepare()
[    0.141566] <err> ipc: ipc4_set_pipeline_state: ipc: prep on pipe-id 1
[    0.141608] <inf> copier: copier_prepare: comp:1 0x20004 copier_prepare()
# KV: pipe-id 0 has higher priority, so host put it first in the list of pipelines to trigger, FW maintains the order
[    0.141638] <err> ipc: ipc4_set_pipeline_state: ipc: trig on pipe-id 0
[    0.141643] <inf> pipe: pipeline_trigger: pipe:0 0x0 pipe trigger cmd 7
[    0.141650] <inf> ll_schedule: zephyr_ll_task_schedule_common: task add 0xa0107a80 0x20210U priority 1 flags 0x0
[    0.141666] <inf> ll_schedule: zephyr_domain_register: zephyr_domain_register domain->type 1 domain->clk 3 domain->ticks_per_ms 38400 period 1000
[    0.141670] <err> ipc: ipc4_set_pipeline_state: ipc: trig on pipe-id 1
# KV: here the unexpected thing happens, pipe-id 1 is triggered first (i.e. just opposite of what host asked)
[    0.141676] <inf> pipe: pipeline_trigger: pipe:1 0x0 pipe trigger cmd 7
[    0.141683] <inf> ll_schedule: zephyr_ll_task_schedule_common: task add 0xa0108e40 0x20210U priority 0 flags 0x0
[    0.141688] <err> ipc: ipc4_set_pipeline_state: ipc: set_pipeline done
[    0.141808] <inf> pipe: pipeline_trigger_run: pipe:1 0x0 execute trigger cmd 7 on pipe 1
...
# KV: execution fails to -ENODATA to as host order of pipeline triggers was not followed and this fails the enodata check
[    0.141860] <err> pipe: pipeline_trigger_run: pipe:1 0x0 pipeline_trigger_run(): ret = -61, host->comp.id = 131076, cmd = 7

So the question is:
Maybe the driver and firmware have different understandings of the priorities: for the driver, a higher priority number means higher execution priority, while for the firmware, it is the opposite. Is this the case? Could someone clarify how the driver treats pipeline priority numbers? Tagging: @kv2019i, @lyakh, @ranj063, @ujfalusi.

Just in case, the topology file contains such different pipeline priorities:
GOOGLE_AEC_HOST_PIPELINE_PRIORITY: 3
GOOGLE_AEC_PIPELINE_PRIORITY: 2
DMIC_PIPELINE_PRIORITY: 1
ECHO_REF_PIPELINE_PRIORITY: 0

If the problem lies in the different treatment of priority numbers in the driver and firmware, we can fix it and revert #8504 to get faster multi-pipeline-set-state execution.

Navigation Menu

Repository navigation

[BUG] DMIC capture failed to start #8481

6 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[BUG] DMIC capture failed to start #8481

Description

Activity

lgirdwood commented on Nov 17, 2023

lgirdwood commented on Nov 17, 2023

singalsu commented on Nov 17, 2023

singalsu commented on Nov 17, 2023

abonislawski commented on Nov 17, 2023

yongzhi1 commented on Nov 19, 2023

kv2019i commented on Nov 20, 2023

ujfalusi commented on Nov 20, 2023

kv2019i commented on Nov 20, 2023

kv2019i commented on Nov 20, 2023

6 remaining items

abonislawski commented on Nov 21, 2023

yongzhi1 commented on Nov 24, 2023

serhiy-katsyuba-intel commented on May 19, 2025

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions