[BUG][CI][SDW] xrun and trigger pause/release ipc error in multiple-pause-resume

[aiChaoSONG]

Describe the bug
The multiple-pause-resume will start several pipelines, and send space to every pipeline process to trigger pause/release simultaneously. Under this test case, we firstly got xrun in the firmware, and failed to recover, then trigger pause/release ipc error is reported.

Please check Linux CI report 1351

To Reproduce
run multiple-pause-resume.sh, usually can reproduce this issue in 5 sec.

Environment
Kernel Branch: topic/sof-dev
Kernel Commit: 36975c42
SOF Branch: master
SOF Commit: eaa9a55

2. Name of the topology file
   • Topology: {sof-tgl-sdw-max98373-rt5682-4ch.tplg}
3. Name of the platform(s) on which the bug is observed.
   • Platform: {chrome Volteer}

dmesg

kernel: [ 6390.722547] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
kernel: [ 6390.722740] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
kernel: [ 6390.722751] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20240000 successful
kernel: [ 6390.769305] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 3 dir 1 cmd 4
kernel: [ 6390.769828] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x2024001e successful
kernel: [ 6390.769832] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
kernel: [ 6390.770017] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
kernel: [ 6390.817396] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 2 dir 0 cmd 3
kernel: [ 6390.817403] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
kernel: [ 6390.817541] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
kernel: [ 6390.817551] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20140000 successful
kernel: [ 6390.919790] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 2 dir 0 cmd 4
kernel: [ 6390.920311] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x2014001e successful
kernel: [ 6390.920314] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
kernel: [ 6390.920519] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
kernel: [ 6390.928182] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
kernel: [ 6390.928196] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
kernel: [ 6391.428175] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
kernel: [ 6391.428203] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
kernel: [ 6391.454328] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 3 dir 1 cmd 3
kernel: [ 6391.454343] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
kernel: [ 6391.454537] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60060000 size 12
kernel: [ 6391.454556] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20240000 successful
kernel: [ 6391.454567] sof-audio-pci 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_trigger on 0000:00:1f.3: -22
kernel: [ 6391.454575]  echo: ASoC: trigger FE cmd: 3 failed: -22
kernel: [ 6391.454584] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 3 dir 1 cmd 4
kernel: [ 6391.454598] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x24001e successful
kernel: [ 6391.454607] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
kernel: [ 6391.454738] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60070000 size 12
kernel: [ 6391.454744] sof-audio-pci 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_trigger on 0000:00:1f.3: -22
kernel: [ 6391.454750]  echo: ASoC: trigger FE cmd: 4 failed: -22
kernel: [ 6391.455091] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 3 dir 1 cmd 3
kernel: [ 6391.455100] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
kernel: [ 6391.455419] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60060000 size 12
kernel: [ 6391.455440] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20240000 successful
kernel: [ 6391.455452] sof-audio-pci 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_trigger on 0000:00:1f.3: -22
kernel: [ 6391.455459]  echo: ASoC: trigger FE cmd: 3 failed: -22
kernel: [ 6391.455468] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 3 dir 1 cmd 4
kernel: [ 6391.455913] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x2024001e successful
kernel: [ 6391.455926] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
kernel: [ 6391.456098] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60070000 size 12
kernel: [ 6391.456109] sof-audio-pci 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_trigger on 0000:00:1f.3: -22
kernel: [ 6391.456116]  echo: ASoC: trigger FE cmd: 4 failed: -22
kernel: [ 6391.532260] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 2 dir 0 cmd 3
kernel: [ 6391.532267] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
kernel: [ 6391.532385] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60060000 size 12
kernel: [ 6391.532395] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x140000 successful
kernel: [ 6391.532398] sof-audio-pci 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_trigger on 0000:00:1f.3: -22
kernel: [ 6391.532400]  smart373-spk: ASoC: trigger FE cmd: 3 failed: -22
kernel: [ 6391.532402] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 2 dir 0 cmd 4
kernel: [ 6391.532863] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x14001e successful
kernel: [ 6391.532924] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
kernel: [ 6391.533033] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60070000 size 12
kernel: [ 6391.533035] sof-audio-pci 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_trigger on 0000:00:1f.3: -22
kernel: [ 6391.533037]  smart373-spk: ASoC: trigger FE cmd: 4 failed: -22
kernel: [ 6391.533123] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 2 dir 0 cmd 3
kernel: [ 6391.533125] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
kernel: [ 6391.533250] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60060000 size 12
kernel: [ 6391.533802] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x140000 successful
kernel: [ 6391.533842] sof-audio-pci 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_trigger on 0000:00:1f.3: -22
kernel: [ 6391.533844]  smart373-spk: ASoC: trigger FE cmd: 3 failed: -22
kernel: [ 6391.533852] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 2 dir 0 cmd 4
kernel: [ 6391.534401] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x14001e successful
kernel: [ 6391.534403] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
kernel: [ 6391.534508] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60070000 size 12
kernel: [ 6391.534510] sof-audio-pci 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_trigger on 0000:00:1f.3: -22
kernel: [ 6391.534511]  smart373-spk: ASoC: trigger FE cmd: 4 failed: -22
kernel: [ 6391.928238] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
kernel: [ 6391.928270] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
kernel: [ 6392.062353] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 3 dir 1 cmd 3
kernel: [ 6392.062368] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
kernel: [ 6392.062570] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60060000 size 12
kernel: [ 6392.062589] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20240000 successful
kernel: [ 6392.062601] sof-audio-pci 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_trigger on 0000:00:1f.3: -22
kernel: [ 6392.062609]  echo: ASoC: trigger FE cmd: 3 failed: -22
kernel: [ 6392.062618] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 3 dir 1 cmd 4
kernel: [ 6392.062631] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x24001e successful
kernel: [ 6392.062641] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
kernel: [ 6392.062798] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60070000 size 12
kernel: [ 6392.062805] sof-audio-pci 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_trigger on 0000:00:1f.3: -22
kernel: [ 6392.062811]  echo: ASoC: trigger FE cmd: 4 failed: -22
kernel: [ 6392.063103] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 3 dir 1 cmd 3
kernel: [ 6392.063113] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
kernel: [ 6392.063450] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60060000 size 12
kernel: [ 6392.063471] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20240000 successful
kernel: [ 6392.063489] sof-audio-pci 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_trigger on 0000:00:1f.3: -22
kernel: [ 6392.063496]  echo: ASoC: trigger FE cmd: 3 failed: -22
kernel: [ 6392.063505] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 3 dir 1 cmd 4
kernel: [ 6392.063920] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x2024001e successful
kernel: [ 6392.063933] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
kernel: [ 6392.064109] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60070000 size 12
kernel: [ 6392.064120] sof-audio-pci 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_trigger on 0000:00:1f.3: -22
kernel: [ 6392.064127]  echo: ASoC: trigger FE cmd: 4 failed: -22
kernel: [ 6392.142352] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 2 dir 0 cmd 3
kernel: [ 6392.142367] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
kernel: [ 6392.142558] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60060000 size 12
kernel: [ 6392.142580] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x140000 successful
kernel: [ 6392.142591] sof-audio-pci 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_trigger on 0000:00:1f.3: -22
kernel: [ 6392.142599]  smart373-spk: ASoC: trigger FE cmd: 3 failed: -22
kernel: [ 6392.142609] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 2 dir 0 cmd 4
kernel: [ 6392.142621] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x14001e successful
kernel: [ 6392.142633] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
kernel: [ 6392.142830] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60070000 size 12
kernel: [ 6392.142837] sof-audio-pci 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_trigger on 0000:00:1f.3: -22
kernel: [ 6392.142844]  smart373-spk: ASoC: trigger FE cmd: 4 failed: -22
kernel: [ 6392.142953] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 2 dir 0 cmd 3
kernel: [ 6392.142967] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
kernel: [ 6392.143461] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60060000 size 12
kernel: [ 6392.143483] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x140000 successful
kernel: [ 6392.143502] sof-audio-pci 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_trigger on 0000:00:1f.3: -22
kernel: [ 6392.143509]  smart373-spk: ASoC: trigger FE cmd: 3 failed: -22
kernel: [ 6392.143518] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 2 dir 0 cmd 4
kernel: [ 6392.143905] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x14001e successful
kernel: [ 6392.143916] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
kernel: [ 6392.144091] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60070000 size 12
kernel: [ 6392.144103] sof-audio-pci 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_trigger on 0000:00:1f.3: -22
kernel: [ 6392.144111]  smart373-spk: ASoC: trigger FE cmd: 4 failed: -22
kernel: [ 6392.428145] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
kernel: [ 6392.428176] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
kernel: [ 6392.570115] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 3 dir 1 cmd 0
kernel: [ 6392.570132] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
kernel: [ 6392.570411] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60050000 size 12
kernel: [ 6392.570433] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x240000 successful
kernel: [ 6392.570443] sof-audio-pci 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_trigger on 0000:00:1f.3: -22
kernel: [ 6392.570450]  echo: ASoC: trigger FE cmd: 0 failed: -22
kernel: [ 6392.570509] sof-audio-pci 0000:00:1f.3: pcm: free stream 3 dir 1
kernel: [ 6392.570518] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
kernel: [ 6392.570724] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
kernel: [ 6392.570809] sdw_deprepare_stream: subdevice #0-Capture: inconsistent state state 3
kernel: [ 6392.570839] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
kernel: [ 6392.571024] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
kernel: [ 6392.571231] sof-audio-pci 0000:00:1f.3: pcm: close stream 3 dir 1
kernel: [ 6392.650087] sdw_disable_stream: subdevice #0-Playback: inconsistent state state 4
kernel: [ 6392.650100]  SDW1-Playback: sdw_trigger trigger 0 failed: -22
kernel: [ 6392.650106]  SDW1-Playback: ASoC: error at snd_soc_link_trigger on SDW1-Playback: -22
kernel: [ 6392.650111]  SDW1-Playback: ASoC: trigger BE failed -22
kernel: [ 6392.650117]  smart373-spk: ASoC: trigger FE cmd: 0 failed: -22
kernel: [ 6392.650138] sof-audio-pci 0000:00:1f.3: pcm: free stream 2 dir 0
kernel: [ 6392.650150] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
kernel: [ 6392.650420] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
kernel: [ 6392.652381] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
kernel: [ 6392.652519] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
kernel: [ 6392.652703] sof-audio-pci 0000:00:1f.3: pcm: close stream 2 dir 0
kernel: [ 6392.928091] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
kernel: [ 6392.928104] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
kernel: [ 6393.428078] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
kernel: [ 6393.428087] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG

dmesg.txt
logger trace.txt
logger error trace.txt

[mengdonglin]

@slawblauciak This issue may have similar root cause as #3673

[aiChaoSONG]

The commit thesofproject/linux@2dbd71d increase the possibility to reproduce the issue. Before this, issue never reproduced in our CI.

[aiChaoSONG]

issue always happens when we are doing pause-resume simultaneously on smart-373-spk(PCM2P), and echo((PCM3C)) pipelines. Here is how they are connected:

arecord is always the one report arecord: do_pause:1545: pause push error: Invalid argument, I guess there is some issue with MUXDEMUX component.