Skip to content

[BUG][cAVS 1.8][Capture] Pause-release overrun #1760

Closed
Closed
[BUG][cAVS 1.8][Capture] Pause-release overrun#1760
Labels
CFLApplies to Coffee Lake platformCMLApplies to Comet Lake platformCNLApplies to Cannonlake platformWHLApplies to WhiskeyLake platformbugSomething isn't working as expected
Milestone
v1.4

Description

@tlauda
tlauda
opened on Aug 26, 2019

Describe the bug
System shows Input/Output error when pause arecord then release. Similar behavior with all arecord devices. Pipeline overrun after some time of releasing the pause.

To Reproduce

  1. arecord -Dhw:0,1 -r48000 -c2 -fs16_le 1.wav -vv -i
  2. Pause arecord.
  3. Release arecord.

Reproduction Rate
Under 10%.

Expected behavior
Resume capture after pause-release.

Impact
High.

Activity

  1. tlauda
    added
    bugSomething isn't working as expected
    CNLApplies to Cannonlake platform
    WHLApplies to WhiskeyLake platform
    CMLApplies to Comet Lake platform
    CFLApplies to Coffee Lake platform
    on Aug 26, 2019

  2. dengyangchao commented on Aug 27, 2019

    @dengyangchao
    dengyangchao
    on Aug 27, 2019

    issue can reproduce on CFL

    Reproduce rate
    1/33

    Test recipe
    Firmware: 2cbb1a0 https://github.com/thesofproject/sof/commits/master
    Kernel: 136b7aa https://github.com/thesofproject/linux/commits/topic/sof-dev
    Topology: file: tools/topology/sof-hda-generic-4ch.tplg same as firmware
    platform：CFL

    dmesg.log

  3. lgirdwood commented on Aug 30, 2019

    @lgirdwood
    lgirdwood
    on Aug 30, 2019
    Member

    @dengyangchao do you have FW log ? does FW recover after restarting arecord ? Can you show output of arecord.

    [  266.294928] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
[  266.296591] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
[  266.296599] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=4
[  266.522486] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[  266.522524] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[  266.903735] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 1 cmd 3
[  266.904348] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20240000 successful
[  266.904366] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[  266.904621] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60060000 size 12
[  266.904631]  HDA Analog: ASoC: trigger FE failed -22
[  266.904642] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 1 cmd 4
[  266.905220] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x2024001e successful
[  266.905227] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
[  266.905457] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60070000 size 12
[  266.905465]  HDA Analog: ASoC: trigger FE failed -22
[  267.022503] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[  267.022542] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[  267.410138] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 1 cmd 0
[  267.410395] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20240000 successful
[  267.410406] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[  267.410583] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60050000: GLB_STREAM_MSG: TRI
  4. lgirdwood
    modified the milestones: v1.5, v1.4 on Aug 30, 2019

  5. dengyangchao commented on Sep 2, 2019

    @dengyangchao
    dengyangchao
    on Sep 2, 2019

    issue still can reproduce with below recipe, @lgirdwood yes, the FW will recover after restarting arecord

    Firmware: 008285e https://github.com/thesofproject/sof/commits/master
    Kernel: f95e4eb https://github.com/thesofproject/linux/commits/topic/sof-dev
    Topology: file: tools/topology/sof-hda-generic-4ch.tplg same as firmware
    platform：CFL

    dmesg.log
    logger.log

  6. mengdonglin
    changed the title [-][BUG][cAVS 1.8] Pause-release overrun[/-] [+][BUG][cAVS 1.8][Capture] Pause-release overrun[/+] on Sep 9, 2019

  7. dengyangchao commented on Sep 16, 2019

    @dengyangchao
    dengyangchao
    on Sep 16, 2019

    issue still exist on ICL when doing pause 4ch arecord then resume #1731
    frequency
    100%

    recipe
    Firmware: 2bd725d https://github.com/thesofproject/sof/commits/master
    Kernel: 6cf9ef0 https://github.com/thesofproject/linux/commits/topic/sof-dev
    dmesg

    [   65.082274] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50010000: GLB_COMP_MSG: SET_VALUE
[   65.082276] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40020000: GLB_PM_MSG: CTX_RESTORE
[   65.082336] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x40020000: GLB_PM_MSG: CTX_RESTORE
[   65.082345] sof-audio-pci 0000:00:1f.3: pcm: open stream 6 dir 1
[   65.082346] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[   65.082347] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[   65.082347] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[   65.082627] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 6 dir 1
[   65.082629] sof-audio-pci 0000:00:1f.3: generating page table for 000000007f45ad70 size 0xffc0 pages 16
[   65.082661] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x40000 successful
[   65.082680] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x40000 successful
[   65.082682] sof-audio-pci 0000:00:1f.3: period_bytes:0x3fc0
[   65.082683] sof-audio-pci 0000:00:1f.3: periods:4
[   65.082699] sof-audio-pci 0000:00:1f.3: stream_tag 2
[   65.082702] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[   65.083032] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[   65.083033] sof-audio-pci 0000:00:1f.3: pcm: stream dir 1, posn mailbox offset is 790528
[   65.083406] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 6 dir 1 cmd 1
[   65.083950] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x2024001e successful
[   65.083951] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[   65.084137] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[   65.580168] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[   65.580222] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[   66.080235] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[   66.080266] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[   69.133731] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 6 dir 1 cmd 3

    sof-logger

     CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME	CONTENT
    0      1          DAI 10.66   1276721758.072917              nan      src/audio/dai.c:609 	dai_check_for_xrun() error: overrun due to no data available
    0      1         COMP         1276721766.875000         8.802083 of/audio/component.h:758 	comp_overrun() error: dev->comp.id = 66, sink->free = 512, copy_bytes = 0
    0      1         PIPE         1276721848.906250        82.031250 src/audio/pipeline.c:801 	pipeline_copy() error: ret = -61, start->comp.id = 66, dir = 0
    0      1         PIPE 10.67   1276721860.104167        11.197917 src/audio/pipeline.c:977 	pipeline_task(): xrun recover failed! pipeline will be stopped!
    0      1         COMP         1280082978.072917   3361118.000000 rc/audio/component.c:192 	comp_set_state() error: wrong state = 5, COMP_TRIGGER_RESET
    0      1         COMP         1280082998.177083        20.104166 rc/audio/component.c:192 	comp_set_state() error: wrong state = 5, COMP_TRIGGER_RESET

    dmesg.log
    logger.log
    logger_error.log

  8. dengyangchao commented on Sep 16, 2019

    @dengyangchao
    dengyangchao
    on Sep 16, 2019

    issue still exist on CFL
    frequency
    1/80
    recipe
    Firmware: 2bd725d https://github.com/thesofproject/sof/commits/master
    Kernel: 6cf9ef0 https://github.com/thesofproject/linux/commits/topic/sof-dev

    dmesg

    [  184.161645] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[  184.277150] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 1 cmd 3
[  184.277784] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20240000 successful
[  184.277804] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[  184.278035] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60060000 size 12
[  184.278044]  HDA Analog: ASoC: trigger FE failed -22
[  184.278056] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 1 cmd 4
[  184.278636] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x2024001e successful
[  184.278643] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
[  184.278882] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60070000 size 12
[  184.278890]  HDA Analog: ASoC: trigger FE failed -22
[  184.661620] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[  184.661658] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[  184.784878] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 1 cmd 0
[  184.785458] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20240000 successful
[  184.785478] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[  184.785637] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[  184.785642] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  184.785855] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  184.785869] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=0
[  184.785883] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[  184.786157] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
[  184.786472] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[  184.786644] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
[  184.786692] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 1

    sof-logger

     CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME	CONTENT
    0      1          DAI 2.13    229589602.135417 229589600.000000      src/audio/dai.c:609 	dai_check_for_xrun() error: overrun due to no data available
    0      1         COMP         229589609.166667         7.031250 of/audio/component.h:758 	comp_overrun() error: dev->comp.id = 13, sink->free = 768, copy_bytes = 0
    0      1         PIPE         229589644.114583        34.947918 src/audio/pipeline.c:801 	pipeline_copy() error: ret = -61, start->comp.id = 13, dir = 0
    0      1         PIPE 2.14    229589651.666667         7.552083 src/audio/pipeline.c:977 	pipeline_task(): xrun recover failed! pipeline will be stopped!
    0      1         COMP         230346360.468750    756708.812500 rc/audio/component.c:182 	comp_set_state() error: wrong state = 1, COMP_TRIGGER_PAUSE
    0      1          IPC         230346367.708333         7.239583 src/audio/pipeline.c:651 	pipeline_trigger() error: ret = -22, host->comp.id = 9, cmd = 2
    0      1          IPC         230346375.364583         7.656250    src/ipc/handler.c:489 	ipc: comp 9 trigger 0x60000 failed -22
    0      1         COMP         230347421.510417      1046.145874 rc/audio/component.c:156 	comp_set_state() error: wrong state = 1, COMP_TRIGGER_RELEASE
    0      1          IPC         230347428.541667         7.031250 src/audio/pipeline.c:651 	pipeline_trigger() error: ret = -22, host->comp.id = 9, cmd = 3
    0      1          IPC         230347435.833333         7.291667    src/ipc/handler.c:489 	ipc: comp 9 trigger 0x70000 failed -22
    0      1         COMP         230981159.114583    633723.250000 rc/audio/component.c:192 	comp_set_state() error: wrong state = 5, COMP_TRIGGER_RESET

    dmesg.log
    logger.log
    logger_error.log

  9. dengyangchao commented on Sep 26, 2019

    @dengyangchao
    dengyangchao
    on Sep 26, 2019

    issue over 20 times run can not occur on ICL-RVP with #1731

    Recipe
    Firmware: 3ce82a1 https://github.com/thesofproject/sof/commits/master
    Kernel: e03f882 https://github.com/thesofproject/linux/commits/topic/sof-dev
    Topology: file: tools/topology/sof-hda-generic-4ch.tplg same as firmware
    platform: ICL-RVP

  10. lgirdwood commented on Sep 30, 2019

    @lgirdwood
    lgirdwood
    on Sep 30, 2019
    Member

    @tlauda are we blocking next record on DMA copy completion ?

  11. tlauda commented on Sep 30, 2019

    @tlauda
    tlauda
    on Sep 30, 2019
    ContributorAuthor

    @dengyangchao @ClarexZhou This issue should not occur with the latest kernel. Please verify.

  12. lgirdwood commented on Oct 1, 2019

    @lgirdwood
    lgirdwood
    on Oct 1, 2019
    Member

    @tlauda Btw, I've seen this pause release CI failure appear twice today on CI. https://sof-ci.01.org/sofpr/PR1889/build3371/devicetest/

  13. tlauda commented on Oct 1, 2019

    @tlauda
    tlauda
    on Oct 1, 2019
    ContributorAuthor

    @lgirdwood Yes, but it's a different issue. It only happens for HDA Link playback and it's tracked here: thesofproject/linux#1160.
    This one here is for capture and it should be not reproducible with L1SEN disabled.

  14. wenqingfu commented on Oct 2, 2019

    @wenqingfu
    wenqingfu
    on Oct 2, 2019

    after thesofproject/linux#1070 was merged, I don't see Input/Output error happen during capture pause-release on the labelled platforms anymore. Can we close this issue?

  15. tlauda
    closed this as completedon Oct 3, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    CFLApplies to Coffee Lake platformCMLApplies to Comet Lake platformCNLApplies to Cannonlake platformWHLApplies to WhiskeyLake platformbugSomething isn't working as expected

    Type

    No type

    Projects

    No projects

      Milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions