Skip to content

[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) #1592

New issue
New issue
Closed
Closed
[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)#1592
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

@YvonneYang2
YvonneYang2
opened on Dec 4, 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 "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

Activity

  1. YvonneYang2
    added
    bugSomething isn't working
    CMLApplies to Comet Lake platform
    SDWApplies to SoundWire bus for codec connection
    on Dec 4, 2019

  2. YvonneYang2 commented on Dec 4, 2019

    @YvonneYang2
    YvonneYang2
    on Dec 4, 2019
    Author

    @bardliao
    Could you please have a look? Thanks ~

  3. bardliao
    self-assigned this
    on Dec 4, 2019

  4. bardliao commented on Dec 4, 2019

    @bardliao
    bardliao
    on Dec 4, 2019
    Collaborator

    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.

  5. bardliao commented on Dec 5, 2019

    @bardliao
    bardliao
    on Dec 5, 2019
    Collaborator

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

  6. YvonneYang2 commented on Dec 5, 2019

    @YvonneYang2
    YvonneYang2
    on Dec 5, 2019
    Author

    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.

  7. bardliao commented on Dec 5, 2019

    @bardliao
    bardliao
    on Dec 5, 2019
    Collaborator

    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?

  8. YvonneYang2 commented on Dec 5, 2019

    @YvonneYang2
    YvonneYang2
    on Dec 5, 2019
    Author

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

  9. YvonneYang2 commented on Dec 5, 2019

    @YvonneYang2
    YvonneYang2
    on Dec 5, 2019
    Author

    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

  10. YvonneYang2 commented on Dec 6, 2019

    @YvonneYang2
    YvonneYang2
    on Dec 6, 2019
    Author

    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

  11. YvonneYang2 commented on Dec 6, 2019

    @YvonneYang2
    YvonneYang2
    on Dec 6, 2019
    Author

    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.

  12. YvonneYang2
    closed this as completedon Dec 6, 2019
  13. 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