Skip to content

[BUG][SDW]" IPC timed out for 0x60050000 size 12" occured when arecord0,4(RT715) after s3 and terminating arecord0,1(RT711) #1595

New issue
New issue
Closed
Closed
[BUG][SDW]" IPC timed out for 0x60050000 size 12" occured when arecord0,4(RT715) after s3 and terminating arecord0,1(RT711)#1595
Assignees
bardliao
Labels
CMLApplies to Comet Lake platformSDWApplies to SoundWire bus for codec connectionbugSomething isn't workingsuspend resumeIssues related to suspend resume (e.g. rtcwake)

Description

@sinahuang
sinahuang
opened on Dec 5, 2019

Describe the bug
Firstly disable master and sof runtime PM status via add sof-pci-debug=1 and sdw_md_flags=0x01000001.
When wake up from s3 with headset playback/capture(RT711), terminate it and start to arecord0,4(RT715), it will occur "IPC timed out for 0x60050000 size 12". Need reboot to recover.

Note: enable master and sof runtime PM status, issue cannot be reproduced.

To Reproduce
1.Disable master and sof runtime PM status via add sof-pci-debug=1 and sdw_md_flags=0x01000001, then reboot to make it work.
2.Arecord0,1 via "arecord -Dhw:0,1 -r 48000 -c2 -fs16_le 1.wav -vvv -i"
3.Enter s3 via "sudo rtcwake -m mem -s 10"
4.Terminate arecord after waking up from s3, then start to arecord0,4(RT715)

Reproduce rate
5/5

Expected result
Arecord0,4 normally, no error occured.

Actual result
"IPC timed out for 0x60050000 size 12" occured when arecord0,4(RT715) after s3 and terminating arecord0,1(RT711)

dmesg error log 
[  190.985434] rt715 sdw:3:25d:715:0: [rt715_sdw_write] 3501 <= 0003
[  190.985438] rt715 sdw:3:25d:715:0: [rt715_sdw_write] 3501 <= 0000
[  190.985457] rt715 sdw:3:25d:715:0: [rt715_sdw_write] 3607 <= 0010
[  190.985463] rt715 sdw:3:25d:715:0: [rt715_sdw_write] 3627 <= 0010
[  190.985489]  SDW3-Capture: ASoC: BE SDW3-Capture event 1 dir 1
[  190.985683]  SDW3-Capture: ASoC: trigger BE SDW3-Capture cmd 1
[  190.985685] intel-sdw sdw-master-3: intel_trigger: SDW3 Pin2: start
[  190.985705] rt715 sdw:3:25d:715:0: [rt715_sdw_write] 00e0 <= 0001
[  190.985708] rt715 sdw:3:25d:715:0: [rt715_sdw_write] 00f0 <= 0001
[  190.985710] sdw_enable_stream: SDW3 Pin2-Capture: done
[  190.985712] intel-sdw sdw-master-3: intel_trigger: SDW3 Pin2: done
[  190.985715]  DMIC: ASoC: post trigger FE DMIC cmd 1
[  190.985717] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 4 dir 1 cmd 1
[  190.986231] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x2024001e successful
[  190.986233] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[  190.986449] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[  191.489674]  DMIC: ASoC: pre trigger FE DMIC cmd 0
[  191.489682] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 4 dir 1 cmd 0
[  191.489688] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[  191.553489]  Headphone: ASoC: pre trigger FE Headphone cmd 0
[  191.553495] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 0
[  191.993433] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60050000 size 12
[  191.993440] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[  191.993450] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  191.993601] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[  191.993615] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000083 rirb 00
[  191.993618] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[  191.993638] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x000000                      03
[  191.993641] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[  191.993706] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  191.993724] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  191.993727] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[  191.994226] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20240000 successful
[  191.994234]  DMIC: ASoC: trigger FE cmd: 0 failed: -110
[  191.994252]  DMIC: ASoC: hw_free FE DMIC
[  191.994258] sof-audio-pci 0000:00:1f.3: pcm: free stream 4 dir 1
[  192.497425] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60050000 size 12
[  192.497431] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[  192.497437] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  192.497583] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[  192.497595] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000081 rirb 00
[  192.497599] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[  192.497608] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x000000                      03
[  192.497611] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[  192.497668] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  192.498185] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20140000 successful
[  192.498192]  Headphone: ASoC: trigger FE cmd: 0 failed: -110
[  193.001443] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[  193.001450] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[  193.001456] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  193.001602] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[  193.001616] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000001 rirb 00
[  193.001619] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[  193.001628] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x000000                      03
[  193.001631] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[  193.001681] intel-sdw sdw-master-3: intel_hw_free: SDW3 Pin2: start
[  193.001685] sdw_deprepare_stream: SDW3 Pin2-Capture: inconsistent state state 3
[  193.001688] sdw_deprepare_stream: SDW3 Pin2-Capture: done
[  193.001691] intel-sdw sdw-master-3: sdw_deprepare_stream: failed -22
[  193.001694]  SDW3-Capture: ASoC: close BE SDW3-Capture
[  193.001697] intel-sdw sdw-master-3: intel_shutdown: SDW3 Pin2: start
[  193.001701] intel-sdw sdw-master-3: intel_shutdown: SDW3 Pin2: done
[  193.001738]  DMIC: ASoC: close FE DMIC
[  193.001742] sof-audio-pci 0000:00:1f.3: pcm: close stream 4 dir 1
[  193.001878] rt715 sdw:3:25d:715:0: [rt715_sdw_write] 3607 <= 0000
[  193.001884] rt715 sdw:3:25d:715:0: [rt715_sdw_write] 3627 <= 0000
[  193.001950] rt715 sdw:3:25d:715:0: [rt715_sdw_write] 3501 <= 0003
[  193.002011]  SDW3-Capture: ASoC: BE SDW3-Capture event 2 dir 1
[  193.002044]  DMIC: ASoC: BE capture disconnect check for SDW3-Capture
[  193.002046]  DMIC: freed DSP capture path DMIC <- SDW3-Capture
[  193.002112]  Headphone: ASoC: hw_free FE Headphone
[  193.002120] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 0
[  193.002125] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  193.505433] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[  193.505440] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[  193.505448] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  193.505600] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[  193.505614] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000001 rirb 00
[  193.505617] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[  193.505634] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x000000                      03
[  193.505637] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[  193.505702] intel-sdw sdw-master-0: intel_hw_free: SDW0 Pin2: start
[  193.505706] sdw_deprepare_stream: SDW0 Pin2-Playback: inconsistent state state 3
[  193.505709] sdw_deprepare_stream: SDW0 Pin2-Playback: done
[  193.505712] intel-sdw sdw-master-0: sdw_deprepare_stream: failed -22
[  193.505716]  SDW0-Playback: ASoC: close BE SDW0-Playback
[  193.505719] intel-sdw sdw-master-0: intel_shutdown: SDW0 Pin2: start
[  193.505723] intel-sdw sdw-master-0: intel_shutdown: SDW0 Pin2: done
[  193.505761]  Headphone: ASoC: close FE Headphone
[  193.505766] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 0
[  193.505774]  SDW0-Playback: ASoC: BE SDW0-Playback event 2 dir 0
[  193.506170] sdw_cdns_irq: 129 callbacks suppressed
[  193.506174] intel-sdw sdw-master-3: Parity error
[  193.506180] sdw_cdns_irq: 129 callbacks suppressed
[  193.506182] intel-sdw sdw-master-3: Bus clash for control word
[  193.506184] sdw_cdns_irq: 129 callbacks suppressed
[  193.506186] intel-sdw sdw-master-3: Bus clash for data word
[  193.506240] rt711 sdw:0:25d:711:0: [rt711_sdw_write] 7321 83a1 <= b080

Test recipe

Kernel:https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: add887e+PR #1589
FW: https://github.com/thesofproject/sof/commits/master commit: 65de27d
Tplg: Same with FW branch, sof-cml-rt711-rt1308-rt715.tplg
Platform:CML-H Laptop with codec ALC711, 2 x RT1308, RT715 in SDW mode。

sof_trace.log
dmesg.log

Activity

  1. sinahuang
    added
    bugSomething isn't working
    SDWApplies to SoundWire bus for codec connection
    on Dec 5, 2019

  2. sinahuang commented on Dec 5, 2019

    @sinahuang
    sinahuang
    on Dec 5, 2019
    Author

    Check this issue with integration/soundwire-latest(add887e) + #1594 , issue can't be fixed.

  3. sinahuang
    added
    CMLApplies to Comet Lake platform
    on Dec 5, 2019

  4. sinahuang commented on Dec 5, 2019

    @sinahuang
    sinahuang
    on Dec 5, 2019
    Author

    Issue also can be reproduced on CML-H with below steps:

    1. paplay 1.wav -vvv via headset
    2. .Enter s3 via "sudo rtcwake -m mem -s 10
    3. "parecord 22.wav -vvv " via DMIC 0,4
    4. Enter s3 via "sudo rtcwake -m mem -s 10

    dmesg9.log
    sof_trace99.log
    Test recipe

    Kernel:https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: add887e+PR #1598
    FW: https://github.com/thesofproject/sof/commits/master commit: 65de27d
    Tplg: Same with FW branch, sof-cml-rt711-rt1308-rt715.tplg
    Platform:CML-H Laptop with codec ALC711, 2 x RT1308, RT715 in SDW mode。

  5. bardliao commented on Dec 5, 2019

    @bardliao
    bardliao
    on Dec 5, 2019
    Collaborator

    The root cause is similar to #1592 The different is that the intel_suspend() is not even triggered in this case.

    [  131.335166] intel-sdw sdw-master-1: intel_suspend start
[  131.335169] intel-sdw sdw-master-1: intel_suspend: pm_runtime status: suspended
[  131.335176] intel-sdw sdw-master-0: intel_suspend start
[  131.335178] intel-sdw sdw-master-0: intel_suspend: pm_runtime status: suspended

    @sinahuang Could you test it with #1599 and #1594 ?
    In fact, #1592 (with one rt1308) and #1595(with two rt1308) are seen on different laptops.

    The reason why intel_suspend() is triggered on all sdw links on the one rt1308 laptop is that rt700 acpi id is on all sdw links. Besides, rt700 codec driver enable runtime pm when rt700 is attached.

    However, there is no rt700 on the laptop actually. So rt700 driver is loaded, but rt700 is never attached. As a result, rt700's suspend callback function and dpm_clear_superiors_direct_complete() will be triggered in suspend. And sdw-master's power.direct_complete will be set to false in dpm_clear_superiors_direct_complete(). Sdw-master's suspend callback function is invoked then.

    @plbossart @ranj063 What I don't understand yet is the dev->power.no_pm_callbacks is 0 on rt700 and 1 on sdw-master. I will look into it tomorrow.
    I also think we may not need pm_runtime_status_suspended(dev) in intel_suspend() if there is no ghost acpi id in the system.

  6. sinahuang commented on Dec 6, 2019

    @sinahuang
    sinahuang
    on Dec 6, 2019
    Author

    Verified this issue on CML-H Laptop with soundwire-latest (commit: d64c4a3 +PR #1599), issue can't be reproduced.

    Test recipe

    Kernel:https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: d64c4a3 +PR #1599
    FW: https://github.com/thesofproject/sof/commits/master commit: 65de27d
    Tplg: Same with FW branch, sof-cml-rt711-rt1308-rt715.tplg
    Platform:CML-H Laptop with codec ALC711, 2 x RT1308, RT715 in SDW mode.

  7. plbossart commented on Dec 7, 2019

    @plbossart
    plbossart
    on Dec 7, 2019
    Member

    @bardliao I am quite lost so could use more explanations:

    1. I do see in the logs that we do start the suspend on master 0 and 1, but not on 2 and 3?

    2. what is the issue with the rt700 suspend? that routine does nothing if there is no hardware present on the board?

    3. the use of pm_runtime_suspended() is only to make sure we reset the status on resume. I don't see what this has to do with 'ghost' devices

  8. bardliao
    self-assigned this
    on Dec 9, 2019

  9. bardliao commented on Dec 9, 2019

    @bardliao
    bardliao
    on Dec 9, 2019
    Collaborator

    @bardliao I am quite lost so could use more explanations:

    1. I do see in the logs that we do start the suspend on master 0 and 1, but not on 2 and 3?

    Right, and that's what we are trying to fix.

    1. what is the issue with the rt700 suspend? that routine does nothing if there is no hardware present on the board?

    I won't say there is a issue on rt700 suspend. The impact of rt700 suspend is it will clear the direct_complete flag of its parent which is sdw-master and it will trigger intel_suspend() function. In other words, intel_suspend() function will not be triggered in suspend if there is no unattached slave on the link.

    1. the use of pm_runtime_suspended() is only to make sure we reset the status on resume. I don't see what this has to do with 'ghost' devices

    That is not related to this issue. What I think is that ideally, intel_suspend() will only be triggered when the device is not runtime suspended. That's one of the purpose the power.direct_complete flag. Currently, intel_suspend() is triggered even when sdw-master is runtime suspended is due to a unattached slave will clear the sdw-master's power.direct_complete flag and then intel_suspend() will be triggered. For the reason above, if there is no 'ghost' devices, intel_suspend() will not be triggered in runtime suspended and pm_runtime_suspended() will return false when we test it in intel_suspend().

  10. plbossart commented on Dec 9, 2019

    @plbossart
    plbossart
    on Dec 9, 2019
    Member

    @bardliao @sinahuang @YvonneYang2 I cannot reproduce this error with plain vanilla integration/soundwire-latest

    kernel e375909
    Firmware 8f51e6b

  11. bardliao commented on Dec 10, 2019

    @bardliao
    bardliao
    on Dec 10, 2019
    Collaborator

    @bardliao @sinahuang @YvonneYang2 I cannot reproduce this error with plain vanilla integration/soundwire-latest

    kernel e375909
    Firmware 8f51e6b

    @plbossart Could you check if there is any unattached slave on your device? Also, could you check if intel_suspend() is triggered for all links in suspend? The IPC timed out is only the result of intel_suspend() is not triggered. So what I really concern about is if intel_suspend() is triggered for all links.

  12. sinahuang commented on Dec 10, 2019

    @sinahuang
    sinahuang
    on Dec 10, 2019
    Author

    Verified this issue on CML-H with master and sof runtime PM status disabled via "options snd-sof-intel-hda-common sdw_clock_stop_quirks=0x1 ", issue cannot be reproduced.

    Kernel:https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: e375909 +PR #1586
    FW: https://github.com/thesofproject/sof/commits/master commit: 8f51e6b
    Tplg: Same with FW branch, sof-cml-rt711-rt1308-rt715.tplg
    Platform:CML-H Laptop with codec ALC711, 2 x RT1308, RT715 in SDW mode.

  13. bardliao commented on Dec 10, 2019

    @bardliao
    bardliao
    on Dec 10, 2019
    Collaborator

    Verified this issue on CML-H with master and sof runtime PM status disabled via "options snd-sof-intel-hda-common sdw_clock_stop_quirks=0x1 ", issue cannot be reproduced.

    @sinahuang Sorry, but options snd-sof-intel-hda-common sdw_clock_stop_quirks=0x1 will not disable runtime PM, will it?

  14. RanderWang commented on Dec 11, 2019

    @RanderWang
    RanderWang
    on Dec 11, 2019

    @bardliao

    	if (clock_stop_quirks & SDW_INTEL_CLK_STOP_NOT_ALLOWED) {  // quirks = 0x1
		/*
		 * To keep the clock running we need to prevent
		 * pm_runtime suspend from happening by increasing the
		 * reference count.
		 * This quirk is specified by the parent PCI device in
		 * case of specific latency requirements. It will have
		 * no effect if pm_runtime is disabled by the user via
		 * a module parameter for testing purposes.
		 */
		pm_runtime_get_noresume(&md->dev);
}

  15. ClarexZhou commented on Dec 11, 2019

    @ClarexZhou
    ClarexZhou
    on Dec 11, 2019

    Error only seen with option sof-pci-debug=1 and sdw_md_flags=0x01000001.

  16. bardliao commented on Dec 11, 2019

    @bardliao
    bardliao
    on Dec 11, 2019
    Collaborator

    The root case is described on #1614. We can trace the issue there.

  17. bardliao commented on Dec 12, 2019

    @bardliao
    bardliao
    on Dec 12, 2019
    Collaborator

    @sinahuang We can close it if it can't be reproduced with integration/soundwire-latest + #1607. Thanks.

  18. sinahuang commented on Dec 12, 2019

    @sinahuang
    sinahuang
    on Dec 12, 2019
    Author

    Verified this issue with original steps on CM-H with integration/soundwire-latest , issue cannot be reproduced, since #1607 had been merged into integration/soundwire-latest, so closed it.

  19. sinahuang
    closed this as completedon Dec 12, 2019
  20. marc-hb
    added
    suspend resumeIssues related to suspend resume (e.g. rtcwake)
    on Jul 19, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

CMLApplies to Comet Lake platformSDWApplies 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