[BUG][SDW]"rt715 sdw:3:25d:715:0: Initialization not complete, timed out" occurred when arecord0,4(RT715) after s3 and terminating arecord0,1(RT711)

[YvonneYang2]

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 "rt715 sdw:3:25d:715:0: Initialization not complete, timed out", then ipc timed out, system freeze.

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)

Reproduced rate
100%
Only forced reboot can recover the issue.

Expected result
Arecord0,4 normally

Actual result
Arecord0,4 failed, dmesg showed "rt715 sdw:3:25d:715:0: Initialization not complete, timed out", then timed out, system hung.

Dmesg

[   59.678345] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[   59.678369] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[   63.838072]  DMIC: ASoC: found 2 audio capture paths
[   63.838074] sdw_rt711_rt1308_rt715 sdw_rt711_rt1308_rt715: ASoC: find BE for widget ALH0x302.IN
[   63.838075] sdw_rt711_rt1308_rt715 sdw_rt711_rt1308_rt715: ASoC: try BE (not set)
[   63.838077] sdw_rt711_rt1308_rt715 sdw_rt711_rt1308_rt715: ASoC: try BE ALH3.IN
[   63.838077] sdw_rt711_rt1308_rt715 sdw_rt711_rt1308_rt715: ASoC: try BE (not set)
[   63.838078] sdw_rt711_rt1308_rt715 sdw_rt711_rt1308_rt715: ASoC: try BE ALH0x302.IN
[   63.838080]  DMIC: connected new DPCM capture path DMIC <- SDW3-Capture
[   63.838085]  DMIC: ASoC: found 1 new BE paths
[   63.838086]  SDW3-Capture: ASoC: open capture BE SDW3-Capture
[   64.302181]  Headphone: ASoC: pop wq checking: Playback status: inactive waiting: yes
[   65.902144] rt715 sdw:3:25d:715:0: Initialization not complete, timed out
[   65.902157] intel-sdw sdw-master-3: intel_startup: SDW3 Pin2: start
[   65.902164] intel-sdw sdw-master-3: intel_startup: SDW3 Pin2: done
[   65.902171]  DMIC: ASoC: open FE DMIC
[   65.902180] sof-audio-pci 0000:00:1f.3: pcm: open stream 4 dir 1
[   65.902184] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[   65.902186] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[   65.902188] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[   65.902550]  SDW3-Capture: ASoC: hw_params BE SDW3-Capture
[   65.902563] rt715 sdw:3:25d:715:0: Update DAI routes for rt715-aif2 capture
[   65.902567] rt715 sdw:3:25d:715:0: Connecting DAI route rt715 DP4TX -> rt715 DP4 Capture
[   65.902570] intel-sdw sdw-master-3: intel_hw_params: SDW3 Pin2: start
[   65.902590] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[   65.902765] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
[   65.902768] intel-sdw sdw-master-3: intel_hw_params: SDW3 Pin2: done
[   65.902772] intel-sdw sdw-master-3: Update DAI routes for SDW3 Pin2 capture
[   65.902776]  DMIC: ASoC: hw_params FE DMIC rate 48000 chan 2 fmt 2
[   65.902779] sof-audio-pci 0000:00:1f.3: Update DAI routes for DMIC 4 capture
[   65.902782] sof-audio-pci 0000:00:1f.3: Connecting DAI route PCM4C -> Passthrough Capture 4
[   65.902785] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 4 dir 1
[   65.902790] sof-audio-pci 0000:00:1f.3: generating page table for 00000000eb4375b6 size 0xffc0 pages 16
[   65.902797] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x240000 successful
[   65.902814] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x40000 successful
[   65.902817] sof-audio-pci 0000:00:1f.3: period_bytes:0x3fc0
[   65.902819] sof-audio-pci 0000:00:1f.3: periods:4
[   65.902832] sof-audio-pci 0000:00:1f.3: stream_tag 2
[   65.902842] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[   65.903063] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[   65.903069] sof-audio-pci 0000:00:1f.3: pcm: stream dir 1, posn mailbox offset is 790604
[   65.903107]  DMIC: ASoC: prepare FE DMIC
[   65.903112]  SDW3-Capture: ASoC: prepare BE SDW3-Capture
[   65.903120] intel-sdw sdw-master-3: intel_prepare: SDW3 Pin2: start
[   65.903154] sdw_prepare_stream: SDW3 Pin2-Capture: done
[   65.903164] intel-sdw sdw-master-3: intel_prepare: SDW3 Pin2: done
[   65.903559]  SDW3-Capture: ASoC: BE SDW3-Capture event 1 dir 1
[   65.908368]  SDW3-Capture: ASoC: trigger BE SDW3-Capture cmd 1
[   65.908370] intel-sdw sdw-master-3: intel_trigger: SDW3 Pin2: start
[   65.908380] sdw_enable_stream: SDW3 Pin2-Capture: done
[   65.908381] intel-sdw sdw-master-3: intel_trigger: SDW3 Pin2: done
[   65.908382]  DMIC: ASoC: post trigger FE DMIC cmd 1
[   65.908384] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 4 dir 1 cmd 1
[   65.908931] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x2024001e successful
[   65.908934] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[   65.909098] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[   66.414578]  DMIC: ASoC: pre trigger FE DMIC cmd 0
[   66.414592] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 4 dir 1 cmd 0
[   66.414603] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[   66.918161] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60050000 size 12
[   66.918170] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[   66.918177] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[   66.918269] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[   66.918279] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000003 rirb 00
[   66.918283] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[   66.918290] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[   66.918294] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[   66.918306] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20240000 successful
[   66.918313]  DMIC: ASoC: trigger FE cmd: 0 failed: -110
[   66.918337]  DMIC: ASoC: hw_free FE DMIC
[   66.918345] sof-audio-pci 0000:00:1f.3: pcm: free stream 4 dir 1
[   66.918351] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[   67.422184] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[   67.422195] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[   67.422205] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[   67.422305] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[   67.422317] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000001 rirb 00
[   67.422322] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[   67.422332] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[   67.422337] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[   67.422459] intel-sdw sdw-master-3: intel_hw_free: SDW3 Pin2: start
[   67.422465] sdw_deprepare_stream: SDW3 Pin2-Capture: inconsistent state state 3
[   67.422469] sdw_deprepare_stream: SDW3 Pin2-Capture: done
[   67.422474] intel-sdw sdw-master-3: sdw_deprepare_stream: failed -22
[   67.422480]  SDW3-Capture: ASoC: close BE SDW3-Capture
[   67.422485] intel-sdw sdw-master-3: intel_shutdown: SDW3 Pin2: start
[   67.422491] intel-sdw sdw-master-3: intel_shutdown: SDW3 Pin2: done
[   67.422544]  DMIC: ASoC: close FE DMIC
[   67.422551] sof-audio-pci 0000:00:1f.3: pcm: close stream 4 dir 1
[   67.422801]  SDW3-Capture: ASoC: BE SDW3-Capture event 2 dir 1
[   67.422859]  DMIC: ASoC: BE capture disconnect check for SDW3-Capture
[   67.422863]  DMIC: freed DSP capture path DMIC <- SDW3-Capture

dmesg.log
sof_trace.log

Test recipe:
kernel: https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: f6e2dba
FW: https://github.com/thesofproject/sof/commits/master commit: 0205c95
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]

@bardliao
Could you please have a look? Thanks ~

[bardliao]

I can't reproduce the rt715 sdw:3:25d:715:0: Initialization not complete, timed out issue. But I can see

[   54.684632] intel-sdw sdw-master-3: Invalid slave 1 status:3

[   54.696108] intel-sdw sdw-master-3: Slave attached, programming device number
[   54.696210] intel-sdw sdw-master-3: SDW Slave Addr: ffffffffffff
[   54.696212] intel-sdw sdw-master-3: SDW Slave class_id ff, part_id ffff, mfg_id ffff, unique_id f, version f
[   54.696212] intel-sdw sdw-master-3: Slave Entry not found
[   54.696220] intel-sdw sdw-master-3: End of sdw_program_device_num ret 0

I will look into it tomorrow.

[bardliao]

@YvonneYang2 Could you test it with
0001-Soundwire-cadence_master-check-if-cdns-power-in-irq.patch?
Somehow sdw 3 is powered down while cdns->link_up is false. I will keep looking into it.

[YvonneYang2]

Added
0001-Soundwire-cadence_master-check-if-cdns-power-in-irq.patch.txt on the top of integration/soundwire-latest(add887e ), issue cannot be reproduced.

[bardliao]

The issue is that pm_runtime_status_suspended(dev) will return true if pm runtime is disabled. Therefore, will do nothing in intel_suspend(). @YvonneYang2 Could you retest it with #1594?

[YvonneYang2]

Tested it on integration/soundwire-latest(add887e) + #1594 , issue cannot be reproduced.

[YvonneYang2]

When ran multi-pipline stress test, occurred "rt1308 sdw:1:25d:1308:0: Initialization not complete, timed out" with on integration/soundwire-latest(add887e) + #1589. Will try to test it with #1594 to check if it could be fixed by #1594

failed_multipipeline_test_289_dmesg.log
failed_multipipeline_test_289_logger_error.log

[YvonneYang2]

Tested it 1000 times with #1594 , "rt1308 sdw:1:25d:1308:0: Initialization not complete, timed out" can still be reproduced. Split this issue to #1600

[YvonneYang2]

Firstly disable master and sof runtime PM status via add sof-pci-debug=1 and sdw_md_flags=0x01000001.
Original issue cannot be reproduced after #1594 commit merged into integration/soundwire-latest(d64c4a3). Close it.