Skip to content

multiple-pipeline-capture: Fail to find 4 pipelines still alive, only 3 left #472

Closed
#538
Closed
multiple-pipeline-capture: Fail to find 4 pipelines still alive, only 3 left#472
#538
Assignees
marc-hb
Labels
P1Blocker bugs or important featurestype:bugSomething doesn't work as expected

Description

@mengdonglin
mengdonglin
opened on Oct 26, 2020

This is a random issue on multiple platforms.

e.g. on EHL RVP and CML-U notebook Olym* in daily test on 2020-10-25, report ID 613.

2020-10-25 23:07:04 UTC [REMOTE_INFO] /home/ubuntu/sof-test/test-case/multiple-pipeline-capture.sh will use topology /lib/firmware/intel/sof-tplg/sof-ehl-rt5660.tplg to run the test case
2020-10-25 23:07:04 UTC [REMOTE_INFO] Pipeline list to ignore is specified, will ignore 'pcm=HDA Digital' in test case
2020-10-25 23:07:04 UTC [REMOTE_INFO] Run command to get pipeline parameters
2020-10-25 23:07:04 UTC [REMOTE_COMMAND] sof-tplgreader.py /lib/firmware/intel/sof-tplg/sof-ehl-rt5660.tplg -f 'type:playback' -b ' pcm:HDA Digital' -s 0 -e
2020-10-25 23:07:04 UTC [REMOTE_INFO] Testing: Headset [hw:0,0]
2020-10-25 23:07:04 UTC [REMOTE_COMMAND] aplay -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/zero -q
2020-10-25 23:07:04 UTC [REMOTE_INFO] pipeline start sleep 0.5s for device wakeup
2020-10-25 23:07:09 UTC [REMOTE_INFO] checking pipeline status
2020-10-25 23:07:09 UTC [REMOTE_INFO] preparing sleep 5
2020-10-25 23:07:14 UTC [REMOTE_INFO] checking pipeline status again
/home/ubuntu/sof-test/test-case/multiple-pipeline-capture.sh: line 103: 66312 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
/home/ubuntu/sof-test/test-case/multiple-pipeline-capture.sh: line 103: 66321 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
/home/ubuntu/sof-test/test-case/multiple-pipeline-capture.sh: line 103: 66330 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
/home/ubuntu/sof-test/test-case/multiple-pipeline-capture.sh: line 103: 66350 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
2020-10-25 23:07:14 UTC [REMOTE_INFO] ===== Testing: (Loop: 32/50) =====
2020-10-25 23:07:14 UTC [REMOTE_INFO] /home/ubuntu/sof-test/test-case/multiple-pipeline-capture.sh will use topology /lib/firmware/intel/sof-tplg/sof-ehl-rt5660.tplg to run the test case
2020-10-25 23:07:14 UTC [REMOTE_INFO] Pipeline list to ignore is specified, will ignore 'pcm=HDA Digital' in test case
2020-10-25 23:07:14 UTC [REMOTE_INFO] Run command to get pipeline parameters
2020-10-25 23:07:14 UTC [REMOTE_COMMAND] sof-tplgreader.py /lib/firmware/intel/sof-tplg/sof-ehl-rt5660.tplg -f 'type:capture' -b ' pcm:HDA Digital' -s 0 -e
2020-10-25 23:07:14 UTC [REMOTE_INFO] Testing: Headset [hw:0,0]
2020-10-25 23:07:14 UTC [REMOTE_COMMAND] arecord -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/null -q
2020-10-25 23:07:14 UTC [REMOTE_INFO] Testing: DMIC [hw:0,1]
2020-10-25 23:07:14 UTC [REMOTE_COMMAND] arecord -D hw:0,1 -c 4 -r 48000 -f S16_LE /dev/null -q
2020-10-25 23:07:14 UTC [REMOTE_INFO] Testing: DMIC16kHz [hw:0,2]
2020-10-25 23:07:14 UTC [REMOTE_COMMAND] arecord -D hw:0,2 -c 2 -r 16000 -f S16_LE /dev/null -q
2020-10-25 23:07:14 UTC [REMOTE_INFO] /home/ubuntu/sof-test/test-case/multiple-pipeline-capture.sh will use topology /lib/firmware/intel/sof-tplg/sof-ehl-rt5660.tplg to run the test case
2020-10-25 23:07:14 UTC [REMOTE_INFO] Pipeline list to ignore is specified, will ignore 'pcm=HDA Digital' in test case
2020-10-25 23:07:14 UTC [REMOTE_INFO] Run command to get pipeline parameters
2020-10-25 23:07:14 UTC [REMOTE_COMMAND] sof-tplgreader.py /lib/firmware/intel/sof-tplg/sof-ehl-rt5660.tplg -f 'type:playback' -b ' pcm:HDA Digital' -s 0 -e
2020-10-25 23:07:14 UTC [REMOTE_INFO] Testing: Headset [hw:0,0]
2020-10-25 23:07:14 UTC [REMOTE_COMMAND] aplay -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/zero -q
2020-10-25 23:07:14 UTC [REMOTE_INFO] pipeline start sleep 0.5s for device wakeup
2020-10-25 23:07:20 UTC [REMOTE_INFO] checking pipeline status
2020-10-25 23:07:20 UTC [REMOTE_INFO] preparing sleep 5
2020-10-25 23:07:25 UTC [REMOTE_ERROR] Target pipeline count: 4, current process count: 3
/home/ubuntu/sof-test/test-case/multiple-pipeline-capture.sh: line 96: 66463 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
2020-10-25 23:07:25 UTC [REMOTE_ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
/home/ubuntu/sof-test/case-lib/hijack.sh: line 17: 66434 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
/home/ubuntu/sof-test/case-lib/hijack.sh: line 17: 66443 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
/home/ubuntu/sof-test/case-lib/hijack.sh: line 23: 66424 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
2020-10-25 23:07:25 UTC [REMOTE_ERROR]  func_error_exit()  @  /home/ubuntu/sof-test/test-case/multiple-pipeline-capture.sh
2020-10-25 23:07:25 UTC [REMOTE_ERROR]  main()  @  /home/ubuntu/sof-test/test-case/multiple-pipeline-capture.sh:140

Activity

  1. mengdonglin
    added
    type:bugSomething doesn't work as expected
    P2Critical bugs or normal features
    EHL
    CML
    on Oct 26, 2020
  2. aiChaoSONG
    self-assigned this
    on Nov 2, 2020

  3. aiChaoSONG commented on Nov 2, 2020

    @aiChaoSONG
    aiChaoSONG
    on Nov 2, 2020

    Try to add some debug log, to see which pipeline is dead.

  4. plbossart commented on Nov 3, 2020

    @plbossart
    plbossart
    on Nov 3, 2020
    Member

    I ran 500 iterations on GLK, for which this error was reported in one daily test log. No luck, it's a PASS status. Will try with longer values.

  5. plbossart commented on Nov 3, 2020

    @plbossart
    plbossart
    on Nov 3, 2020
    Member

    Of course Murphy's Law applies, failure detected on GLK at the 552th iteration - SOF firmware master and topic/sof-dev.

    2020-11-03 03:26:26 UTC [INFO] ===== Testing: (Loop: 552/5000) =====
2020-11-03 03:26:26 UTC [INFO] /root/sof-test/test-case/multiple-pipeline-capture.sh will use topology /lib/firmware/intel/sof-tplg/sof-glk-da7219.tplg to run the test case
2020-11-03 03:26:26 UTC [INFO] Pipeline list to ignore is specified, will ignore 'pcm=HDA Digital' in test case
2020-11-03 03:26:26 UTC [INFO] Run command to get pipeline parameters
2020-11-03 03:26:26 UTC [COMMAND] sof-tplgreader.py /lib/firmware/intel/sof-tplg/sof-glk-da7219.tplg -f 'type:capture' -b ' pcm:HDA Digital' -s 0 -e
2020-11-03 03:26:26 UTC [INFO] Testing: Headset [hw:0,1]
2020-11-03 03:26:26 UTC [COMMAND] arecord -D hw:0,1 -c 2 -r 48000 -f S16_LE /dev/null -q
2020-11-03 03:26:26 UTC [INFO] Testing: DMIC [hw:0,99]
2020-11-03 03:26:26 UTC [COMMAND] arecord -D hw:0,99 -c 4 -r 48000 -f S16_LE /dev/null -q
2020-11-03 03:26:26 UTC [INFO] /root/sof-test/test-case/multiple-pipeline-capture.sh will use topology /lib/firmware/intel/sof-tplg/sof-glk-da7219.tplg to run the test case
2020-11-03 03:26:26 UTC [INFO] Pipeline list to ignore is specified, will ignore 'pcm=HDA Digital' in test case
2020-11-03 03:26:26 UTC [INFO] Run command to get pipeline parameters
2020-11-03 03:26:26 UTC [COMMAND] sof-tplgreader.py /lib/firmware/intel/sof-tplg/sof-glk-da7219.tplg -f 'type:playback' -b ' pcm:HDA Digital' -s 0 -e
2020-11-03 03:26:26 UTC [INFO] Testing: Speakers [hw:0,0]
2020-11-03 03:26:26 UTC [COMMAND] aplay -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/zero -q
2020-11-03 03:26:26 UTC [INFO] Testing: Headset [hw:0,1]
2020-11-03 03:26:26 UTC [COMMAND] aplay -D hw:0,1 -c 2 -r 48000 -f S16_LE /dev/zero -q
2020-11-03 03:26:26 UTC [INFO] pipeline start sleep 0.5s for device wakeup
2020-11-03 03:26:31 UTC [INFO] checking pipeline status
2020-11-03 03:26:31 UTC [INFO] preparing sleep 5
2020-11-03 03:26:36 UTC [ERROR] Target pipeline count: 4, current process count: 3
/root/sof-test/test-case/multiple-pipeline-capture.sh: line 96: 125680 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
/root/sof-test/test-case/multiple-pipeline-capture.sh: line 96: 125689 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
2020-11-03 03:26:36 UTC [ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
/root/sof-test/case-lib/hijack.sh: line 23: 125651 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
/root/sof-test/case-lib/hijack.sh: line 23: 125660 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
2020-11-03 03:26:36 UTC [ERROR]  func_error_exit()  @  /root/sof-test/test-case/multiple-pipeline-capture.sh
2020-11-03 03:26:36 UTC [ERROR]  main()  @  /root/sof-test/test-case/multiple-pipeline-capture.sh:140
2020-11-03 03:26:36 UTC [INFO] Starting /usr/local/bin/sof-logger  -l /etc/sof/sof-glk.ldc -o /root/sof-test/logs/multiple-pipeline-capture/2020-11-02-19:47:14-8753/etrace.txt
2020-11-03 03:26:37 UTC [INFO] pkill -TERM sof-logger
Terminated
2020-11-03 03:26:39 UTC [INFO] nlines=7 /root/sof-test/logs/multiple-pipeline-capture/2020-11-02-19:47:14-8753/etrace.txt
2020-11-03 03:26:39 UTC [INFO] Test Result: FAIL!

    multiple-pipeline-capture-glk.tar.gz

  6. plbossart commented on Nov 3, 2020

    @plbossart
    plbossart
    on Nov 3, 2020
    Member

    And unfortunately there is zero information on what the errors might be in sof-test logs. @aiChaoSONG we really need to update the script to provide more information on which capture failed.

  7. aiChaoSONG commented on Nov 4, 2020

    @aiChaoSONG
    aiChaoSONG
    on Nov 4, 2020

    @plbossart I have added some debug info in my personal sof-test repo to this case, and also trying to reproduce this issue on some platforms, check report 663, 662, 661, will test more.
    Note: CI now supports to use my personal sof-test to run a test plan

  8. marc-hb
    changed the title [-]multiple-pipeline-capture: Fail to find 4 active pipelines, can only find 3[/-] [+]multiple-pipeline-capture: Fail to find 4 pipelines still alive, only 3 left[/+] on Nov 10, 2020

  9. marc-hb commented on Nov 10, 2020

    @marc-hb
    marc-hb
    on Nov 10, 2020
    Collaborator

    ... to provide more information on which capture failed.

    I just submitted two-lines pgrep-a #507 which helps.

    And unfortunately there is zero information on what the errors might be in sof-test logs.

    I checked and there's no silly /dev/null redirection this time, so this is not a problem with sof-test this time.

    Is there any chance --quiet would silence errors too? --quiet options do not normally silence errors but man aplay is very vague.

    I have added some debug info in my personal sof-test repo to this case

    More specifically?

  10. fredoh9 commented on Nov 11, 2020

    @fredoh9
    fredoh9
    on Nov 11, 2020
    Contributor

    I saw this problem in ICL_HDA_HDA/WHL_RVP_HDA with multiple-pipeline-capture.sh recently. #507 will help debug which process might be the problem but still I don't see any error message.

  11. mengdonglin
    added
    P1Blocker bugs or important features
    and removed
    P2Critical bugs or normal features
    on Nov 16, 2020

  12. 9 remaining items

  13. marc-hb
    added a commit that references this issue on Dec 1, 2020

    multiple-pipeline: replace pidof->ps to catch uninterruptible sleep

    d56e0b9

  14. marc-hb commented on Dec 1, 2020

    @marc-hb
    marc-hb
    on Dec 1, 2020
    Collaborator

    I scanned man pidof and I just found -z,

    Confirmed to be the issue, see longer explanation in commit message of candidate fix PR #538

  15. marc-hb
    unassigned
    aiChaoSONG
    on Dec 1, 2020
  16. xiulipan
    closed this as completedin #538on Dec 2, 2020
  17. xiulipan
    added a commit that references this issue on Dec 2, 2020

    multiple-pipeline: replace pidof->ps to catch uninterruptible sleep

    e5c6f98
  18. marc-hb
    added a commit that references this issue on Dec 2, 2020

    multiple-pipeline: remove initial sleep and clarify second sleep

    254a6fc

  19. marc-hb commented on Dec 2, 2020

    @marc-hb
    marc-hb
    on Dec 2, 2020
    Collaborator

    Nightly tests run 912 still shows some failures, let's not let github auto close this and close it manually only when we actually stop seeing it (PR tests almost never showed it; they don't run for long enough)

    Tentative fix #538 was merged 15 hours ago, Nightly tests run 912 started at 2020-12-02 05:31:57 UTC which is unfortunately about the same time so it's not obvious which sof-test version 912 they ran (internal issue 619, possible solution in #544)

    By sheer luck I also fixed a log message in the same #538 ("pipeline start sleep 0.5s for device wakeup") which shows that run 912 didn't run with fix #538 yet.

  20. marc-hb
    reopened this on Dec 2, 2020

  21. marc-hb commented on Dec 3, 2020

    @marc-hb
    marc-hb
    on Dec 3, 2020
    Collaborator

    Nightly tests run 937 seems OK; including the report of an actual failure!

  22. marc-hb commented on Dec 4, 2020

    @marc-hb
    marc-hb
    on Dec 4, 2020
    Collaborator

    Looks like this test bug is gone, closing. However note the fix #538 broke the directory name for the logs/, see tentative fix #546 (+ internal Jenkins issue 640)

  23. marc-hb
    closed this as completedon Dec 4, 2020
  24. marc-hb
    added a commit that references this issue on Mar 5, 2021

    multiple-pipeline: remove initial sleep and clarify second sleep

    d42d281
  25. marc-hb
    added 3 commits that reference this issue on Apr 27, 2021

    multiple-pipeline: remove initial sleep and clarify second sleep

    f93a3c8

    multiple-pipeline: simplify sleeps

    61761f9

    multiple-pipeline: simplify sleeps

    a726dc1
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

P1Blocker bugs or important featurestype:bugSomething doesn't work as expected

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions