[BUG]ipc timed out when pause-release while capturing on TGLH_RVP_NOCODEC_ZEPHYR

[XiaoyunWu6666]

Describe the bug
When checking pause-release while capturing , TGLH_RVP_NOCODEC_ZEPHYR ipc timed out when TRIG_RELEASE.
This happened happened twice in inner daily tests . One was 6422 , the other was 6472.
The 6422 was a daily test with Kernel PR: 3141 whille 6472 was today’s daily test ( alsothe first daily that after Kernel PR: 3141 got merged ).
So this issue is probably brought by Kernel PR: 3141 thesofproject/linux#3141 Merge/sound upstream 20210907

To Reproduce
TPLG=/lib/firmware/intel/sof-tplg/sof-tgl-h-nocodec.tplg ~/sof-test/test-case/check-pause-resume.sh -c 100 -m capture
The reproduction rate is 100%
Environment
Kernel Branch: topic/sof-dev
Kernel Commit: 85398998
storage: 85398998
SOF Branch: main
SOF Commit: 9a23191
storage: 9a23191
Topology: /lib/firmware/intel/sof-tplg/sof-tgl-h-nocodec.tplg
Platform: TGLH_RVP_NOCODEC_ZEPHYR

Screenshots or console output
[dmesg]

[ 2841.112477] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 11 dir 1 cmd 1
[ 2841.113081] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0xa0]=0x2024001e successful
[ 2841.113090] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 2841.114381] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 2841.365848] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 11 dir 1 cmd 3
[ 2841.365867] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[ 2841.366402] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[ 2841.366430] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0xa0]=0x20240000 successful
[ 2841.366507] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 11 dir 1 cmd 4
[ 2841.366521] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0xa0]=0x24001e successful
[ 2841.366531] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
[ 2841.868116] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x60070000 (msg/reply size: 12/12)
[ 2841.868136] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: preventing DSP entering D3 state to preserve context
[ 2841.868141] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 2841.868173] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000003 rirb 00
[ 2841.868181] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 2841.868223] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 2841.868229] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 2841.868235] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 2841.868274] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: status: fw entered - code 00000005
[ 2841.868367] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 2841.868373] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 2841.868382] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
[ 2841.868392] kernel:  DMIC16kHz: ASoC: trigger FE cmd: 4 failed: -110
[ 2841.868404] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 11 dir 1 cmd 3
[ 2841.868416] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[ 2842.372106] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x60060000 (msg/reply size: 12/12)
[ 2842.372157] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0xa0]=0x20240000 successful
[ 2842.372207] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
[ 2842.372217] kernel:  DMIC16kHz: ASoC: trigger FE cmd: 3 failed: -110

[fw stack dump]

# Core header:

# arch        00000000 # totalsize   00000000 # stackptr    00000000 # stackoffset 00000000
# configidhi  00000000 # configidlo  00000000 # numaregs    00000000

# CPU registers:

# exccause    00000000 # excvaddr    00000000 # ps          00000000
# epc1        00000000 # epc2        00000000 # epc3        00000000 # epc4        00000000
# epc5        00000000 # epc6        00000000 # epc7        00000000
# eps2        00000000 # eps3        00000000 # eps4        00000000 # eps5        00000000
# eps6        00000000 # eps7        00000000
# depc        00000000 # intenable   00000000 # interrupt   00000000 # sar         00000000
# debugcause  00000000
# windowbase  00000000 # windowstart 00000000
# excsave1    00000000
# ar0         00000000 # ar1         00000000 # ar2         00000000 # ar3         00000000
# ar4         00000000 # ar5         00000000 # ar6         00000000 # ar7         00000000
# ar8         00000000 # ar9         00000000 # ar10        00000000 # ar11        00000000
# ar12        00000000 # ar13        00000000 # ar14        00000000 # ar15        00000000
# ar16        00000000 # ar17        00000000 # ar18        00000000 # ar19        00000000
# ar20        00000000 # ar21        00000000 # ar22        00000000 # ar23        00000000
# ar24        00000000 # ar25        00000000 # ar26        00000000 # ar27        00000000
# ar28        00000000 # ar29        00000000 # ar30        00000000 # ar31        00000000
# ar32        00000000 # ar33        00000000 # ar34        00000000 # ar35        00000000
# ar36        00000000 # ar37        00000000 # ar38        00000000 # ar39        00000000
# ar40        00000000 # ar41        00000000 # ar42        00000000 # ar43        00000000
# ar44        00000000 # ar45        00000000 # ar46        00000000 # ar47        00000000
# ar48        00000000 # ar49        00000000 # ar50        00000000 # ar51        00000000
# ar52        00000000 # ar53        00000000 # ar54        00000000 # ar55        00000000
# ar56        00000000 # ar57        00000000 # ar58        00000000 # ar59        00000000
# ar60        00000000 # ar61        00000000 # ar62        00000000 # ar63        00000000


# windowbase: 0
#
# windowstart: b0

#      reg         a0         a1
#                  (return)   (sptr)
#      ---         --------   -------

# Stack dumped from 00000000 dwords num 406

# *EXCEPTION*

# exccause: IllegalInstructionCause: Illegal instruction

[XiaoyunWu6666]

@kv2019i hi kai , do you have any new comments for this issue ? Thanks.
I just found this issue 'gone' in daily tests, but I have no idea what happened because no fix PR is mentioned here.

I am double checking whether this issue did really go , or just become less likely to reproduce

[XiaoyunWu6666]

happened in inner daily 6601 again
on both APL_UP2_NOCODEC_ZEPHYR and TGLH_RVP_NOCODEC_ZEPHYR

[lgirdwood]

This looks like a deadlock or HW hang as stack is empty.

[kv2019i]

Tested with the recent changes:

• cached heap (merged)
• DMA stop patches, kernel+fw (in review)

The failure is still happening. One new observation is that when the failure occurs, there's is the following warning from ll-scheduler:

3493953085 90988361 us, 5 us:  dw_dma_pause(): dma 0 channel 0 pause
3493968700 90988768 us, 406 us:  dmic_stop(), dmic_active_fifos_mask = 0x2
3493995231 90989459 us, 690 us:  pipe trigger cmd 10
3493997123 90989508 us, 49 us:  task add 0x9e079000 0x1fffa180U priority 0 flags 0x0
3494000301 90989591 us, 82 us:  task 0x9e079000 (0x1fffa180U) already scheduled
3494010359 90989853 us, 261 us:  task complete 0x9e079000 0x1fffa180U

[kv2019i]

After #4898 is merged, there is still one failure left. This shows up as following kernel error:

[ 83.635645] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx error for 0x60070000 (msg/reply size: 12/12): -32
[ 83.635660] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -32
[ 83.635668] kernel: Port0: ASoC: trigger FE cmd: 4 failed: -32
[ 93.700503] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx error for 0x60070000 (msg/reply size: 12/12): -32
[ 93.700518] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -32
[ 93.700526] kernel: Port0: ASoC: trigger FE cmd: 4 failed: -32

This only occurs with the nocodec topology. -32 is -EPIPE and set in pipeline_task() in FW.

[XiaoyunWu6666]

FYI , multiple-pause-resume having lower possibility to encounter ipc timed out an fail in today's daily .
Before it almost happened every daily , but today it did not. I also run multiple pause resume case for merely APL zephyr and TGLH zephyr ,the results look rather good.

see inner test 7662 and 7652 .