[BUG] multiple-pipeline.sh fails due to number of PID mismatch

[fredoh9]

Found in GLK but not GLK related. Possibly slow platform might run into same problem.

Ran 7 of aplay/arecord, but detected 6/7. Error~. Then killed 7 of PIDs.

Internal daily test 3669 with GLK_BOB_DA7219.

2021-05-02 00:06:25 UTC [REMOTE_ERROR] Running process count is 6, but 7 is expected

19298 aplay -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/zero -q
19307 aplay -D hw:0,1 -c 2 -r 48000 -f S16_LE /dev/zero -q
19317 aplay -D hw:0,5 -c 2 -r 48000 -f S16_LE /dev/zero -q
19325 aplay -D hw:0,6 -c 2 -r 48000 -f S16_LE /dev/zero -q
19332 aplay -D hw:0,7 -c 2 -r 48000 -f S16_LE /dev/zero -q
/home/ubuntu/sof-test/test-case/../case-lib/lib.sh: line 312: 19298 Killed                  aplay $SOF_ALSA_OPTS $SOF_APLAY_OPTS "$@"
/home/ubuntu/sof-test/test-case/../case-lib/lib.sh: line 312: 19307 Killed                  aplay $SOF_ALSA_OPTS $SOF_APLAY_OPTS "$@"
/home/ubuntu/sof-test/test-case/../case-lib/lib.sh: line 312: 19332 Killed                  aplay $SOF_ALSA_OPTS $SOF_APLAY_OPTS "$@"
/home/ubuntu/sof-test/test-case/../case-lib/lib.sh: line 312: 19325 Killed                  aplay $SOF_ALSA_OPTS $SOF_APLAY_OPTS "$@"
/home/ubuntu/sof-test/test-case/../case-lib/lib.sh: line 312: 19317 Killed                  aplay $SOF_ALSA_OPTS $SOF_APLAY_OPTS "$@"
19354 arecord -D hw:0,1 -c 2 -r 48000 -f S16_LE /dev/null -q
19364 arecord -D hw:0,99 -c 4 -r 48000 -f S16_LE /dev/null -q
/home/ubuntu/sof-test/test-case/../case-lib/lib.sh: line 318: 19354 Killed                  arecord $SOF_ALSA_OPTS $SOF_ARECORD_OPTS "$@"
/home/ubuntu/sof-test/test-case/../case-lib/lib.sh: line 318: 19364 Killed                  arecord $SOF_ALSA_OPTS $SOF_ARECORD_OPTS "$@"

[fredoh9]

is this side effect of #671?

[fredoh9]

Found on JSL_RVP_NOCODEC for internal test 3691

[marc-hb]

After looking at this in more detail I think I have an explanation.

is this side effect of #671?

Likely yes.

When I did #671 I didn't think it was possible for ps to miss a process just started in the background and I still believe that HOWEVER I think I missed one important detail: the aplay_opts() indirection. It is this function and not aplay (resp. arecord) that is started in the background. So when ps_checks() starts running, it can expect to find 7 aplay_opts() subshells for sure but maybe not 7 aplay processes yet.

The fact that ps_checks() finds only 6 processes while func_error_exit() finds the 7 expected processes immediately after is consistent with that explanation.

This is all horribly racy and I wish we could rethink and refactor how we manage background processes but that wouldn't be a quick fix. For now I can only think about adding yet another sleep as @fredoh9 is offering in #674

@plbossart , @lgirdwood , @kv2019i , any thought?

At least we have decent logging, relatively simple logic and no more copy/paste in this test now, better times than #472 that took me days!

[marc-hb]

I did a bit more testing. As with any race condition, reproduction is about making it worse and the change below does reproduce the exact same log after a few iterations.

@fredoh9 I "stole" your sleep in #674, added a comment explaining the problem and submitted #676

--- a/case-lib/lib.sh
+++ b/case-lib/lib.sh
@@ -339,6 +339,7 @@ func_lib_check_pa()
 aplay_opts()
 {
     dlogc "aplay $SOF_ALSA_OPTS $SOF_APLAY_OPTS $*"
+    sleep 0.2
     # shellcheck disable=SC2086
     aplay $SOF_ALSA_OPTS $SOF_APLAY_OPTS "$@"
 }