[BUG][Zephyr] multiple-pipeline-capture.sh test fails on TGL

[kv2019i]

Describe the bug
Run sof-test case multi-pipeline-record.sh

To Reproduce
cd sof-test/test-case
export TPLG=/lib/firmware/intel/sof-tplg/sof-tgl-rt711-4ch.tplg
./multiple-pipeline-capture.sh

Reproduction Rate
100%

Expected behavior
Test case passes without error.

Impact
Use-case failure. Affects CI test set.

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • Kernel: dcea805219d0276916c6ef3266fa1c4d40eced55
   • SOF: d6e29ce
   • Zephyr: 1f0b783bbb2cd0546d0fee12d72cccc694847915
   • Zephyr-SDK: 0.12.4 (gcc)
2. Name of the topology file
   • Topology: sof-tgl-rt711-rt1308-4ch.tplg
3. Name of the platform(s) on which the bug is observed.
   • Platform: TGL

Screenshots or console output

Notes

This seems to be a regression related to moving to timer based scheduling. By reverting the following two patches, the test passes:

62caecc zephyr: schedule: start the timer during domain registration
19117f6 zephyr: ll-scheduler: convert Zephyr scheduling domain to timer API

[kv2019i]

Sof-test error:

2020-04-01 18:30:38 UTC [INFO] ===== Testing: (Loop: 1/1) =====
2020-04-01 18:30:38 UTC [INFO] /home/kvehmane/sof-test/test-case/multiple-pipeline.sh will use topology /lib/firmware/intel/sof-tplg/sof-tgl-rt711-4ch.tplg to run the test case
2020-04-01 18:30:38 UTC [INFO] Pipeline list to ignore is specified, will ignore 'pcm=HDA Digital' in test case
2020-04-01 18:30:38 UTC [INFO] Run command to get pipeline parameters
2020-04-01 18:30:38 UTC [COMMAND] sof-tplgreader.py /lib/firmware/intel/sof-tplg/sof-tgl-rt711-4ch.tplg -f 'type:capture' -b ' pcm:HDA Digital' -s 0 -e
2020-04-01 18:30:38 UTC [INFO] Testing: DMIC [hw:0,10]
2020-04-01 18:30:38 UTC [COMMAND] arecord   -D hw:0,10 -c 4 -r 48000 -f S16_LE /dev/null -q
2020-04-01 18:30:38 UTC [INFO] Testing: DMIC16kHz [hw:0,11]
2020-04-01 18:30:38 UTC [COMMAND] arecord   -D hw:0,11 -c 4 -r 16000 -f S16_LE /dev/null -q
2020-04-01 18:30:38 UTC [INFO] Testing: Jack In [hw:0,1]
2020-04-01 18:30:38 UTC [COMMAND] arecord   -D hw:0,1 -c 2 -r 48000 -f S16_LE /dev/null -q
2020-04-01 18:30:38 UTC [INFO] /home/kvehmane/sof-test/test-case/multiple-pipeline.sh will use topology /lib/firmware/intel/sof-tplg/sof-tgl-rt711-4ch.tplg to run the test case
2020-04-01 18:30:38 UTC [INFO] Pipeline list to ignore is specified, will ignore 'pcm=HDA Digital' in test case
2020-04-01 18:30:38 UTC [INFO] Run command to get pipeline parameters
2020-04-01 18:30:38 UTC [COMMAND] sof-tplgreader.py /lib/firmware/intel/sof-tplg/sof-tgl-rt711-4ch.tplg -f 'type:playback' -b ' pcm:HDA Digital' -s 0 -e
2020-04-01 18:30:38 UTC [INFO] Testing: Jack Out [hw:0,0]
2020-04-01 18:30:38 UTC [INFO] wait 0.5s for aplay_opts()
2020-04-01 18:30:38 UTC [COMMAND] aplay   -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/zero -q
2020-04-01 18:30:38 UTC [INFO] checking pipeline status
2020-04-01 18:30:38 UTC [INFO] Letting playback/capture run for 5s
arecord: pcm_read:2153: read error: Input/output error
2020-04-01 18:30:43 UTC [INFO] checking pipeline status again
2020-04-01 18:30:43 UTC [ERROR] Running process count is 3, but 4 is expected
3848 aplay -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/zero -q
3813 arecord -D hw:0,10 -c 4 -r 48000 -f S16_LE /dev/null -q
3827 arecord -D hw:0,1 -c 2 -r 48000 -f S16_LE /dev/null -q
2020-04-01 18:30:44 UTC [ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
/home/kvehmane/sof-test/test-case/../case-lib/lib.sh: line 312:  3848 Killed                  aplay $SOF_ALSA_OPTS $SOF_APLAY_OPTS "$@"
/home/kvehmane/sof-test/test-case/../case-lib/lib.sh: line 318:  3827 Killed                  arecord $SOF_ALSA_OPTS $SOF_ARECORD_OPTS "$@"
2020-04-01 18:30:44 UTC [ERROR]  func_error_exit()  @  /home/kvehmane/sof-test/test-case/multiple-pipeline.sh
/home/kvehmane/sof-test/test-case/../case-lib/lib.sh: line 318:  3813 Killed                  arecord $SOF_ALSA_OPTS $SOF_ARECORD_OPTS "$@"
2020-04-01 18:30:44 UTC [ERROR]  ps_checks()  @  /home/kvehmane/sof-test/test-case/multiple-pipeline.sh:135
2020-04-01 18:30:44 UTC [ERROR]  main()  @  /home/kvehmane/sof-test/test-case/multiple-pipeline.sh:178
2020-04-01 18:30:44 UTC [INFO] Test Result: FAIL!
2020-04-01 18:30:38 UTC [INFO] ===== Testing: (Loop: 1/1) =====
2020-04-01 18:30:38 UTC [INFO] /home/kvehmane/sof-test/test-case/multiple-pipeline.sh will use topology /lib/firmware/intel/sof-tplg/sof-tgl-rt711-4ch.tplg to run the test case
2020-04-01 18:30:38 UTC [INFO] Pipeline list to ignore is specified, will ignore 'pcm=HDA Digital' in test case
2020-04-01 18:30:38 UTC [INFO] Run command to get pipeline parameters
2020-04-01 18:30:38 UTC [COMMAND] sof-tplgreader.py /lib/firmware/intel/sof-tplg/sof-tgl-rt711-4ch.tplg -f 'type:capture' -b ' pcm:HDA Digital' -s 0 -e
2020-04-01 18:30:38 UTC [INFO] Testing: DMIC [hw:0,10]
2020-04-01 18:30:38 UTC [COMMAND] arecord   -D hw:0,10 -c 4 -r 48000 -f S16_LE /dev/null -q
2020-04-01 18:30:38 UTC [INFO] Testing: DMIC16kHz [hw:0,11]
2020-04-01 18:30:38 UTC [COMMAND] arecord   -D hw:0,11 -c 4 -r 16000 -f S16_LE /dev/null -q
2020-04-01 18:30:38 UTC [INFO] Testing: Jack In [hw:0,1]
2020-04-01 18:30:38 UTC [COMMAND] arecord   -D hw:0,1 -c 2 -r 48000 -f S16_LE /dev/null -q
2020-04-01 18:30:38 UTC [INFO] /home/kvehmane/sof-test/test-case/multiple-pipeline.sh will use topology /lib/firmware/intel/sof-tplg/sof-tgl-rt711-4ch.tplg to run the test case
2020-04-01 18:30:38 UTC [INFO] Pipeline list to ignore is specified, will ignore 'pcm=HDA Digital' in test case
2020-04-01 18:30:38 UTC [INFO] Run command to get pipeline parameters
2020-04-01 18:30:38 UTC [COMMAND] sof-tplgreader.py /lib/firmware/intel/sof-tplg/sof-tgl-rt711-4ch.tplg -f 'type:playback' -b ' pcm:HDA Digital' -s 0 -e
2020-04-01 18:30:38 UTC [INFO] Testing: Jack Out [hw:0,0]
2020-04-01 18:30:38 UTC [INFO] wait 0.5s for aplay_opts()
2020-04-01 18:30:38 UTC [COMMAND] aplay   -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/zero -q
2020-04-01 18:30:38 UTC [INFO] checking pipeline status
2020-04-01 18:30:38 UTC [INFO] Letting playback/capture run for 5s
arecord: pcm_read:2153: read error: Input/output error
2020-04-01 18:30:43 UTC [INFO] checking pipeline status again
2020-04-01 18:30:43 UTC [ERROR] Running process count is 3, but 4 is expected
3848 aplay -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/zero -q
3813 arecord -D hw:0,10 -c 4 -r 48000 -f S16_LE /dev/null -q
3827 arecord -D hw:0,1 -c 2 -r 48000 -f S16_LE /dev/null -q
2020-04-01 18:30:44 UTC [ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
/home/kvehmane/sof-test/test-case/../case-lib/lib.sh: line 312:  3848 Killed                  aplay $SOF_ALSA_OPTS $SOF_APLAY_OPTS "$@"
/home/kvehmane/sof-test/test-case/../case-lib/lib.sh: line 318:  3827 Killed                  arecord $SOF_ALSA_OPTS $SOF_ARECORD_OPTS "$@"
2020-04-01 18:30:44 UTC [ERROR]  func_error_exit()  @  /home/kvehmane/sof-test/test-case/multiple-pipeline.sh
/home/kvehmane/sof-test/test-case/../case-lib/lib.sh: line 318:  3813 Killed                  arecord $SOF_ALSA_OPTS $SOF_ARECORD_OPTS "$@"
2020-04-01 18:30:44 UTC [ERROR]  ps_checks()  @  /home/kvehmane/sof-test/test-case/multiple-pipeline.sh:135
2020-04-01 18:30:44 UTC [ERROR]  main()  @  /home/kvehmane/sof-test/test-case/multiple-pipeline.sh:178
2020-04-01 18:30:44 UTC [INFO] Test Result: FAIL!

[kv2019i]

FW log (with adsplog.py) log-adsplog.txt

[kv2019i]

In terminal, I can reproduce also with these steps:

arecord   -D hw:0,10 -d 15 -c 4 -r 48000 -f S16_LE /dev/null -q &
arecord   -D hw:0,11 -d 15 -c 4 -r 48000 -f S16_LE /dev/null -q &
arecord -D hw:0,1 -d 15 -c 2 -r 48000 -f S16_LE /dev/null -q &
aplay   -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/zero -q

PCM numbers may vary based on tplg. In my test, four pipelines are needed, with three pipeline test passes.

[kv2019i]

I'll take this to myself. With PR4306 the test works on many systems, but with the TGL RVP configuration it still fails due to too high DSP load. I'm working on moving application buffers back to cached address range, which will solve this issue, but let's keep the bug open until then.