Skip to content

ADL - N : Resume failures with IPC causing suspend failures in stress tests #6475

Closed
Closed
ADL - N : Resume failures with IPC causing suspend failures in stress tests#6475
Assignees
abonislawskikv2019isathyap-chrome
Labels
ADLApplies to Alder Lake platformP1Blocker bugs or important features

Description

@sathyap-chrome
sathyap-chrome
opened on Oct 22, 2022

We have multiple reports of suspend failures due to audio driver failing to suspend. This is due to unsuccessful resume in previous cycle.

Sharing the 2 scenarios where the failure seems to be either same or similar.

Scenario thesofproject/linux#1: Seen in local testing when we tried to repro the thesofproject/linux#3915 with debug enabled and ran suspend stess test. Here we found ipc errors while the FW load itself resumed fine.
log slice :
pipeline_ipc_fail.txt

Scenario thesofproject/linux#2: Seen in ODM reporting with a dozing script ( variation of suspend_stress_test with additonal parameters)
suspend_stress_test --count 15 --suspend_max 30 --suspend_min 28 --wake_max 10 --wake_min 5 --suspend_time_margin_min -1 --suspend_time_margin_max 30 --fw_errors_fatal --premature_wake_fatal --late_wake_fatal --record_dmesg_dir /var/log/suspend

Logs :
kernel_log_20221017.txt

Errors seen in scenario thesofproject/linux#1
0000:00:1f.3: ipc tx error for 0x30030000 (msg/reply size: 16/12): -22
0000:00:1f.3: sof_ipc3_route_setup: route DMIC1.IN -> BUF11.0 failed
0000:00:1f.3: sof_ipc3_set_up_all_pipelines: route set up failed
0000:00:1f.3: Failed to restore pipeline after resume -22
0000:00:1f.3: PM: pci_pm_resume+0x0/0xef returned -22 after 114680 usecs
0000:00:1f.3: PM: failed to resume async: error -22

Errors seen in scenario thesofproject/linux#2
0000:00:1f.3: ipc tx error for 0x30130000 (msg/reply size: 12/12): -22
0000:00:1f.3: Failed to restore pipeline after resume -22
0000:00:1f.3: PM: pci_pm_resume+0x0/0xef returned -22 after 113515 usecs
0000:00:1f.3: PM: failed to resume async: error -22
0000:00:1f.3: PM: calling pci_pm_suspend+0x0/0x1da @ 5476, parent: pci0000:00
0000:00:1f.3: ipc tx error for 0x30020000 (msg/reply size: 12/12): -19
0000:00:1f.3: failed to free widget DMIC1.IN
0000:00:1f.3: failed to tear down paused pipelines

Activity

  1. sathyap-chrome
    assigned
    sathyap-chrome
    and
    kv2019i
    on Oct 22, 2022
  2. sathyap-chrome
    added
    ADLApplies to Alder Lake platform
    on Oct 22, 2022
  3. keqiaozhang
    added
    P1Blocker bugs or important features
    on Oct 24, 2022

  4. kv2019i commented on Oct 24, 2022

    @kv2019i
    kv2019i
    on Oct 24, 2022
    Collaborator

    Note on kernel version:

    • kernel is Linux 5.15.73 plus chromeos patches (other log had Linux 5.15.73-12723-g849d83202f61 )
    • FW is 2:0:0-1153b

  5. kv2019i commented on Oct 24, 2022

    @kv2019i
    kv2019i
    on Oct 24, 2022
    Collaborator

    The failures seem to be IPC timeouts with no reported DSP crash.

    In the first log (pipeline_ipc_fail.txt) the first error is timeout on TRIG_STOP for DMIC pipeline:

    2022-10-19T12:46:19.604815Z DEBUG kernel: [  153.584391] sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 99 dir 1 cmd 1
2022-10-19T12:46:19.606803Z DEBUG kernel: [  153.585471] sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0xa0]=0x2024001e successful
2022-10-19T12:46:19.606823Z DEBUG kernel: [  153.585489] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
2022-10-19T12:46:50.377658Z DEBUG kernel: [  184.365905] sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 99 dir 1 cmd 0
2022-10-19T12:46:50.377700Z DEBUG kernel: [  184.365935] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
2022-10-19T12:46:50.879621Z ERR kernel: [  184.867686] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x60050000 (msg/reply size: 12/12)

    The suspend is done with error on CTX_SAVE (as DSP in unresponsive), and there are further errors on next resume.

    In the other log (kernel_log_20221017.txt), SOF dynamic debug log are not enabled, so there is less to see, but the first error is reported on resume. So this looks a bit different.

    So far nothing wrong spotted in the kernel side logs (e.g. an invalid sequence).

  6. kv2019i commented on Oct 24, 2022

    @kv2019i
    kv2019i
    on Oct 24, 2022
    Collaborator

    Only similar bug (searched open and clossed, kernel + fw) is this one: #6185 .. but this happens with playback (so different direction) and a different use-case (multiple-pipeline-playback).

    Given the kernel side flow looks ok, moving to firmware side.

  7. kv2019i
    transferred this issue fromthesofproject/linuxon Oct 24, 2022

  8. lgirdwood commented on Oct 24, 2022

    @lgirdwood
    lgirdwood
    on Oct 24, 2022
    Member

    @sathyap-chrome do you have the FW log ? I would say we are broken at the resume time if we cant hookup a route to DMIC.

  9. lgirdwood commented on Oct 24, 2022

    @lgirdwood
    lgirdwood
    on Oct 24, 2022
    Member

    @mwasko fyi - pls assign.

  10. mwasko
    assigned
    abonislawski
    on Oct 24, 2022

  11. sathyap-chrome commented on Oct 25, 2022

    @sathyap-chrome
    sathyap-chrome
    on Oct 25, 2022
    ContributorAuthor

    @lgirdwood We dont have a clear reproduction scenario. FW trace wont help with suspend resume right ? ( since FW trace starts after DSP starts) - but will try how we can get it.

  12. lgirdwood commented on Oct 25, 2022

    @lgirdwood
    lgirdwood
    on Oct 25, 2022
    Member

    @lgirdwood We dont have a clear reproduction scenario. FW trace wont help with suspend resume right ? ( since FW trace starts after DSP starts) - but will try how we can get it.

    Sorry, I mean we need the log from part 1 - the resume that fails.

    0000:00:1f.3: ipc tx error for 0x30030000 (msg/reply size: 16/12): -22
0000:00:1f.3: sof_ipc3_route_setup: route DMIC1.IN -> BUF11.0 failed
0000:00:1f.3: sof_ipc3_set_up_all_pipelines: route set up failed
0000:00:1f.3: Failed to restore pipeline after resume -22
0000:00:1f.3: PM: pci_pm_resume+0x0/0xef returned -22 after 114680 usecs
0000:00:1f.3: PM: failed to resume async: error -22

    This may shed some light on the previous suspend (where we may not have shutdown cleanly).

  13. kv2019i commented on Oct 26, 2022

    @kv2019i
    kv2019i
    on Oct 26, 2022
    Collaborator

    @sathyap-chrome Would be good to have more samples of failing case logs. It would be curious to see if the problem is always:

    1. TRIG_STOP fail on DMIC before suspend (ADSP hw potentially in undefined state)
    2. suspend (ADSP powered off but not cleanly as we have CTX_SAVE error, hw potentially in undefined state)
    3. resume
    4. error in setting up path for dmic

    The HW power-cycling should of course help, but we've had cases in the past where e.g. the DMA hw has had issues that cannot be recovered by the above flow. The rootcause would then be the TRIG_STOP on DMIC.

  14. kv2019i commented on Oct 26, 2022

    @kv2019i
    kv2019i
    on Oct 26, 2022
    Collaborator

    I was now able to reproduce once locally on a "Nereid" device. FYI @abonislawski as you have the same hw.

    No FW logs yet, but below are kernel logs showing the IPC sequence of a working and non-working case. Reproduction is once per day for me now, so will spend some time looking at the logs and then planning what to try next. But FYI with others who have same hw, it is possible to trigger this bug with this setup.

    The sequence of IPC messages kernel sends seems valid. Here the failure is not with DMIC, but rather the first IPC sent to tear down the DSP pipelines for suspend (COMP_FREE for SSP1.IN). E.g. this line pair (not the timestamp showing 2sec, first line is last message to set up the DSP, second is start of suspend):

    2022-10-26T12:01:59.399869Z DEBUG kernel: [ 1811.337622] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40020000
2022-10-26T12:02:01.380028Z DEBUG kernel: [ 1813.465770] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30110000

    FAIL case

    2022-10-26T12:01:59.399860Z DEBUG kernel: [ 1811.336836] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T12:01:59.399863Z DEBUG kernel: [ 1811.337023] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T12:01:59.399865Z DEBUG kernel: [ 1811.337218] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T12:01:59.399868Z DEBUG kernel: [ 1811.337408] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T12:01:59.399869Z DEBUG kernel: [ 1811.337622] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40020000
2022-10-26T12:02:01.380028Z DEBUG kernel: [ 1813.465770] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30110000
2022-10-26T12:02:01.401225Z DEBUG kernel: [ 1813.479839] snd_sof:sof_widget_free: sof-audio-pci-intel-tgl 0000:00:1f.3: widget PIPELINE.29.SSP1.IN freed
2022-10-26T12:02:01.449898Z DEBUG kernel: [ 1813.513956] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30020000
2022-10-26T12:02:01.962621Z ERR kernel: [ 1814.043734] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x30020000 (msg/reply size: 12/12)
2022-10-26T12:02:09.613173Z DEBUG kernel: [ 1821.701262] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40010000
2022-10-26T12:02:10.762189Z INFO kernel: [ 1822.845534] PM: suspend entry (s2idle)
2022-10-26T12:02:49.675106Z DEBUG kernel: [ 1823.028655] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30100000
2022-10-26T12:02:49.675109Z DEBUG kernel: [ 1823.028925] snd_sof:sof_widget_setup: sof-audio-pci-intel-tgl 0000:00:1f.3: widget PIPELINE.29.SSP1.IN setup complete
2022-10-26T12:02:49.675110Z DEBUG kernel: [ 1823.028938] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30010000
2022-10-26T12:02:49.675112Z DEBUG kernel: [ 1823.029582] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x80010000
2022-10-26T12:02:49.675113Z DEBUG kernel: [ 1823.030063] snd_sof:sof_widget_setup: sof-audio-pci-intel-tgl 0000:00:1f.3: widget SSP1.IN setup complete

    OK case:

    2022-10-26T11:57:28.430481Z DEBUG kernel: [ 1540.333981] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T11:57:28.430484Z DEBUG kernel: [ 1540.334174] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T11:57:28.430518Z DEBUG kernel: [ 1540.334333] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T11:57:28.430520Z DEBUG kernel: [ 1540.334522] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T11:57:28.430523Z DEBUG kernel: [ 1540.334705] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T11:57:28.430525Z DEBUG kernel: [ 1540.334869] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T11:57:28.430528Z DEBUG kernel: [ 1540.335031] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T11:57:28.430531Z DEBUG kernel: [ 1540.335222] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T11:57:28.430533Z DEBUG kernel: [ 1540.335385] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T11:57:28.430536Z DEBUG kernel: [ 1540.335590] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T11:57:28.430538Z DEBUG kernel: [ 1540.335783] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T11:57:28.430539Z DEBUG kernel: [ 1540.335984] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40020000
2022-10-26T11:57:29.994080Z DEBUG kernel: [ 1542.070562] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30110000
2022-10-26T11:57:32.035186Z DEBUG kernel: [ 1544.120273] snd_sof:sof_widget_free: sof-audio-pci-intel-tgl 0000:00:1f.3: widget PIPELINE.29.SSP1.IN freed
2022-10-26T11:57:32.245961Z DEBUG kernel: [ 1544.323824] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30020000
2022-10-26T11:57:32.586207Z DEBUG kernel: [ 1544.662649] snd_sof:sof_widget_free: sof-audio-pci-intel-tgl 0000:00:1f.3: widget SSP1.IN freed
2022-10-26T11:57:32.630703Z DEBUG kernel: [ 1544.706783] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30110000
2022-10-26T11:57:32.676550Z DEBUG kernel: [ 1544.752087] snd_sof:sof_widget_free: sof-audio-pci-intel-tgl 0000:00:1f.3: widget PIPELINE.12.DMIC1.IN freed
2022-10-26T11:57:32.699443Z DEBUG kernel: [ 1544.774999] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30210000
2022-10-26T11:57:32.722328Z DEBUG kernel: [ 1544.797890] snd_sof:sof_widget_free: sof-audio-pci-intel-tgl 0000:00:1f.3: widget BUF12.2 freed
2022-10-26T11:57:32.744949Z DEBUG kernel: [ 1544.820776] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30210000
2022-10-26T11:57:32.791439Z DEBUG kernel: [ 1544.867276] snd_sof:sof_widget_free: sof-audio-pci-intel-tgl 0000:00:1f.3: widget BUF12.1 freed

  15. 40 remaining items

  16. ammarfaizi2
    added a commit that references this issue on Dec 2, 2022

    ASoC: SOF: ipc3-topology: use old pipeline teardown flow with SOF2.1 …

    82e4052
  17. zhijianli88
    added a commit that references this issue on Dec 6, 2022

    ASoC: SOF: ipc3-topology: use old pipeline teardown flow with SOF2.1 …

    4c9c7dc
  18. sboyanex
    added a commit that references this issue on Dec 12, 2022

    BACKPORT: FROMGIT: ASoC: SOF: ipc3-topology: use old pipeline teardow…

    626f4f3
  19. dineshXadireddi
    added a commit that references this issue on Dec 27, 2022

    BACKPORT: ASoC: SOF: ipc3-topology: use old pipeline teardown flow wi…

    e5b3394
  20. rutumberx
    added a commit that references this issue on Jan 5, 2023

    BACKPORT: FROMGIT: ASoC: SOF: ipc3-topology: use old pipeline teardow…

    06377c1
  21. Vamshigopal
    added a commit that references this issue on Jan 9, 2023

    BACKPORT: ASoC: SOF: ipc3-topology: use old pipeline teardown flow wi…

    a96157a
  22. Vamshigopal
    added a commit that references this issue on Jan 16, 2023

    BACKPORT: ASoC: SOF: ipc3-topology: use old pipeline teardown flow wi…

    b667378
  23. rutumberx
    added a commit that references this issue on Jan 19, 2023

    BACKPORT: ASoC: SOF: ipc3-topology: use old pipeline teardown flow wi…

    fc2e35b
  24. taskset
    added a commit that references this issue on Jan 30, 2023

    ASoC: SOF: ipc3-topology: use old pipeline teardown flow with SOF2.1 …

    cef9d6b
  25. akku1139
    added 5 commits that reference this issue on Dec 9, 2025

    FROMGIT: ASoC: SOF: ipc3-topology: use old pipeline teardown flow wit…

    6a275c0

    BACKPORT: ASoC: SOF: ipc3-topology: use old pipeline teardown flow wi…

    e01712e

    BACKPORT: ASoC: SOF: ipc3-topology: use old pipeline teardown flow wi…

    9a1a644

    BACKPORT: FROMGIT: ASoC: SOF: ipc3-topology: use old pipeline teardow…

    8927f45

    FROMGIT: ASoC: SOF: ipc3-topology: use old pipeline teardown flow wit…

    c9db5c6
  26. kernelorg-mirror-bot
    added a commit that references this issue on Sep 15, 2026

    FROMGIT: ASoC: SOF: ipc3-topology: use old pipeline teardown flow wit…

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

Metadata

Metadata

Assignees

Labels

ADLApplies to Alder Lake platformP1Blocker bugs or important features

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions