[BUG] TGL_RVP_NOCODEC_ZEPHYR ipc timed out when TRIG_STOP with multiple-pipeline test

[kv2019i]

Describe the bug
TGLH_RVP_NOCODEC_ZEPHYR ipc timed out when issuing GLB_STREAM_MSG: TRIG_STOP.

To Reproduce
TPLG=/lib/firmware/intel/sof-tplg/sof-tgl-h-nocodec.tplg ~/sof-test/test-case/multiple-pipeline.sh -f p -l 50

Reproduction Rate
100%

Environment
Kernel Branch: topic/sof-dev
Kernel Commit: eb55816743ecf7a68a94e0306d069c5e50783722
SOF Branch: main
SOF Commit: 7df3674
Topology:/lib/firmware/intel/sof-tplg/sof-tgl-h-nocodec.tplg
Platform: TGL_RVP_NOCODEC_ZEPHYR

Console output

[1374480.474916] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[1374480.475125] sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 3 dir 0 cmd 0
[1374480.982904] sof-audio-pci-intel-tgl 0000:00:1f.3: error: ipc timed out for 0x60050000 size 12
[1374480.982912] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[1374480.982921] sof-audio-pci-intel-tgl 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000781 rirb 00
[1374480.982923] sof-audio-pci-intel-tgl 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[1374480.982929] sof-audio-pci-intel-tgl 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[1374480.982931] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[1374480.982933] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[1374480.982936] sof-audio-pci-intel-tgl 0000:00:1f.3: status: fw entered - code 00000005
[1374480.983031] sof-audio-pci-intel-tgl 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[1374480.983033] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[1374480.983053] sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x20140000 successful

[XiaoyunWu6666]

in inner daily 6090, on TGLH_RVP_NOCODEC_ZEPHYR
multiple-pipeline-all-15: ipc timed out when issuing GLB_DAI_MSG: CONFIG(msg/reply size: 216/12)
check-runtime-pm-status-15: ipc timed out when issuing GLB_TPLG_MSG: PIPE_FREE(msg/reply size: 12/12)

[lgirdwood]

@kv2019i do you suspect this is related to allocator or something else ?

[kv2019i]

@lgirdwood This is something else. When DSP is overloaded (>100% workload), processing of TRIG_STOP sometimes fails. The DSP doesn't crash and subsequent actions succeed. The overload situation does occur because we moved the audio buffers back to uncached now.

[lgirdwood]

@kv2019i ok, lets wait for @lyakh triggering PR to merge. The 100% utilisation means we get in a state - do we get any data from the Zephyr LL scheduler ? i.e. is tick late or does work overrrun in logs ?

[ujfalusi]

@lgirdwood This is something else. When DSP is overloaded (>100% workload), processing of TRIG_STOP sometimes fails. The DSP doesn't crash and subsequent actions succeed. The overload situation does occur because we moved the audio buffers back to uncached now.

@kv2019i, the TRIG_STOP ipc message times out, Linux would think that the DSP is crashed (we get timeout on IPC message). I have pending new fw_state to be taken by Linux in this case and this would block further IPC communications until the DSP is rebooted.
But in this case the DSP is just too busy to respond. Should the IPC timeout be treated as a feature from now on and only the panic message from DSP should be treated as crash? I would think that the firmware can crash in a not clean way to be able to tell Linux that it crashed..

[lgirdwood]

@ujfalusi @kv2019i if FW is too busy to respond I would expect to see something in the logs to say this. e.g. LL should count number of times (per 1024 LL perf logging cycle) that there is little overhead for other work. This overhead could just be a subtraction of current time to next LL tick time and if it's less than limit we increment the count.