Skip to content

[BUG] Xrun on ADP_RVP_NOCODEC #5469

Closed
Closed
[BUG] Xrun on ADP_RVP_NOCODEC#5469
Assignees
keqiaozhangkv2019i
Labels
ADLApplies to Alder Lake platformP2Critical bugs or normal featuresTGLApplies to Tiger LakebugSomething isn't working as expectedxrunXRUN is observed and firmware may not recover
Milestone
v2.1

Description

@plbossart
plbossart
opened on Mar 3, 2022

Describe the bug

https://sof-ci.01.org/linuxpr/PR3338/build7261/devicetest/?model=ADLP_RVP_NOCODEC&testcase=multiple-pause-resume-5

(4/5) pcm'Port0' cmd'aplay' id'2': Wait for 22 ms before resume
                                                                           
                                                                            
 aplay: pcm_write:2086: write error: Input/output error

#+                                                 | 00%
=== PAUSE ===                                                            
(5/5) pcm'Port0 Deep Buffer' cmd'aplay' id'8': Wait for 39 ms before pause

(5/5) pcm'Port0 Deep Buffer' cmd'aplay' id'8': Wait for 47 ms before resume

2022-03-03 20:13:04 UTC [REMOTE_INFO] pipeline: Port0 with aplay
2022-03-03 20:13:04 UTC [REMOTE_INFO] pipeline: Port0 Deep Buffer with aplay
2022-03-03 20:13:04 UTC [REMOTE_INFO] Check expect exit status
declare -- cmd="journalctl_cmd --since=@1646338352"
2022-03-03 20:13:04 UTC [REMOTE_ERROR] pause resume PID 6074 had non-zero exit status
2022-03-03 20:13:04 UTC [REMOTE_ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
2022-03-03 20:13:04 UTC [REMOTE_ERROR]  die()  @  /home/ubuntu/sof-test/test-case/../case-lib/lib.sh
2022-03-03 20:13:04 UTC [REMOTE_ERROR]  main()  @  /home/ubuntu/sof-test/test-case/multiple-pause-resume.sh:191
2022-03-03 20:13:04 UTC [REMOTE_INFO] Starting /usr/local/bin/sof-logger -l /etc/sof/sof-adl.ldc -o /home/ubuntu/sof-test/logs/multiple-pause-resume/2022-03-03-20:12:40-25145/etrace.txt
2022-03-03 20:13:07 UTC [REMOTE_INFO] pkill -TERM sof-logger
Terminated
2022-03-03 20:13:08 UTC [REMOTE_INFO] nlines=47 /home/ubuntu/sof-test/logs/multiple-pause-resume/2022-03-03-20:12:40-25145/etrace.txt
2022-03-03 20:13:08 UTC [REMOTE_INFO] Test Result: FAIL!

To Reproduce

TPLG=/lib/firmware/intel/sof-tplg/sof-adl-nocodec.tplg MODEL=ADLP_RVP_NOCODEC ~/sof-test/test-case/multiple-pause-resume.sh -l 3 -r 5

Reproduction Rate
unclear, just observed this issue.

Expected behavior
No Xrun

Impact
showstopper.

Environment
Linux: 2528d9538dfd ASoC: SOF: sof-client: Allow the message injector for IPC4 as well
SOF: c42ede6 topology: sof-adl-max98360a-rt5682-waves: add new topology

  1. Name of the topology file
    • Topology: sof-adl-nocodec.tplg
  2. Name of the platform(s) on which the bug is observed.
    • Platform: ADL_RVP_NOCODEC

@keqiaozhang @XiaoyunWu6666 FYI

Activity

  1. plbossart
    added
    bugSomething isn't working as expected
    on Mar 3, 2022

  2. plbossart commented on Mar 4, 2022

    @plbossart
    plbossart
    on Mar 4, 2022
    MemberAuthor

    @lgirdwood this needs to be on your radar for 2.1

  3. lgirdwood
    added this to the v2.1 milestone on Mar 4, 2022
  4. kfrydryx
    assigned
    keqiaozhang
    on Mar 8, 2022
  5. kfrydryx
    added
    P3Low-impact bugs or features
    on Mar 8, 2022
  6. marc-hb
    added
    P1Blocker bugs or important features
    and removed
    P3Low-impact bugs or features
    on Mar 10, 2022

  7. marc-hb commented on Mar 10, 2022

    @marc-hb
    marc-hb
    on Mar 10, 2022
    Collaborator

    P1 because it was one of the most common failures in daily run 10879, reproduced on 3 ADL and 1 TGL system (10879?model=TGLH_RVP_NOCODEC_ZEPHYR&testcase=multiple-pause-resume-50)

    There were a number of underruns in that test run, see example below.

    [    20564241.578684] (        1349.218750) c0 mixer        1.0      src/audio/component.c:64   INFO comp_set_state(), state already set to 6
[    20564268.974516] (          27.395832) c0 mixer        1.0      src/audio/component.c:64   INFO comp_set_state(), state already set to 5
[    20566392.776515] (        2123.802002) c0 dw-dma                 src/drivers/dw/dma.c:1128 ERROR dw_dma_get_data_size(): xrun detected
[    20566552.620259] (         159.843750) c0 dai          1.2            src/audio/dai.c:879  ERROR dai_report_xrun(): underrun due to no data available
[    20566744.182751] (         191.562500) c0 dai          1.2            src/audio/dai.c:748  ERROR comp_underrun(): dev->comp.id = 2, source->avail = 756, copy_by
[    20566990.641075] (         246.458328) c0 pipe         1.3   ....../pipeline-stream.c:261  INFO pipe trigger cmd 6
[    20567028.661906] (          38.020832) c0 pipe         1.3   ....../pipeline-stream.c:134  ERROR pipeline_copy(): ret = -61, start->comp.id = 2, dir = 1
[    20567238.036898] (         209.374985) c0 pipe         1.3   ..../pipeline-schedule.c:183  ERROR pipeline_task(): xrun recovery failed! pipeline is stopped.
[    20567446.995223] (         208.958328) c0 zll-schedule       src/schedule/zephyr_ll.c:67   INFO task complete 0xbe07d0c0 pipe-task
[    20567464.807722] (          17.812500) c0 zll-schedule       src/schedule/zephyr_ll.c:69   INFO num_tasks 5 total_num_tasks 5
[    20568122.463946] (         657.656250) c0 zll-schedule       src/schedule/zephyr_ll.c:67   INFO task complete 0xbe07e740 pipe-task
[    20568141.266029] (          18.802082) c0 zll-schedule       src/schedule/zephyr_ll.c:69   INFO num_tasks 4 total_num_tasks 4
[    20584130.327893] (       15989.061523) c0 host         7.36          src/audio/host.c:475  INFO no bytes to copy, 0 free in buffer, 384 available in DMA
[    20586129.963231] (        1999.635376) c0 host         7.36          src/audio/host.c:475  INFO no bytes to copy, 0 free in buffer, 384 available in DMA
[    20588130.171485] (        2000.208252) c0 host         7.36          src/audio/host.c:475  INFO no bytes to copy, 0 free in buffer, 384 available in DMA
[    20590129.702655] (        1999.531128) c0 host         7.36          src/audio/host.c:475  INFO no bytes to copy, 0 free in buffer, 384 available in DMA
[    20592129.858826] (        2000.156128) c0 host         7.36          src/audio/host.c:475  INFO no bytes to copy, 0 free in buffer, 384 available in DMA
[    20594129.285829] (        1999.427002) c0 host         7.36          src/audio/host.c:475  INFO no bytes to copy, 0 free in buffer, 384 available in DMA
[    20596129.910750] (        2000.624878) c0 host         7.36          src/audio/host.c:475  INFO no bytes to copy, 0 free in buffer, 384 available in DMA

    I noticed a mixer in the middle of a pipeline on all failing systems. Is this an unsupported configuration and problem similar to this?

    Should some pipelines be skipped like this?

  8. mengdonglin
    added
    ADLApplies to Alder Lake platform
    TGLApplies to Tiger Lake
    on Mar 10, 2022

  9. mengdonglin commented on Mar 10, 2022

    @mengdonglin
    mengdonglin
    on Mar 10, 2022
    Collaborator

    Comments by @keqiaozhang "this issue has affected all ADLP and TGLU/H nocodec platforms. The reproduction rate has become extremely high now. " on 2022-03-09 UTC, report ID 10879. Both XTOS and Zephyr can reproduce this issue.

  10. mengdonglin
    added
    xrunXRUN is observed and firmware may not recover
    on Mar 10, 2022

  11. lgirdwood commented on Mar 10, 2022

    @lgirdwood
    lgirdwood
    on Mar 10, 2022
    Member

    @keqiaozhang is there a bisect ? I'm trying to think of any recent pipeline or DMA changes, but it could be something else unrelated.

  12. kv2019i commented on Mar 10, 2022

    @kv2019i
    kv2019i
    on Mar 10, 2022
    Collaborator

    I now reproduced this once. Seems like the mixer is not working properly after a paused->active transition. We can see components both side of the mixer complaining that data is not moving although mixer is in active state:

    [      220042.074590] (        1113.281250) c2 mixer        1.0      src/audio/component.c:64   INFO comp_set_state(), state already set to 6
[      220072.439172] (          30.364582) c2 mixer        1.0      src/audio/component.c:64   INFO comp_set_state(), state already set to 5
[      222040.043260] (        1967.604126) c2 host         7.36          src/audio/host.c:475  INFO no bytes to copy, 0 free in buffer, 384 available in DMA
[      222109.470341] (          69.427078) c2 dw-dma                 src/drivers/dw/dma.c:1093 INFO dw_dma_free_data_size() size is 0!
[      222133.220340] (          23.750000) c2 dw-dma                 src/drivers/dw/dma.c:1128 ERROR dw_dma_get_data_size(): xrun detected
[      222154.470339] (          21.250000) c2 dai          1.2            src/audio/dai.c:879  ERROR dai_report_xrun(): underrun due to no data available
  13. lgirdwood
    removed
    P1Blocker bugs or important features
    on Mar 10, 2022

  14. 12 remaining items

  15. kv2019i commented on Mar 29, 2022

    @kv2019i
    kv2019i
    on Mar 29, 2022
    Collaborator

    This issue still exists in Intel daily plan 11433, so the fix to #5556 has no impact to this case (this is expected).

  16. kv2019i commented on Mar 29, 2022

    @kv2019i
    kv2019i
    on Mar 29, 2022
    Collaborator

    Returned to this issue today. I have found two issues -- first is a mixer logic issue related to how it handles its sources switching state to PAUSED in high frequency. Another issue relates to doing PIPE_FREE on a pipe that has a mixer and is running on non-primary core. Fixes are fairly rough with a performance hit to other cases, so some development time is still needed before these can be submitted for review.

  17. kv2019i
    added 3 commits that reference this issue on Mar 31, 2022

    pipeline: do not reschedule pipe task if already in target state

    fbe3d9b

    ipc: run buffer free in context of active pipeline

    cb57461
  18. lgirdwood
    added 2 commits that reference this issue on Apr 4, 2022

    pipeline: do not reschedule pipe task if already in target state

    e4e3dd9

    ipc: run buffer free in context of active pipeline

    69db9c8

  19. kv2019i commented on Apr 8, 2022

    @kv2019i
    kv2019i
    on Apr 8, 2022
    Collaborator

    Multiple PRs merged to addres sthis bug, but #5628 is still open (and under work).

  20. lgirdwood
    added a commit that references this issue on Apr 13, 2022

    mixer: add logic to maintain data flow when sources are paused

    5ec02e3

  21. kv2019i commented on Apr 14, 2022

    @kv2019i
    kv2019i
    on Apr 14, 2022
    Collaborator

    All patches merged for XTOS builds. For Zephyr builds I still have one patch in the works, but this is harder to hit. Let's monitor test results and close the bug if failure not seen.

  22. keqiaozhang commented on Apr 18, 2022

    @keqiaozhang
    keqiaozhang
    on Apr 18, 2022
    Collaborator

    haven't seen this issue in CI for 10 days, closing this bug.

  23. keqiaozhang
    closed this as completedon Apr 18, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

ADLApplies to Alder Lake platformP2Critical bugs or normal featuresTGLApplies to Tiger LakebugSomething isn't working as expectedxrunXRUN is observed and firmware may not recover

Type

No type

Projects

No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions