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

[sinahuang]

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

[sinahuang]

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

[sinahuang]

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。

[bardliao]

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.

[sinahuang]

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.

[plbossart]

@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

[bardliao]

@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.

2. 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.

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

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().

[plbossart]

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

kernel e375909
Firmware 8f51e6b

[bardliao]

@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.