Skip to content

[BUG] DMA trigger stop failed when suspend-resume during capturing on CML-SKU0983-SDW #4779

Closed
Closed
[BUG] DMA trigger stop failed when suspend-resume during capturing on CML-SKU0983-SDW#4779
Labels
CMLApplies to Comet Lake platformIntel Linux Daily testsThis issue can be found in internal Linux daily testsJSLApplies to Jasper Lake platformbugSomething isn't working as expectedsuspend-resumeIssues observed when doing system suspend and resume

Description

@1994lwz
1994lwz
opened on Sep 17, 2021

Describe the bug
DMA trigger stop failed when suspend-resume during capturing on CML-SKU0983-SDW

To Reproduce
Run command: "TPLG=/lib/firmware/intel/sof-tplg/sof-cml-rt711-rt1308-mono-rt715.tplg ~/sof-test/test-case/check-suspend-resume-with-audio.sh -l 5 -m capture"
The reproduction rate is 100%

Environment
Kernel Branch: topic/sof-dev
Kernel Commit: a7bb845e
SOF Branch: main
SOF Commit: 9fadef7
Platform: CML-SKU0983-SDW

Screenshots or console output
[dmesg & slogger]
dmesg.txt
slogger.txt

[console]

2021-09-16 23:12:22 UTC Sub-Test: [REMOTE_COMMAND] Run the command: rtcwake -m mem -s 5
rtcwake: assuming RTC uses UTC ...
rtcwake: wakeup from "mem" using /dev/rtc0 at Thu Sep 16 23:12:28 2021
2021-09-16 23:12:28 UTC Sub-Test: [REMOTE_COMMAND] sleep for 5
2021-09-16 23:12:33 UTC Sub-Test: [REMOTE_INFO] Check for the kernel log status
declare -- cmd="journalctl_cmd --since=@1631833937"
2021-09-16 23:12:34 UTC Sub-Test: [REMOTE_INFO] Check for the wakeup_count
2021-09-16 23:12:34 UTC Sub-Test: [REMOTE_INFO] ===== Round(4/5) =====
2021-09-16 23:12:34 UTC Sub-Test: [REMOTE_COMMAND] Run the command: rtcwake -m mem -s 5
rtcwake: assuming RTC uses UTC ...
rtcwake: wakeup from "mem" using /dev/rtc0 at Thu Sep 16 23:12:40 2021
2021-09-16 23:12:48 UTC Sub-Test: [REMOTE_COMMAND] sleep for 5
arecord: suspend:1716: suspend: prepare error: Connection timed out
2021-09-16 23:12:53 UTC Sub-Test: [REMOTE_INFO] Check for the kernel log status
declare -- cmd="journalctl_cmd --since=@1631833949"
2021-09-16 23:12:53 UTC [ERROR] Caught kernel log error
===========================>>
[ 6554.616307] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: hda_dsp_stream_trigger: cmd 5 on dai_link "Jack In" (Capture, stream_tag: 2): timeout on STREAM_SD_OFFSET read
[ 6563.817077] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: cl_copy_fw: timeout HDA_DSP_SRAM_REG_ROM_STATUS read
[ 6563.817746] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: hda_dsp_stream_trigger: cmd 0 on -- (Playback, stream_tag: 1): timeout on STREAM_SD_OFFSET read
[ 6563.817758] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: DMA trigger stop failed
[ 6563.817765] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 6563.817793] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: extended rom status:  0x5000001 0x0 0x0 0x0 0x0 0x0 0x1811102 0x0
[ 6563.817800] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 6563.817805] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: load fw failed ret: -110
[ 6563.817862] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: failed to start DSP
[ 6563.817869] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: failed to boot DSP firmware after resume -110
[ 6563.817875] kernel: PM: dpm_run_callback(): pci_pm_resume+0x0/0x80 returns -110
[ 6563.817906] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: PM: failed to resume async: error -110
[ 6563.819289] kernel: soundwire_intel soundwire_intel.link.0: Failed to power up link: -11
[ 6568.918927] kernel: rt711 sdw:0:025d:0711:00: Initialization not complete, timed out
[ 6568.918943] kernel: PM: dpm_run_callback(): acpi_subsys_resume+0x0/0x70 returns -110
[ 6568.918975] kernel: rt711 sdw:0:025d:0711:00: PM: failed to resume: error -110
[ 6568.920244] kernel: soundwire_intel soundwire_intel.link.1: Failed to power up link: -11
[ 6568.920603] kernel: soundwire_intel soundwire_intel.link.1: sdw_cdns_init failed: MCP_CONTROL_SW_RST is not cleared
[ 6568.920612] kernel: soundwire_intel soundwire_intel.link.1: sdw_cdns_init failed: MCP_CONTROL_CLK_STOP_CLR is not cleared
[ 6568.920620] kernel: soundwire_intel soundwire_intel.link.1: sdw_cdns_init failed: MCP_CONTROL_HW_RST is not cleared
[ 6568.922181] kernel: soundwire_intel soundwire_intel.link.1: intel_resume failed: MCP_CONTROL_SW_RST is not cleared
[ 6568.922187] kernel: soundwire_intel soundwire_intel.link.1: intel_resume failed: MCP_CONTROL_CLK_STOP_CLR is not cleared

[coredump log]

# Core header:

# arch        00030500 # totalsize   80000000 # stackptr    00000000 # stackoffset 00000000
# configidhi  00000000 # configidlo  00000000 # numaregs    00000000

# CPU registers:

# exccause    00000000 # excvaddr    00000000 # ps          00000000
# epc1        00000000 # epc2        00000000 # epc3        00000000 # epc4        00000000
# epc5        00000000 # epc6        00000000 # epc7        00000000
# eps2        00000000 # eps3        00000000 # eps4        00000000 # eps5        00000000
# eps6        00000000 # eps7        00000000
# depc        00000000 # intenable   00000000 # interrupt   00000000 # sar         00000000
# debugcause  00000000
# windowbase  00000000 # windowstart 00000000
# excsave1    00000000
# ar0         00000000 # ar1         00000000 # ar2         00000000 # ar3         00000000
# ar4         00000000 # ar5         00000000 # ar6         00000000 # ar7         00000000
# ar8         00000000 # ar9         00000000 # ar10        00000000 # ar11        00000000
# ar12        00000000 # ar13        00000000 # ar14        00000000 # ar15        00000000
# ar16        00000000 # ar17        00000000 # ar18        00000000 # ar19        00000000
# ar20        00000000 # ar21        00000000 # ar22        00000000 # ar23        00000000
# ar24        00000000 # ar25        00000000 # ar26        00000000 # ar27        00000000
# ar28        00000000 # ar29        00000000 # ar30        00000000 # ar31        00000000
# ar32        00000000 # ar33        00000000 # ar34        00000000 # ar35        00000000
# ar36        00000000 # ar37        00000001 # ar38        00000000 # ar39        00000000
# ar40        00000000 # ar41        00000001 # ar42        00000000 # ar43        00000000
# ar44        00000000 # ar45        00000001 # ar46        00000000 # ar47        00000000
# ar48        00000000 # ar49        00000001 # ar50        00000000 # ar51        00000000
# ar52        00000000 # ar53        00000001 # ar54        00000000 # ar55        00000000
# ar56        00000000 # ar57        00000001 # ar58        00000000 # ar59        00000000
# ar60        00000000 # ar61        00000001 # ar62        00000000 # ar63        00000000


# windowbase: 0
#
# windowstart: b0

#      reg         a0         a1
#                  (return)   (sptr)
#      ---         --------   -------

# Stack dumped from 00000000 dwords num 406

# *EXCEPTION*

# exccause: IllegalInstructionCause: Illegal instruction

Activity

  1. 1994lwz
    added
    bugSomething isn't working as expected
    CMLApplies to Comet Lake platform
    suspend-resumeIssues observed when doing system suspend and resume
    on Sep 17, 2021

  2. XiaoyunWu6666 commented on Sep 17, 2021

    @XiaoyunWu6666
    XiaoyunWu6666
    on Sep 17, 2021
    Contributor

    this happened in 6200 6292 6655
    Sorry for skipping them since 'MCP_CONTROL_HW_RST is not cleared at iteration' exists and I took them as thesofproject/linux#3012

  3. XiaoyunWu6666
    added
    Intel Linux Daily testsThis issue can be found in internal Linux daily tests
    on Sep 17, 2021

  4. plbossart commented on Sep 17, 2021

    @plbossart
    plbossart
    on Sep 17, 2021
    Member

    Sorry @XiaoyunWu6666, not following you. Are you saying the "timeout on STREAM_SD_OFFSET" and "MCP_CONTROL_HW_RST is not cleared at iteration N" errors are correlated somehow?

    @bardliao this would be interesting indeed.

  5. lgirdwood commented on Sep 17, 2021

    @lgirdwood
    lgirdwood
    on Sep 17, 2021
    Member

    @XiaoyunWu6666 @1994lwz can someone try reverting 9fadef7 and retest.
    @ranj063 and I have a suspicion this is related to

    1. DSP -> host DMA traffic volume prior to suspend (in which case multiple capture streams would also show this).
    2. Time between trace being disabled and DSP entering D3. More traffic may mean DMA takes longer to enter idle (and safe to enter D3).
      @keyonjie fyi.

  6. XiaoyunWu6666 commented on Sep 18, 2021

    @XiaoyunWu6666
    XiaoyunWu6666
    on Sep 18, 2021
    Contributor

    @lgirdwood @RanderWang @plbossart
    In today's inner daily 6686
    both CML_SKU0983_SDW and CML_SKU0955_HDA have this issue

    FYI , I tried to revert 9fadef7 and retest on CML_SKU0983_SDW (running suspend-resume-5-time during capture , for 100 rounds )
    so far so good . haven't reproduce the issue (noted that this issue isn't 100% reproducible so this is just a reference)

  7. ranj063 commented on Sep 18, 2021

    @ranj063
    ranj063
    on Sep 18, 2021
    Collaborator

    @1994lwz @XiaoyunWu6666 could you please check if thesofproject/linux#3166 helps fix the issue?

  8. 1994lwz commented on Sep 18, 2021

    @1994lwz
    1994lwz
    on Sep 18, 2021
    Author

    I tried to revert 9fadef7 and retest on CML_SKU0955_HDA (running suspend-resume-5-time during capture , for 50 rounds ), haven't reproduce the issue.

  9. XiaoyunWu6666 commented on Sep 18, 2021

    @XiaoyunWu6666
    XiaoyunWu6666
    on Sep 18, 2021
    Contributor

    @1994lwz @XiaoyunWu6666 could you please check if thesofproject/linux#3166 helps fix the issue?

    hi @ranj063 . I am afraid not , the same error appears again.
    kernel commit : 0620fb04b2d01
    sof commit ：509eef9c96b8
    PR ：3166
    @1994lwz will make a double confirm

    Also I run a test in CI with 3166 (see inner result test 6693) , it got a FAIL too

  10. 1994lwz commented on Sep 18, 2021

    @1994lwz
    1994lwz
    on Sep 18, 2021
    Author

    @1994lwz @XiaoyunWu6666 could you please check if thesofproject/linux#3166 helps fix the issue?

    hi @ranj063 . I am afraid not , the same error appears again.
    kernel commit : 0620fb04b2d01
    sof commit ：509eef9c96b8
    PR ：3166
    @1994lwz will make a double confirm

    the same error appears again on CML_SKU0955_HDA.

  11. ranj063
    added a commit that references this issue on Sep 18, 2021

    ASoC: SOF: Intel: hda: reset dma_sata during suspend

    e63a9a1

  12. ranj063 commented on Sep 18, 2021

    @ranj063
    ranj063
    on Sep 18, 2021
    Collaborator

    @XiaoyunWu6666 @1994lwz I have updated my PR thesofproject/linux#3166 to fix the issues during suspend-resume on capture on the CML Helios and the CML-HDA. Could you please double confirm?

    @plbossart I need your help for the CML SDW case.

  13. ranj063
    added a commit that references this issue on Sep 18, 2021

    ASoC: SOF: Intel: hda: reset dma_sata during suspend

    1328342

  14. 18 remaining items

  15. 1994lwz
    closed this as completedon Oct 14, 2021

  16. marc-hb commented on Oct 15, 2021

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

    thesofproject/linux#3167 is not merged yet and neither is #4558

  17. marc-hb
    reopened this on Oct 15, 2021

  18. 1994lwz commented on Oct 18, 2021

    @1994lwz
    1994lwz
    on Oct 18, 2021
    Author

    This issue is not reproduce anymore after merged the PR #4785, we will close it after the Linux PR thesofproject/linux#3167 and SOF PR #4793 be merged and verified.

  19. 1994lwz
    closed this as completedon Oct 18, 2021
  20. 1994lwz
    reopened this on Oct 18, 2021

  21. marc-hb commented on Nov 2, 2021

    @marc-hb
    marc-hb
    on Nov 2, 2021
    Collaborator

    #4793 was replaced by #4820 and #4844

  22. XiaoyunWu6666 commented on Nov 8, 2021

    @XiaoyunWu6666
    XiaoyunWu6666
    on Nov 8, 2021
    Contributor

    Since relevant PRs were already merged and havent happened in inner daily tests for nearly 50 days . So close it

    relevant PRs : thesofproject/linux#3167 #4820 and #4844

  23. XiaoyunWu6666
    closed this as completedon Nov 8, 2021

  24. keqiaozhang commented on Nov 30, 2021

    @keqiaozhang
    keqiaozhang
    on Nov 30, 2021
    Collaborator

    Observed this issue again when running suspend/resume stress testing on CML_SKU0983_SDW. Test ID:8054.

    [ 1592.161340] kernel: rt1308 sdw:1:025d:1308:00: sdw_modify_slave_status: signaling enumeration completion for Slave 1
[ 1592.292468] kernel: rt1308 sdw:1:025d:1308:00: rt1308_io_init m_btl_l=0xffe2, m_btl_r=0x8
[ 1592.292481] kernel: rt1308 sdw:1:025d:1308:00: rt1308_io_init c_btl_l=0x2ef, c_btl_r=0x10
[ 1592.301784] kernel: rt1308 sdw:1:025d:1308:00: rt1308_io_init hw_init complete
[ 1592.301790] kernel: rt1308 sdw:1:025d:1308:00: sdw_handle_slave_status: signaling initialization completion for Slave 1
[ 1592.314783] kernel: soundwire_intel soundwire_intel.link.2: intel_resume: MCP_CONTROL_HW_RST is not cleared at iteration 0
[ 1592.316316] kernel: soundwire_intel soundwire_intel.link.2: intel_resume: MCP_CONTROL_HW_RST is not cleared at iteration 1
[ 1592.317774] kernel: soundwire_intel soundwire_intel.link.2: intel_resume: MCP_CONTROL_HW_RST is not cleared at iteration 2
[ 1592.319304] kernel: soundwire_intel soundwire_intel.link.2: intel_resume: MCP_CONTROL_HW_RST is not cleared at iteration 3
[ 1592.320779] kernel: soundwire_intel soundwire_intel.link.2: intel_resume: MCP_CONTROL_HW_RST is not cleared at iteration 4
[ 1592.322308] kernel: soundwire_intel soundwire_intel.link.2: intel_resume: MCP_CONTROL_HW_RST is not cleared at iteration 5
[ 1592.323777] kernel: soundwire_intel soundwire_intel.link.2: intel_resume: MCP_CONTROL_HW_RST is not cleared at iteration 6
[ 1592.325361] kernel: soundwire_intel soundwire_intel.link.2: intel_resume: MCP_CONTROL_HW_RST is not cleared at iteration 7
[ 1592.326844] kernel: soundwire_intel soundwire_intel.link.2: intel_resume: MCP_CONTROL_HW_RST is not cleared at iteration 8
[ 1592.328468] kernel: soundwire_intel soundwire_intel.link.2: intel_resume: MCP_CONTROL_HW_RST is not cleared at iteration 9
[ 1592.329841] kernel: soundwire_intel soundwire_intel.link.2: intel_resume failed: MCP_CONTROL_HW_RST is not cleared
  25. keqiaozhang
    reopened this on Nov 30, 2021

  26. plbossart commented on Nov 30, 2021

    @plbossart
    plbossart
    on Nov 30, 2021
    Member

    wrong bug @keqiaozhang, this had nothing to do with DMA. This should be added in thesofproject/linux#3012

  27. plbossart
    closed this as completedon Nov 30, 2021
  28. marc-hb
    changed the title [-][BUG] DMA trigger stop failed when suspend-resume during capturing on CML-SKU0983-SDW[/-] [+][BUG] DMA trigger stop failed when suspend-resume during capturing on CML-SKU0983-SDW (MCP_CONTROL_HW_RST)[/+] on Feb 17, 2022
  29. marc-hb
    changed the title [-][BUG] DMA trigger stop failed when suspend-resume during capturing on CML-SKU0983-SDW (MCP_CONTROL_HW_RST)[/-] [+][BUG] DMA trigger stop failed when suspend-resume during capturing on CML-SKU0983-SDW[/+] on Feb 17, 2022
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

    CMLApplies to Comet Lake platformIntel Linux Daily testsThis issue can be found in internal Linux daily testsJSLApplies to Jasper Lake platformbugSomething isn't working as expectedsuspend-resumeIssues observed when doing system suspend and resume

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions