Skip to content

[BUG][MAX98373][SDW] "Initialization not complete, timed out" in suspend-resume test #2522

New issue
New issue
Closed
Closed
[BUG][MAX98373][SDW] "Initialization not complete, timed out" in suspend-resume test#2522
Assignees
bardliao
Labels
MAX98373Issues with Max98373 codecP3Low-impact bugs or featuresSDWApplies to SoundWire bus for codec connectionTGLApplies to Tiger Lake platformcodecCodec HW or driver restriction

Description

@aiChaoSONG
aiChaoSONG
opened on Oct 22, 2020

In daily test report 594 on TGL SDW Chromebook, below error observed from dmesg in suspend-resume test:

[   39.456408] max98373 sdw:1:19f:8373:0:3: Initialization not complete, timed out
[   39.456421] PM: Device sdw:1:19f:8373:0:3 failed to resume: error -110

Recipe:
Kernel: topic/sof-dev d0a335d
SOF : master e04610b
TPLG: sof-tgl-sdw-max98373-rt5682-4ch.tplg
Platform: TGL Chrome book proto-2

Activity

  1. aiChaoSONG commented on Oct 22, 2020

    @aiChaoSONG
    aiChaoSONG
    on Oct 22, 2020
    Author

    @bardliao Please help to confirm if this is real issue, if not, I will transfer the issue to sof-test

  2. bardliao
    self-assigned this
    on Oct 22, 2020

  3. bardliao commented on Oct 22, 2020

    @bardliao
    bardliao
    on Oct 22, 2020
    Collaborator
    [   38.453229] max98373 sdw:1:19f:8373:0:7: Parity error detected
[   38.454043] max98373 sdw:1:19f:8373:0:3: Parity error detected

    may not be a real problem

    kernel: [   39.456408] max98373 sdw:1:19f:8373:0:3: Initialization not complete, timed out
kernel: [   39.456418] PM: dpm_run_callback(): max98373_resume+0x0/0x70 [snd_soc_max98373_sdw] returns -110
kernel: [   39.456421] PM: Device sdw:1:19f:8373:0:3 failed to resume: error -110

    could be a problem. Does it happen consistently?

    kernel: [ 8742.635706] intel-sdw intel-sdw.0: Msg NACK received
kernel: [ 8742.635707] intel-sdw intel-sdw.0: Msg NACKed for Slave 1
kernel: [ 8742.635708] soundwire sdw-master-0: trf on Slave 1 failed:-5
kernel: [ 8742.635735] intel-sdw intel-sdw.0: Slave status change
kernel: [ 8742.635746] soundwire sdw-master-0: Slave attached, programming device number

    is an issue.
    Looks like driver is trying to read codec register before it is attached.

  4. bardliao commented on Oct 22, 2020

    @bardliao
    bardliao
    on Oct 22, 2020
    Collaborator

    @aiChaoSONG I just ran the check-suspend-resume.sh -l 50 test on the same device. But the test result was PASS and I didn't see any error in dmesg log. Could you retrigger the daily test? Or we can wait for the test result of tomorrow's daily test.

  5. plbossart commented on Oct 22, 2020

    @plbossart
    plbossart
    on Oct 22, 2020
    Member

    @bardliao looks like we have issues for both link1 and link0, so that would point to a general issue at the DSP level.

    I see that on this device we already have other problems with multiple-pipeline-capture-50

    I also see that in some cases we seem to recover

    kernel: [ 8742.634508] intel-sdw intel-sdw.0: intel_resume: pm_runtime status was suspended, forcing active
kernel: [ 8742.634511] intel-sdw intel-sdw.0: intel_link_power_up: powering up all links
kernel: [ 8742.634512] intel-sdw intel-sdw.0: intel_link_power_up: first link up, programming SYNCPRD
kernel: [ 8742.634797] rt5682 sdw:0:25d:5682:0: sdw_modify_slave_status: initializing completion for Slave 1
kernel: [ 8742.634931] intel-sdw intel-sdw.1: intel_resume: pm_runtime status was suspended, forcing active
kernel: [ 8742.635060] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
kernel: [ 8742.635072] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
kernel: [ 8742.635106] max98373 sdw:1:19f:8373:0:7: sdw_modify_slave_status: initializing completion for Slave 1
kernel: [ 8742.635107] max98373 sdw:1:19f:8373:0:3: sdw_modify_slave_status: initializing completion for Slave 2
kernel: [ 8742.635212] cdns_fill_msg_resp: 16 callbacks suppressed
kernel: [ 8742.635215] intel-sdw intel-sdw.0: Msg Ack not received
kernel: [ 8742.635217] cdns_fill_msg_resp: 6 callbacks suppressed
kernel: [ 8742.635218] intel-sdw intel-sdw.0: Msg ignored for Slave 1
kernel: [ 8742.635280] intel-sdw intel-sdw.0: Msg Ack not received
kernel: [ 8742.635280] intel-sdw intel-sdw.0: Msg ignored for Slave 1
kernel: [ 8742.635330] intel-sdw intel-sdw.0: Msg Ack not received
kernel: [ 8742.635330] intel-sdw intel-sdw.0: Msg ignored for Slave 1
kernel: [ 8742.635374] intel-sdw intel-sdw.0: Msg Ack not received
kernel: [ 8742.635374] intel-sdw intel-sdw.0: Msg ignored for Slave 1
kernel: [ 8742.635414] intel-sdw intel-sdw.0: Msg Ack not received
kernel: [ 8742.635415] intel-sdw intel-sdw.0: Msg ignored for Slave 1
kernel: [ 8742.635457] intel-sdw intel-sdw.0: Msg Ack not received
kernel: [ 8742.635458] intel-sdw intel-sdw.0: Msg ignored for Slave 1
kernel: [ 8742.635520] intel-sdw intel-sdw.0: Msg Ack not received
kernel: [ 8742.635520] intel-sdw intel-sdw.0: Msg ignored for Slave 1
kernel: [ 8742.635561] intel-sdw intel-sdw.0: Msg Ack not received
kernel: [ 8742.635561] intel-sdw intel-sdw.0: Msg ignored for Slave 1
kernel: [ 8742.635622] intel-sdw intel-sdw.0: Msg Ack not received
kernel: [ 8742.635622] intel-sdw intel-sdw.0: Msg ignored for Slave 1
kernel: [ 8742.635706] intel-sdw intel-sdw.0: Msg Ack not received
kernel: [ 8742.635706] intel-sdw intel-sdw.0: Msg NACK received
kernel: [ 8742.635707] intel-sdw intel-sdw.0: Msg NACKed for Slave 1
kernel: [ 8742.635708] soundwire sdw-master-0: trf on Slave 1 failed:-5
kernel: [ 8742.635735] intel-sdw intel-sdw.0: Slave status change
kernel: [ 8742.635746] soundwire sdw-master-0: Slave attached, programming device number
kernel: [ 8742.635769] intel-sdw intel-sdw.0: Msg ignored for Slave 1
kernel: [ 8742.635988] intel-sdw intel-sdw.1: Slave status change
kernel: [ 8742.635992] soundwire sdw-master-1: Slave attached, programming device number
kernel: [ 8742.636003] soundwire sdw-master-0: No more devices to enumerate
kernel: [ 8742.636028] intel-sdw intel-sdw.0: Slave status change
kernel: [ 8742.636156] soundwire sdw-master-1: SDW Slave Addr: 27019f837300
kernel: [ 8742.636160] soundwire sdw-master-1: SDW Slave class_id 0, part_id 8373, mfg_id 19f, unique_id 7, version 2
kernel: [ 8742.636161] soundwire sdw-master-1: Slave already registered, reusing dev_num:1
kernel: [ 8742.636173] intel-sdw intel-sdw.0: Slave status change
kernel: [ 8742.636192] soundwire sdw-master-0: Slave attached, programming device number
kernel: [ 8742.636403] soundwire sdw-master-1: SDW Slave Addr: 23019f837300
kernel: [ 8742.636403] soundwire sdw-master-1: SDW Slave class_id 0, part_id 8373, mfg_id 19f, unique_id 3, version 2
kernel: [ 8742.636404] soundwire sdw-master-1: Slave already registered, reusing dev_num:2
kernel: [ 8742.636469] soundwire sdw-master-0: SDW Slave Addr: 20025d568200
kernel: [ 8742.636470] soundwire sdw-master-0: SDW Slave class_id 0, part_id 5682, mfg_id 25d, unique_id 0, version 2
kernel: [ 8742.636471] soundwire sdw-master-0: Slave already registered, reusing dev_num:1
kernel: [ 8742.636632] soundwire sdw-master-1: No more devices to enumerate
kernel: [ 8742.636650] intel-sdw intel-sdw.1: Slave status change
kernel: [ 8742.636654] max98373 sdw:1:19f:8373:0:7: sdw_modify_slave_status: signaling completion for Slave 1
kernel: [ 8742.636780] max98373 sdw:1:19f:8373:0:3: sdw_modify_slave_status: signaling completion for Slave 2
kernel: [ 8742.636823] soundwire sdw-master-0: No more devices to enumerate
kernel: [ 8742.636849] intel-sdw intel-sdw.0: Slave status change
kernel: [ 8742.636852] rt5682 sdw:0:25d:5682:0: sdw_modify_slave_status: signaling completion for Slave 1
kernel: [ 8742.682769] intel-sdw intel-sdw.0: Slave status change
kernel: [ 8742.683154] intel-sdw intel-sdw.0: Slave status change
  6. mengdonglin
    added
    SDWApplies to SoundWire bus for codec connection
    TGLApplies to Tiger Lake platform
    on Oct 26, 2020

  7. keyonjie commented on Oct 26, 2020

    @keyonjie
    keyonjie
    on Oct 26, 2020

    @aiChaoSONG can you help to split and file issues:

    1. Parity error detected
    2. Initialization not complete, timed out
    3. Msg NACK received, trf on Slave 1 failed
  8. aiChaoSONG
    changed the title [-][BUG][CI][SDW] Parity error/codec resume failure/trf on Slave 1 failed in suspend-resume[/-] [+][BUG][CI][SDW] codec resume failure in suspend-resume test[/+] on Oct 26, 2020

  9. aiChaoSONG commented on Oct 26, 2020

    @aiChaoSONG
    aiChaoSONG
    on Oct 26, 2020
    Author

    can you help to split and file issues:

    Done, check #2533 and #2534

  10. keyonjie
    changed the title [-][BUG][CI][SDW] codec resume failure in suspend-resume test[/-] [+][BUG][CI][SDW] "Initialization not complete, timed out" in suspend-resume test[/+] on Nov 2, 2020
  11. keyonjie
    added
    P3Low-impact bugs or features
    codecCodec HW or driver restriction
    on Nov 2, 2020

  12. mengdonglin commented on Nov 2, 2020

    @mengdonglin
    mengdonglin
    on Nov 2, 2020

    Set to P3 as it's MAX98373 specific, will monitor reproduce rate on TGL Chrome EVT devices.

  13. plbossart commented on Nov 2, 2020

    @plbossart
    plbossart
    on Nov 2, 2020
    Member

    @bardliao @aiChaoSONG @mengdonglin in Intel tests #649 with kernel PR #2530 applied, we only see the parity issue. We'd need someone with access to the device to try to reproduce the errors and check if indeed we see an improvement with PR #2530 or if this is a random result.

  14. mengdonglin
    added
    MAX98373Issues with Max98373 codec
    on Nov 9, 2020

  15. aiChaoSONG commented on Nov 13, 2020

    @aiChaoSONG
    aiChaoSONG
    on Nov 13, 2020
    Author

    After #2530, This issue is not reproduced.

  16. aiChaoSONG
    closed this as completedon Nov 13, 2020
  17. WYL-12
    reopened this on Dec 14, 2020

  18. WYL-12 commented on Dec 14, 2020

    @WYL-12
    WYL-12
    on Dec 14, 2020

    This issue reproduce on 12-14-2020 daily report.
    Case detail:
    https://sof-ci.sh.intel.com/#/result/planresultdetail/1151?model=TGLU_RVP_SDW&testcase=check-suspend-resume-50

    2020-12-13 23:52:28 UTC [ERROR] Caught kernel log error
===========================>>
[ 8696.605729] kernel: rt711 sdw:0:25d:711:0: Initialization not complete, timed out
[ 8696.605744] kernel: PM: dpm_run_callback(): rt711_dev_resume+0x0/0x90 [snd_soc_rt711] returns -110
[ 8696.605749] kernel: PM: Device sdw:0:25d:711:0 failed to resume: error -110
<<===========================
2020-12-13 23:52:28 UTC Sub-Test: [REMOTE_ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
2020-12-13 23:52:28 UTC Sub-Test: [REMOTE_ERROR]  main()  @  /home/ubuntu/sof-test/tools/sof-kernel-log-check.sh
2020-12-13 23:52:28 UTC Sub-Test: [REMOTE_INFO] Test Result: FAIL!
2020-12-13 23:52:28 UTC [REMOTE_ERROR] Caught error in kernel log
2020-12-13 23:52:28 UTC [REMOTE_ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
2020-12-13 23:52:28 UTC [REMOTE_ERROR]  die()  @  /home/ubuntu/sof-test/test-case/../case-lib/lib.sh
2020-12-13 23:52:28 UTC [REMOTE_ERROR]  main()  @  /home/ubuntu/sof-test/test-case/check-suspend-resume.sh:86

    https://sof-ci.sh.intel.com/#/result/planresultdetail/1151?model=TGLU_SKU0A32_SDCA&testcase=check-suspend-resume-50

    2020-12-13 23:23:18 UTC [ERROR] Caught kernel log error
===========================>>
[ 6910.189762] kernel: rt711-sdca sdw:0:25d:711:1: Initialization not complete, timed out
[ 6910.189779] kernel: PM: dpm_run_callback(): rt711_sdca_dev_resume+0x0/0x80 [snd_soc_rt711_sdca] returns -110
[ 6910.189786] kernel: PM: Device sdw:0:25d:711:1 failed to resume: error -110
<<===========================
2020-12-13 23:23:18 UTC Sub-Test: [REMOTE_ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
2020-12-13 23:23:18 UTC Sub-Test: [REMOTE_ERROR]  main()  @  /home/ubuntu/sof-test/tools/sof-kernel-log-check.sh
2020-12-13 23:23:18 UTC Sub-Test: [REMOTE_INFO] Test Result: FAIL!
2020-12-13 23:23:18 UTC [REMOTE_ERROR] Caught error in kernel log
2020-12-13 23:23:18 UTC [REMOTE_ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
2020-12-13 23:23:18 UTC [REMOTE_ERROR]  die()  @  /home/ubuntu/sof-test/test-case/../case-lib/lib.sh
2020-12-13 23:23:18 UTC [REMOTE_ERROR]  main()  @  /home/ubuntu/sof-test/test-case/check-suspend-resume.sh:86

  19. bardliao commented on Dec 14, 2020

    @bardliao
    bardliao
    on Dec 14, 2020
    Collaborator

    @WYL-12 This issue is for max98373 and we trace rt711 Initialization not complete, timed out issue on #2599. Your log is rt711 so close this one.

  20. bardliao
    closed this as completedon Dec 14, 2020

  21. plbossart commented on Dec 14, 2020

    @plbossart
    plbossart
    on Dec 14, 2020
    Member

    @WYL-12 the correct bug report would be #2599

  22. aiChaoSONG
    changed the title [-][BUG][CI][SDW] "Initialization not complete, timed out" in suspend-resume test[/-] [+][BUG][MAX98373][SDW] "Initialization not complete, timed out" in suspend-resume test[/+] on Dec 15, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

MAX98373Issues with Max98373 codecP3Low-impact bugs or featuresSDWApplies to SoundWire bus for codec connectionTGLApplies to Tiger Lake platformcodecCodec HW or driver restriction

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions