[BUG][Zephyr][TGL] PIPE_FREE IPC fails if pipe running on non-primary DSP core

[kv2019i]

Describe the bug
When pipeline is freed after playback, PIPE_FREE IPC fails if the pipeline is loaded to non-primary core on cAVS2.5 platform.

To Reproduce
Assign one pipeline and DAI to non-primary core. E.g. iDisp1. Reload SOF driver.

Reproduction Rate
100%

Expected behavior
Driver can tear down the pipeline successfully.

Impact
Driver not usable until pm-runtime kicks in, suspends and restarts the DSP.

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • Kernel: bed17efc810afcd0eb07c16b889de3cb9f32239c
   • SOF: ffff0b0
   • Zephyr: 6badb7f1b8ea896aa5259ca099f14a3c368cb5f7
   • Zephyr-SDK: 0.13
2. Name of the topology file
   • Topology: sof-hda-generic-2ch.tplg
3. Name of the platform(s) on which the bug is observed.
   • Platform: TGL

Screenshots or console output

[691968.620570] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x30020000: GLB_TPLG_MSG: COMP_FREE
[691968.620574] sof-audio-pci-intel-tgl 0000:00:1f.3: widget HDA0.OUT freed
[691968.620578] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30110000: GLB_TPLG_MSG: PIPE_FREE
[691969.128479] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x30110000 (msg/reply size: 12/12)
[691969.128490] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[691969.128499] sof-audio-pci-intel-tgl 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000001 rirb 00
[691969.128504] sof-audio-pci-intel-tgl 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[691969.128509] sof-audio-pci-intel-tgl 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[691969.128513] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[691969.128517] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[691969.128521] sof-audio-pci-intel-tgl 0000:00:1f.3: status: fw entered - code 00000005
[691969.128600] sof-audio-pci-intel-tgl 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[691969.128604] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[691969.128609] sof-audio-pci-intel-tgl 0000:00:1f.3: error: failed to free widget PIPELINE.1.HDA0.OUT
[691969.128618] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[691969.632483] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x40070000 (msg/reply size: 12/12)
[691969.632497] sof-audio-pci-intel-tgl 0000:00:1f.3: error: failed to disable target core: 1 for widget PIPELINE.1.HDA0.OUT
[691969.632504] sof-audio-pci-intel-tgl 0000:00:1f.3: widget PIPELINE.1.HDA0.OUT freed
[691969.632520] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_hw_free on 0000:00:1f.3: -110

[kv2019i]

FYI @andyross @lyakh We can close #4298 but this failure at streaming end stil lhappens. Probably some bookkeeping issue related to core disabling in the SOF wrapper.

[andyross]

I promised to leave notes but forgot:

I bumped into an edge case in initialization earlier too, where the IPC interrupt task added from the ISR was being run on the wrong CPU. This hits an error condition in ipc_platform_complete_cmd() where "cpu_is_me()" is false, which then exits early and never ACKs the host interrupt, causing a timeout in the linux driver.

This feels broadly similar. I dug around in the Zephyr task wrapper layer and didn't see anywhere where this handling was being enforced, but it's a big tree and I'm not an expert. Basically things work right now only via timing, relying on the IPC interrupt to be handled on core 0 (I think that's done by interrupt masking setup?) and for core 1 to be synchronously idle so it can run the task before core 0 gets back to it. If that breaks down, then I think this is likely to happen in a few different regimes.

I think, anyway. At least it's a reasonable hypothesis.

[lgirdwood]

@kv2019i is this the last IPC before we power off the core ? or is it the first after the stream stop ? The DW DMA LLI issue showed a similar behavior too.

[kv2019i]

This still happens. Last logs with sof-logger working on Zephyr build:
[ 11058504.716825] ( 130.625000) c1 hda-dma ..../intel/hda/hda-dma.c:937 INFO hda-dmac :7 -> remove
[ 11059868.570937] ( 1363.854126) c1 dma src/lib/dma.c:141 INFO dma_put(), dma = 0x9e05fbf0, sref = 0
[ 11060057.529263] ( 188.958328) c1 hda-dai 3.0 /drivers/intel/hda/hda.c:86 INFO hda_remove()
[ 11060291.695920] ( 234.166656) c1 dai src/lib/dai.c:188 INFO dai_put type 3 index 0 new sref 0
[ 11061010.445892] ( 718.750000) c0 ipc src/ipc/ipc3/handler.c:1576 INFO ipc: new cmd 0x30110000
[ 11061034.456307] ( 24.010416) c0 ipc src/ipc/ipc3/handler.c:1358 INFO ipc: comp 6 -> free
[ 11061258.675048] ( 224.218735) c1 ipc src/ipc/ipc3/handler.c:1358 INFO ipc: comp 6 -> free
error: in logger_read(), fread(..., /sys/kernel/debug/sof/trace) failed: Operation not permitted(-1)

[keyonjie]

#4994 might help, @kv2019i

[lyakh]

as you last tested this, was #4987 already in your tree? It got merged a couple of hours before your last post

[kv2019i]

Still fails with today's SOF main. I think this is something in the Zephyr wrapper as this happens with 100% production rate, so this is not a timing race or anything like that.

[5261581.452358] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30110000: GLB_TPLG_MSG: PIPE_FREE

[kv2019i]

Hmm, with latest SOF and Zephyr, PIPE_FREE no longer fails:

[   78.040658] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   78.040770] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   78.040773] sof-audio-pci-intel-tgl 0000:00:1f.3: Core 1 powered up
[   78.040786] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30100000: GLB_TPLG_MSG: PIPE_NEW
[   78.041869] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x30100000: GLB_TPLG_MSG: PIPE_NEW
[   78.041874] sof-audio-pci-intel-tgl 0000:00:1f.3: widget PIPELINE.7.HDA1.OUT setup complete
...
[  101.046859] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x30020000: GLB_TPLG_MSG: COMP_FREE
[  101.046877] sof-audio-pci-intel-tgl 0000:00:1f.3: widget PCM7P freed
[  101.046886] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30110000: GLB_TPLG_MSG: PIPE_FREE
[  101.047408] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x30110000: GLB_TPLG_MSG: PIPE_FREE

Interesting. But it works, so closing.