Skip to content

[BUG] [SDW] IO error in rt700_jack_detect_handler on CML_RVP_SDW #2943

Closed

Description

@XiaoyunWu6666

Describe the bug
Appeared on May 27 internal daily test , 4235 . in case check-suspend-resume-50
IO error in rt700_jack_detect_handler on CML_RVP_SDW

To Reproduce
TPLG=sof-cml-rt700-4ch.tplg ~/sof-test/test-case/check-suspend-resume.sh -l 50

Reproduction Rate
100%

Model
CML_RVP_SDW

Environment
Kernel Branch: topic/sof-dev
Kernel Commit: 6dca03a
SOF Branch: main
SOF Commit: d736888

Screenshots or console output
[console]

2021-06-01 03:03:18 UTC [INFO] ===== Round(1/50) =====
2021-06-01 03:03:18 UTC [COMMAND] Run the command: rtcwake -m mem -s 5
rtcwake: assuming RTC uses UTC ...
rtcwake: wakeup from "mem" using /dev/rtc0 at Tue Jun  1 03:03:24 2021
2021-06-01 03:03:26 UTC [COMMAND] sleep for 5
2021-06-01 03:03:31 UTC [INFO] Check for the kernel log status
declare -- cmd="journalctl_cmd --since=@1622516593"
2021-06-01 03:03:31 UTC [ERROR] Caught kernel log error
===========================>>
[  526.518862] kernel: IO error in rt700_jack_detect_handler, ret -16
<<===========================
2021-06-01 03:03:31 UTC [ERROR] Caught error in kernel log

Activity

  1. plbossart commented on May 27, 2021

    @plbossart
    Member
  2. plbossart commented on May 27, 2021

    @plbossart
    Member

    @XiaoyunWu6666 is this really 100% reproducible? If yes, can you try reverting PR #2941 to see if this makes the problem go away?

  3. added
    CMLApplies to Comet Lake platform
    SDWApplies to SoundWire bus for codec connection
    on May 27, 2021
  4. changed the title [-][BUG] IO error in rt700_jack_detect_handler on CML_RVP_SDW[/-] [+][BUG] [SDW] IO error in rt700_jack_detect_handler on CML_RVP_SDW[/+] on May 27, 2021
  5. plbossart commented on May 27, 2021

    @plbossart
    Member

    @shumingfan @bardliao I wonder if there is a potential for a race condition. The set_jack callback is invoked from the machine driver level, and I wonder if we should have a pm_runtime_get_sync()/ pm_runtime_put_autosuspend() protection when we try to initialize the jack. The current test on hw_init is a bit flaky IMHO. I also wonder if we should set the jack to NULL when we suspend, as done for a lot of cards.

  6. shumingfan commented on May 28, 2021

    @shumingfan

    @shumingfan @bardliao I wonder if there is a potential for a race condition. The set_jack callback is invoked from the machine driver level, and I wonder if we should have a pm_runtime_get_sync()/ pm_runtime_put_autosuspend() protection when we try to initialize the jack. The current test on hw_init is a bit flaky IMHO. I also wonder if we should set the jack to NULL when we suspend, as done for a lot of cards.

    @plbossart I also think it is possible that the unexpected interrupt happened after the codec suspended.
    @XiaoyunWu6666 Could you test with PR #2949 and turn on the debug log of the codec driver?
    If the test result still fails, please share the kernel log.

  7. XiaoyunWu6666 commented on May 31, 2021

    @XiaoyunWu6666
    Author

    @XiaoyunWu6666 Could you test with PR #2949 and turn on the debug log of the codec driver?
    If the test result still fails, please share the kernel log.

    Tested with PR #2949 and the test result still failed.
    The kernel log is as the attachment.
    dmesg.txt

  8. shumingfan commented on May 31, 2021

    @shumingfan

    Tested with PR #2949 and the test result still failed.
    The kernel log is as the attachment.
    dmesg.txt

    @XiaoyunWu6666 Could you enable the debug log of the codec driver and share the kernel log again?

  9. XiaoyunWu6666 commented on May 31, 2021

    @XiaoyunWu6666
    Author
  10. shumingfan commented on May 31, 2021

    @shumingfan

    @shumingfan Sure
    dmesg_with_codeclog.txt

    @bardliao @plbossart I checked this log. The system is so quick going to suspend from the resume state when the issue happened.

    [ 170.958907] rt700 sdw:1:025d:0700:00: in rt700_dev_resume jd enable
    [ 170.958987] rt700 sdw:1:025d:0700:00: [rt700_sdw_write] 3501 <= 0003
    [ 170.959013] soundwire_intel soundwire_intel.link.1: Slave status change: 0x40
    [ 170.959079] rt700 sdw:1:025d:0700:00: [rt700_sdw_write] 3501 <= 0000
    [ 170.959312] rt700 sdw:1:025d:0700:00: Slave impl defined interrupt
    [ 170.959316] rt700 sdw:1:025d:0700:00: rt700_interrupt_callback control_port_stat=4
    [ 170.959407] rt700 sdw:1:025d:0700:00: [rt700_sdw_write] 3819 <= 0000
    [ 170.959676] rt700 sdw:1:025d:0700:00: [rt700_sdw_write] 3821 <= 0000
    [ 170.959761] rt700 sdw:1:025d:0700:00: [rt700_sdw_write] 3855 <= 0000
    [ 170.959765] rt700 sdw:1:025d:0700:00: in rt700_dev_suspend jd disable
    [ 170.959934] rt700 sdw:1:025d:0700:00: [rt700_sdw_write] 3501 <= 0003
    [ 170.959954] soundwire_intel soundwire_intel.link.1: Slave status change: 0x20
    [ 170.960045] soundwire_intel soundwire_intel.link.1: intel_link_power_down: powering down all links
    [ 170.960081] soundwire_intel soundwire_intel.link.0: intel_suspend: pm_runtime status: suspended
    [ 170.960202] sof-audio-pci-intel-cnl 0000:00:1f.3: FW Poll Status: reg[0x80]=0x20140000 successful
    [ 170.960235] sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
    [ 170.960479] sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx succeeded: 0x40010000: GLB_PM_MSG: CTX_SAVE
    [ 170.960624] sof-audio-pci-intel-cnl 0000:00:1f.3: FW Poll Status: reg[0x4]=0x1010f0f successful
    [ 170.960656] sof-audio-pci-intel-cnl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf0f successful
    [ 170.960667] sof-audio-pci-intel-cnl 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask 1
    [ 170.960923] sof-audio-pci-intel-cnl 0000:00:1f.3: Debug PCIR: 00000010 at 00000044
    [ 170.960944] sof-audio-pci-intel-cnl 0000:00:1f.3: Turning i915 HDAC power 0
    [ 170.960949] sof-audio-pci-intel-cnl 0000:00:1f.3: Current DSP power state: D3
    [ 170.963055] e1000e: EEE TX LPI TIMER: 00000011
    [ 171.212657] IO error in rt700_jack_detect_handler, ret -16

    There is a Slave impl defined interrupt when the resume state, however, the system went to suspend state before the interrupt handler finishes.
    In the bus driver, the sdw_handle_slave_alerts function should wake up the codec driver and call the interrupt callback function.
    Could we add the pm_runtime_mark_last_busy in the front of sdw_handle_slave_alerts function that keeps the codec driver active?

  11. bardliao commented on Jun 1, 2021

    @bardliao
    Collaborator

    It is weird. We have pm_runtime_mark_last_busy(&slave->dev); in sdw_handle_slave_alerts. rt700_dev_suspend is supposed to triggered after 3 sec.

  12. 57 remaining items

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 Daily testsThis issue can be found in Intel internal daily testsP2Critical bugs or normal featuresSDWApplies to SoundWire bus for codec connectionbugSomething 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