You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
{{ message }}
Repository navigation
[BUG]ADLP firmware boot delayed by i915 issue (failure in check-sof-logger) #3042
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)
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 .
@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
changed the title [-][BUG]after check-sof-logger failed ADLP_RVP_HDA and ADLP_RVP_SDW cannot suspend after over 30seconds[/-][+][BUG] ADLP firmware boot delayed by i915 issue (failure in check-sof-logger)[/+]on Jul 14, 2021
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.
changed the title [-][BUG] ADLP firmware boot delayed by i915 issue (failure in check-sof-logger)[/-][+][BUG]check-sof-logger failed on ADLP_RVP_HDA and ADLP_RVP_SDW because of i915[/+]on Jul 15, 2021
changed the title [-][BUG]check-sof-logger failed on ADLP_RVP_HDA and ADLP_RVP_SDW because of i915[/-][+][BUG]ADLP firmware boot delayed by i915 issue (failure in check-sof-logger)[/+]on Jul 15, 2021
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 0fa9f7d 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 0fa9f7d 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)
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.
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?
@marc-hb The only indication that the probe workqueue finished is this dynamic debug log:
Thanks @plbossart. I took a closer look at the logs on sh-adlp-rvp-hda-02 and it does look indeed like an intermittent, display related issue. I'm copying two extracts from the logs below. The first one is from a successful firmware load, the second log is when the firmware failed to fully load and this happened only minutes later on the same system without any reboot in between.
Note there are other, earlier differences before the Completing SOF PCI probe message. Any insight?
Not sure in this particular case but in general this is just systemd monitoring /proc/asound/cards for dependency tracking purposes: other services may require a soundcard - like pulseaudio for instance. Even when disabling pulseaudio systemd still keeps track.
Very easy to see it for yourself:
sof-test/tools/kmod/sof_insert.sh
journalctl -f # in a different terminal
Jul 15 16:17:44 up2 systemd[1]: Reached target Sound Card.
sof-test/tools/kmod/sof_remove.sh
Jul 15 16:18:05 up2 systemd[527]: Stopped target Sound Card.
systemctl show sound.target
=> FragmentPath=/lib/systemd/system/sound.target
man systemd.special
sound.target
This target is started automatically as soon as a sound card is plugged in or becomes available at boot.
This may be used to pull in audio management daemons dynamically when audio hardware is found.
@kv2019i@marc-hb@libinyang
Adding new PCI IDs manually to i915.force_probe has been a regular step on any bleeding edge platform (otherwise i915 refuses to load on these)
On ADL DUTs , add following contents can help.
cat /etc/modprobe.d/i915.conf (if there is no i915.conf , add it by yourself)
options i915 force_probe=*
I have modified i915.conf on all ADLP_RVP_SDW ADLP_RVP_HDA DUTs, they all pass check-sof-logger testcase now.
@marc-hb Correct, on platforms where i915.force_probe is needed, driver probe will fail every time if the setting is not set.
It is possible the i915 negotiation failed earlier on some occasions (but i915 was still not functional), but definitely now with recent upstream merge and the force_probe setting, expecation is that at least i915 is no longer causing delays to the probe.
Thanks @kv2019i! @XiaoyunWu6666, at your leisure please remove the i915.force_probe you just added. I don't think they can cause any harm but they can cause confusion.
FYI, I changed that on ADLP_RVP_SDW and ADLP_RVP_HDA DUTs.
in inner daily-ADL 5495 5635 they worked well(ADL models have been added back to daily testplan)
Activity
XiaoyunWu6666 commentedon Jul 14, 2021
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 commentedon Jul 14, 2021
This bug should be related to the i915 probe taking a long time.
XiaoyunWu6666 commentedon Jul 14, 2021
@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
[-][BUG]after check-sof-logger failed ADLP_RVP_HDA and ADLP_RVP_SDW cannot suspend after over 30seconds[/-][+][BUG] ADLP firmware boot delayed by i915 issue (failure in check-sof-logger)[/+]marc-hb commentedon Jul 14, 2021
Thanks, I renamed this bug.
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.
check-sof-logger: SKIP on ADL because of i915 delay
[-][BUG] ADLP firmware boot delayed by i915 issue (failure in check-sof-logger)[/-][+][BUG]check-sof-logger failed on ADLP_RVP_HDA and ADLP_RVP_SDW because of i915[/+][-][BUG]check-sof-logger failed on ADLP_RVP_HDA and ADLP_RVP_SDW because of i915[/-][+][BUG]ADLP firmware boot delayed by i915 issue (failure in check-sof-logger)[/+]marc-hb commentedon Jul 15, 2021
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.comat with SOF commit 0fa9f7d and linux kernel commit 9b277b8In 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.comand onsh-adlp-rvp-sdw-03with the SAME SOF commit 0fa9f7d and kernel commit 9b277b8!In the same runs the test passed on other systems like
sh-adlp-rvp-nocodec-02(5285) orsh-adls-rvp-hda-04(5285) orsh-adls-rvp-hda-05(5288)EDIT: more failure examples listed in (unrelated) thesofproject/sof#4333
Does this happen randomly? Or is it happening only on certain units? @plbossart , Is it possible to see this long probe time in
journalctl -band if yes how?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.
plbossart commentedon Jul 15, 2021
@marc-hb The only indication that the probe workqueue finished is this dynamic debug log:
marc-hb commentedon Jul 15, 2021
Thanks @plbossart. I took a closer look at the logs on
sh-adlp-rvp-hda-02and it does look indeed like an intermittent, display related issue. I'm copying two extracts from the logs below. The first one is from a successful firmware load, the second log is when the firmware failed to fully load and this happened only minutes later on the same system without any reboot in between.Note there are other, earlier differences before the
Completing SOF PCI probemessage. Any insight?Successful log
Failing kernel log (no SOF log because the firmware didn't fully boot)
plbossart commentedon Jul 15, 2021
any idea what this is @marc-hb ?
This seems to come even before the card is created?
marc-hb commentedon Jul 15, 2021
Not sure in this particular case but in general this is just
systemdmonitoring/proc/asound/cardsfor dependency tracking purposes: other services may require a soundcard - like pulseaudio for instance. Even when disabling pulseaudiosystemdstill keeps track.Very easy to see it for yourself:
XiaoyunWu6666 commentedon Jul 23, 2021
@kv2019i @marc-hb @libinyang
Adding new PCI IDs manually to i915.force_probe has been a regular step on any bleeding edge platform (otherwise i915 refuses to load on these)
On ADL DUTs , add following contents can help.
cat /etc/modprobe.d/i915.conf (if there is no i915.conf , add it by yourself) options i915 force_probe=*I have modified i915.conf on all ADLP_RVP_SDW ADLP_RVP_HDA DUTs, they all pass check-sof-logger testcase now.
marc-hb commentedon Jul 23, 2021
@kv2019i can you confirm that i915.force_probe is helpful only when
i915REFUSES to load AT ALL? Not when it is flaky like here.This test was failing only from time to time, so maybe you just got lucky.
XiaoyunWu6666 commentedon Jul 23, 2021
Yes so I will track how they perform in daily tests
kv2019i commentedon Jul 23, 2021
@marc-hb Correct, on platforms where i915.force_probe is needed, driver probe will fail every time if the setting is not set.
It is possible the i915 negotiation failed earlier on some occasions (but i915 was still not functional), but definitely now with recent upstream merge and the force_probe setting, expecation is that at least i915 is no longer causing delays to the probe.
marc-hb commentedon Jul 23, 2021
Thanks @kv2019i!
@XiaoyunWu6666, at your leisure please remove the
i915.force_probeyou just added. I don't think they can cause any harm but they can cause confusion.kv2019i commentedon Jul 23, 2021
@marc-hb @XiaoyunWu6666 no, please keep the i915.force_probe . It's still needed. i915 won't load on new platforms without this option.
marc-hb commentedon Jul 23, 2021
@XiaoyunWu6666 changed it only on systems where i915 was already loading.
XiaoyunWu6666 commentedon Jul 27, 2021
FYI, I changed that on ADLP_RVP_SDW and ADLP_RVP_HDA DUTs.
in inner daily-ADL 5495 5635 they worked well(ADL models have been added back to daily testplan)
XiaoyunWu6666 commentedon Aug 2, 2021
HDMI1 worked well on ADLP_RVP_SDW (-Dhw:0,5 )and ADLP_RVP_HDA(-Dhw:0,3) with latest sof-dev and /etc/modprobe.d/i915.conf
hi , @kv2019i , shall we close this ? :) thanks
kv2019i commentedon Aug 5, 2021
Excellent @XiaoyunWu6666 , that sounds good now, let's close.