Skip to content

[BUG][APL]ipc error and error trace with "ERROR dw_dma_get_data_size(): xrun detected" when do Pause/Release: simultaneous playback/capture test #2735

Closed
Closed
[BUG][APL]ipc error and error trace with "ERROR dw_dma_get_data_size(): xrun detected" when do Pause/Release: simultaneous playback/capture test#2735
Assignees
plbossart
Labels
APLApplies to Apollolake platformP1Blocker bugs or important featuresbugSomething isn't working as expected
Milestone
v1.6

Description

@Liviali155
Liviali155
opened on Apr 7, 2020

Describe the bug
"ERROR dw_dma_get_data_size(): xrun detected" when do Pause/Release: simultaneous playback/capture test
After error occured,all the pipeline can not work,reboot can recovery

Used ubuntu@sh-apl-up2-pcm512x-02:

ubuntu@sh-apl-up2-pcm512x-02:~$ aplay -l
**** List of PLAYBACK Hardware Devices ****
card 0: sofpcm512x [sof-pcm512x], device 0: Port5 (*) []
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 0: sofpcm512x [sof-pcm512x], device 1: HDMI1 (*) []
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 0: sofpcm512x [sof-pcm512x], device 2: HDMI2 (*) []
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 0: sofpcm512x [sof-pcm512x], device 3: HDMI3 (*) []
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 0: sofpcm512x [sof-pcm512x], device 4: Media Playback 4 (*) []
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 1: Device [USB Audio Device], device 0: USB Audio [USB Audio]
  Subdevices: 1/1
  Subdevice #0: subdevice #0

ubuntu@sh-apl-up2-pcm512x-02:~$ arecord -l
**** List of CAPTURE Hardware Devices ****
card 0: sofpcm512x [sof-pcm512x], device 0: Port5 (*) []
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 0: sofpcm512x [sof-pcm512x], device 5: DMIC (*) []
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 0: sofpcm512x [sof-pcm512x], device 6: DMIC16kHz (*) []
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 1: Device [USB Audio Device], device 0: USB Audio [USB Audio]
  Subdevices: 1/1
  Subdevice #0: subdevice #0

To Reproduce
1.sudo reboot
2.cd sof-test
3.cd test-case
4.export TPLG=/lib/firmware/intel/sof-tplg/sof-apl-pcm512x.tplg
5../multiple-pause-resume.sh -r 25(https://github.com/thesofproject/sof-test/blob/master/test-case/multiple-pause-resume.sh)

Reproduction Rate
2/3

Expected behavior
There is o error occured when do do Pause/Release: simultaneous playback/capture test

Impact
Connection timed out,dmesg show ""error: ipc timed out for 0x60070000 size 12" when do pause/release of aplay(0,0) and arecord (0,0)

1

dmesgerror.log 
32110] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 0 dir 0 cmd 4
sh-apl-up2-pcm512x-02 kernel: [ 1094.433119] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x2014001e successful
sh-apl-up2-pcm512x-02 kernel: [ 1094.433137] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
sh-apl-up2-pcm512x-02 kernel: [ 1094.844684] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 0 dir 1 cmd 3
sh-apl-up2-pcm512x-02 kernel: [ 1094.936041] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60070000 size 12
sh-apl-up2-pcm512x-02 kernel: [ 1094.936055] sof-audio-pci 0000:00:0e.0: info: preventing DSP entering D3 state to preserve context
sh-apl-up2-pcm512x-02 kernel: [ 1094.936064] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
sh-apl-up2-pcm512x-02 kernel: [ 1094.936120] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
sh-apl-up2-pcm512x-02 kernel: [ 1094.936132] sof-audio-pci 0000:00:0e.0: error: hda irq intsts 0x00000000 intlctl 0xc0000083 rirb 00
sh-apl-up2-pcm512x-02 kernel: [ 1094.936138] sof-audio-pci 0000:00:0e.0: error: dsp irq ppsts 0x00000000 adspis 0x00000000
sh-apl-up2-pcm512x-02 kernel: [ 1094.936147] sof-audio-pci 0000:00:0e.0: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
sh-apl-up2-pcm512x-02 kernel: [ 1094.936153] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
sh-apl-up2-pcm512x-02 kernel: [ 1094.936172]  Port5: ASoC: trigger FE cmd: 4 failed: -110
sh-apl-up2-pcm512x-02 kernel: [ 1094.936190] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 0 dir 0 cmd 3
sh-apl-up2-pcm512x-02 kernel: [ 1094.936201] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
sh-apl-up2-pcm512x-02 kernel: [ 1094.936212] sof-audio-pci 0000:00:0e.0: error: trace IO error
sh-apl-up2-pcm512x-02 kernel: [ 1095.440015] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60060000 size 12
sof_errortrace.log 
    TIMESTAMP              DELTA C# COMPONENT          LOCATION                       CONTENT
[1094283701.770833] (             nan) c0 DMA                    src/drivers/dw/dma.c:1063  ERROR dw_dma_get_data_size(): xrun detected
[1094283706.406250] (        4.635417) c0 dai          6.39           src/audio/dai.c:648   ERROR dai_report_xrun(): overrun due to no data available
[1094283709.791667] (        3.385417) c0 dai          6.39           src/audio/dai.c:657   ERROR comp_overrun(): sink->free = 768, copy_bytes = 0
[1094283770.156250] (       60.364582) c0 PIPE                   src/audio/pipeline.c:860   ERROR pipeline_copy(): ret = -61, start->comp.id = 39, dir = 0
[1094283774.166667] (        4.010417) c0 PIPE         6.40      src/audio/pipeline.c:1040  ERROR pipeline_task(): xrun recover failed! pipeline will be stopped!

Platform: APL UP2 with I2S PCM512x
Firmware: b4e8b1e https://github.com/thesofproject/sof/commits/master
Kernel: 052e45d https://github.com/thesofproject/linux/commits/topic/sof-dev
Topology: file: tools/topology/sof-apl-pcm512x.tplg same as firmware

dmesg.txt
etrace.txt
slogger.txt

Activity

  1. Liviali155
    added
    bugSomething isn't working as expected
    APLApplies to Apollolake platform
    P2Critical bugs or normal features
    on Apr 7, 2020

  2. Liviali155 commented on Apr 7, 2020

    @Liviali155
    Liviali155
    on Apr 7, 2020
    Author

    Bisect result:Caused by firmware commit 8b7f1fa

  3. paulstelian97 commented on Apr 7, 2020

    @paulstelian97
    paulstelian97
    on Apr 7, 2020
    Collaborator

    Bisect result:Caused by firmware commit 8b7f1fa

    Did you turn off the agent on that firmware? This commit switches to DMA scheduling which doesn't work well with the agent (currently).

  4. Liviali155 commented on Apr 9, 2020

    @Liviali155
    Liviali155
    on Apr 9, 2020
    Author

    Bisect result:Caused by firmware commit 8b7f1fa

    Did you turn off the agent on that firmware? This commit switches to DMA scheduling which doesn't work well with the agent (currently).

    After turn off the agent，issue still can be reproduced

  5. paulstelian97 commented on Apr 9, 2020

    @paulstelian97
    paulstelian97
    on Apr 9, 2020
    Collaborator

    How many pipelines? It's possible we have an issue of overloading the system so you may need to also disable the low-power clock (if it applies to this platform, I'm not sure)

  6. Liviali155 commented on Apr 9, 2020

    @Liviali155
    Liviali155
    on Apr 9, 2020
    Author

    How many pipelines? It's possible we have an issue of overloading the system so you may need to also disable the low-power clock (if it applies to this platform, I'm not sure)

    Error occured when do pause/release of
    aplay -D hw:0,0 -r 48000 -c 2 -f S16_LE -vv -i /dev/zero -q
    arecord -D hw:0,0 -r 48000 -c 2 -f S16_LE -vv -i /dev/null -q

    I will try to disable the low power to check it

  7. Liviali155 commented on Apr 9, 2020

    @Liviali155
    Liviali155
    on Apr 9, 2020
    Author

    It seems it has no low power clock item,I have no method to disable low-power clock
    Capture

  8. paulstelian97 commented on Apr 9, 2020

    @paulstelian97
    paulstelian97
    on Apr 9, 2020
    Collaborator

    Hm, the particular topology you mention in the issue shouldn't be affected at all by that commit if I read it correctly. @plbossart @tlauda can you take a look?

    The commit contents says you manually copy one of the topologies (removing the -master and -44100 suffixes if there). The one without such a suffix should remain identical and thus this commit shouldn't affect it.

  9. plbossart commented on Apr 10, 2020

    @plbossart
    plbossart
    on Apr 10, 2020
    Member

    that bisect result looks like a false positive to me?

  10. Liviali155 commented on Apr 10, 2020

    @Liviali155
    Liviali155
    on Apr 10, 2020
    Author

    I retest it：
    8b7f1fa fail
    1ecf435 "./multiple-pause-resume.sh -r 2000" +"./multiple-pause-resume.sh -r 500" pass

  11. ClarexZhou
    added
    P1Blocker bugs or important features
    and removed
    P2Critical bugs or normal features
    on Apr 13, 2020
  12. mengdonglin
    added
    topologyTopology issues
    on Apr 14, 2020

  13. 7 remaining items

  14. YvonneYang2
    changed the title [-][BUG][APL]"error: ipc timed out for 0x60070000 size 12" when do Pause/Release: simultaneous playback/capture test[/-] [+][BUG][APL]"ERROR dw_dma_get_data_size(): xrun detected" when do Pause/Release: simultaneous playback/capture test[/+] on Jun 8, 2020
  15. lgirdwood
    added this to the v1.6 milestone on Jun 10, 2020
  16. YvonneYang2
    changed the title [-][BUG][APL]"ERROR dw_dma_get_data_size(): xrun detected" when do Pause/Release: simultaneous playback/capture test[/-] [+][BUG][APL]ipc error and error trace with "ERROR dw_dma_get_data_size(): xrun detected" when do Pause/Release: simultaneous playback/capture test[/+] on Jun 11, 2020

  17. Liviali155 commented on Jul 24, 2020

    @Liviali155
    Liviali155
    on Jul 24, 2020
    Author

    Issue still can be reproduced with latest sof-dev(e1a25077)+master(44a65d8)on apl pcm512 when run multiple-pause-resume

    dmesg_error.log 
    [  143.399029] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
[  143.604184] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 0 dir 1 cmd 3
[  143.604197] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[  143.604339] sof-audio-pci 0000:00:0e.0: error: ipc error for 0x60060000 size 12
[  143.604356] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x20240000 successful
[  143.604363] sof-audio-pci 0000:00:0e.0: ASoC: error at snd_soc_pcm_component_trigger on 0000:00:0e.0: -22
[  143.604370]  Port5: ASoC: trigger FE cmd: 3 failed: -22
[  143.604382] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 0 dir 1 cmd 4
[  143.604887] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x2024001e successful
[  143.604897] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
[  143.605173] sof-audio-pci 0000:00:0e.0: error: ipc error for 0x60070000 size 12
[  143.605183] sof-audio-pci 0000:00:0e.0: ASoC: error at snd_soc_pcm_component_trigger on 0000:00:0e.0: -22
[  143.605187]  Port5: ASoC: trigger FE cmd: 4 failed: -22
[  143.605558] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 0 dir 1 cmd 3
[  143.605565] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[  143.605680] sof-audio-pci 0000:00:0e.0: error: ipc error for 0x60060000 size 12
[  143.605691] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x20240000 successful
[  143.605697] sof-audio-pci 0000:00:0e.0: ASoC: error at snd_soc_pcm_component_trigger on 0000:00:0e.0: -22
[  143.605701]  Port5: ASoC: trigger FE cmd: 3 failed: -22
[  143.605709] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 0 dir 1 cmd 4
[  143.606255] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x2024001e successful
[  143.606277] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
[  143.606373] sof-audio-pci 0000:00:0e.0: error: ipc error for 0x60070000 size 12
[  143.606378] sof-audio-pci 0000:00:0e.0: ASoC: error at snd_soc_pcm_component_trigger on 0000:00:0e.0: -2
    sof_error.log 
    0 ll-schedule        ./schedule/ll_schedule.c:249  num_tasks 2 total_num_tasks 2
[  1285222.031250] (    11874.948242) c0 dw-dma                 src/drivers/dw/dma.c:1020 dw_dma_avail_data_size() size is 0!
[  1285234.895833] (       12.864583) c0 host         6.35          src/audio/host.c:383  host_copy_normal(): no bytes to copy
[  1289223.750000] (     3988.854248) c0 dw-dma                 src/drivers/dw/dma.c:1056 ERROR dw_dma_get_data_size(): xrun detected
[  1289227.083333] (        3.333333) c0 dai          6.39           src/audio/dai.c:667  ERROR dai_report_xrun(): overrun due to no data available
[  1289229.583333] (        2.500000) c0 dai          6.39           src/audio/dai.c:694  ERROR comp_overrun(): sink->free = 768, copy_bytes = 0
[  1289232.604167] (        3.020833) c0 pipe         6.40      src/audio/pipeline.c:791  pipe trigger cmd 8
[  1289237.031250] (        4.427083) c0 dai          6.39           src/audio/dai.c:638  dai_comp_trigger(), XRUN
[  1289240.520833] (        3.489583) c0 dw-dma                 src/drivers/dw/dma.c:406  dw_dma_stop(): dma 1 channel 0 stop
[  1289245.677083] (        5.156250) c0 ssp-dai      1.5   /drivers/intel/ssp/ssp.c:760  ssp_trigger() cmd 8
[  1289252.552083] (        6.875000) c0 dai          6.39      src/audio/pipeline.c:206  perf comp_copy peak plat 567 cpu 9494
[  1289255.989583] (        3.437500) c0 pipe         6.40      src/audio/pipeline.c:951  ERROR pipeline_copy(): ret = -61, start->comp.id = 39, dir = 0
[  1289259.010417] (        3.020833) c0 pipe         6.40      src/audio/pipeline.c:1141 ERROR pipeline_task(): xrun recover failed! pipeline will be stopped!
[  1289262.187500] (        3.177083) c0 ll-schedule        ./schedule/ll_schedule.c:118  task complete 0xbe04b3c0 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[  1289265.468750] (        3.281250) c0 ll-schedule        ./schedule/ll_schedule.c:121  num_tasks 1 total_num_tasks 1
[  1311222.447917] (    21956.978516) c0 dai          1.8       src/audio/pipeline.c:206  perf comp_copy peak plat 267 cpu 4454
[  1359222.500000] (    48000.050781) c0 dai          1.8       src/audio/pipeline.c:206  perf comp_copy peak plat 268 cpu 4456
[  1533655.156250] (   174432.656250) c0 pipe         1.9       src/audio/pipeline.c:791  pipe trigger cmd 2

    dmesg0724.log
    sof-logger0724.log

  18. plbossart commented on Jul 30, 2020

    @plbossart
    plbossart
    on Jul 30, 2020
    Member

    Issue #3256 seems to be a duplicate, but contains additional information that point to the DW DMA handling being the problem?

  19. slawblauciak
    assigned
    ktrzcinx
    and unassigned
    plbossart
    and
    slawblauciak
    on Sep 1, 2020

  20. ktrzcinx commented on Sep 3, 2020

    @ktrzcinx
    ktrzcinx
    on Sep 3, 2020
    Member

    The issue can't be reproduced with RVP-APL platform, bisect shows commit with topology changes, so it doesn't look like FW issue. I can't effectively handle this issue because of limited access to full-linux-stack apl platform.

  21. ktrzcinx
    assigned
    plbossart
    and unassigned
    ktrzcinx
    on Sep 3, 2020

  22. mengdonglin commented on Sep 8, 2020

    @mengdonglin
    mengdonglin
    on Sep 8, 2020
    Collaborator

    @plbossart @lyakh #3289 has been merged. Can you help check if this issue can be reproduced on your UP2 with PCM512?

    Suggest lower the priority to P2 as this topology is not a product one.

  23. lyakh commented on Sep 8, 2020

    @lyakh
    lyakh
    on Sep 8, 2020
    Collaborator

    @plbossart @lyakh #3289 has been merged. Can you help check if this issue can be reproduced on your UP2 with PCM512?

    Suggest lower the priority to P2 as this topology is not a product one.

    @mengdonglin @plbossart I've run a multiple-pause-resume.sh test with 25 repetitions (-r 25). The first attempt failed with a "device busy" error from aplay (or arecord). No errors in dmesg or in FW traces. The second attempt ran through successfully. So, I would say I cannot reproduce it. The log does seem to look a bit different from #3256 but it's possible that the switch to the timer scheduling domain has fixed this one too...

  24. mengdonglin commented on Sep 8, 2020

    @mengdonglin
    mengdonglin
    on Sep 8, 2020
    Collaborator

    @lyakh Many thanks for the fix and double check! Let's close it.

  25. mengdonglin
    closed this as completedon Sep 8, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

APLApplies to Apollolake platformP1Blocker bugs or important featuresbugSomething isn't working as expected

Type

No type

Projects

No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions