Skip to content

[SoundWire] intel_resume: MCP_CONTROL_HW_RST not cleared at iteration (dev_err logs) #3012

Open
Open
[SoundWire] intel_resume: MCP_CONTROL_HW_RST not cleared at iteration (dev_err logs)#3012
Labels
ADLApplies to Alder Lake platformCMLApplies to Comet Lake platformP2Critical bugs or normal featuresSDWApplies to SoundWire bus for codec connectionTGLApplies to Tiger Lake platformbugSomething isn't workingsuspend resumeIssues related to suspend resume (e.g. rtcwake)

Description

@XiaoyunWu6666
XiaoyunWu6666
opened on Jun 25, 2021

description
sdw_cdns_clock_stop failed: MCP_CONTROL_HW_RST is not cleared when check-suspend-resume-50 on CML_SKU0983_SDW
happen in inner daily 4778 model=CML_SKU0983_SDW testcase=check-suspend-resume-50
[console log]

[ 4876.595463] kernel: soundwire_intel soundwire_intel.link.0: intel_resume: MCP_CONTROL_HW_RST is not cleared at iteration 0
……
[ 4876.608536] kernel: soundwire_intel soundwire_intel.link.0: intel_resume: MCP_CONTROL_HW_RST is not cleared at iteration 9
[ 4876.610117] kernel: soundwire_intel soundwire_intel.link.0: intel_resume failed: MCP_CONTROL_HW_RST is not cleared
[ 4880.767350] kernel: soundwire_intel soundwire_intel.link.0: sdw_cdns_clock_stop failed: MCP_CONTROL_HW_RST is not cleared

This is not a new issue, the dev_err logs above were added on purpose to help root-cause #2606 which has occurred randomly for the last 6 months, so far only on CML_RVP.

EDIT: later seen on TGL too.

Activity

  1. XiaoyunWu6666
    added
    NOT on topic/sof-devissue that does not happen on branch topic/sof-dev
    on Jun 25, 2021
  2. plbossart
    added
    CMLApplies to Comet Lake platform
    SDWApplies to SoundWire bus for codec connection
    and removed
    NOT on topic/sof-devissue that does not happen on branch topic/sof-dev
    on Jun 25, 2021
  3. plbossart
    changed the title [-]dev_err logs for root-cause[/-] [+][SoundWire] MCP_CONTROL_HW_RST not cleared dev_err logs[/+] on Jun 25, 2021

  4. fredoh9 commented on Jun 27, 2021

    @fredoh9
    fredoh9
    on Jun 27, 2021
    Collaborator

    Weekly stress test(test result 4894) found same problem with CML_RVP_SDW.

    ===========================>>
[ 9449.385740] kernel: soundwire_intel soundwire_intel.link.1: intel_resume_runtime BUS_RESET: MCP_CONTROL_HW_RST is not cleared at iteration 0
[ 9449.387130] kernel: soundwire_intel soundwire_intel.link.1: intel_resume_runtime BUS_RESET: MCP_CONTROL_HW_RST is not cleared at iteration 1
[ 9449.388635] kernel: soundwire_intel soundwire_intel.link.1: intel_resume_runtime BUS_RESET: MCP_CONTROL_HW_RST is not cleared at iteration 2
[ 9449.390185] kernel: soundwire_intel soundwire_intel.link.1: intel_resume_runtime BUS_RESET: MCP_CONTROL_HW_RST is not cleared at iteration 3
[ 9449.391714] kernel: soundwire_intel soundwire_intel.link.1: intel_resume_runtime BUS_RESET: MCP_CONTROL_HW_RST is not cleared at iteration 4
[ 9449.393157] kernel: soundwire_intel soundwire_intel.link.1: intel_resume_runtime BUS_RESET: MCP_CONTROL_HW_RST is not cleared at iteration 5
[ 9449.394707] kernel: soundwire_intel soundwire_intel.link.1: intel_resume_runtime BUS_RESET: MCP_CONTROL_HW_RST is not cleared at iteration 6
[ 9449.396156] kernel: soundwire_intel soundwire_intel.link.1: intel_resume_runtime BUS_RESET: MCP_CONTROL_HW_RST is not cleared at iteration 7
[ 9449.397253] kernel: soundwire_intel soundwire_intel.link.1: intel_resume_runtime BUS_RESET: MCP_CONTROL_HW_RST is not cleared at iteration 8
[ 9449.398875] kernel: soundwire_intel soundwire_intel.link.1: intel_resume_runtime BUS_RESET: MCP_CONTROL_HW_RST is not cleared at iteration 9
[ 9449.400241] kernel: soundwire_intel soundwire_intel.link.1: intel_resume_runtime BUS_RESET failed: MCP_CONTROL_HW_RST is not cleared
<<===========================

    dmesg_test_4894_cml.txt

  5. marc-hb
    changed the title [-][SoundWire] MCP_CONTROL_HW_RST not cleared dev_err logs[/-] [+][SoundWire] MCP_CONTROL_HW_RST not cleared at iteration (dev_err logs)[/+] on Jun 28, 2021
  6. marc-hb
    changed the title [-][SoundWire] MCP_CONTROL_HW_RST not cleared at iteration (dev_err logs)[/-] [+][SoundWire] intel_resume: MCP_CONTROL_HW_RST not cleared at iteration (dev_err logs)[/+] on Jun 28, 2021
  7. keqiaozhang
    added
    P3Low-impact bugs or features
    bugSomething isn't working
    on Jun 28, 2021

  8. plbossart commented on Jul 20, 2021

    @plbossart
    plbossart
    on Jul 20, 2021
    Member

    same warnings seen on Intel daily test 5356 (started on July 19).

    The next daily tests after that will rely on #3006 which was merged on July 20.

    If we see this error again then my theory of a clock stop issue was wrong... Let's see!

  9. plbossart commented on Jul 27, 2021

    @plbossart
    plbossart
    on Jul 27, 2021
    Member

    Seems my theory was wrong, this error still happens with the latest kernel, however this is the first time I managed to see it on Dell SKU 09c6

    dmesg.txt

  10. plbossart commented on Aug 20, 2021

    @plbossart
    plbossart
    on Aug 20, 2021
    Member

    Seen by @bardliao (c.f. #3098 (comment))

  11. plbossart commented on Oct 12, 2021

    @plbossart
    plbossart
    on Oct 12, 2021
    Member

    Issue seen in https://sof-ci.sh.intel.com/#/result/planresultdetail/7312?model=CML_SKU0983_SDW&testcase=multiple-pause-resume-25

  12. plbossart commented on Nov 30, 2021

    @plbossart
    plbossart
    on Nov 30, 2021
    Member

    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

  13. 21 remaining items

  14. plbossart commented on Apr 17, 2023

    @plbossart
    plbossart
    on Apr 17, 2023
    Member

    PR #4225 change the way the reset is done, so it's super interesting if we see this error after April 17, 2023 in our test results.

  15. plbossart
    closed this as completedon Feb 2, 2024
  16. plbossart
    reopened this on Mar 25, 2024

  17. plbossart commented on Mar 25, 2024

    @plbossart
    plbossart
    on Mar 25, 2024
    Member

    Seen again in Intel daily tests

    planresultdetail/39159?model=TGLU_SKU0A32_SDCA-ipc3&testcase=check-runtime-pm-status-15

    [ 3757.004272] kernel: soundwire_intel soundwire_intel.link.0: intel_start_bus_after_reset: MCP_CONTROL_HW_RST is not cleared at iteration 0
[ 3757.005828] kernel: soundwire_intel soundwire_intel.link.0: intel_start_bus_after_reset: MCP_CONTROL_HW_RST is not cleared at iteration 1
[ 3757.007261] kernel: soundwire_intel soundwire_intel.link.0: intel_start_bus_after_reset: MCP_CONTROL_HW_RST is not cleared at iteration 2
[ 3757.008806] kernel: soundwire_intel soundwire_intel.link.0: intel_start_bus_after_reset: MCP_CONTROL_HW_RST is not cleared at iteration 3
[ 3757.010309] kernel: soundwire_intel soundwire_intel.link.0: intel_start_bus_after_reset: MCP_CONTROL_HW_RST is not cleared at iteration 4
[ 3757.011854] kernel: soundwire_intel soundwire_intel.link.0: intel_start_bus_after_reset: MCP_CONTROL_HW_RST is not cleared at iteration 5
[ 3757.013310] kernel: soundwire_intel soundwire_intel.link.0: intel_start_bus_after_reset: MCP_CONTROL_HW_RST is not cleared at iteration 6
[ 3757.014856] kernel: soundwire_intel soundwire_intel.link.0: intel_start_bus_after_reset: MCP_CONTROL_HW_RST is not cleared at iteration 7
[ 3757.016357] kernel: soundwire_intel soundwire_intel.link.0: intel_start_bus_after_reset: MCP_CONTROL_HW_RST is not cleared at iteration 8
[ 3757.017927] kernel: soundwire_intel soundwire_intel.link.0: intel_start_bus_after_reset: MCP_CONTROL_HW_RST is not cleared at iteration 9
[ 3757.019355] kernel: soundwire_intel soundwire_intel.link.0: intel_start_bus_after_reset failed: MCP_CONTROL_HW_RST is not cleared
[ 3762.647781] kernel: soundwire_intel soundwire_intel.link.0: sdw_cdns_clock_stop failed: MCP_CONTROL_HW_RST is not cleared

  18. plbossart commented on Apr 4, 2024

    @plbossart
    plbossart
    on Apr 4, 2024
    Member

    the report from last week is due to other problems and fixed by #4896

  19. plbossart
    closed this as completedon Apr 4, 2024

  20. marc-hb commented on Jul 11, 2024

    @marc-hb
    marc-hb
    on Jul 11, 2024
    Collaborator

    Just seen again, re-opening to be on the safe side.

    https://sof-ci.01.org/softestpr/PR1220/build635/devicetest/index.html?model=CML_RVP_SDW-ipc3&testcase=check-runtime-pm-status

    Details 
    [  589.632188] kernel: snd_sof:ipc3_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x30130000: GLB_TPLG_MSG: PIPE_COMPLETE
[  589.632316] kernel: snd_sof:ipc3_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x40020000: GLB_PM_MSG: CTX_RESTORE
[  589.632398] kernel: soundwire_intel:intel_link_power_up: soundwire_intel soundwire_intel.link.1: powering up all links
[  589.632400] kernel: soundwire_intel:intel_link_power_up: soundwire_intel soundwire_intel.link.1: first link up, programming SYNCPRD
[  589.632584] kernel: soundwire_bus:sdw_modify_slave_status: rt700 sdw:0:1:025d:0700:00: initializing enumeration and init completion for Slave 6
[  589.632591] kernel: soundwire_cadence:cdns_init_clock_ctrl: soundwire_intel soundwire_intel.link.1: mclk 12000000 max 6000000 row 125 col 2
[  589.633471] kernel: soundwire_cadence:cdns_update_slave_status_work: soundwire_intel soundwire_intel.link.1: Slave status change: 0x1000000
[  589.633895] kernel: soundwire_cadence:cdns_update_slave_status_work: soundwire_intel soundwire_intel.link.1: Slave status change: 0x2
[  589.633911] kernel: soundwire_bus:sdw_handle_slave_status: soundwire sdw-master-0-1: Slave attached, programming device number
[  589.634078] kernel: soundwire_bus:sdw_extract_slave_id: soundwire sdw-master-0-1: SDW Slave Addr: 10025d070000
[  589.634080] kernel: soundwire_bus:sdw_extract_slave_id: soundwire sdw-master-0-1: SDW Slave class_id 0x00, mfg_id 0x025d, part_id 0x0700, unique_id 0x0, version 0x1
[  589.634083] kernel: soundwire_bus:sdw_assign_device_num: soundwire sdw-master-0-1: Slave already registered, reusing dev_num:6
[  589.634284] kernel: soundwire_cadence:cdns_fill_msg_resp: soundwire_intel soundwire_intel.link.1: Msg ignored for Slave 0
[  589.634287] kernel: soundwire_bus:sdw_program_device_num: soundwire sdw-master-0-1: No more devices to enumerate
[  589.634309] kernel: soundwire_cadence:cdns_update_slave_status_work: soundwire_intel soundwire_intel.link.1: Slave status change: 0x2000001
[  589.634322] kernel: soundwire_bus:sdw_modify_slave_status: rt700 sdw:0:1:025d:0700:00: signaling enumeration completion for Slave 6
[  589.634453] kernel: soundwire_intel soundwire_intel.link.1: intel_start_bus_after_reset: MCP_CONTROL_HW_RST is not cleared at iteration 0
[  589.634537] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] ff01 <= 0000
[  589.634676] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7520 85a0 <= 001a
[  589.634781] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7420 84a0 <= c003
[  589.634843] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3501 <= 0000
[  589.634906] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3721 <= 0040
[  589.634967] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3714 <= 0040
[  589.635031] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3c14 <= 0002
[  589.635092] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3712 <= 0020
[  589.635155] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3713 <= 0020
[  589.635218] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3719 <= 0020
[  589.635280] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4f12 <= 0091
[  589.635343] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4e12 <= 00d6
[  589.635405] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4d12 <= 0011
[  589.635468] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4c12 <= 0020
[  589.635535] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4f13 <= 0091
[  589.635593] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4e13 <= 00d6
[  589.635655] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4d13 <= 0011
[  589.635719] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4c13 <= 0021
[  589.635780] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4f19 <= 0002
[  589.635842] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4e19 <= 00a1
[  589.635905] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4d19 <= 0090
[  589.635967] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4c19 <= 0080
[  589.636030] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 371b <= 0040
[  589.636064] kernel: soundwire_intel soundwire_intel.link.1: intel_start_bus_after_reset: MCP_CONTROL_HW_RST is not cleared at iteration 1
[  589.636155] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 731b 839b <= 00b0
[  589.636259] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 839b 731b <= 0000
[  589.636468] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7520 85a0 7420 84a0 <= 004a 201b
[  589.636697] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7520 85a0 7420 84a0 <= 0045 5089
[  589.636884] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7520 85a0 7420 84a0 <= 006b 5064
[  589.637113] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7520 85a0 7420 84a0 <= 0048 d249
[  589.637176] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3501 <= 0003
[  589.637238] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3501 <= 0000
[  589.637301] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3819 <= 0082
[  589.637363] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3821 <= 0081
[  589.637426] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3855 <= 0083
[  589.637453] kernel: soundwire_intel soundwire_intel.link.1: intel_start_bus_after_reset: MCP_CONTROL_HW_RST is not cleared at iteration 2
[  589.637676] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7520 85a0 7420 84a0 <= 0010 2420
[  589.637886] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7520 85a0 7420 84a0 <= 0019 2e11
[  589.637888] kernel: snd_soc_rt700:rt700_jack_init: rt700 sdw:0:1:025d:0700:00: in rt700_jack_init enable
[  589.637947] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3501 <= 0003
[  589.637950] kernel: snd_soc_rt700:rt700_io_init: rt700 sdw:0:1:025d:0700:00: rt700_io_init hw_init complete
[  589.637952] kernel: soundwire_bus:sdw_handle_slave_status: rt700 sdw:0:1:025d:0700:00: signaling initialization completion for Slave 6
[  589.638963] kernel: soundwire_intel soundwire_intel.link.1: intel_start_bus_after_reset: MCP_CONTROL_HW_RST is not cleared at iteration 3
[  589.640453] kernel: soundwire_intel soundwire_intel.link.1: intel_start_bus_after_reset: MCP_CONTROL_HW_RST is not cleared at iteration 4
[  589.641962] kernel: soundwire_intel soundwire_intel.link.1: intel_start_bus_after_reset: MCP_CONTROL_HW_RST is not cleared at iteration 5
[  589.643453] kernel: soundwire_intel soundwire_intel.link.1: intel_start_bus_after_reset: MCP_CONTROL_HW_RST is not cleared at iteration 6
[  589.644962] kernel: soundwire_intel soundwire_intel.link.1: intel_start_bus_after_reset: MCP_CONTROL_HW_RST is not cleared at iteration 7
[  589.646449] kernel: soundwire_intel soundwire_intel.link.1: intel_start_bus_after_reset: MCP_CONTROL_HW_RST is not cleared at iteration 8
[  589.647958] kernel: soundwire_intel soundwire_intel.link.1: intel_start_bus_after_reset: MCP_CONTROL_HW_RST is not cleared at iteration 9
[  589.649452] kernel: soundwire_intel soundwire_intel.link.1: intel_start_bus_after_reset failed: MCP_CONTROL_HW_RST is not cleared
[  589.649511] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3121 <= 0000
[  589.649570] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3501 <= 0003
[  589.649633] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3602 <= 0000
[  589.649695] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3609 <= 0000
[  589.649757] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3712 <= 0020
[  589.649799] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3713 <= 0020
[  589.649840] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3714 <= 0040
[  589.649882] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3719 <= 0020
[  589.649924] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 371b <= 0040
[  589.649965] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3721 <= 0040
[  589.650007] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3819 <= 0082
[  589.650049] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3821 <= 0081
[  589.650090] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3855 <= 0083
[  589.650132] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 3c14 <= 0002
[  589.650174] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4c12 <= 0020
[  589.650215] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4c13 <= 0021
[  589.650257] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4c19 <= 0080
[  589.650299] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4d12 <= 0011
[  589.650340] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4d13 <= 0011
[  589.650382] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4d19 <= 0090
[  589.650424] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4e12 <= 00d6
[  589.650465] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4e13 <= 00d6
[  589.650507] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4e19 <= 00a1
[  589.650549] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4f12 <= 0091
[  589.650590] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4f13 <= 0091
[  589.650632] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 4f19 <= 0002
[  589.650715] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7203 8283 <= 0031
[  589.650799] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7209 8289 <= 0031
[  589.650882] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7302 8382 <= b050
[  589.650965] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7308 8388 <= 7080
[  589.651049] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7309 8389 <= 7080
[  589.651132] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7312 8392 <= 0000
[  589.651215] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7313 8393 <= 0000
[  589.651299] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7314 8394 <= b080
[  589.651382] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7319 8399 <= 7002
[  589.651465] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 731b 839b <= 00b0
[  589.651549] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7321 83a1 <= b080
[  589.651632] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7420 84a0 <= c003
[  589.651715] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7520 85a0 <= 001a
[  589.651799] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 8382 7302 <= b050
[  589.651882] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 8383 7303 <= 0057
[  589.651965] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 8388 7308 <= 7080
[  589.652049] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 8389 7309 <= 7080
[  589.652132] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 8393 7313 <= 0000
[  589.652216] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 8399 7319 <= 7002
[  589.652319] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 839b 731b <= 0000
[  589.652507] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7520 85a0 7420 84a0 <= 0010 2420
[  589.652694] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7520 85a0 7420 84a0 <= 0019 2e11
[  589.652861] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7520 85a0 7420 84a0 <= 001a 8003
[  589.653028] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7520 85a0 7420 84a0 <= 0045 5089
[  589.653194] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7520 85a0 7420 84a0 <= 0048 d249
[  589.653361] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7520 85a0 7420 84a0 <= 004a 201b
[  589.653550] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7520 85a0 7420 84a0 <= 006b 5064
[  589.653560] kernel: snd_sof:sof_pcm_open: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: open stream 0 dir 0
[  589.653562] kernel: snd_sof:sof_pcm_open: sof-audio-pci-intel-cnl 0000:00:1f.3: period min 192 max 16384 bytes
[  589.653564] kernel: snd_sof:sof_pcm_open: sof-audio-pci-intel-cnl 0000:00:1f.3: period count 2 max 16
[  589.653566] kernel: snd_sof:sof_pcm_open: sof-audio-pci-intel-cnl 0000:00:1f.3: buffer max 65536 bytes
[  589.653686] kernel: snd_soc_rt700:rt700_pcm_hw_params: rt700 sdw:0:1:025d:0700:00: rt700_pcm_hw_params rt700-aif1
[  589.653778] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7203 8283 <= 0031
[  589.653882] kernel: snd_soc_rt700:rt700_sdw_write: rt700 sdw:0:1:025d:0700:00: [rt700_sdw_write] 7209 8289 <= 0031
[  589.653890] kernel: snd_sof:ipc3_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[  589.654089] kernel: snd_sof:sof_pcm_hw_params: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: hw params stream 0 dir 0
[  589.654094] kernel: snd_sof_intel_hda_common:hda_dsp_stream_hw_params: sof-audio-pci-intel-cnl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x40000 successful
[  589.654110] kernel: snd_sof_intel_hda_common:hda_dsp_stream_hw_params: sof-audio-pci-intel-cnl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x40000 successful
[  589.654113] kernel: snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-cnl 0000:00:1f.3: period_bytes:0x4000
[  589.654115] kernel: snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-cnl 0000:00:1f.3: periods:4
[  589.654135] kernel: snd_sof:sof_ipc3_pcm_hw_params: sof-audio-pci-intel-cnl 0000:00:1f.3: stream_tag 1
[  589.654136] kernel: snd_sof:ipc3_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
  21. marc-hb
    reopened this on Jul 11, 2024

  22. marc-hb commented on Jul 11, 2024

    @marc-hb
    marc-hb
    on Jul 11, 2024 · Hidden as off-topic

  23. plbossart commented on Jul 15, 2024

    @plbossart
    plbossart
    on Jul 15, 2024
    Member

    Humm, just one report on CML_RVP_SDW in over 14 months, that is going to be tricky to solve....

  24. marc-hb commented on Jul 19, 2024

    @marc-hb
    marc-hb
    on Jul 19, 2024
    Collaborator

    Another one:

    https://sof-ci.01.org/linuxpr/PR5106/build4064/devicetest/index.html?model=CML_RVP_SDW-ipc3&testcase=multiple-pipeline-all

    It's coming back!

  25. plbossart commented on Jul 19, 2024

    @plbossart
    plbossart
    on Jul 19, 2024
    Member

    from https://sof-ci.01.org/softestpr/PR1220/build635/devicetest/index.html?model=CML_RVP_SDW-ipc3&testcase=check-runtime-pm-status, it looks like the first error started with the AMD machine driver rework

    8245a14

    I am not sure how this commit might have interfered with the low-level reset sequence on CML.

    @bardliao @marc-hb @ssavati can you double-check if this bisect information seems correct?

  26. plbossart commented on Jul 19, 2024

    @plbossart
    plbossart
    on Jul 19, 2024
    Member

    I tried to reproduce this manually on one of the test devices jf-cml-rvp-sdw-3. So far no luck. I am already at 150 cycles of multiple-pipelines + pm_runtime suspend/resume and nothing logged.

  27. plbossart commented on Jul 19, 2024

    @plbossart
    plbossart
    on Jul 19, 2024
    Member
    2024-07-19 16:31:07 UTC [INFO] Test Result: PASS!
iteration 1568 done

    I will stop the tests for now, unless we can reproduce it with a simple sequence we are not going to make progress or be able to bisect. Gah.

  28. marc-hb commented on Jul 19, 2024

    @marc-hb
    marc-hb
    on Jul 19, 2024
    Collaborator

    I am not sure how this commit might have interfered with the low-level reset sequence on CML.

    This always had a low reproduction rate, didn't it? So I doubt this can be bisected.

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

    ADLApplies to Alder Lake platformCMLApplies to Comet Lake platformP2Critical bugs or normal featuresSDWApplies to SoundWire bus for codec connectionTGLApplies to Tiger Lake platformbugSomething isn't workingsuspend resumeIssues related to suspend resume (e.g. rtcwake)

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions