[BUG][SDW] IPC timed out for 0x80010000 size 120 occurred during multipipline stress test.

Describe the bug
IPC timed out for 0x60050000: GLB_STREAM_MSG: TRIG_STOP occurred during multipipline stress test.

To Reproduce
Run command "./multiplex_pipeline-test.sh pcm0p pcm4p pcm1c pcm2c pcm3c"

Reproduction Rate
1/54

Expected behavior
Multipipline works normally.

Impact
Dmesg shows 0x60050000: GLB_STREAM_MSG: TRIG_STOP.

Environment
Firmware: e755494 Master
Kernel: d2b55e0 on integration/soundwire-latest
Topology: file: same with firmware branch, sof-cml-rt700.m4
platform: CML RVP with onboard ALC700 in SDW mode
Other: Runtime PM status is enabled (without debug=1 options)

Dmesg

[ 1791.900263] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 1791.900266] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=1
[ 1791.902220] rt700 sdw:1:25d:700:0:0: rt700_clock_config complete, clk_freq=6000000
[ 1791.904254] rt700 sdw:1:25d:700:0:0: rt700_clock_config complete, clk_freq=6000000
[ 1791.906705] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 1
[ 1791.906729] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x14001e successful
[ 1791.906730] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 2 dir 1 cmd 1
[ 1791.906731] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 1791.906754] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 3 dir 1 cmd 1
[ 1791.906761] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x2034001e successful
[ 1791.906950] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 1791.906953] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 1791.907148] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 1791.907312] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x2044001e successful
[ 1791.907314] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 1791.907553] rt700 sdw:1:25d:700:0:0: rt700_clock_config complete, clk_freq=6000000
[ 1791.907577] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 1791.909164] rt700 sdw:1:25d:700:0:0: rt700_clock_config complete, clk_freq=6000000
[ 1791.912206] rt700 sdw:1:25d:700:0:0: rt700_clock_config complete, clk_freq=6000000
[ 1791.914182] rt700 sdw:1:25d:700:0:0: rt700_clock_config complete, clk_freq=6000000
[ 1792.411109] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 2 dir 1 cmd 0
[ 1792.411116] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 1792.914890] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60050000 size 12
[ 1792.914893] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[ 1792.914899] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 1792.914970] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 1792.914976] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc000018f rirb 00
[ 1792.914977] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 1792.914982] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 1792.914983] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 1792.915069] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915070] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915070] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915071] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915072] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915073] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915073] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915074] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915075] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915076] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915076] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915078] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20340000 successful
[ 1792.915084]  DMIC01: ASoC: trigger FE failed -110
[ 1792.915100] sof-audio-pci 0000:00:1f.3: pcm: free stream 2 dir 1
[ 1792.915102] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 1792.915106] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915113] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915195] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915197] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915212] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915213] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915214] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915215] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915215] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915224] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915225] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915226] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915226] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915228] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915309] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915318] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915321] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915323] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915323] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915325] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915326] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915343] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915343] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915351] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915353] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915353] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915397] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915413] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915414] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915420] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915424] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915426] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915429] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915435] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915455] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915455] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915463] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915508] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915537] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915543] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915543] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915547] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915550] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915584] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1792.915585] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 1793.418674] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[ 1793.418678] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[ 1793.418690] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 1793.418765] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 1793.418771] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc000018b rirb 00
[ 1793.418772] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 1793.418779] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 1793.418780] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 1793.418837] sof-audio-pci 0000:00:1f.3: pcm: close stream 2 dir 1
[ 1793.619229] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 4 dir 0 cmd 0
[ 1793.619239] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 1793.635016] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 0
[ 1794.122924] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60050000 size 12
[ 1794.122932] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[ 1794.122946] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 1794.123036] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 1794.123047] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc000018b rirb 00
[ 1794.123050] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 1794.123063] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 1794.123066] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 1794.123088] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20240000 successful
[ 1794.123095]  HDMI1: ASoC: trigger FE failed -110
[ 1794.123119] sof-audio-pci 0000:00:1f.3: pcm: free stream 4 dir 0
[ 1794.123125] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 1794.626671] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[ 1794.626674] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[ 1794.626682] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 1794.626756] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 1794.626762] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc000008b rirb 00
[ 1794.626763] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 1794.626769] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 1794.626770] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 1794.626811] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 1794.735138] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 1 dir 1 cmd 0
[ 1794.735160] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 3 dir 1 cmd 0
[ 1795.130990] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60050000 size 12
[ 1795.130999] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[ 1795.131015] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 1795.131109] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 1795.131119] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc000008b rirb 00
[ 1795.131123] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 1795.131139] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 1795.131142] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 1795.131165] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x140000 successful
[ 1795.131174]  SDW1-speakers: ASoC: trigger FE failed -110
[ 1795.131224] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[ 1795.634974] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x80010000 size 120
[ 1795.634982] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[ 1795.634994] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 1795.635088] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 1795.635100] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc000000b rirb 00
[ 1795.635103] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 1795.635119] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 1795.635123] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 1795.635132] sof-audio-pci 0000:00:1f.3: error: failed to set dai config for iDisp1
[ 1795.635151] sof-audio-pci 0000:00:1f.3: pcm: close stream 4 dir 0
[ 1795.635203] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP

error logger

	 0      1         DMIC         2245801105.885417        12.083333 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245801117.343750        11.458333 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245801129.479167        12.135417 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245801140.937500        11.458333 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245801153.020833        12.083333 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245801164.479167        11.458333 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245801176.562500        12.083333 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245801188.020833        11.458333 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245801200.104167        12.083333 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245801211.614583        11.510417 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245801223.750000        12.135417 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245801235.260417        11.510417 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245801247.395833        12.135417 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245801258.906250        11.510417 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245801271.041667        12.135417 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245801282.552083        11.510417 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245801294.635417        12.083333 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245801306.093750        11.458333 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1          DAI 4.18    2245801331.770833        25.677084      src/audio/dai.c:591 	dai_check_for_xrun() error: overrun due to no data available
    0      1         COMP         2245801336.614583         4.843750 of/audio/component.h:759 	comp_overrun() error: dev->comp.id = 18, sink->free = 0, copy_bytes = 0
    0      1         PIPE         2245801388.906250        52.291668 src/audio/pipeline.c:847 	pipeline_copy() error: ret = -61, start->comp.id = 18, dir = 0
    0      1         PIPE 4.19    2245801395.052083         6.145833 src/audio/pipeline.c:1030	pipeline_task(): xrun recover failed! pipeline will be stopped!
    0      1         DMIC         2245794820.625000              nan rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245794832.135417        11.510417 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245794844.218750        12.083333 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245794855.677083        11.458333 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245794867.760417        12.083333 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245794879.218750        11.458333 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245794891.354167        12.135417 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245794902.864583        11.510417 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245794914.947917        12.083333 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245794926.406250        11.458333 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245794938.541667        12.135417 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245794950.052083        11.510417 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245794962.187500        12.135417 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245794973.697917        11.510417 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245794985.833333        12.135417 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245794997.343750        11.510417 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245795009.479167        12.135417 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245795020.989583        11.510417 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245795033.125000        12.135417 rs/intel/cavs/dmic.c:1503	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC         2245795044.635417

multipipeline_test_54_logger.txt
multipipeline_test_54_logger_error.txt
multipipeline_test_54_dmesg.txt

Error was 100% reproduced previously, seen thesofproject/sof#1839, might be improved by PR thesofproject/sof#1887

@singalsu

@singalsu hey, mind taking a look at this? In the error log of FW I can see a whole lot of traces indicating, that the DMIC FIFO is full. Any hints what this might point at?

@ClarexZhou

@ClarexZhou @YvonneYang2 Can it still be reproduced with master + linux#1277?

ipc timed out for 0x80010000 size 120 occurred at multipipline stress test 70th times with latest kernel(commit: d88ee7d) + linux PR thesofproject/sof#1227 and master(commit: 81cc31b).

Run with command: sudo ./multiplex_pipeline-test.sh pcm0p pcm2p pcm5c pcm1c pcm4c"
dmesg:

[  778.678834] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=0
[  778.678839] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[  778.683355] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 1 dir 1 cmd 0
[  778.683448] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 4 dir 1 cmd 0
[  779.185782] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x80010000 size 120
[  779.185791] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[  779.185799] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  779.186136] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[  779.186154] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x80000006 intlctl 0xc0000007 rirb 00
[  779.186157] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x80000000 adspis 0x00000001
[  779.186174] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x00000000 mask 0x00000003
[  779.186177] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[  779.186383] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  779.186389] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  779.186392] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  779.186395] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  779.186397] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  779.186400] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  779.186402] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  779.186428] sof-audio-pci 0000:00:1f.3: error: failed to set dai config for iDisp1
[  779.186436]  iDisp1: ASoC: trigger BE failed -110
[  779.186441]  HDMI1: ASoC: trigger FE cmd: 0 failed: -110
[  779.186461] sof-audio-pci 0000:00:1f.3: pcm: free stream 5 dir 0
[  779.186491] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[  779.186548] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  779.186730] sof-audio-pci 0000:00:1f.3: error: trace IO error

multipipeline_test_70_error_logger.log
multipipeline_test_70_logger_error.log
multipipeline_test_70_dmesg.log

I tried to reproduce it on ICL RVP (FW master 0234df5, linux 29debf8 + PR thesofproject/sof#1277).
I get completely different results however:

dmesg.log
test.log

I will try again using the same exact recipe, and then later on CML RVP when I get one.

I can't seem to be able to find the right kernel commit with the d88ee7d hash, can you please provide the full hash?

@slawblauciak

@slawblauciak
kernel: https://github.com/thesofproject/linux/tree/integration/soundwire-latest
commit: d88ee7d

Hmm, I can't fetch that commit, it might no longer exist on the remote branch. Somebody might've force-pushed or something.

issue still reproduce when run " ./multiplex_pipeline-test.sh pcm0p pcm2p pcm6p pcm4c"
,failed info occurs from 267th time.
267th IPC time out log.zip

besides during test, dmesg starts to show error info "error: iteration 0 of Core En/ROM load failed: -110" from 113th time.

113th failed error log.zip

kernel: https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: 15f27d8
FW: https://github.com/thesofproject/sof/commits/master commit: f277189
tplg: Same with FW branch, sof-icl-rt711-rt1308-rt715-hdmi.tplg rename to sof-icl-rt711-rt1308-rt715.tplg
platform: ICL RVP, with codec ALC711 -RT1308, RT715 in SDW mode

@slawblauciak

@slawblauciak Previous reproduced kernel already contains PR#1277. kernel: https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: 15f27d8

IO tranfer timed out occurred then showed ipc timed out for 0x80010000 size 120 when ran multipipline stress test. Failed at 117th time.

Run with command: sudo ./multiplex_pipeline-test.sh pcm0p pcm2p pcm4c"

IO transfer timed out

[ 5105.486953] rt711 sdw:0:25d:711:0: [rt711_sdw_write] 7321 83a1 <= b000
[ 5105.486964]  SDW0-Playback: ASoC: BE SDW0-Playback event 1 dir 0
[ 5105.486972]  SDW3-Capture: ASoC: hw_params BE SDW3-Capture
[ 5105.486986]  SDW0-Playback: ASoC: trigger BE SDW0-Playback cmd 1
[ 5105.486987] intel-sdw sdw-master-0: intel_trigger: SDW0 Pin2: start
[ 5105.486988] sdw_enable_stream: SDW0 Pin2-Playback: start
[ 5107.507036] intel-sdw sdw-master-0: IO transfer timed out
[ 5107.507080] intel-sdw sdw-master-3: IO transfer timed out
[ 5109.555045] intel-sdw sdw-master-3: IO transfer timed out
[ 5109.555049] intel-sdw sdw-master-0: IO transfer timed out
[ 5109.555069] rt715 sdw:3:25d:715:0: [rt715_sdw_write] 7520 85a0 7420 84a0 <= 0039 a000
[ 5111.603034] intel-sdw sdw-master-0: IO transfer timed out
[ 5111.603059] intel-sdw sdw-master-3: IO transfer timed out
[ 5113.651043] intel-sdw sdw-master-3: IO transfer timed out
[ 5113.651066] rt715 sdw:3:25d:715:0: [rt715_sdw_write] 7207 8287 <= 0031
[ 5113.651084] intel-sdw sdw-master-0: IO transfer timed out
[ 5115.699010] intel-sdw sdw-master-0: IO transfer timed out
[ 5115.699011] intel-sdw sdw-master-3: IO transfer timed out
[ 5117.747000] intel-sdw sdw-master-3: IO transfer timed out
[ 5117.747001] intel-sdw sdw-master-0: IO transfer timed out
[ 5117.747008] rt715 sdw:3:25d:715:0: [rt715_sdw_write] 7208 8288 <= 0031
[ 5119.795063] intel-sdw sdw-master-3: IO transfer timed out
[ 5119.795067] intel-sdw sdw-master-0: IO transfer timed out
[ 5121.843007] intel-sdw sdw-master-3: IO transfer timed out
[ 5121.843008] intel-sdw sdw-master-0: IO transfer timed out
[ 5121.843016] rt715 sdw:3:25d:715:0: [rt715_sdw_write] 7209 8289 <= 0031
[ 5123.891013] intel-sdw sdw-master-0: IO transfer timed out
[ 5123.891014] intel-sdw sdw-master-3: IO transfer timed out
[ 5123.891024] rt711 sdw:0:25d:711:0: [rt711_sdw_write] 00e0 <= 0001
[ 5125.939065] intel-sdw sdw-master-3: IO transfer timed out
[ 5125.939070] intel-sdw sdw-master-0: IO transfer timed out
[ 5125.939087] rt711 sdw:0:25d:711:0: [rt711_sdw_write] 00f0 <= 0001
[ 5125.939095] rt715 sdw:3:25d:715:0: [rt715_sdw_write] 7227 82a7 <= 0031
[ 5125.939100] rt711 sdw:0:25d:711:0: rt711_clock_config complete, clk_freq=6000000
[ 5125.939112] rt715 sdw:3:25d:715:0: Update DAI routes for rt715-aif2 capture
[ 5125.939121] rt715 sdw:3:25d:715:0: Connecting DAI route rt715 DP4TX -> rt715 DP4 Capture
[ 5125.939133] intel-sdw sdw-master-3: intel_hw_params: SDW3 Pin2: start

IPC timed out

[ 5126.448082] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 5126.448152] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 5126.448155] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 5126.448350] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 5126.448368] sof-audio-pci 0000:00:1f.3: error: trace IO error
[ 5126.955043] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x80010000 size 120
[ 5126.955054] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[ 5126.955066] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 5126.955325] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 5126.955337] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x80000000 intlctl 0xc0000001 rirb 00
[ 5126.955342] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x80000000 adspis 0x00000001
[ 5126.955353] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x90020000 mask 0x00000003
[ 5126.955358] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 5126.955366] sof-audio-pci 0000:00:1f.3: error: failed to set DAI hw_params for link 1 dai->id 2 ALH 23
[ 5126.955375] intel-sdw sdw-master-1: ASoC: cpu DAI prepare error: -110
[ 5126.955381]  SDW1-Playback: ASoC: backend prepare failed -110
[ 5126.955489]  DMIC: ASoC: found 2 audio capture paths
[ 5126.955498] sdw_rt711_rt1308_rt715 sdw_rt711_rt1308_rt715: ASoC: find BE for widget ALH0x302.IN
[ 5126.955503] sdw_rt711_rt1308_rt715 sdw_rt711_rt1308_rt715: ASoC: try BE (not set)
[ 5126.955507] sdw_rt711_rt1308_rt715 sdw_rt711_rt1308_rt715: ASoC: try BE ALH3.IN
[ 5126.955510] sdw_rt711_rt1308_rt715 sdw_rt711_rt1308_rt715: ASoC: try BE (not set)
[ 5126.955513] sdw_rt711_rt1308_rt715 sdw_rt711_rt1308_rt715: ASoC: try BE ALH0x302.IN
[ 5126.955520]  DMIC: connected new DPCM capture path DMIC <- SDW3-Capture

kernel: https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: 9f1bd5b + PR1359
FW: https://github.com/thesofproject/sof/commits/master commit: 2ca6a4a
tplg: https://github.com/bardliao/sof/commits/soundwire-tplg (commit: 0408153), sof-cml-rt711-rt1308-rt715.tplg
platform: CML SDW Laptop with ALC711+ ALC1308+ ALC715

Logs:
multipipeline_test_117_error_logger.log
multipipeline_test_117_logger_error.log
multipipeline_test_117_dmesg.log

Script:
multiplex_pipeline-test.sh.txt

@plbossart

@plbossart @ranj063 I think you still have some kind of problem with receiving an IPC from DSP. It's IPC timeout, but you clearly can see that DSP has generated reply:

[ 5126.955337] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x80000000 intlctl 0xc0000001 rirb 00
[ 5126.955342] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x80000000 adspis 0x00000001
[ 5126.955353] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x90020000 mask 0x00000003

It only reproduced with SDW, so I would look there.

The IO transfer timeouts are the most concerning I'd say, as they point to a problem in the communication with the codec.

The IO transfer timeouts are the most concerning I'd say, as they point to a problem in the communication with the codec.

no. all transfers are handled through the controller, and we share a common interrupt line between SoundWire and DSP.

Issue can be reproduced with MSI IRQ mode, test for 500 times, failed at 230th time.
To reproduce:
Run command "./multiplex_pipeline-test.sh pcm0p pcm2p pcm1c pcm3c pcm4c"

Scripts:
multiplex_pipeline-test.txt

dmesg

[ 2445.912647] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[ 2445.912650] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[ 2445.912660]  SDW0-Playback: ASoC: hw_params BE SDW0-Playback
[ 2445.912665] rt711 sdw:0:25d:711:0: rt711_pcm_hw_params rt711-aif1
[ 2445.912675] rt711 sdw:0:25d:711:0: Update DAI routes for rt711-aif1 playback
[ 2445.912678] rt711 sdw:0:25d:711:0: Connecting DAI route DP3 Playback -> DP3RX
[ 2445.912681] intel-sdw sdw-master-0: intel_hw_params: SDW0 Pin2: start
[ 2445.912714] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[ 2446.415696] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x80010000 size 120
[ 2446.415707] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[ 2446.415726] sof-audio-pci 0000:00:1f.3: unknown ROM status value 01009701
[ 2446.416035] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x001d003c trace 0x00000000
[ 2446.416071] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0x00000000 rirb 00
[ 2446.416075] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 2446.416098] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00040000 mask 0x00000000
[ 2446.416104] sof-audio-pci 0000:00:1f.3: error: failed to set DAI hw_params for link 0 dai->id 2 ALH 7
[ 2446.416111] intel-sdw sdw-master-0: intel_hw_params: SDW0 Pin2: done
[ 2446.416116] intel-sdw sdw-master-0: ASoC: can't set SDW0 Pin2 hw params: -110
[ 2446.416126]  SDW0-Playback: ASoC: hw_params BE failed -110
[ 2446.416130]  SDW0-headphone: ASoC: hw_params BE failed -110
[ 2446.416148]  SDW0-headphone: ASoC: hw_free FE SDW0-headphone
[ 2446.416160] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 0
[ 2446.416190]  SDW0-Capture: ASoC: hw_params BE SDW0-Capture
[ 2446.416209] rt711 sdw:0:25d:711:0: rt711_pcm_hw_params rt711-aif1
[ 2446.416221] rt711 sdw:0:25d:711:0: Update DAI routes for rt711-aif1 capture
[ 2446.416226] rt711 sdw:0:25d:711:0: Connecting DAI route DP4TX -> DP4 Capture
[ 2446.416229] intel-sdw sdw-master-0: intel_hw_params: SDW0 Pin3: start
[ 2446.416270] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[ 2446.919721] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x80010000 size 120
[ 2446.919735] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[ 2446.919755] sof-audio-pci 0000:00:1f.3: unknown ROM status value 01009701
[ 2446.920057] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x001d003c trace 0x00000000
[ 2446.920093] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0x00000000 rirb 00
[ 2446.920099] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 2446.920124] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00040000 mask 0x00000000
[ 2446.920131] sof-audio-pci 0000:00:1f.3: error: failed to set DAI hw_params for link 0 dai->id 3 ALH 8
[ 2446.920140] intel-sdw sdw-master-0: intel_hw_params: SDW0 Pin3: done
[ 2446.920147] intel-sdw sdw-master-0: ASoC: can't set SDW0 Pin3 hw params: -110
[ 2446.920160]  SDW0-Capture: ASoC: hw_params BE failed -110
[ 2446.920166]  SDW0-mics: ASoC: hw_params BE failed -110
[ 2446.920180]  SDW0-mics: ASoC: hw_free FE SDW0-mics
[ 2446.920188] sof-audio-pci 0000:00:1f.3: pcm: free stream 1 dir 1
[ 2446.920281]  dmic16k: ASoC: hw_params BE dmic16k
[ 2446.920292] dmic-codec dmic-codec: Update DAI routes for dmic-hifi capture
[ 2446.920297] dmic-codec dmic-codec: Connecting DAI route DMIC AIF -> Capture
[ 2446.920302] sof-audio-pci 0000:00:1f.3: Update DAI routes for DMIC16k Pin capture
[ 2446.920308]  DMIC16k: ASoC: hw_params FE DMIC16k rate 16000 chan 4 fmt 2
[ 2446.920312] sof-audio-pci 0000:00:1f.3: Update DAI routes for DMIC16k 4 capture
[ 2446.920315] sof-audio-pci 0000:00:1f.3: Connecting DAI route PCM4C -> Passthrough Capture 4
[ 2446.920318] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 4 dir 1
[ 2446.920323] sof-audio-pci 0000:00:1f.3: generating page table for 000000008b3fb397 size 0xf9c0 pages 16
[ 2446.920363] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x40000 successful

Test recipe

Kernel:https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: 4cd6497
FW: https://github.com/thesofproject/sof/commits/master commit: dbb70c8
Tplg: Same with TGL FW branch commit: sof-tgl-rt711-rt1308-nohdmi.tplg rename to sof-tgl-rt711-rt1308.tplg
Platform:TGL RVP with onboard ACL711 in SDW mod and ALC1308 in I2S mode.

multipipeline_test_230_all_logger.log
multipipeline_test_230_dmesg.log

@bardliao

@bardliao
Issue can still be reproduced after changes merged.

Round 1 : failed at 11th time. Occurred ipc timed out for 0x60050000 size 12
Round 2 : failed at 26th time. Occurred ipc timed out for 0x80010000 size 120

Dmesg of round 1

[  521.328168] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[  521.328186]  DMIC: ASoC: pre trigger FE DMIC cmd 0
[  521.328188] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 4 dir 1 cmd 0
[  521.831054] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60050000 size 12
[  521.831066] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[  521.831077] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  521.831336] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[  521.831348] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0xc0000004 intlctl 0xc0000007 rirb 01
[  521.831353] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x80000000 adspis 0x00000001
[  521.831365] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x00000000 mask 0x00000003
[  521.831370] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[  521.831434] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  521.831455] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  521.831468] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  521.831471] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  521.831481] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  521.831484] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  521.831491] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  521.831498] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[  521.831519] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  521.831934] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x240000 successful
[  521.831953]  Headset mic: ASoC: trigger FE cmd: 0 failed: -110
[  521.831969]  Headset mic: ASoC: hw_free FE Headset mic

Dmesg of round 2

[  371.934085] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[  371.938103]  DMIC: ASoC: pre trigger FE DMIC cmd 0
[  371.938105] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 4 dir 1 cmd 0
[  371.938157]  Headset mic: ASoC: pre trigger FE Headset mic cmd 0
[  371.938160] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 1 dir 1 cmd 0
[  372.439446] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x80010000 size 120
[  372.439455] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[  372.439465] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  372.439724] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[  372.439734] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x80000006 intlctl 0xc0000007 rirb 00
[  372.439739] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x80000000 adspis 0x00000001
[  372.439746] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x00000000 mask 0x00000003
[  372.439749] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[  372.439850] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.439854] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.439856] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.439862] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.439865] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.439868] sof-audio-pci 0000:00:1f.3: error: failed to set dai config for iDisp1
[  372.439871] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.439873] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.439878]  iDisp1: ASoC: close BE iDisp1
[  372.439962]  HDMI1: ASoC: close FE HDMI1
[  372.439972] sof-audio-pci 0000:00:1f.3: pcm: close stream 5 dir 0
[  372.439983]  iDisp1: ASoC: BE iDisp1 event 2 dir 0
[  372.440012]  HDMI1: ASoC: BE playback disconnect check for iDisp1
[  372.440016]  HDMI1: freed DSP playback path HDMI1 -> iDisp1
[  372.440187] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.440252] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.440260] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.440264] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.440290] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.440319] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.440548] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.440554] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.440556] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.440560] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.440572] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.440844] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.440854] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.441172] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.441294] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.441393] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.441590] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.441605] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[  372.441643] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.441661] sof-audio-pci 0000:00:1f.3: error: trace IO error
[  372.943442] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60050000 size 12
[  372.943452] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[  372.943462] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  372.943738] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[  372.943751] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0xc0000006 intlctl 0xc0000007 rirb 01
[  372.943756] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x80000000 adspis 0x00000001
[  372.943766] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x90020000 mask 0x00000003
[  372.943771] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[  372.943790] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x340000 successful
[  372.943799]  DMIC: ASoC: trigger FE cmd: 0 failed: -110
[  372.943811]  DMIC: ASoC: hw_free FE DMIC
[  372.943819] sof-audio-pci 0000:00:1f.3: pcm: free stream 4 dir 1
[  372.943828] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  372.943946] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  372.943959] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[  372.943974] intel-sdw sdw-master-3: intel_hw_free: SDW3 Pin2: start
[  372.943980] sdw_deprepare_stream: SDW3 Pin2-Capture: inconsistent state state 3
[  372.943985] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[  372.943988] sdw_deprepare_stream: SDW3 Pin2-Capture: done
[  372.943995] intel-sdw sdw-master-3: sdw_deprepare_stream: failed -22
[  372.944000]  SDW3-Capture: ASoC: close BE SDW3-Capture
[  372.944005] intel-sdw sdw-master-3: intel_shutdown: SDW3 Pin2: start
[  372.944012] intel-sdw sdw-master-3: intel_shutdown: SDW3 Pin2: done
[  372.944023] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[  372.944077]  DMIC: ASoC: close FE DMIC

Test recipe:
kernel: https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: 68cadd8
FW: https://github.com/thesofproject/sof/commits/master commit: 9b5dc8c
tplg: Same with FW branch, sof-cml-rt711-rt1308-mono-rt715.tplg
platform: CML Laptop with ALC711+ ALC1308+ ALC715

multipipeline_test_11_error_logger.log
multipipeline_test_26_all_logger.log
multipipeline_test_26_dmesg.log
multipipeline_test_11_dmesg.log

@YvonneYang2

@YvonneYang2 Could you retest it with #1543?

Tested it with #1543 300 times, issue cannot be reproduced.
Some failed messages start showing from 151th to 156th time, but multipipline function works fine.

Failed info:

[ 1691.303538] intel-sdw sdw-master-0: intel_suspend_runtime start
[ 1691.303549] intel-sdw sdw-master-3: intel_suspend_runtime start
[ 1691.303623] intel-sdw sdw-master-0: intel_suspend_runtime done
[ 1691.304139] intel-sdw sdw-master-3: Link power down failed: -11
[ 1691.499862] intel-sdw sdw-master-1: intel_suspend_runtime start
[ 1691.499940] intel-sdw sdw-master-1: intel_suspend_runtime done

Failed info:

[ 1720.577003]  SDW3-Capture: ASoC: hw_free BE SDW3-Capture
[ 1720.577017] intel-sdw sdw-master-3: intel_hw_free: SDW3 Pin2: start
[ 1720.577026] sdw_deprepare_stream: SDW3 Pin2-Capture: inconsistent state state 1
[ 1720.577030] sdw_deprepare_stream: SDW3 Pin2-Capture: done
[ 1720.577036] intel-sdw sdw-master-3: sdw_deprepare_stream: failed -22
[ 1720.577048]  SDW3-Capture: ASoC: close BE SDW3-Capture
[ 1720.577052] intel-sdw sdw-master-3: intel_shutdown: SDW3 Pin2: start
[ 1720.577057] intel-sdw sdw-master-3: intel_shutdown: SDW3 Pin2: done
[ 1720.577106]  DMIC: ASoC: close FE DMIC

multipipeline_test_154_dmesg.log
multipipeline_test_154_error_logger.log

Test recipe:
kernel: https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: 68cadd8 + #1543
FW: https://github.com/thesofproject/sof/commits/master commit: 9b5dc8c
tplg: Same with FW branch, sof-cml-rt711-rt1308-mono-rt715.tplg
platform: CML Laptop with ALC711+ ALC1308+ ALC715

Run multi-pipline stress test 300 times, issue cannot be reproduced with #1548

Test recipe:
kernel: https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: a370cb0 + #1548
FW: https://github.com/thesofproject/sof/commits/master commit: db7671a
tplg: Same with FW branch, sof-cml-rt711-rt1308-mono-rt715.tplg
platform: CML Laptop with ALC711+ ALC1308+ ALC715

Validation is blocked by #1555 . Will retest it to check if can close the bug after #1555 is fixed.

Added patch
0001-soundiwre-Intel-set-link_control-bits-again-when-it-.patch.txt to walk around issue #1555 , then tested it 500 times, issue cannot be reproduced. So close it.

Test recipe:
kernel: https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: d6078f9
FW: https://github.com/thesofproject/sof/commits/master commit: d740a3e
tplg: Same with FW branch, sof-cml-rt711-rt1308-mono-rt715.tplg
platform: CML Laptop with ALC711+ ALC1308+ ALC715 in SDW mode

Navigation Menu

Repository navigation

[BUG][SDW] IPC timed out for 0x80010000 size 120 occurred during multipipline stress test. #1476

32 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[BUG][SDW] IPC timed out for 0x80010000 size 120 occurred during multipipline stress test. #1476

Description

Activity

ClarexZhou commented on Oct 14, 2019

slawblauciak commented on Oct 15, 2019

tlauda commented on Oct 17, 2019

YvonneYang2 commented on Oct 18, 2019

slawblauciak commented on Oct 21, 2019

slawblauciak commented on Oct 22, 2019

YvonneYang2 commented on Oct 22, 2019

slawblauciak commented on Oct 22, 2019

sinahuang commented on Oct 24, 2019

ClarexZhou commented on Oct 24, 2019

YvonneYang2 commented on Oct 30, 2019

tlauda commented on Oct 30, 2019

slawblauciak commented on Oct 30, 2019

plbossart commented on Oct 30, 2019

32 remaining items

sinahuang commented on Nov 19, 2019

YvonneYang2 commented on Nov 22, 2019

bardliao commented on Nov 25, 2019

YvonneYang2 commented on Nov 25, 2019

YvonneYang2 commented on Nov 26, 2019

YvonneYang2 commented on Nov 27, 2019

YvonneYang2 commented on Dec 2, 2019

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions