[BUG]ADLP firmware boot delayed by i915 issue (failure in check-sof-logger)

[XiaoyunWu6666]

description
on ADLP_RVP_SDW and ADLP_RVP_HDA check-sof-logger failed with logger.error showing "error: Unable to open version file /sys/kernel/debug/sof/fw_version: No such file or directory" which may indicate slow/incomplete firmware boot.

And this failure leads to two FAIL/TIMEOUT in following 2 testcases , eg.
when check-alsabat-headset-playback

ALSA lib pcm_hw.c:1829:(_snd_pcm_hw_open) Invalid value for card
aplay: main:830: audio open error: No such device

when check playback all formats

2021-07-13 21:26:34 UTC [REMOTE_INFO] No SOF sound card found, exporting pipeline parameters from proc file system
error: Unable to open version file /sys/kernel/debug/sof/fw_version: No such file or directory

Something weird is long time to get suspend after ,check-sof-logger failed
after executing check-sof-logger , I got a 'fail' and then I tried 'cat /sys/bus/pci/devices/0000:00:1f.3/power/runtime_status' over and over again .
I got 'active' and then eventually got 'suspend' at the time which is actually 50 seconds after check-sof-logger failed. (You can see a 50 seconds' gap in the following picture)

I think after check-sof-logger testcase failed , there should be nothing using audio ,right ? So taking so much time to get suspend looks weird (However I am not quite sure whether this has something to do with 'no SOF sound card found' log in check-playback-all-formats testcase)

[XiaoyunWu6666]

BTW , reloading driver in check-sof-logger.sh is for getting logs from BYT ,right? For those platforms which can provide wanted logs, we can skip driver reloading maybe .

[libinyang]

This bug should be related to the i915 probe taking a long time.

[XiaoyunWu6666]

@marc-hb hi marc , let's discuss about it here .
Since check the non-stale logs as well as restarting the firmware is necessary , shall we give ADLP_RVP_SDW / ADLP_RVP_HDA more time to complete the firmware boot?
These two platforms can reboot firmware successfully , they just need more time

[marc-hb]

This bug should be related to the i915 probe taking a long time.

Thanks, I renamed this bug.

Since check the non-stale logs as well as restarting the firmware is necessary , shall we give ADLP_RVP_SDW / ADLP_RVP_HDA more time to complete the firmware boot?

I'm just going to temporarily skip the check-sof-logger test on these systems, it will be more visible with less risk to forget to restore the test later.

[marc-hb]

In 5288?model=ADLP_RVP_HDA&testcase=check-sof-logger the same test passed! This was on 2021-07-15 02:10:50 UTC and sh-adlp-rvp-hda-01.sh.intel.com at with SOF commit 0fa9f7d89202 and linux kernel commit 9b277b8

In the 9 minutes older 5285?model=ADLP_RVP_HDA&testcase=check-sof-logger it failed as described above and sh-adlp-rvp-hda-02.sh.intel.com and on sh-adlp-rvp-sdw-03 with the SAME SOF commit 0fa9f7d89202 and kernel commit 9b277b8!

In the same runs the test passed on other systems like sh-adlp-rvp-nocodec-02 (5285) or sh-adls-rvp-hda-04 (5285) or sh-adls-rvp-hda-05 (5288)

EDIT: more failure examples listed in (unrelated) thesofproject/sof#4333

This bug should be related to the i915 probe taking a long time.

Does this happen randomly? Or is it happening only on certain units? @plbossart , Is it possible to see this long probe time in journalctl -b and if yes how?

I'm just going to temporarily skip the check-sof-logger test on these systems, it will be more visible with less risk to forget to restore the test later.

I submitted this in thesofproject/sof-test#741 but I'm closing it because if this bug is intermittent then we first want to know how frequent it is.