Skip to content

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

Closed
Closed
[BUG] DSP reset fails occasionally on ICL (rarer on other platorms?)#3395
Labels
ICLApplies to IceLake platformP3Low-impact bugs or featuresbugSomething isn't working as expectedwon't fixThis will not be worked on atm (e.g. a bug closed for lack of user request, hardware etc)

Description

@kv2019i
kv2019i
opened on Sep 8, 2020

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

Activity

  1. kv2019i
    added
    bugSomething isn't working as expected
    P3Low-impact bugs or features
    ICLApplies to IceLake platform
    on Sep 8, 2020

  2. marc-hb commented on Sep 9, 2020

    @marc-hb
    marc-hb
    on Sep 9, 2020
    Collaborator

    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

  3. kv2019i commented on Sep 9, 2020

    @kv2019i
    kv2019i
    on Sep 9, 2020
    CollaboratorAuthor

    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

  4. marc-hb commented on Sep 9, 2020

    @marc-hb
    marc-hb
    on Sep 9, 2020
    Collaborator

    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 ?

  5. marc-hb commented on Sep 10, 2020

    @marc-hb
    marc-hb
    on Sep 10, 2020
    Collaborator

    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

  6. marc-hb commented on Sep 23, 2020

    @marc-hb
    marc-hb
    on Sep 23, 2020
    Collaborator

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

  7. xiulipan
    changed the title [-][BUG] FW boot fails occasionally on ICL [/-] [+][BUG] FW boot fails occasionally on ICL(rare on other platorms)[/+] on Oct 21, 2020
  8. xiulipan
    changed the title [-][BUG] FW boot fails occasionally on ICL(rare on other platorms)[/-] [+][BUG] DSP reset fails occasionally on ICL(rare on other platorms)[/+] on Oct 21, 2020

  9. xiulipan commented on Oct 21, 2020

    @xiulipan
    xiulipan
    on Oct 21, 2020
    Contributor

    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.

  10. kv2019i commented on Nov 2, 2020

    @kv2019i
    kv2019i
    on Nov 2, 2020
    CollaboratorAuthor

    WIP version of ICCMAX flow implementation now available: thesofproject/linux#2548 This could potentially help with this bug.

  11. fredoh9 commented on Nov 2, 2020

    @fredoh9
    fredoh9
    on Nov 2, 2020
    Contributor

    Trying to reproducing without/with linux#2548. To test this, sof-test 61b077be should be reverted first, otherwise it ignores this error.

  12. fredoh9 commented on Nov 3, 2020

    @fredoh9
    fredoh9
    on Nov 3, 2020
    Contributor

    I'm still able to reproduce same problem with PR#2548. Hum... I doubled checked without the PR the problem is reproduced. This is NOT 100% but when I tried this command it's high chance to see the problem.

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

    without/with PR#2548, I'm seeing same error pattern.
    With the PR, powering up C3 may be too late?

    [ 1263.646048] sof-audio-pci 0000:00:1f.3: booting DSP firmware
...
**1st attempt
[ 1263.646371] sof-audio-pci 0000:00:1f.3: Attempting iteration 0 of Core En/ROM load...
[ 1263.646832] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f0f0f successful
[ 1263.646848] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f0f0e successful
[ 1263.646853] sof-audio-pci 0000:00:1f.3: unstall/run core: core_mask = 1
[ 1263.646860] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 1 : core_mask 1
[ 1263.647396] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x80000000 successful
[ 1263.647416] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf010e0e successful
[ 1263.947820] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x6000010 timedout
[ 1263.947831] sof-audio-pci 0000:00:1f.3: unknown ROM status value 06000010
[ 1263.947837] sof-audio-pci 0000:00:1f.3: status = 0x00000000 panic = 0x00000000
[ 1263.947853] sof-audio-pci 0000:00:1f.3: extended rom status:  0x6000010 0x0 0x0 0x0 0x0 0x0 0x2001182 0x0
[ 1263.947858] sof-audio-pci 0000:00:1f.3: unknown ROM status value 06000010
[ 1263.947866] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1010f0f successful
[ 1263.947874] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1000f0f successful
[ 1263.947876] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask f
**2nd attempt
[ 1263.947878] sof-audio-pci 0000:00:1f.3: Attempting iteration 1 of Core En/ROM load...
[ 1263.947896] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f0f0f successful
[ 1263.947912] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f0f0e successful
[ 1263.947915] sof-audio-pci 0000:00:1f.3: unstall/run core: core_mask = 1
[ 1263.947922] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 1 : core_mask 1
[ 1263.948469] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x80000000 successful
[ 1263.948477] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1010e0e successful
[ 1264.021805] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x5000001 successful
[ 1264.035803] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x5 successful
[ 1264.036347] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x140000 successful
[ 1264.036350] sof-audio-pci 0000:00:1f.3: Firmware download successful, booting...
[ 1264.046033] sof-audio-pci 0000:00:1f.3: ipc rx: 0x70000000: FW_READY
[ 1264.046039] sof-audio-pci 0000:00:1f.3: ipc: DSP is ready 0x70000000 offset 0x81000
[ 1264.046044] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x70000000: FW_READY
[ 1264.046074] sof-audio-pci 0000:00:1f.3: firmware boot complete
**power up C3 now and stall
[ 1264.046095] sof-audio-pci 0000:00:1f.3: core power up: icl_core_mask=8
[ 1264.046100] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x9090e0e successful
[ 1264.046105] sof-audio-pci 0000:00:1f.3: stall icl_core_mask = 8
[ 1264.046116] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000000 at  0
  13. marc-hb
    changed the title [-][BUG] DSP reset fails occasionally on ICL(rare on other platorms)[/-] [+][BUG] DSP reset fails occasionally on ICL (rarer on other platorms?)[/+] on Nov 4, 2020

  14. plbossart commented on Jun 10, 2021

    @plbossart
    plbossart
    on Jun 10, 2021
    Member

    @kv2019i @fredoh9 @marc-hb is this issue still occurring, if not can we close?

  15. kv2019i commented on Jun 10, 2021

    @kv2019i
    kv2019i
    on Jun 10, 2021
    CollaboratorAuthor

    I believe yes, we are hiding this with the multiple DSP boot retries. The boot-from-IMR code @keyonjie might actually help to this.
    That's another question whether we want to keep a bug open.

  16. marc-hb commented on Jun 10, 2021

    @marc-hb
    marc-hb
    on Jun 10, 2021
    Collaborator

    I think we could easily monitor this with a small, [DO NOT UPSTREAM] kernel patch that prints an error after the 1st or 2nd boot retry. Maybe not right now but once the daily results get better.

  17. fredoh9 commented on Jun 11, 2021

    @fredoh9
    fredoh9
    on Jun 11, 2021
    Contributor

    [DO NOT UPSTREAM] patch is up to maintainers, but I think there is no point to keep this issue OPEN as we are hiding this issue already and set P3 for this. I will close this if no one has objection in 24 hours.

  18. marc-hb
    added
    won't fixThis will not be worked on atm (e.g. a bug closed for lack of user request, hardware etc)
    on Jun 11, 2021
  19. fredoh9
    closed this as completedon Jun 14, 2021

  20. marc-hb commented on Oct 25, 2021

    @marc-hb
    marc-hb
    on Oct 25, 2021
    Collaborator

    It's back? #4873

  21. aiChaoSONG commented on Oct 26, 2021

    @aiChaoSONG
    aiChaoSONG
    on Oct 26, 2021
    Collaborator

    @marc-hb I tried to reproduced #4873, even with the commits that spotted #4873, I failed to reproduce it.

  22. marc-hb commented on Dec 6, 2021

    @marc-hb
    marc-hb
    on Dec 6, 2021
    Collaborator

    Important, November 2021 refactoring: thesofproject/linux#3250

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    ICLApplies to IceLake platformP3Low-impact bugs or featuresbugSomething isn't working as expectedwon't fixThis will not be worked on atm (e.g. a bug closed for lack of user request, hardware etc)

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions