[BUG]ipc timed out when PIPE_NEW/TRIG_START and schedule ERROR,xrun on CML_RVP_SDWCML_RVP_NOCODEC/CML_RVP_NOCODEC

[XiaoyunWu6666]

Describe the bug
found in inner daily 6244 on CML_RVP_SDW
When trying to run aplay on multiple pipelines , IO error occurred with ipc timed out when issuing TRIG_START , in the 1st iteration

in inner daily 6272 on model=CML_RVP_NOCODEC in testcase=multiple-pipeline-playback-50,
When trying to run aplay on multiple pipelines , IO error occurred with ipc timed out when issuing PIPE_NEW, in the 5th iteration

in inner daily 6292,on model=CML_RVP_NOCODEC in testcase=multiple-pause-resume
ipc timed out when CONFIG , schedule ERROR and xrun in the etrace (details are in the comment below)

To Reproduce
TPLG=/lib/firmware/intel/sof-tplg/sof-cml-rt700-4ch.tplg ~/sof-test/test-case/multiple-pipeline.sh -f p -l 50

Reproduction Rate
not sure

Environment
Kernel Branch: topic/sof-dev
Kernel Commit: bed17ef
SOF Branch: main
SOF Commit: 8fa5ff5
Topology:/lib/firmware/intel/sof-tplg/sof-cml-rt700-4ch.tplg
Platform: CML_RVP_SDW

Screenshots or console output
[console]

(in the first iteration)
2021-08-31 22:22:31 UTC [REMOTE_INFO] Testing: Jack Out [hw:0,0]
2021-08-31 22:22:31 UTC [REMOTE_COMMAND] aplay   -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/zero -q
2021-08-31 22:22:31 UTC [REMOTE_INFO] Testing: HDMI 1 [hw:0,5]
2021-08-31 22:22:31 UTC [REMOTE_COMMAND] aplay   -D hw:0,5 -c 2 -r 48000 -f S16_LE /dev/zero -q
2021-08-31 22:22:31 UTC [REMOTE_INFO] Testing: HDMI 2 [hw:0,6]
2021-08-31 22:22:31 UTC [REMOTE_COMMAND] aplay   -D hw:0,6 -c 2 -r 48000 -f S16_LE /dev/zero -q
2021-08-31 22:22:31 UTC [REMOTE_INFO] Testing: HDMI 3 [hw:0,7]
2021-08-31 22:22:31 UTC [REMOTE_INFO] wait 0.5s for aplay_opts()
2021-08-31 22:22:31 UTC [REMOTE_COMMAND] aplay   -D hw:0,7 -c 2 -r 48000 -f S16_LE /dev/zero -q
2021-08-31 22:22:31 UTC [REMOTE_INFO] checking pipeline status
2021-08-31 22:22:31 UTC [REMOTE_INFO] Letting playback/capture run for 5s
error: in logger_read(), fread(..., /sys/kernel/debug/sof/trace) failed: Operation not permitted(-1)
aplay: pcm_write:2061: write error: Input/output error
aplay: pcm_write:2061: write error: Input/output error

[dmesg]

[ 3489.592359] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 3489.592437] kernel: rt700 sdw:1:025d:0700:00: [rt700_sdw_write] 3501 <= 0003
[ 3489.592498] kernel: rt700 sdw:1:025d:0700:00: [rt700_sdw_write] 3501 <= 0000
[ 3489.592602] kernel: rt700 sdw:1:025d:0700:00: [rt700_sdw_write] 7321 83a1 <= b000
[ 3489.592643] kernel: rt700 sdw:1:025d:0700:00: [rt700_sdw_write] 3602 <= 0010
[ 3489.592726] kernel: rt700 sdw:1:025d:0700:00: [rt700_sdw_write] 7314 8394 <= b000
[ 3489.592782] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 1
[ 3489.592948] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: In hda_link_pcm_trigger cmd=1
[ 3489.592952] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: trigger stream 6 dir 0 cmd 1
[ 3489.593079] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: In hda_link_pcm_trigger cmd=1
[ 3489.593084] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: trigger stream 7 dir 0 cmd 1
[ 3489.593181] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x14001e successful
[ 3489.593202] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: FW Poll Status: reg[0x1a0]=0x34001e successful
[ 3489.593205] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 3489.593448] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 3489.593455] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 3489.593597] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: FW Poll Status: reg[0x1c0]=0x44001e successful
[ 3489.593839] kernel: soundwire_intel soundwire_intel.link.1: Slave status change: 0x40
[ 3489.593877] kernel: rt700 sdw:1:025d:0700:00: [rt700_sdw_write] 00e0 <= 0001
[ 3489.593935] kernel: rt700 sdw:1:025d:0700:00: [rt700_sdw_write] 00f0 <= 0001
[ 3489.593936] kernel: rt700 sdw:1:025d:0700:00: rt700_clock_config complete, clk_freq=6000000
[ 3489.594500] kernel: rt700 sdw:1:025d:0700:00: Slave impl defined interrupt
[ 3489.594501] kernel: rt700 sdw:1:025d:0700:00: rt700_interrupt_callback control_port_stat=4
[ 3489.594689] kernel: soundwire_intel soundwire_intel.link.1: Slave status change: 0x20
[ 3489.850130] kernel: rt700 sdw:1:025d:0700:00: [rt700_sdw_read] b921 0000 => 80000000
[ 3489.850864] kernel: rt700 sdw:1:025d:0700:00: [rt700_sdw_read] 7520 85a0 9c20 aca0 => 00000400
[ 3489.851573] kernel: rt700 sdw:1:025d:0700:00: [rt700_sdw_read] 7520 85a0 9c20 aca0 => 00000000
[ 3489.851585] kernel: rt700 sdw:1:025d:0700:00: in rt700_jack_detect_handler, jack_type=0x3
[ 3489.851593] kernel: rt700 sdw:1:025d:0700:00: in rt700_jack_detect_handler, btn_type=0x0
[ 3490.049798] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 3490.049830] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 3490.097538] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx timed out for 0x60040000 (msg/reply size: 12/12)
[ 3490.097560] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: preventing DSP entering D3 state to preserve context
[ 3490.097566] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 3490.097581] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000781 rirb 00
[ 3490.097590] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 3490.097602] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 3490.097610] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 3490.097616] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 3490.097627] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: status: fw entered - code 00000005
[ 3490.097892] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 3490.097900] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 3490.097923] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
[ 3490.097935] kernel:  HDMI 2: ASoC: trigger FE cmd: 1 failed: -110
[ 3490.097947] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: trigger stream 6 dir 0 cmd 0
[ 3490.097961] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 3490.097973] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: trace IO error

[etrace]

[       89202.756872] (       89202.757812) c0 edf-schedule       /schedule/edf_schedule.c:117  ERROR schedule_edf_task(), task already queued or running 3

[lgirdwood]

@XiaoyunWu6666 thanks, do you have the FW register dump and stack trace ? (its part of dmesg)

[plbossart]

@lgirdwood has anything changed in the firmware for triggers? I don't think we've had any changes for SoundWire merged on the kernel side.

[lgirdwood]

@plbossart yes it's probably FW and not driver. @lyakh can you take a look. Thanks !

[XiaoyunWu6666]

in inner daily 6272 on model=CML_RVP_NOCODEC in testcase=multiple-pipeline-playback-50, When trying to run aplay on multiple pipelines , IO error occurred with ipc timed out when issuing PIPE_NEW, in the 5th iteration

Etrace has schedule ERROR too

[ 4270.919815] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: stream_tag 3
[ 4270.920163] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 4270.920169] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x30100000: GLB_TPLG_MSG: PIPE_NEW
[ 4271.417477] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 4271.417528] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 4271.425311] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx timed out for 0x30100000 (msg/reply size: 48/20)
[ 4271.425332] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: preventing DSP entering D3 state to preserve context
[ 4271.425338] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 4271.425359] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000181 rirb 00
[ 4271.425369] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 4271.425389] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 4271.425398] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 4271.425405] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 4271.425416] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: status: fw entered - code 00000005
[ 4271.425683] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 4271.425692] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 4271.425708] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: failed to load widget PIPELINE.9.SSP2.OUT
[ 4271.425717] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: failed widget list set up for pcm 2 dir 0
[ 4271.425728] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_hw_params on 0000:00:1f.3: -110
[ 4271.425743] kernel:  Port2: ASoC: soc_pcm_hw_params() failed (-110)
[ 4271.425764] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: trace IO error
[ 4271.425782] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[ 4271.917466] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 4271.917510] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 4271.929377] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx timed out for 0x80010000 (msg/reply size: 216/12)
[ 4271.929403] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: failed resetting DAI config for SSP2.OUT

[etrace]

c0 edf-schedule       /schedule/edf_schedule.c:117  ERROR schedule_edf_task(), task already queued or running 3

on CML_RVP_NOCODEC,can manually reproduce the problem , manual reproduced it and found xrun in etrace

[   139671933.512436] (     5272692.500000) c0 edf-schedule       /schedule/edf_schedule.c:117  ERROR schedule_edf_task(), task already queued or running 3
[   147335386.489168] (     7663453.000000) c0 dw-dma                 src/drivers/dw/dma.c:1102 ERROR dw_dma_get_data_size(): xrun detected
[   147335397.426667] (          10.937500) c0 dai          1.2            src/audio/dai.c:892  ERROR dai_report_xrun(): underrun due to no data available
[   147335408.260000] (          10.833333) c0 dai          1.2            src/audio/dai.c:687  ERROR comp_underrun(): dev->comp.id = 2, source->avail = 0, copy_bytes = 0
[   147335421.020416] (          12.760416) c0 pipe         1.3   ....../pipeline-stream.c:318  ERROR pipeline_trigger_run(): ret = -22, host->comp.id = 0, cmd = 8
[   147335432.687083] (          11.666666) c0 pipe         1.3   ......../pipeline-xrun.c:159  ERROR pipeline_xrun(): Pipelines notification about XRUN failed, ret = -22
[   147335457.478748] (          24.791666) c0 pipe         1.3   ....../pipeline-stream.c:205  ERROR pipeline_copy(): ret = -61, start->comp.id = 2, dir = 1
[   147335468.676664] (          11.197916) c0 pipe         1.3   ..../pipeline-schedule.c:106  ERROR pipeline_task(): xrun recovery failed! pipeline is stopped.
[   147966657.037000] (      631188.375000) c0 dw-dma                 src/drivers/dw/dma.c:1102 ERROR dw_dma_get_data_size(): xrun detected
[   147966667.766166] (          10.729166) c0 dai          3.14           src/audio/dai.c:892  ERROR dai_report_xrun(): underrun due to no data available
[   147966678.391166] (          10.625000) c0 dai          3.14           src/audio/dai.c:687  ERROR comp_underrun(): dev->comp.id = 14, source->avail = 0, copy_bytes = 0
[   147966690.005749] (          11.614583) c0 pipe         3.15  ....../pipeline-stream.c:318  ERROR pipeline_trigger_run(): ret = -22, host->comp.id = 12, cmd = 8
[   147966701.724498] (          11.718750) c0 pipe         3.15  ......../pipeline-xrun.c:159  ERROR pipeline_xrun(): Pipelines notification about XRUN failed, ret = -22
[   147966726.203664] (          24.479166) c0 pipe         3.15  ....../pipeline-stream.c:205  ERROR pipeline_copy(): ret = -61, start->comp.id = 14, dir = 1
[   147966737.193247] (          10.989583) c0 pipe         3.15  ..../pipeline-schedule.c:106  ERROR pipeline_task(): xrun recovery failed! pipeline is stopped.

[coredump-to-gdb logs]

# Core header:

# arch        00000000 # totalsize   00000000 # stackptr    00000000 # stackoffset 00000000
# configidhi  00000000 # configidlo  00000000 # numaregs    00000000

# CPU registers:

# exccause    00000000 # excvaddr    00000000 # ps          00000000
# epc1        00000000 # epc2        00000000 # epc3        00000000 # epc4        00000000
# epc5        00000000 # epc6        00000000 # epc7        00000000
# eps2        00000000 # eps3        00000000 # eps4        00000000 # eps5        00000000
# eps6        00000000 # eps7        00000000
# depc        00000000 # intenable   00000000 # interrupt   00000000 # sar         00000000
# debugcause  00000000
# windowbase  00000000 # windowstart 00000000
# excsave1    00000000
# ar0         00000000 # ar1         00000000 # ar2         00000000 # ar3         00000000
# ar4         00000000 # ar5         00000000 # ar6         00000000 # ar7         00000000
# ar8         00000000 # ar9         00000000 # ar10        00000000 # ar11        00000000
# ar12        00000000 # ar13        00000000 # ar14        00000000 # ar15        00000000
# ar16        00000000 # ar17        00000000 # ar18        00000000 # ar19        00000000
# ar20        00000000 # ar21        00000000 # ar22        00000000 # ar23        00000000
# ar24        00000000 # ar25        00000000 # ar26        00000000 # ar27        00000000
# ar28        00000000 # ar29        00000000 # ar30        00000000 # ar31        00000000
# ar32        00000000 # ar33        00000000 # ar34        00000000 # ar35        00000000
# ar36        00000000 # ar37        00000000 # ar38        00000000 # ar39        00000000
# ar40        00000000 # ar41        00000000 # ar42        00000000 # ar43        00000000
# ar44        00000000 # ar45        00000000 # ar46        00000000 # ar47        00000000
# ar48        00000000 # ar49        00000000 # ar50        00000000 # ar51        00000000
# ar52        00000000 # ar53        00000000 # ar54        00000000 # ar55        00000000
# ar56        00000000 # ar57        00000000 # ar58        00000000 # ar59        00000000
# ar60        00000000 # ar61        00000000 # ar62        00000000 # ar63        00000000


# windowbase: 0
#
# windowstart: b0

#      reg         a0         a1
#                  (return)   (sptr)
#      ---         --------   -------

# Stack dumped from 00000000 dwords num 406

# *EXCEPTION*

# exccause: IllegalInstructionCause: Illegal instruction

[lgirdwood]

@XiaoyunWu6666 we really need the FW stack trace from the FW crash AND the FW logs attached.

The FW stack trace needs to be enabled in the kernel for all daily testing otherwise its impossible for developers to debug based on the message above. @keyonjie can you help @XiaoyunWu6666 configure her kernels to dump the FW stack trace ?

[keyonjie]

@lgirdwood do you mean using the sof-coredump-reader.py to read out the FW call trace from the /sys/kernel/debug/sof/exception?

[lgirdwood]

@lgirdwood do you mean using the sof-coredump-reader.py to read out the FW call trace from the /sys/kernel/debug/sof/exception?

Yes, this would be very nice, and the stack dump that is the dmesg. These may not be available if FW is spinning so even just a statement saying that neither is available is also helpful (as it tells us FW is probably spinning somewhere).

[plbossart]

@lgirdwood if we have similar bugs for SoundWire and nocodec topologies, this points to a problem that can be checked on UpExtreme. My money is on the trace changes by @keyonjie and the scheduling changes by @lyakh

[plbossart]

Not able to reproduce the error reported in nocodec mode w/ test 6272:
TPLG=/lib/firmware/intel/sof-tplg/sof-cnl-nocodec.tplg ~/sof-test/test-case/multiple-pipeline.sh -f p -l 50

SOF: 94db5c7 toolschain: update header files to support newer toolschain
kernel: 6a95ae1a6a50 fixup! ASoC: SOF: handle paused streams during system suspend

[plbossart]

Never mind, I retried and it failed at iteration 35 on my UpExtreme. See logs attached
test.tar.gz

TPLG=/lib/firmware/intel/sof-tplg/sof-cnl-nocodec.tplg ~/sof-test/test-case/multiple-pipeline.sh -f p -l 50