[BUG][CML] IPC timed out when headset playback/capture in two-pipeline test

[aiChaoSONG]

Describe the bug
In one-capture and one-playback multi-pipeline test, if headset playback or capture (not both) present, an i/o error will be raised in both terminal. Then check dmesg output, you will see ipc timeout error. Note that single pipeline works normally.

To Reproduce
Method 1

1. do aplay through speaker with command: aplay -Dhw:0,5 -c2 -fdat -i -vvv ./longwave.wav in one terminal.
2. do arecord through headset with command: arecord -Dhw:0,0 -c2 -fdat -i -vvv ./headset.wav in another terminal.
3. both terminal will raise i/o error, check dmesg with command: dmesg, you should see ipc timeout error in the log.
   Note: You can try other combination, ensure one capture pipeline and one playback pipeline, and one of the pipelines is headset

Method 2

1. ensure ucm is correct and enable pulseaudio.
2. reboot with command sudo reboot.
3. after reboot, check dmesg with command: dmesg, you should see ipc timeout error in the log.

Reproduction Rate
100%

Expected behavior
two pipelines should work normally.

Environment

1. kernel: topic/sof-dev 136b7aaf
2. sof: master 2cbb1a02
3. topology: sof-cml-rt5682-max98357a.tplg

Error Message

[  185.573420] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[  185.573756] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[  185.573763] sof-audio-pci 0000:00:1f.3: pcm: stream dir 0, posn mailbox offset is 790604
[  185.574718] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 5 dir 0 cmd 1
[  185.575253] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x14001e successful
[  185.575259] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[  185.575534] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[  187.249887] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 1 cmd 0
[  187.250444] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20240000 successful
[  187.250457] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[  187.297869] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 5 dir 0 cmd 0
[  187.298532] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20140000 successful
[  187.753800] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60050000 size 12
[  187.753821] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  187.754085] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[  187.754109] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000001 rirb 00
[  187.754114] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[  187.754132] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[  187.754136] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[  187.754190] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 1
[  187.754198] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  188.257781] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[  188.257802] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  188.258067] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[  188.258091] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000001 rirb 00
[  188.258095] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[  188.258113] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[  188.258118] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[  188.258210] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[  188.258284] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 1
[  188.761779] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60050000 size 12
[  188.761797] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  188.762053] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[  188.762070] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000001 rirb 00
[  188.762073] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[  188.762089] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[  188.762092] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[  188.762129] sof-audio-pci 0000:00:1f.3: pcm: free stream 5 dir 0
[  188.762135] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  189.265796] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[  189.265816] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  189.266075] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[  189.266098] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000001 rirb 00
[  189.266102] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[  189.266117] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[  189.266121] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[  189.266210] sof-audio-pci 0000:00:1f.3: pcm: close stream 5 dir 0
[  191.299185] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20140000 successful
[  191.319032] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[  191.825781] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x40010000 size 76
[  191.825800] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  191.826060] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[  191.826083] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000000 rirb 00
[  191.826088] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[  191.826105] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[  191.826110] sof-audio-pci 0000:00:1f.3: ctx_save ipc error -110, proceeding with suspend
[  191.826159] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1010f0f successful
[  191.826173] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1000f0f successful
[  191.826181] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask f
[  191.826271] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000010 at  00000044

dmesg.log
sof-logger.log

[aiChaoSONG]

Test with today's kernel and topology(08/27) and yestoday's sof, this issue not present.

[aiChaoSONG]

commit 53529b10 introduces this bug. byt: fix simultaneous playback and capture

[lgirdwood]

@ClarexZhou @aiChaoSONG I see that the latest kernel fixes this issue, but we still have a FW crash. Can FW be recovered without a reboot ?
@tlauda given the absense of any errors in the FW log we could be stuck in DW DMA IRQ handler ?

[aiChaoSONG]

FW can automatically recover without a reboot, after recovery, aplay & arecord via single pipeline still works, but two-pipeline test still fail if only one pipeline being headset.

[aiChaoSONG]

can only reproduce this issue with headset capture + speaker playback or DMIC capture + headset playback now. Kernel: 6fc7eb3 SOF:573e0b17

[plbossart]

@wenqingfu did you really intend to close this issue? Doesn't look like it's fixed?