2022-11-23 09:32:29 UTC [INFO] ===== Testing: (Loop: 28/200) =====
2022-11-23 09:32:29 UTC [INFO] /home/test/sof-test/test-case/multiple-pipeline.sh will use topology /lib/firmware/intel/avs-tplg/sof-tgl-nocodec.tplg to run the test case
2022-11-23 09:32:29 UTC [INFO] Pipeline list to ignore is specified, will ignore 'pcm=HDA Digital' in test case
2022-11-23 09:32:29 UTC [INFO] Run command to get pipeline parameters
2022-11-23 09:32:29 UTC [COMMAND] sof-tplgreader.py /lib/firmware/intel/avs-tplg/sof-tgl-nocodec.tplg -f 'type:capture & ~pcm:Amplifier Reference' -b ' pcm:HDA Digital' -s 0 -e
2022-11-23 09:32:29 UTC [INFO] Testing: Port0 [hw:0,0]
2022-11-23 09:32:29 UTC [COMMAND] arecord -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/null -q
2022-11-23 09:32:29 UTC [INFO] Testing: ssp-capture [hw:0,12]
2022-11-23 09:32:29 UTC [COMMAND] arecord -D hw:0,12 -c 2 -r 48000 -f S16_LE /dev/null -q
2022-11-23 09:32:29 UTC [INFO] Testing: DMIC [hw:0,10]
2022-11-23 09:32:29 UTC [COMMAND] arecord -D hw:0,10 -c 4 -r 48000 -f S32_LE /dev/null -q
2022-11-23 09:32:29 UTC [INFO] /home/test/sof-test/test-case/multiple-pipeline.sh will use topology /lib/firmware/intel/avs-tplg/sof-tgl-nocodec.tplg to run the test case
2022-11-23 09:32:29 UTC [INFO] Pipeline list to ignore is specified, will ignore 'pcm=HDA Digital' in test case
2022-11-23 09:32:29 UTC [INFO] Run command to get pipeline parameters
2022-11-23 09:32:29 UTC [COMMAND] sof-tplgreader.py /lib/firmware/intel/avs-tplg/sof-tgl-nocodec.tplg -f 'type:playback ' -b ' pcm:HDA Digital' -s 0 -e
2022-11-23 09:32:29 UTC [INFO] Testing: Port0 [hw:0,0]
2022-11-23 09:32:29 UTC [INFO] wait 0.5s for aplay_opts()
2022-11-23 09:32:29 UTC [COMMAND] aplay -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/zero -q
2022-11-23 09:32:29 UTC [INFO] checking pipeline status
2022-11-23 09:32:29 UTC [INFO] Letting playback/capture run for 1s
2022-11-23 09:32:30 UTC [INFO] checking pipeline status again
2022-11-23 09:32:31 UTC [COMMAND] pkill -9 aplay arecord
/home/test/sof-test/test-case/../case-lib/lib.sh: line 624: 5229 Killed arecord $SOF_ALSA_OPTS $SOF_ARECORD_OPTS "$@"
/home/test/sof-test/test-case/../case-lib/lib.sh: line 624: 5213 Killed arecord $SOF_ALSA_OPTS $SOF_ARECORD_OPTS "$@"
/home/test/sof-test/test-case/../case-lib/lib.sh: line 624: 5222 Killed arecord $SOF_ALSA_OPTS $SOF_ARECORD_OPTS "$@"
/home/test/sof-test/test-case/../case-lib/lib.sh: line 618: 5249 Killed aplay $SOF_ALSA_OPTS $SOF_APLAY_OPTS "$@"
declare -- cmd="journalctl_cmd --since=@1669195948"
2022-11-23 09:32:32 UTC [INFO] ===== Testing: (Loop: 29/200) =====
2022-11-23 09:32:32 UTC [INFO] /home/test/sof-test/test-case/multiple-pipeline.sh will use topology /lib/firmware/intel/avs-tplg/sof-tgl-nocodec.tplg to run the test case
2022-11-23 09:32:32 UTC [INFO] Pipeline list to ignore is specified, will ignore 'pcm=HDA Digital' in test case
2022-11-23 09:32:32 UTC [INFO] Run command to get pipeline parameters
2022-11-23 09:32:32 UTC [COMMAND] sof-tplgreader.py /lib/firmware/intel/avs-tplg/sof-tgl-nocodec.tplg -f 'type:capture & ~pcm:Amplifier Reference' -b ' pcm:HDA Digital' -s 0 -e
2022-11-23 09:32:32 UTC [INFO] Testing: Port0 [hw:0,0]
2022-11-23 09:32:32 UTC [COMMAND] arecord -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/null -q
2022-11-23 09:32:32 UTC [INFO] Testing: ssp-capture [hw:0,12]
2022-11-23 09:32:32 UTC [COMMAND] arecord -D hw:0,12 -c 2 -r 48000 -f S16_LE /dev/null -q
2022-11-23 09:32:32 UTC [INFO] Testing: DMIC [hw:0,10]
2022-11-23 09:32:32 UTC [INFO] /home/test/sof-test/test-case/multiple-pipeline.sh will use topology /lib/firmware/intel/avs-tplg/sof-tgl-nocodec.tplg to run the test case
2022-11-23 09:32:32 UTC [COMMAND] arecord -D hw:0,10 -c 4 -r 48000 -f S32_LE /dev/null -q
2022-11-23 09:32:32 UTC [INFO] Pipeline list to ignore is specified, will ignore 'pcm=HDA Digital' in test case
2022-11-23 09:32:32 UTC [INFO] Run command to get pipeline parameters
2022-11-23 09:32:32 UTC [COMMAND] sof-tplgreader.py /lib/firmware/intel/avs-tplg/sof-tgl-nocodec.tplg -f 'type:playback ' -b ' pcm:HDA Digital' -s 0 -e
2022-11-23 09:32:32 UTC [INFO] Testing: Port0 [hw:0,0]
2022-11-23 09:32:32 UTC [INFO] wait 0.5s for aplay_opts()
2022-11-23 09:32:32 UTC [COMMAND] aplay -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/zero -q
2022-11-23 09:32:33 UTC [INFO] checking pipeline status
2022-11-23 09:32:33 UTC [INFO] Letting playback/capture run for 1s
2022-11-23 09:32:34 UTC [INFO] checking pipeline status again
2022-11-23 09:32:34 UTC [COMMAND] pkill -9 aplay arecord
/home/test/sof-test/test-case/../case-lib/lib.sh: line 624: 5360 Killed arecord $SOF_ALSA_OPTS $SOF_ARECORD_OPTS "$@"
/home/test/sof-test/test-case/../case-lib/lib.sh: line 624: 5351 Killed arecord $SOF_ALSA_OPTS $SOF_ARECORD_OPTS "$@"
/home/test/sof-test/test-case/../case-lib/lib.sh: line 624: 5371 Killed arecord $SOF_ALSA_OPTS $SOF_ARECORD_OPTS "$@"
/home/test/sof-test/test-case/../case-lib/lib.sh: line 618: 5387 Killed aplay $SOF_ALSA_OPTS $SOF_APLAY_OPTS "$@"
declare -- cmd="journalctl_cmd --since=@1669195951"
2022-11-23 09:32:35 UTC [INFO] ===== Testing: (Loop: 30/200) =====
2022-11-23 09:32:35 UTC [INFO] /home/test/sof-test/test-case/multiple-pipeline.sh will use topology /lib/firmware/intel/avs-tplg/sof-tgl-nocodec.tplg to run the test case
2022-11-23 09:32:35 UTC [INFO] Pipeline list to ignore is specified, will ignore 'pcm=HDA Digital' in test case
2022-11-23 09:32:35 UTC [INFO] Run command to get pipeline parameters
2022-11-23 09:32:35 UTC [COMMAND] sof-tplgreader.py /lib/firmware/intel/avs-tplg/sof-tgl-nocodec.tplg -f 'type:capture & ~pcm:Amplifier Reference' -b ' pcm:HDA Digital' -s 0 -e
2022-11-23 09:32:35 UTC [INFO] Testing: Port0 [hw:0,0]
2022-11-23 09:32:35 UTC [COMMAND] arecord -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/null -q
2022-11-23 09:32:35 UTC [INFO] Testing: ssp-capture [hw:0,12]
2022-11-23 09:32:35 UTC [COMMAND] arecord -D hw:0,12 -c 2 -r 48000 -f S16_LE /dev/null -q
2022-11-23 09:32:35 UTC [INFO] Testing: DMIC [hw:0,10]
2022-11-23 09:32:35 UTC [COMMAND] arecord -D hw:0,10 -c 4 -r 48000 -f S32_LE /dev/null -q
2022-11-23 09:32:35 UTC [INFO] /home/test/sof-test/test-case/multiple-pipeline.sh will use topology /lib/firmware/intel/avs-tplg/sof-tgl-nocodec.tplg to run the test case
2022-11-23 09:32:35 UTC [INFO] Pipeline list to ignore is specified, will ignore 'pcm=HDA Digital' in test case
2022-11-23 09:32:35 UTC [INFO] Run command to get pipeline parameters
2022-11-23 09:32:35 UTC [COMMAND] sof-tplgreader.py /lib/firmware/intel/avs-tplg/sof-tgl-nocodec.tplg -f 'type:playback ' -b ' pcm:HDA Digital' -s 0 -e
2022-11-23 09:32:35 UTC [INFO] Testing: Port0 [hw:0,0]
2022-11-23 09:32:35 UTC [INFO] wait 0.5s for aplay_opts()
2022-11-23 09:32:35 UTC [COMMAND] aplay -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/zero -q
2022-11-23 09:32:36 UTC [INFO] checking pipeline status
2022-11-23 09:32:36 UTC [INFO] Letting playback/capture run for 1s
2022-11-23 09:32:37 UTC [INFO] checking pipeline status again
2022-11-23 09:32:37 UTC [COMMAND] pkill -9 aplay arecord
/home/test/sof-test/test-case/../case-lib/lib.sh: line 624: 5505 Killed arecord $SOF_ALSA_OPTS $SOF_ARECORD_OPTS "$@"
/home/test/sof-test/test-case/../case-lib/lib.sh: line 624: 5498 Killed arecord $SOF_ALSA_OPTS $SOF_ARECORD_OPTS "$@"
/home/test/sof-test/test-case/../case-lib/lib.sh: line 624: 5489 Killed arecord $SOF_ALSA_OPTS $SOF_ARECORD_OPTS "$@"
/home/test/sof-test/test-case/../case-lib/lib.sh: line 618: 5525 Killed aplay $SOF_ALSA_OPTS $SOF_APLAY_OPTS "$@"
declare -- cmd="journalctl_cmd --since=@1669195954"
2022-11-23 09:32:39 UTC [INFO] ===== Testing: (Loop: 31/200) =====
2022-11-23 09:32:39 UTC [INFO] /home/test/sof-test/test-case/multiple-pipeline.sh will use topology /lib/firmware/intel/avs-tplg/sof-tgl-nocodec.tplg to run the test case
2022-11-23 09:32:39 UTC [INFO] Pipeline list to ignore is specified, will ignore 'pcm=HDA Digital' in test case
2022-11-23 09:32:39 UTC [INFO] Run command to get pipeline parameters
2022-11-23 09:32:39 UTC [COMMAND] sof-tplgreader.py /lib/firmware/intel/avs-tplg/sof-tgl-nocodec.tplg -f 'type:capture & ~pcm:Amplifier Reference' -b ' pcm:HDA Digital' -s 0 -e
2022-11-23 09:32:39 UTC [INFO] Testing: Port0 [hw:0,0]
2022-11-23 09:32:39 UTC [COMMAND] arecord -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/null -q
2022-11-23 09:32:39 UTC [INFO] Testing: ssp-capture [hw:0,12]
2022-11-23 09:32:39 UTC [COMMAND] arecord -D hw:0,12 -c 2 -r 48000 -f S16_LE /dev/null -q
2022-11-23 09:32:39 UTC [INFO] Testing: DMIC [hw:0,10]
2022-11-23 09:32:39 UTC [COMMAND] arecord -D hw:0,10 -c 4 -r 48000 -f S32_LE /dev/null -q
2022-11-23 09:32:39 UTC [INFO] /home/test/sof-test/test-case/multiple-pipeline.sh will use topology /lib/firmware/intel/avs-tplg/sof-tgl-nocodec.tplg to run the test case
2022-11-23 09:32:39 UTC [INFO] Pipeline list to ignore is specified, will ignore 'pcm=HDA Digital' in test case
2022-11-23 09:32:39 UTC [INFO] Run command to get pipeline parameters
2022-11-23 09:32:39 UTC [COMMAND] sof-tplgreader.py /lib/firmware/intel/avs-tplg/sof-tgl-nocodec.tplg -f 'type:playback ' -b ' pcm:HDA Digital' -s 0 -e
2022-11-23 09:32:39 UTC [INFO] Testing: Port0 [hw:0,0]
2022-11-23 09:32:39 UTC [INFO] wait 0.5s for aplay_opts()
2022-11-23 09:32:39 UTC [COMMAND] aplay -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/zero -q
arecord: pcm_read:2103: read error: Input/output error
2022-11-23 09:32:39 UTC [INFO] checking pipeline status
2022-11-23 09:32:39 UTC [INFO] Letting playback/capture run for 1s
arecord: set_params:1363: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 32
CHANNELS: 2
RATE: 48000
PERIOD_TIME: (85333 85334)
PERIOD_SIZE: 4096
PERIOD_BYTES: 16384
PERIODS: 4
BUFFER_TIME: (341333 341334)
BUFFER_SIZE: 16384
BUFFER_BYTES: 65536
TICK_TIME: 0
2022-11-23 09:32:40 UTC [INFO] checking pipeline status again
2022-11-23 09:32:40 UTC [ERROR] Running process count is 3, but 4 is expected
5663 aplay -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/zero -q
5627 arecord -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/null -q
5643 arecord -D hw:0,10 -c 4 -r 48000 -f S32_LE /dev/null -q
2022-11-23 09:32:40 UTC [ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
2022-11-23 09:32:40 UTC [ERROR] func_error_exit() @ /home/test/sof-test/test-case/multiple-pipeline.sh
2022-11-23 09:32:40 UTC [ERROR] ps_checks() @ /home/test/sof-test/test-case/multiple-pipeline.sh:144
2022-11-23 09:32:40 UTC [ERROR] main() @ /home/test/sof-test/test-case/multiple-pipeline.sh:198
/home/test/sof-test/test-case/../case-lib/lib.sh: line 618: 5663 Killed aplay $SOF_ALSA_OPTS $SOF_APLAY_OPTS "$@"
2022-11-23 09:32:41 UTC [INFO] pkill -TERM -f mtrace-reader.py
2022-11-23 09:32:41 UTC [INFO] ktime=696 sof-test PID=1355: ending
2022-11-23 09:32:41 UTC [INFO] Test Result: FAIL!
test@whl:~$ /home/test/sof-test/test-case/../case-lib/lib.sh: line 624: 5643 Killed arecord $SOF_ALSA_OPTS $SOF_ARECORD_OPTS "$@"
/home/test/sof-test/test-case/../case-lib/lib.sh: line 624: 5627 Killed arecord $SOF_ALSA_OPTS $SOF_ARECORD_OPTS "$@"
[ 1005.551592] sof-audio-pci-intel-tgl 0000:00:1f.3: bind copier.module.8.2:1 -> copier.module.17.2:0
[ 1005.551595] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx : 0x45010004|0x8040004: MOD_BIND
[ 1006.055179] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc timed out for 0x45010004|0x8040004
[ 1006.055189] sof-audio-pci-intel-tgl 0000:00:1f.3: preventing DSP entering D3 state to preserve context
[ 1006.055192] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 1006.055204] sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000001 rirb 00
[ 1006.055208] sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 1006.055228] sof-audio-pci-intel-tgl 0000:00:1f.3: Host IPC initiator: 0xc5010004|0x8040004|0x0, target: 0x0|0x0|0x80000000, ctl: 0x3
[ 1006.055233] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 1006.055236] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 1006.055239] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[ 1006.055242] sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (6)
[ 1006.055250] sof-audio-pci-intel-tgl 0000:00:1f.3: 0x00000005: module: ROM, state: FW_ENTERED, running
[ 1006.055267] sof-audio-pci-intel-tgl 0000:00:1f.3: extended rom status: 0x5 0x0 0x0 0x0 0x0 0x0 0x0 0x1
[ 1006.055271] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 1006.055275] sof-audio-pci-intel-tgl 0000:00:1f.3: failed to bind modules copier.module.8.2:1 -> copier.module.17.2:0
I don't see obvious error from firmware trace. But the same test passed with IPC4 tester.
Note that the error always happens in binding copier.module.8.2:1 -> copier.module.17.2:0.
I.e. Binding copier.module.8.2:1 -> copier.module.17.2:0 can be success, but when the pcm IO error happens, it always fail at binding copier.module.8.2:1 -> copier.module.17.2:0.
Describe the bug
"failed to bind modules copier.module.8.2:1 -> copier.module.17.2:0" error will happen when I run "~/sof-test/test-case/multiple-pipeline.sh -f c -l 200 -w 1" test with SSP multi stream capture topology.
To Reproduce
run "~/sof-test/test-case/multiple-pipeline.sh -f c -l 200 -w 1"
Reproduction Rate
> 90%
Expected behavior
No error on the test
Impact
We will see CI test fail if #6601 is merged
Environment
Screenshots or console output
I don't see obvious error from firmware trace. But the same test passed with IPC4 tester.
Note that the error always happens in binding copier.module.8.2:1 -> copier.module.17.2:0.
I.e. Binding copier.module.8.2:1 -> copier.module.17.2:0 can be success, but when the pcm IO error happens, it always fail at binding copier.module.8.2:1 -> copier.module.17.2:0.
dmesg_bind_fail.txt
out.txt