[BUG][CML]"SDW_SCP_INTMASK1 write failed:-61" occurred when run suspend/resume stress test.

[YvonneYang2]

Describe the bug
Firstly disable master and sof runtime PM status via add sof-pci-debug=1 and sdw_md_flags=0x01000001. Run suspend/resume stress test with integration/soundwire-latest + #1589 , dmesg sometimes shows

[  179.694010] intel-sdw sdw-master-1: sdw_handle_slave_status: Updating Slave 1 status done
[  179.694012] intel-sdw sdw-master-1: sdw_handle_slave_status: end
[  179.694018] intel-sdw sdw-master-3: Msg ignored for Slave 0
[  179.694026] rt715 sdw:3:25d:715:0: Program device_num 1 failed: -61
[  179.694028] intel-sdw sdw-master-3: Assign dev_num failed:-61
[  179.694029] intel-sdw sdw-master-3: Slave attach failed: -61
[  179.694122] intel-sdw sdw-master-3: Slave status change
[  179.694133] intel-sdw sdw-master-3: sdw_handle_slave_status: start

Run 50 times without #1589 ,issue cannot be reproduced. Will test much more times to check if it is related to #1589

Note: Function cannot be effected when issue occurred.

To Reproduce

1. Boot up.
2. Run with command "sudo ./stress-s3.sh 200 1 0"
3. Check the logs in folder named logs

Script:
stress-s3.sh.txt

Reproduced rate
15/200
Function will not be effected when issue occurred. Terminate and restart it can recover the issue.

Expected result
Dmesg should not show any error during suspend/resume stress test.

Actual result
Dmesg shows "intel-sdw sdw-master-3: SDW_SCP_INTMASK1 write failed:-61" during stress test

s3_test_11_logger_all.log
test_11.log

Test recipe:
kernel: https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: add887e + PR1589
FW: https://github.com/thesofproject/sof/commits/master commit: 65de27d
tplg: Same with FW branch, sof-cml-rt711-rt1308-mono-rt715.tplg
platform: CML-U Laptop with codec ALC711, RT1308, RT715 in SDW mode

Dmesg

[  179.693925] intel-sdw sdw-master-3: SDW Slave Addr: 21025d071500
[  179.693928] intel-sdw sdw-master-3: SDW Slave class_id 0, part_id 715, mfg_id 25d, unique_id 1, version 2
[  179.693930] intel-sdw sdw-master-3: in sdw_assign_device_num
[  179.693932] intel-sdw sdw-master-3: in sdw_assign_device_num
[  179.693934] intel-sdw sdw-master-3: Slave already registered, reusing dev_num:1
[  179.693936] intel-sdw sdw-master-3: in sdw_assign_device_num, writing dev_num 1
[  179.694007] intel-sdw sdw-master-1: Updating Slave 1 status
[  179.694010] intel-sdw sdw-master-1: sdw_handle_slave_status: Updating Slave 1 status done
[  179.694012] intel-sdw sdw-master-1: sdw_handle_slave_status: end
[  179.694018] intel-sdw sdw-master-3: Msg ignored for Slave 0
[  179.694026] rt715 sdw:3:25d:715:0: Program device_num 1 failed: -61
[  179.694028] intel-sdw sdw-master-3: Assign dev_num failed:-61
[  179.694029] intel-sdw sdw-master-3: Slave attach failed: -61
[  179.694122] intel-sdw sdw-master-3: Slave status change
[  179.694133] intel-sdw sdw-master-3: sdw_handle_slave_status: start
[  179.694135] intel-sdw sdw-master-3: sdw_handle_slave_status: end
[  179.696141]  Headphone: ASoC: prepare FE Headphone
[  179.696144]  SDW0-Playback: ASoC: prepare BE SDW0-Playback
[  179.696148] intel-sdw sdw-master-0: intel_prepare: SDW0 Pin2: start
[  179.696162] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[  179.696406] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
[  179.696901] rt711 sdw:0:25d:711:0: [rt711_sdw_write] 00e0 <= 0001
[  179.696999] rt711 sdw:0:25d:711:0: [rt711_sdw_write] 00f0 <= 0001
[  179.697001] rt711 sdw:0:25d:711:0: rt711_clock_config complete, clk_freq=6000000
[  179.697509] sdw_prepare_stream: SDW0 Pin2-Playback: done
[  179.697514] intel-sdw sdw-master-0: intel_prepare: SDW0 Pin2: done
[  179.697544] sof-audio-pci 0000:00:1f.3: pcm: prepare stream 0 dir 0
[  179.697546] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 0 dir 0
[  179.697555] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x140000 successful
[  179.697578] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x40000 successful
[  179.697582] sof-audio-pci 0000:00:1f.3: period_bytes:0x3fc0
[  179.697583] sof-audio-pci 0000:00:1f.3: periods:4
[  179.697613] sof-audio-pci 0000:00:1f.3: stream_tag 1
[  179.697617] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[  179.697837] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[  179.697839] sof-audio-pci 0000:00:1f.3: pcm: stream dir 0, posn mailbox offset is 790528
[  179.697858]  SDW0-Playback: ASoC: BE SDW0-Playback event 1 dir 0
[  179.697912]  SDW0-Playback: ASoC: trigger BE SDW0-Playback cmd 1
[  179.697915] intel-sdw sdw-master-0: intel_trigger: SDW0 Pin2: start
[  179.698683] rt711 sdw:0:25d:711:0: [rt711_sdw_write] 00e0 <= 0001
[  179.698739] rt711 sdw:0:25d:711:0: [rt711_sdw_write] 00f0 <= 0001
[  179.698741] rt711 sdw:0:25d:711:0: rt711_clock_config complete, clk_freq=6000000
[  179.699001] sdw_enable_stream: SDW0 Pin2-Playback: done
[  179.699005] intel-sdw sdw-master-0: intel_trigger: SDW0 Pin2: done
[  179.699009]  Headphone: ASoC: post trigger FE Headphone cmd 1
[  179.699013] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 1
[  179.699566] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x14001e successful
[  179.699569] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[  179.699740] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[  179.752072] PM: suspend exit

[plbossart]

@YvonneYang2 please update if indeed PR #1589 is the root cause of this issue

[YvonneYang2]

Since PR1589's fix has been merged into PR1586. Run 500 times, issue cannot be reproduced with snd-sof-intel-hda-common sdw_clock_stop_quirks=0x1 with #1586 .
But according to ww49.5 test report, issue can be reproduced with snd-sof-intel-hda-common sdw_clock_stop_quirks=0x8, so will test it with and without #1586 to check if issue can still be reproduced .

[YvonneYang2]

Tested it with snd-sof-intel-hda-common sdw_clock_stop_quirks=0x8
Run 1000 times suspend/resume stress test with #1586 ,issue can be reproduced. Reproduced rate is 4/1000
Run 1000 times without #1586 , issue cannot be reproduced.
So #1586 seems the root cause of the issue.

test_66.log

s3_test_66_logger_all.zip

Test recipe:
kernel: https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: b036eac
FW: https://github.com/thesofproject/sof/commits/master commit: 65de27d
tplg: Same with FW branch, sof-cml-rt711-rt1308-mono-rt715.tplg
platform: CML-U Laptop with codec ALC711, RT1308, RT715 in SDW mode

[YvonneYang2]

Double confirmed with sof runtime PM status via add sof-pci-debug=1 and sdw_md_flags=0x01000001 as bug description mentioned, run 1000 times, issue cannot be reproduced on integration/soundwire-latest(e375909). So the PR #1586 is the root cause of the issue.

[RanderWang]

I checked the log, it happened with master1 resumed by intel_resume, so it is not a issue caused by clock stop explicitly

[YvonneYang2]

Firstly disable master and sof runtime PM status via add sof-pci-debug=1 and sdw_md_flags=0x01000001.
Tested it 1000 times with integration/soundwire-latest(9645962) + plbossart#12, issue cannot be reproduced.
Since plbossart#12 has been merged into integration/soundwire-latest, will retest it. If issue cannot be reproduced, will close the bug.

[YvonneYang2]

Firstly disable master and sof runtime PM status via add sof-pci-debug=1 and sdw_md_flags=0x01000001.
Tested it 500 times with integration/soundwire-latest( cf2660a ) and cml-010-drop-stable( 5e5f69e),
issue cannot be reproduced. Close it.