sof [BUG] I/O error when testing multiple-pipeline on MTL/LNL NOCODEC

Describe the bug Observed this issue in daily test. There's no obvious error in kernel message, but there're some dai_intel_ssp errors in mtrace. The reproduction rate is ~50%.

[   41.216620] <inf> dma: dma_put: dma_put(), dma = 0x400f69c0, sref = 1
[   41.216633] <inf> dai_intel_ssp: dai_ssp_pm_runtime_dis_ssp_power: dai_ssp_pm_runtime_dis_ssp_power index 0
[   41.216766] <err> dai_intel_ssp: dai_ssp_poll_for_register_delay: dai_ssp_poll_for_register_delay poll timeout reg 165892 mask 256 val 256 us 125
[   41.216776] <wrn> dai_intel_ssp: dai_ssp_pm_runtime_dis_ssp_power: dai_ssp_pm_runtime_dis_ssp_power warning: timeout
[   41.216783] <inf> dai_intel_ssp: dai_ssp_pm_runtime_dis_ssp_power: dai_ssp_pm_runtime_dis_ssp_power I2SLCTL
[   41.217330] <inf> ipc: ipc_cmd: rx	: 0x12080000|0x0
[   41.217440] <inf> dma: dma_put: dma_put(), dma = 0x400f6a10, sref = 1
[   41.218488] <inf> ipc: ipc_cmd: rx	: 0x13000002|0x1
[   41.218531] <inf> pipe: pipeline_trigger: pipe:16 0x0 pipe trigger cmd 0
[   41.218591] <inf> src: src_reset: comp:16 0x10008 src_reset()
[   41.218605] <inf> pipe: pipeline_trigger: pipe:15 0x0 pipe trigger cmd 0
[   41.218658] <inf> dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 2a000, reg 34, mask 100, value 0
[   41.218736] <inf> dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 2a000, reg 8, mask 80, value 80
[   41.218748] <inf> dai_intel_ssp: dai_ssp_stop: dai_ssp_stop RX stop
[   41.218755] <inf> dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 2a000, reg 4, mask 300000, value 0
[   41.218761] <inf> dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 2a000, reg 0, mask 80, value 0
[   41.218770] <inf> dai_intel_ssp: dai_ssp_stop: dai_ssp_stop SSE clear SSP2
[   41.218785] <inf> dma_intel_adsp_gpdma: intel_adsp_gpdma_power_off: intel_adsp_gpdma_power_off: dma dma@7d000 power off
[   41.219226] <inf> ipc: ipc_cmd: rx	: 0x46130004|0x10008
[   41.219631] <inf> ipc: ipc_cmd: rx	: 0x120f0000|0x0
[   41.219676] <inf> dma: dma_put: dma_put(), dma = 0x400f69c0, sref = 0
[   41.219690] <inf> dai_intel_ssp: dai_ssp_pm_runtime_dis_ssp_power: dai_ssp_pm_runtime_dis_ssp_power index 2
[   41.219823] <err> dai_intel_ssp: dai_ssp_poll_for_register_delay: dai_ssp_poll_for_register_delay poll timeout reg 165892 mask 1024 val 1024 us 125
[   41.219830] <wrn> dai_intel_ssp: dai_ssp_pm_runtime_dis_ssp_power: dai_ssp_pm_runtime_dis_ssp_power warning: timeout
[   41.219836] <inf> dai_intel_ssp: dai_ssp_pm_runtime_dis_ssp_power: dai_ssp_pm_runtime_dis_ssp_power I2SLCTL
[   41.220363] <inf> ipc: ipc_cmd: rx	: 0x12100000|0x0
[   41.220401] <inf> src: src_free: comp:16 0x10008 src_free()
[   41.220463] <inf> dma: dma_put: dma_put(), dma = 0x400f6a10, sref = 0
[   41.220910] <inf> ipc: ipc_cmd: rx	: 0x47000000|0x0Terminated

To Reproduce ~/sof-test/test-case/multiple-pipeline.sh -f a -c 20 -l 50

Reproduction Rate

50%

Environment

Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
- Kernel: {0f2bd45a0723}
- SOF: {e1cd2d2c9959}
Name of the topology file
- Topology: {sof-mtl-nocodec.tplg}
Name of the platform(s) on which the bug is observed.
- Platform: {MTLP_RVP_NOCODEC}

Screenshots or console output

2023-11-21 23:41:45 UTC [REMOTE_INFO] ===== Testing: (Loop: 21/50) =====
2023-11-21 23:41:45 UTC [REMOTE_INFO] /home/ubuntu/sof-test/test-case/multiple-pipeline.sh will use topology /usr/lib/firmware/intel/development/sof-mtl-nocodec.tplg to run the test case
2023-11-21 23:41:45 UTC [REMOTE_INFO] Pipeline list to ignore is specified, will ignore 'pcm=HDA Digital' in test case
2023-11-21 23:41:45 UTC [REMOTE_INFO] Run command to get pipeline parameters
2023-11-21 23:41:45 UTC [REMOTE_COMMAND] sof-tplgreader.py /usr/lib/firmware/intel/development/sof-mtl-nocodec.tplg -f 'type:playback  & ~pcm:HDMI' -b ' pcm:HDA Digital' -s 0 -e
2023-11-21 23:41:45 UTC [REMOTE_INFO] Testing: Port0 [hw:0,0]
2023-11-21 23:41:45 UTC [REMOTE_COMMAND] aplay   -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/zero -q
2023-11-21 23:41:45 UTC [REMOTE_INFO] Testing: Port2 [hw:0,2]
2023-11-21 23:41:45 UTC [REMOTE_COMMAND] aplay   -D hw:0,2 -c 2 -r 8000 -f S16_LE /dev/zero -q
2023-11-21 23:41:45 UTC [REMOTE_INFO] Testing: Deepbuffer Port0 [hw:0,31]
2023-11-21 23:41:45 UTC [REMOTE_COMMAND] aplay   -D hw:0,31 -c 2 -r 48000 -f S16_LE /dev/zero -q
2023-11-21 23:41:45 UTC [REMOTE_INFO] Testing: Port1 [hw:0,1]
2023-11-21 23:41:45 UTC [REMOTE_COMMAND] aplay   -D hw:0,1 -c 2 -r 48000 -f S16_LE /dev/zero -q
2023-11-21 23:41:45 UTC [REMOTE_INFO] /home/ubuntu/sof-test/test-case/multiple-pipeline.sh will use topology /usr/lib/firmware/intel/development/sof-mtl-nocodec.tplg to run the test case
2023-11-21 23:41:45 UTC [REMOTE_INFO] Pipeline list to ignore is specified, will ignore 'pcm=HDA Digital' in test case
2023-11-21 23:41:45 UTC [REMOTE_INFO] Run command to get pipeline parameters
2023-11-21 23:41:45 UTC [REMOTE_COMMAND] sof-tplgreader.py /usr/lib/firmware/intel/development/sof-mtl-nocodec.tplg -f 'type:capture & ~pcm:Amplifier Reference & ~pcm:HDMI' -b ' pcm:HDA Digital' -s 0 -e
2023-11-21 23:41:45 UTC [REMOTE_INFO] Testing: Port0 [hw:0,0]
2023-11-21 23:41:45 UTC [REMOTE_COMMAND] arecord   -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/null -q
2023-11-21 23:41:45 UTC [REMOTE_INFO] Testing: DMIC Raw [hw:0,10]
2023-11-21 23:41:45 UTC [REMOTE_COMMAND] arecord   -D hw:0,10 -c 4 -r 48000 -f S32_LE /dev/null -q
2023-11-21 23:41:45 UTC [REMOTE_INFO] Testing: Port0 2nd Capture [hw:0,12]
2023-11-21 23:41:45 UTC [REMOTE_COMMAND] arecord   -D hw:0,12 -c 2 -r 48000 -f S16_LE /dev/null -q
2023-11-21 23:41:45 UTC [REMOTE_INFO] Testing: DMIC SFX1 [hw:0,27]
2023-11-21 23:41:45 UTC [REMOTE_COMMAND] arecord   -D hw:0,27 -c 4 -r 48000 -f S32_LE /dev/null -q
2023-11-21 23:41:45 UTC [REMOTE_INFO] Testing: DMIC SFX2 [hw:0,28]
2023-11-21 23:41:45 UTC [REMOTE_COMMAND] arecord   -D hw:0,28 -c 4 -r 48000 -f S32_LE /dev/null -q
2023-11-21 23:41:45 UTC [REMOTE_INFO] Testing: Port2 [hw:0,2]
2023-11-21 23:41:45 UTC [REMOTE_COMMAND] arecord   -D hw:0,2 -c 2 -r 8000 -f S16_LE /dev/null -q
2023-11-21 23:41:45 UTC [REMOTE_INFO] Testing: Port1 [hw:0,1]
2023-11-21 23:41:45 UTC [REMOTE_COMMAND] arecord   -D hw:0,1 -c 2 -r 48000 -f S16_LE /dev/null -q
2023-11-21 23:41:45 UTC [REMOTE_INFO] wait 0.5s for aplay_opts()
2023-11-21 23:41:45 UTC [REMOTE_INFO] checking pipeline status
arecord: pcm_read:2221: read error: Input/output error
2023-11-21 23:41:46 UTC [REMOTE_INFO] Letting playback/capture run for 5s
2023-11-21 23:41:51 UTC [REMOTE_INFO] checking pipeline status again
2023-11-21 23:41:51 UTC [REMOTE_ERROR] Running process count is 10, but 11 is expected
44101 aplay -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/zero -q
44110 aplay -D hw:0,2 -c 2 -r 8000 -f S16_LE /dev/zero -q
44119 aplay -D hw:0,31 -c 2 -r 48000 -f S16_LE /dev/zero -q
44127 aplay -D hw:0,1 -c 2 -r 48000 -f S16_LE /dev/zero -q
44146 arecord -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/null -q
44157 arecord -D hw:0,10 -c 4 -r 48000 -f S32_LE /dev/null -q
44167 arecord -D hw:0,12 -c 2 -r 48000 -f S16_LE /dev/null -q
44173 arecord -D hw:0,27 -c 4 -r 48000 -f S32_LE /dev/null -q
44183 arecord -D hw:0,28 -c 4 -r 48000 -f S32_LE /dev/null -q
44193 arecord -D hw:0,2 -c 2 -r 8000 -f S16_LE /dev/null -q
2023-11-21 23:41:51 UTC [REMOTE_INFO] Starting func_exit_handler(1)
2023-11-21 23:41:51 UTC [REMOTE_ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
2023-11-21 23:41:51 UTC [REMOTE_ERROR]  func_error_exit()  @  /home/ubuntu/sof-test/test-case/multiple-pipeline.sh
2023-11-21 23:41:51 UTC [REMOTE_ERROR]  ps_checks()  @  /home/ubuntu/sof-test/test-case/multiple-pipeline.sh:146
2023-11-21 23:41:51 UTC [REMOTE_ERROR]  main()  @  /home/ubuntu/sof-test/test-case/multiple-pipeline.sh:200
/home/ubuntu/sof-test/test-case/../case-lib/lib.sh: line 723: 44127 Killed                  aplay $SOF_ALSA_OPTS $SOF_APLAY_OPTS "$@"
/home/ubuntu/sof-test/test-case/../case-lib/lib.sh: line 723: 44101 Killed                  aplay $SOF_ALSA_OPTS $SOF_APLAY_OPTS "$@"
/home/ubuntu/sof-test/test-case/../case-lib/lib.sh: line 723: 44110 Killed                  aplay $SOF_ALSA_OPTS $SOF_APLAY_OPTS "$@"
/home/ubuntu/sof-test/test-case/../case-lib/lib.sh: line 723: 44119 Killed                  aplay $SOF_ALSA_OPTS $SOF_APLAY_OPTS "$@"
/home/ubuntu/sof-test/test-case/../case-lib/lib.sh: line 729: 44173 Killed                  arecord $SOF_ALSA_OPTS $SOF_ARECORD_OPTS "$@"
/home/ubuntu/sof-test/test-case/../case-lib/lib.sh: line 729: 44183 Killed                  arecord $SOF_ALSA_OPTS $SOF_ARECORD_OPTS "$@"
/home/ubuntu/sof-test/test-case/../case-lib/lib.sh: line 729: 44157 Killed                  arecord $SOF_ALSA_OPTS $SOF_ARECORD_OPTS "$@"
/home/ubuntu/sof-test/test-case/../case-lib/lib.sh: line 729: 44167 Killed                  arecord $SOF_ALSA_OPTS $SOF_ARECORD_OPTS "$@"
/home/ubuntu/sof-test/test-case/../case-lib/lib.sh: line 729: 44146 Killed                  arecord $SOF_ALSA_OPTS $SOF_ARECORD_OPTS "$@"
/home/ubuntu/sof-test/test-case/../case-lib/lib.sh: line 729: 44193 Killed                  arecord $SOF_ALSA_OPTS $SOF_ARECORD_OPTS "$@"
2023-11-21 23:41:54 UTC [REMOTE_INFO] pkill -TERM -f mtrace-reader.py
2023-11-21 23:41:54 UTC [REMOTE_INFO] nlines=20432 /home/ubuntu/sof-test/logs/multiple-pipeline/2023-11-21-23:39:11-32725/mtrace.txt
2023-11-21 23:41:58 UTC [REMOTE_INFO] ktime=5465 sof-test PID=39892: ending
2023-11-21 23:41:58 UTC [REMOTE_INFO] Test Result: FAIL!

dmesg.txt

mtrace.txt

Nov 22 '23 01:11 keqiaozhang

@keqiaozhang can i ask for the ipc payload logs?

Dec 08 '23 09:12 wszypelt

@keqiaozhang, thanks for logs, we made a python test and we're catching some errors, not sure if the same but we'll be working on the confirmation.

During checking the log I've noticed two things:

You're using Dmic Copier with container size 32/32bit witch is not supported - Dmic Copier is limited to 16/16bit or 24/32 bit.
EQ_IIR Large config set is for 2channels but format used by the module is 4 channels

I can't tell if those points can cause I/O error but they look like improper usage of the fw.

Logs used for reproduction script: https://sof-ci.ostc.intel.com/#/result/planresultdetail/35712?model=LNLM_RVP_NOCODEC&testcase=check-capture-100times

Dec 08 '23 10:12 mszleszy

@singalsu could you please verify config issues?

Dec 12 '23 08:12 abonislawski

@mszleszy It's more efficient for MCPS to treat DMIC FIFO as S32_LE data, no need to mask and shift every PCM sample. The LSB bits b(7:2) are zeros except b(1:0). For every channel there is a very very tiny DC value from those bits (channel number 0 - 3). It can be simply ignored. And if there is a high-pass IIR in the pipeline it will cancel the tiny DC.

Yep, I will check that IIR handles correctly the larger channels amount vs. blob. It's supposed to extrapolate the last channel config from the blob to added channels.

Dec 12 '23 09:12 singalsu

Seems the failing case is this " arecord -D hw:0,1 -c 2 -r 48000 -f S16_LE /dev/null -q", so not dmic. The pipeline is really with just a dai copier and host copier. Only unusual thing is that the pipeline is run on secondary core (core1), but based on FW log, all looks good.

I also checked another case spotted in Intel internal test plan #35606 . In this case, the fail is with multiple-pipeline-playback case, but curiously the fail is again on PCM1. Again a simple pipeline, but running on secondary core. When the fail occurs, we see this pattern:

[   92.359840] <inf> pipe: pipeline_trigger: pipe:5 0x0 pipe trigger cmd 7
[   92.359856] <inf> ll_schedule: zephyr_ll_task_schedule_common: task add 0xa01229c0 0x20210U priority 0 flags 0x0
[   92.360155] <inf> host_comp: host_get_copy_bytes_normal: comp:5 0x50004 no bytes to copy, available samples: 0, free_samples: 192
[   92.361070] <inf> host_comp: host_get_copy_bytes_normal: comp:5 0x50004 no bytes to copy, available samples: 0, free_samples: 192
[   92.362068] <inf> host_comp: host_get_copy_bytes_normal: comp:5 0x50004 no bytes to copy, available samples: 0, free_samples: 192

... from the timestamps we can gather the host DMA has not provided any data, so the DMA startup has failed. But nothing in the log hints at what would be causing this.

Dec 12 '23 13:12 kv2019i

@abonislawski @ranj063 I've tracked this bug back to kernel PR https://github.com/thesofproject/linux/pull/4705

I can't really yet point out anything wrong with the kernel PR itself, but repeated tests show the failure start/stops appearing when this change is included in kernel. I've tested both old kernels and reverting the PR from latest sof-dev, and results match.

Dec 13 '23 09:12 kv2019i

@singalsu could you please verify config issues?

Good that the mtrace.txt was attached. It can be seen that an IIR response (0) is assigned correctly to every channel 1 - 4:

[    0.277718] <inf> eq_iir: eq_iir_init_coef: comp:2 0x10 eq_iir_init_coef(): 1 responses, 2 channels, stream 4 channels
[    0.277725] <inf> eq_iir: eq_iir_init_coef: comp:2 0x10 eq_iir_init_coef(), ch 0 is set to response 0
[    0.277730] <inf> eq_iir: eq_iir_init_coef: comp:2 0x10 eq_iir_init_coef(), ch 1 is set to response 0
[    0.277735] <inf> eq_iir: eq_iir_init_coef: comp:2 0x10 eq_iir_init_coef(), ch 2 is set to response 0
[    0.277740] <inf> eq_iir: eq_iir_init_coef: comp:2 0x10 eq_iir_init_coef(), ch 3 is set to response 0

The code in https://github.com/thesofproject/sof/blob/d661aadd7ce7c37cf9bdbc55748ea92dc472b245/src/audio/eq_iir/eq_iir_generic.c#L238 ensures that channels 3 - 4 will use response that the blob sets for the last channel 2 from the configuration blob. So IIR is OK here.

Dec 13 '23 13:12 singalsu

Seems the failing case is this " arecord -D hw:0,1 -c 2 -r 48000 -f S16_LE /dev/null -q", so not dmic. The pipeline is really with just a dai copier and host copier. Only unusual thing is that the pipeline is run on secondary core (core1), but based on FW log, all looks good.

@kv2019i Long term, we should really use the memory Window so that each module instance can report its 32 bit position. This would be insightful and cheap as it could be a single cache line write to Window at the end of each LL pipeline task().

Dec 18 '23 16:12 lgirdwood

This bug was caused by XRUN with SSP which suddenly doesn't work, then pcm pointer was not updated in host, so ALSA aborted capture with IO error. It is not hard to reproduce when doing multiple-pipeline stress test. It often jumps out when you want to debug multi-pipeline error

Jan 08 '24 02:01 RanderWang

Looks like this test is using 11 PCM devices at the same time? Is this really intentional to test 4 playback and 7 capture streams in parallel? That makes no sense to me.

Jan 08 '24 08:01 plbossart

Just seen again now : https://sof-ci.01.org/softestpr/PR1146/build163/devicetest/index.html?model=MTLP_RVP_NOCODEC&testcase=multiple-pipeline-all

Jan 08 '24 19:01 marc-hb

That makes no sense to me.

If that does not make sense then it shouldn't fail only ~half~ 10% of the time with a cryptic aplay: pcm_write:2127: write error: Input/output error and zero error in neither the kernel logs nor the firmware log.

Jan 08 '24 19:01 marc-hb

This issue also happens on LNL-NOCODEC platform. Inner test ID:36748.

Jan 12 '24 01:01 keqiaozhang

This is a transient xrun issue and audio can recover after this error. Changing the priority to P2.

Jan 17 '24 06:01 keqiaozhang

IIRC some SSP state transitions had a busy wait which may put LL over budget for 1 tick.

Jan 17 '24 14:01 lgirdwood

This is a transient xrun issue and audio can recover after this error.

Thanks @keqiaozhang , how do you find this? Was there something in the logs?

Jan 17 '24 21:01 marc-hb

See again today in https://sof-ci.01.org/softestpr/PR1146/build163/devicetest/index.html?model=MTLP_RVP_NOCODEC&testcase=multiple-pipeline-all

Didn't spot any xrun.

Jan 22 '24 23:01 marc-hb

See again today in https://sof-ci.01.org/softestpr/PR1146/build163/devicetest/index.html?model=MTLP_RVP_NOCODEC&testcase=multiple-pipeline-all

Didn't spot any xrun.

[    0.428753] <wrn> dai_comp: dai_common_copy: comp:17 0x150004 dai_zephyr_copy(): nothing to copy
[    0.429720] <inf> host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192
[    0.430696] <inf> host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192
[    0.431695] <inf> host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192
[    0.432685] <inf> host_comp: host_get_copy_bytes_normal: 
...

Much longer version:

[ 0.428753] dai_comp: dai_common_copy: comp:17 0x150004 dai_zephyr_copy(): nothing to copy [ 0.429720] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.430696] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.431695] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.432685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.433683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.434696] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.435731] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.436681] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.437683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.438696] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.439675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.440685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.441715] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.442703] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.443685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.444683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.445683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.446685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.447716] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.448685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.449695] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.450676] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.451675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.452683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.453733] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.454683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.455685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.456676] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.457683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.458696] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.459715] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.460685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.461683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.462676] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.463695] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.464685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.465716] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.466685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.467685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.468696] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.469683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.470696] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.471745] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.472690] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.473683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.474676] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.475685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.476695] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.477713] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.478683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.479685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.480683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.481683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.482685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.483718] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.484676] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.485683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.486675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.487695] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.488683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.489730] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.490681] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.491675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.492698] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.493683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.494683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.495711] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.496685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.497683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.498675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.499683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.500676] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.501708] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.502676] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.503675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.504683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.505683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.506675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.507725] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.508690] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.509683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.510696] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.511685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.512683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.513715] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.514685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.515675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.516695] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.517683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.518675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.519706] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.520685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.521695] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.522696] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.523683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.524676] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.525723] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.526681] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.527681] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.528683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.529683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.530675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.531706] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.532676] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.533683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.534685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.535685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.536683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.537715] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.538675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.539675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.540695] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.541683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.542676] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.543723] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.544685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.545695] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.546685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.547675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.548705] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.549716] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.550696] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.551685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.552683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.553683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.554696] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.555715] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.556676] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.557698] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.558696] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.559683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.560685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.561731] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.562683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.563685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.564683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.565683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.566685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.567716] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.568685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.569683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.570696] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.571696] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.572685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.573716] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.574685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.575683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.576683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.577683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.578696] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.579728] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.580681] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.581695] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.582676] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.583675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.584685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.585716] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.586696] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.587693] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.588683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.589675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.590698] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.591711] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.592685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.593683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.594676] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.595695] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.596683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.597730] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.598690] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.599683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.600676] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.601683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.602696] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.603715] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.604685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.605695] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.606675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.607695] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.608683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.609711] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.610683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.611685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.612698] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.613695] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.614696] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.615730] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.616683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.617683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.618675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.619685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.620696] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.621713] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.622676] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.623695] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.624685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.625683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.626675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.627701] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.628685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.629683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.630696] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.631683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.632683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.633731] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.634691] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.635683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.636705] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.637683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.638675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.639706] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.640676] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.641683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.642700] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.643685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.644681] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.645725] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.646681] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.647683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.648695] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.649683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.650675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.651721] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.652696] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.653683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.654695] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.655683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.656683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.657715] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.658675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.659675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.660683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.661683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.662683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.663715] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.664676] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.665683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.666696] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.667685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.668683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.669731] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.670681] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.671675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.672683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.673683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.674696] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.675726] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.676676] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.677683] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.678696] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.679675] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.680685] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.681716] host_comp: host_get_copy_bytes_normal: comp:11 0xe0004 no bytes to copy, available samples: 0, free_samples: 192 [ 0.682685]

Jan 23 '24 08:01 RanderWang

@RanderWang this is known spam:

#8761

Jan 25 '24 17:01 marc-hb

For MTL, DSP Panic found today.

TPLG=/lib/firmware/intel/development/sof-mtl-nocodec.tplg MODEL=MTLP_RVP_NOCODEC SOF_TEST_INTERVAL=5 ~/sof-test/test-case/multiple-pipeline.sh -f p -l 50

dmesg has FW reported error: 104

[ 4173.384884] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: FW reported error: 104 - Other failure of module instance initialization request
[ 4173.384937] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc error for msg 0x40020004|0x20015
[ 4173.384975] kernel: Message payload: 00000000: 00001498 000000c0 00000180 00000001
[ 4173.384979] kernel: Message payload: 00000010: 0000bb80 00000010 ffffff10 00000001
[ 4173.384981] kernel: Message payload: 00000020: 00000000 00011002 0000bb80 00000020
[ 4173.384983] kernel: Message payload: 00000030: ffffff10 00000001 00000000 00012002
[ 4173.384985] kernel: Message payload: 00000040: 00000000 00000000 00000180 00000001
[ 4173.384987] kernel: Message payload: 00000050: 00000000
[ 4173.384989] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: failed to create module host-copier.0.playback
[ 4173.385019] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x12020000|0x0: GLB_DELETE_PIPELINE
[ 4173.385626] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x32000000|0x0: GLB_DELETE_PIPELINE
[ 4173.385645] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x12020000|0x0: GLB_DELETE_PIPELINE
[ 4173.385652] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget pipeline.1 freed
[ 4173.385657] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Failed to set up connected widgets
[ 4173.385690] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: error: failed widget list set up for pcm 0 dir 0
[ 4173.385715] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_hw_params on 0000:00:1f.3: -22

DSP Panic/exception was found in mtrace

[ 4173.388185] <wrn> ipc: ipc_pipeline_complete: ipc_pipeline_complete(): no scheduling component specified, use comp 2
[ 4173.388570] <inf> ipc: ipc_cmd: rx	: 0x13000004|0x1
[ 4173.388681] <err> buffer: buffer_alloc: buffer_alloc(): could not alloc structure
[ 4173.388686] <err> dai_comp: dai_set_dma_buffer: comp:1 0x10004 dai_set_dma_buffer(): failed to alloc dma buffer
[ 4173.388708] <err> dai_comp: dai_common_params: comp:1 0x10004 dai_zephyr_params(): alloc dma buffer failed.
[ 4173.388715] <err> module_adapter: module_prepare: comp:1 0x10004 module_prepare() error -12: module specific prepare failed, comp_id 65540
[ 4173.388723] <err> module_adapter: module_adapter_prepare: comp:1 0x10004 module_adapter_prepare() error fffffff4: module prepare failed
[ 4173.388730] <err> pipe: pipeline_prepare: pipe:1 0x0 pipeline_prepare(): ret = -12, dev->comp.id = 3
[ 4173.388735] <err> ipc: ipc4_pcm_params: ipc: pipe 1 comp 0 prepare failed -12
[ 4173.388768] <inf> component: comp_set_state: comp:1 0x10004 comp_set_state(), state already set to 1
[ 4173.388776] <err> ipc: ipc_cmd: ipc4: FW_GEN_MSG failed with err 7
[ 4173.389285] <inf> ipc: ipc_cmd: rx	: 0x47000000|0x0
[ 4173.389421] <err> os: print_fatal_exception:  ** FATAL EXCEPTION
[ 4173.389430] <err> os: print_fatal_exception:  ** CPU 1 EXCCAUSE 63 (zephyr exception)
[ 4173.389435] <err> os: print_fatal_exception:  **  PC 0xa00663db VADDR (nil)
[ 4173.389441] <err> os: print_fatal_exception:  **  PS 0x60a20
[ 4173.389446] <err> os: print_fatal_exception:  **    (INTLEVEL:0 EXCM: 0 UM:1 RING:0 WOE:1 OWB:10 CALLINC:2)
[ 4173.389453] <err> os: xtensa_dump_stack:  **  A0 0xa0070cea  SP 0xa010eed0  A2 0x4  A3 0x1
[ 4173.389458] <err> os: xtensa_dump_stack:  **  A4 0x1  A5 0x60a23  A6 0x40112874  A7 (nil)
[ 4173.389465] <err> os: xtensa_dump_stack:  **  A8 0xa0045755  A9 0xa010eea0 A10 0x1 A11 0x401128a8
[ 4173.389470] <err> os: xtensa_dump_stack:  ** A12 0x40112061 A13 0x40112061 A14 0x3f A15 (nil)
[ 4173.389476] <err> os: xtensa_dump_stack:  ** LBEG 0xa004575e LEND 0xa004576b LCOUNT 0xa0070ca6
[ 4173.389481] <err> os: xtensa_dump_stack:  ** SAR 0x1c
[ 4173.389488] <err> os: xtensa_dump_stack:  **  THREADPTR (nil)

Intel Internal daily test: planresultdetail/39027?model=MTLP_RVP_NOCODEC&testcase=multiple-pipeline-playback-50

Mar 20 '24 18:03 fredoh9

For LNL, there is no DSP panic.

TPLG=/lib/firmware/intel/development/sof-lnl-nocodec.tplg MODEL=LNLM_RVP_NOCODEC SOF_TEST_INTERVAL=5 ~/sof-test/test-case/multiple-pipeline.sh -f p -l 50

dmesg has FW reported error: 104

[ 3866.049516] kernel: snd_sof:sof_widget_setup_unlocked: sof-audio-pci-intel-lnl 0000:00:1f.3: widget smart_amp.2.1 setup complete
[ 3866.049519] kernel: snd_sof:sof_ipc4_widget_setup: sof-audio-pci-intel-lnl 0000:00:1f.3: Create widget dai-copier.SSP.NoCodec-0.playback (pipe 2) - ID 4, instance 1, core 0
[ 3866.049521] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-lnl 0000:00:1f.3: ipc tx      : 0x40010004|0x10056: MOD_INIT_INSTANCE [data size: 344]
[ 3866.050072] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-lnl 0000:00:1f.3: ipc tx reply: 0x60000068|0x10056: MOD_INIT_INSTANCE
[ 3866.050075] kernel: sof-audio-pci-intel-lnl 0000:00:1f.3: FW reported error: 104 - Other failure of module instance initialization request
[ 3866.050210] kernel: sof-audio-pci-intel-lnl 0000:00:1f.3: ipc error for msg 0x40010004|0x10056

Intel Internal daily test: planresultdetail/39028?model=LNLM_RVP_NOCODEC&testcase=multiple-pipeline-playback-50

Mar 20 '24 18:03 fredoh9

@fredoh9 I think the MTL case is now a new bug and a case of https://github.com/thesofproject/sof/issues/8966 . And I think the the LNL fails are with the same cause

Mar 20 '24 18:03 kv2019i

FW reported error: 104 - Other failure of module instance initialization request

Same message as in:

https://github.com/thesofproject/linux/issues/4832

Mar 20 '24 18:03 marc-hb

This should be fixed now, if now new findings, let's close this.

Mar 22 '24 14:03 kv2019i