[BUG] DSP reset fails occasionally on ICL (rarer on other platorms?)

[kv2019i]

Describe the bug
The ICL FW boot fails occasionally. Example case here:
https://sof-ci.01.org/linuxpr/PR2413/build4423/devicetest/

The driver has had retry logic since the initial upstream version and there has been multiple patches to adjust the trace output so that error-level traces are emitted only if all FW boot attempts fail.

On ICL the first-boot failure seems to happen with fairly high reproduction rate. This could be a symptom of gaps in implementation of ICCMAX flow -> thesofproject/linux#2310 and https://github.com/thesofproject/sof/issues/1739 , but this has not been confirmed.

To Reproduce
Triggered by standard SOF CI test set
Also with this?

$ ./check-runtime-pm-status.sh -l 50

Reproduction Rate
Seen regularly in CI.

Expected behavior
First boot should be successful.

Impact
No end-user impact so thus P3.

Environment
Not specific to any recent version, but for example triggers on:
Linux: 7e7294e230bb .travis.yml: fixup options, cores and clang support, bump to focal
SOF: 35d9034 build-tools.sh: fix misnamed locals DO_BUILD_topology and

ICL HDA configuration with generic topology.

Screenshots or console output
https://sof-ci.01.org/linuxpr/PR2413/build4423/devicetest/

jf-icl-rvp-hda-4 kernel: [  611.727099] sof-audio-pci 0000:00:1f.3: periods:1
jf-icl-rvp-hda-4 kernel: [  611.727186] sof-audio-pci 0000:00:1f.3: Attempting iteration 0 of Core En/ROM load...
jf-icl-rvp-hda-4 kernel: [  611.727748] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f0f0f successful
jf-icl-rvp-hda-4 kernel: [  611.727765] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f0f0e successful
jf-icl-rvp-hda-4 kernel: [  611.727770] sof-audio-pci 0000:00:1f.3: unstall/run core: core_mask = 1
jf-icl-rvp-hda-4 kernel: [  611.727777] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 1 : core_mask 1
jf-icl-rvp-hda-4 kernel: [  611.728304] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x80000000 successful
jf-icl-rvp-hda-4 kernel: [  611.728312] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf010e0e successful
jf-icl-rvp-hda-4 kernel: [  612.028497] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x6000010 timedout
jf-icl-rvp-hda-4 kernel: [  612.028503] sof-audio-pci 0000:00:1f.3: unknown ROM status value 06000010
          -------------> [  612.028509] sof-audio-pci 0000:00:1f.3: status = 0x00000000 panic = 0x00000000
jf-icl-rvp-hda-4 kernel: [  612.028522] sof-audio-pci 0000:00:1f.3: extended rom status:  0x6000010 0x0 0x0 0x0 0x0 0x0 0x2001180 0x0
jf-icl-rvp-hda-4 kernel: [  612.028525] sof-audio-pci 0000:00:1f.3: unknown ROM status value 06000010
jf-icl-rvp-hda-4 kernel: [  612.028530] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1010f0f successful
jf-icl-rvp-hda-4 kernel: [  612.028535] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1000f0f successful
jf-icl-rvp-hda-4 kernel: [  612.028537] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask f
         ------------->  [  612.028539] sof-audio-pci 0000:00:1f.3: Attempting iteration 1 of Core En/ROM load...
jf-icl-rvp-hda-4 kernel: [  612.028934] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f0f0f successful

FYI @marc-hb @xiulipan @ranj063 @fredoh9 @plbossart

[marc-hb]

Just found thesofproject/sof-test#340 which seems like a (partial?) duplicate, @fredoh9 ?

Other related links shared by @xiulipan (thanks!)

thesofproject/linux#2382 ASoC: SOF: Intel: hda: reduce verbosity of boot error logs
thesofproject/sof-test@8797c85a6c64204 remove filter on initial boot issues

[kv2019i]

Did a stress test on one ICL RVP with a loop putting system to suspend, resuming, booting the DSP, and then repeating the sequence.

Bug occurence rate: 0.6% (out of 13000 iterations)

With no system suspend inbetween, I did not see boots fail.

Test script:

while true; do rtcwake -m mem -s 5 ; sleep 5 ; done

[marc-hb]

Thanks to @kv2019i 's indications here are some relevant pointers in the kernel source. As of version 5.8, the retry logic is located in hda_dsp_cl_boot_firmware() in sound/soc/sof/intel/hda-loader.c; this is the function logging some of the relevant messages. HDA_FW_BOOT_ATTEMPTS is currently 3

https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/sound/soc/sof/intel/hda-loader.c?h=v5.8

TIMEOUT_DEFAULT_BOOT_MS is 2000 yet the interval between Attempting iteration 0 and Attempting iteration 1 at https://sof-ci.01.org/linuxpr/PR2413/build4423/devicetest/ is exactly 300 ms, @kv2019i ?

[marc-hb]

From @aiChaoSONG

This also happened (internally) to CML_HEL_RT5682, check the failure on CML_HEL_RT5682 in https://sof-ci.sh.intel.com/#/result/planresultdetail/319

The message is exactly the same (even the PCI ID) and the timeout 300ms too. Only one retry. This has been much, much rarer than on ICL.

I just added cml to thesofproject/sof-test#372

[marc-hb]

@ranj063 thinks thesofproject/linux#2434 might be related.

[xiulipan]

Update the bug title as the issue is actually DSP reset before load FW to DSP.
Also add comments about other platforms, as the issue now can be seen on most platforms but with lower rate.