Skip to content

[BUG][CML] audio stops during aplay playback #3619

New issue
New issue
Closed
#3712
Closed
[BUG][CML] audio stops during aplay playback#3619
#3712
Labels
CMLApplies to Comet Lake platformDisplay AudioIssues with display audio (via external HDMI or DP display)P2Critical bugs or normal featuresbugSomething isn't working as expected

Description

@brentlu
brentlu
opened on Nov 18, 2020

Describe the bug
We've received a chromebox Kaisa which audio stops during playback. Need to reload the firmware to recover from this situation.

To Reproduce

  1. Playing youtube videos to headphone or HDMI.
  2. Or just run aplay

Reproduction Rate
It takes around 10~20 mins to waiting for this issue happens.

Expected behavior
The audio playback should not stops.

Impact
Audio function is broken before going into runtime suspend.

Environment

  1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
    • Kernel: Chrome-v4.19
    • SOF: cml-008-patch-backport 7a84205
  2. Name of the topology file
    • Topology: sof-cml-rt5682.tplg
  3. Name of the platform(s) on which the bug is observed.
    • Platform: CML Chromebox Kaisa

dmesg-fail-3.txt
sof-log-fail-3.txt

Activity

  1. brentlu
    added
    bugSomething isn't working as expected
    on Nov 18, 2020

  2. brentlu commented on Nov 18, 2020

    @brentlu
    brentlu
    on Nov 18, 2020
    ContributorAuthor

    From kernel side only drop command fails. It's interesting that if the trace feature is disabled, the following pcm_free and config commands will fail, too.

    [ 4442.604052] sound pcmC0D2p: snd_pcm_common_ioctl: DROP
    [ 4442.604138] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
    [ 4442.604403] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60050000 size 12
    [ 4442.604431] HDMI1: ASoC: trigger FE cmd: 0 failed: -22
    [ 4442.604508] sound pcmC0D2p: snd_pcm_common_ioctl: HW_FREE
    [ 4442.604526] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
    [ 4442.604844] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
    [ 4442.604920] sound pcmC0D2p: snd_pcm_release:
    [ 4442.604982] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
    [ 4442.605296] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
    [ 4444.934238] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
    [ 4444.934503] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x40010000: GLB_PM_MSG: CTX_SAVE

    From SOF side I can only see some suspicious "no bytes to produce" messages.

    0      2       BUFFER         2448402059.479167  27028618.000000   src/audio/buffer.c:126 	comp_update_buffer_produce(), no bytes to produce, source->comp.id = 16, source->comp.type = 1, sink->comp.id = 17, sink->comp.type = 5
0      2       BUFFER         2450962059.322917   2559999.750000   src/audio/buffer.c:126 	comp_update_buffer_produce(), no bytes to produce, source->comp.id = 16, source->comp.type = 1, sink->comp.id = 17, sink->comp.type = 5
0      2       BUFFER         2497523309.531250  46561252.000000   src/audio/buffer.c:126 	comp_update_buffer_produce(), no bytes to produce, source->comp.id = 16, source->comp.type = 1, sink->comp.id = 17, sink->comp.type =

  3. lgirdwood commented on Nov 19, 2020

    @lgirdwood
    lgirdwood
    on Nov 19, 2020
    Member

    @brentlu can you confirm the test ? Are you testing long duration youtube playback or are you testing runtime suspend.

    It looks like there is no audio data coming from the host (which tries to recover).

        0      2         HOST 4.16    2421372684.739583         5.156250     src/audio/host.c:283 	host_trigger()
    0      2          DMA         2421372690.208333         5.468750 intel/cavs/hda-dma.c:462 	hda-dmac: 5 channel 0 -> start
    0      2          DMA         2421372695.468750         5.260417 intel/cavs/hda-dma.c:313 	hda-dmac: 5 channel 0 -> enable
    0      2       VOLUME         2421372755.729167        60.260418 udio/volume/volume.c:531 	volume_trigger()
    0      2          DAI 4.20    2421372760.989583         5.260417      src/audio/dai.c:494 	dai_comp_trigger(), command = 1
    0      2          DAI 4.20    2421372765.729167         4.739583      src/audio/dai.c:505 	dai_comp_trigger(), START
    0      2          DMA         2421373436.666667       670.937500 intel/cavs/hda-dma.c:462 	hda-dmac: 7 channel 0 -> start
    0      2          DMA         2421373442.447917         5.781250 intel/cavs/hda-dma.c:313 	hda-dmac: 7 channel 0 -> enable
    0      2       BUFFER         2448402059.479167  27028618.000000   src/audio/buffer.c:126 	comp_update_buffer_produce(), no bytes to produce, source->comp.id = 16, source->comp.type = 1, sink->comp.id = 17, sink->comp.type = 5
    0      2       BUFFER         2450962059.322917   2559999.750000   src/audio/buffer.c:126 	comp_update_buffer_produce(), no bytes to produce, source->comp.id = 16, source->comp.type = 1, sink->comp.id = 17, sink->comp.type = 5
    0      2       BUFFER         2497523309.531250  46561252.000000   src/audio/buffer.c:126 	comp_update_buffer_produce(), no bytes to produce, source->comp.id = 16, source->comp.type = 1, sink->comp.id = 17, sink->comp.type = 5

    Comp ID 16 is host DMA. It looks like userspace is sending some ioctls below to recover.

    [ 4432.494400] sound pcmC0D2p: snd_pcm_common_ioctl: FORWARD
[ 4432.934967] sound pcmC0D2p: snd_pcm_common_ioctl: FORWARD
[ 4442.604052] sound pcmC0D2p: snd_pcm_common_ioctl: DROP
[ 4442.604138] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 4442.604403] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60050000 size 12
[ 4442.604431]  HDMI1: ASoC: trigger FE cmd: 0 failed: -22
[ 4442.604508] sound pcmC0D2p: snd_pcm_common_ioctl: HW_FREE
[ 4442.604526] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 4442.604844] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 4442.604920] sound pcmC0D2p: snd_pcm_release:
[ 4442.604982] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[ 4442.605296] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
[ 4444.934238] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[ 4444.934503] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x40010000: GLB_PM_MSG: CTX_SAVE

  4. brentlu commented on Nov 19, 2020

    @brentlu
    brentlu
    on Nov 19, 2020
    ContributorAuthor

    I'm testing youtube playback.

    I do more tests today and found that the issue disappear with topology file built by myself. Still don't know what's wrong with the topology file used by google (sof-cml-rt5682.tplg) but it could explain why this issue does not happen to other CML chromebooks since the topology file is different.

    I will test more times to confirm it's the topology.

  5. lgirdwood commented on Nov 20, 2020

    @lgirdwood
    lgirdwood
    on Nov 20, 2020
    Member

    @brentlu please let us know the differences in topology files.

  6. mengdonglin
    added
    CMLApplies to Comet Lake platform
    on Nov 24, 2020
  7. slawblauciak
    added
    P2Critical bugs or normal features
    on Nov 24, 2020
  8. mengdonglin
    added
    Display AudioIssues with display audio (via external HDMI or DP display)
    on Nov 24, 2020

  9. brentlu commented on Dec 4, 2020

    @brentlu
    brentlu
    on Dec 4, 2020
    ContributorAuthor

    The difference is tool chain. Google's version is built by alsa-lib/alsa-utils 1.1.9 and my version is built by 1.2.4.

  10. brentlu commented on Dec 4, 2020

    @brentlu
    brentlu
    on Dec 4, 2020
    ContributorAuthor

    This issue still could happen with topology built by 1.2.4 but the rate decreases dramatically on my machine. But it seems no difference on other fail machines according to ODM's report.

  11. lgirdwood commented on Dec 4, 2020

    @lgirdwood
    lgirdwood
    on Dec 4, 2020
    Member

    @brentlu can you confirm if aplay works for longer than 10mins. i.e. aplay /dev/zero Lets try and work out if this is down to a timebase difference coming from youtube.

    Can you also confirm if the binary topology files built with different toolchains are the same or different.

  12. brentlu commented on Dec 7, 2020

    @brentlu
    brentlu
    on Dec 7, 2020
    ContributorAuthor

    I've got more log for this issue.

    From SOF side, it's a buffer underrun.

    0      2       BUFFER         160288579.218750  85802368.000000   src/audio/buffer.c:126 	comp_update_buffer_produce(), no bytes to produce, source->comp.id = 16, source->comp.type = 1, sink->comp.id = 17, sink->comp.type = 5
0      2       BUFFER         160289829.114583      1249.895874   src/audio/buffer.c:126 	comp_update_buffer_produce(), no bytes to produce, source->comp.id = 16, source->comp.type = 1, sink->comp.id = 17, sink->comp.type = 5
0      2       BUFFER         160291059.583333      1230.468750   src/audio/buffer.c:126 	comp_update_buffer_produce(), no bytes to produce, source->comp.id = 17, source->comp.type = 5, sink->comp.id = 20, sink->comp.type = 2
0      2       BUFFER         160291064.739583         5.156250   src/audio/buffer.c:208 	comp_update_buffer_consume(), no bytes to consume, source->comp.id = 16, source->comp.type = 1, sink->comp.id = 17, sink->comp.type = 5
0      2       BUFFER         160292308.958333      1244.218750   src/audio/buffer.c:126 	comp_update_buffer_produce(), no bytes to produce, source->comp.id = 17, source->comp.type = 5, sink->comp.id = 20, sink->comp.type = 2
0      2       BUFFER         160292313.958333         5.000000   src/audio/buffer.c:208 	comp_update_buffer_consume(), no bytes to consume, source->comp.id = 16, source->comp.type = 1, sink->comp.id = 17, sink->comp.type = 5
0      1          DAI 4.20    160293556.145833      1242.187500      src/audio/dai.c:586 	dai_check_for_xrun() error: underrun due to no data available
0      1         COMP         160293562.864583         6.718750 of/audio/component.h:743 	comp_underrun() error: dev->comp.id = 20, source->avail = 0, copy_bytes = 0

    But from Linux side, the hw_ptr/appl_prt suggests the buffer is full so audio server stops feeding data. My best guess is there is something wrong in the hda_dsp_pcm_pointer() function for HDMI playback stream.

    [ 128.437711] sound pcmC0D2p: [P] pos 5000 hw_ptr 3294968 appl_ptr 3309568 avail 1768
    ...
    [ 239.652829] sound pcmC0D2p: [P] pos 5000 hw_ptr 3294968 appl_ptr 3311336 avail 0

    dmesg.txt is the kernel log. sof-log.txt is SOF trace before this issue happens and sof-log-3.txt is the trace after the issue happens.

    dmesg.txt
    sof-log.txt
    sof-log-3.txt

  13. brentlu commented on Dec 7, 2020

    @brentlu
    brentlu
    on Dec 7, 2020
    ContributorAuthor

    I print IPC commends in kernel log. The sequence of TPLG_COMP_CONNECT commands is different but it should be fine. I see no other difference in IPC command parameters. Cannot explain why them make difference on certain machine.

    dmesg-1.1.9.txt
    dmesg-1.2.4.txt

  14. brentlu commented on Dec 7, 2020

    @brentlu
    brentlu
    on Dec 7, 2020
    ContributorAuthor

    It also happens to aplay.

    From kernel side the buffer is full.

    [ 877.329983] sound pcmC0D2p: snd_pcm_common_ioctl: WRITEI_FRAMES
    [ 877.329993] sound pcmC0D2p: [P] pos 16328 hw_ptr 36467864 appl_ptr 36483360 avail 872
    [ 877.832337] sof_rt5682 sof_rt5682: playback write error (DMA or IRQ trouble?)
    [ 877.832384] sound pcmC0D2p: snd_pcm_poll:
    [ 877.932653] sound pcmC0D2p: snd_pcm_poll:
    [ 877.932685] sound pcmC0D2p: snd_pcm_common_ioctl: WRITEI_FRAMES
    [ 877.932708] sound pcmC0D2p: [P] pos 1064 hw_ptr 36468968 appl_ptr 36484232 avail 1104
    [ 878.440176] sof_rt5682 sof_rt5682: playback write error (DMA or IRQ trouble?)
    [ 878.440212] sound pcmC0D2p: snd_pcm_poll:
    [ 878.540487] sound pcmC0D2p: snd_pcm_poll:
    [ 878.540519] sound pcmC0D2p: snd_pcm_common_ioctl: WRITEI_FRAMES
    [ 878.540541] sound pcmC0D2p: [P] pos 1064 hw_ptr 36468968 appl_ptr 36485336 avail 0
    [ 879.047743] sof_rt5682 sof_rt5682: playback write error (DMA or IRQ trouble?)
    [ 879.047850] sound pcmC0D2p: snd_pcm_common_ioctl: DROP
    [ 879.048109] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60050000 size 12
    [ 879.048134] HDMI1: ASoC: trigger FE cmd: 0 failed: -22
    [ 879.048161] sound pcmC0D2p: snd_pcm_common_ioctl: HW_FREE
    [ 879.048446] sound pcmC0D2p: snd_pcm_release:

    No error observed in SOF side.

    0      2          DAI 2.10    593748486.562500         4.687500      src/audio/dai.c:505 	dai_comp_trigger(), START
0      2          SSP         593748491.145833         4.583333 ers/intel/cavs/ssp.c:877 	ssp_trigger() cmd 1
0      2          SSP         593748496.770833         5.625000 ers/intel/cavs/ssp.c:806 	ssp_start()
0      2          IPC         593771256.927083     22760.156250    src/ipc/handler.c:455 	ipc: comp 6 -> trigger cmd 0x50000
0      2         PIPE 2.11    593771265.156250         8.229167 src/audio/pipeline.c:674 	pipeline_trigger()
0      2         HOST 2.6     593771270.208333         5.052083     src/audio/host.c:283 	host_trigger()
0      2          DMA         593771275.833333         5.625000 intel/cavs/hda-dma.c:538 	hda-dmac: 4 channel 1 -> stop
0      2       VOLUME         593771281.458333         5.625000 udio/volume/volume.c:531 	volume_trigger()
0      2          DAI 2.10    593771286.562500         5.104167      src/audio/dai.c:494 	dai_comp_trigger(), command = 0
0      2          DAI 2.10    593771291.302083         4.739583      src/audio/dai.c:558 	dai_comp_trigger(), PAUSE/STOP
0      2          DMA         593771296.197917         4.895833 src/drivers/dw/dma.c:353 	dw_dma_stop(): dma 1 channel 0 stop
0      2          SSP         593771301.875000         5.677083 ers/intel/cavs/ssp.c:877 	ssp_trigger() cmd 0
0      2          SSP         593771362.708333        60.833332 ers/intel/cavs/ssp.c:848 	ssp_stop(), RX stop
0      2          SSP         593771368.385417         5.677083 ers/intel/cavs/ssp.c:867 	ssp_stop(), SSP port disabled
0      2          IPC         593771691.875000       323.489594    src/ipc/handler.c:344 	ipc: comp 6 -> free
0      2         PIPE 2.11    593771699.583333         7.708333 src/audio/pipeline.c:752 	pipeline_reset()
0      2         HOST 2.6     593771704.479167         4.895833     src/audio/host.c:717 	host_reset()
0      2       VOLUME         593771714.218750         9.739583 udio/volume/volume.c:675 	volume_reset()

    sof-log-aplay.txt
    dmesg-aplay.txt

  15. lgirdwood commented on Dec 7, 2020

    @lgirdwood
    lgirdwood
    on Dec 7, 2020
    Member

    @slawblauciak fyi - aplay can also cause this issue. Could be HDA DMA getting confused over data free/avail ?

  16. lgirdwood
    changed the title [-][BUG][CML] audio stops during youtube playback[/-] [+][BUG][CML] audio stops during aplay playback[/+] on Dec 7, 2020

  17. lgirdwood commented on Dec 7, 2020

    @lgirdwood
    lgirdwood
    on Dec 7, 2020
    Member

    @brentlu can you tell us the aplay command line and length of time it takes to fail with aplay (plus any other settings).

  18. brentlu commented on Dec 7, 2020

    @brentlu
    brentlu
    on Dec 7, 2020
    ContributorAuthor

    @lgirdwood

    Hi,

    This is the command:
    $ aplay -D hw:0,2 -c 2 -f S16_LE -r 48000 /dev/zero

    It takes 13mins to reproduce:
    2020-12-07T09:41:46.395049Z DEBUG kernel: [ 93.594668] sound pcmC0D2p: snd_pcm_playback_open:
    ...
    2020-12-07T09:54:51.025137Z DEBUG kernel: [ 877.832337] sof_rt5682 sof_rt5682: playback write error (DMA or IRQ trouble?)

    It's interesting that this only happen to few Kaisa devices which is CML chromebox with rt5682 headphone codec. My experience is that for those devices which has this issue, there is an around 80% possibility to fail in 10 mins audio playback. OS version seems irrelevant according to ODM's rest result since we are using cml-008-patch-backport for long time.

    messages.txt

  19. brentlu
    linked a pull request that will close this issueBackport 1bfb1978d ('dma: alloc separate buffers for DMAs') #3682on Dec 10, 2020
  20. brentlu
    linked a pull request that will close this issueBackport 1bfb1978d ('dma: alloc separate buffers for DMAs') #3712on Dec 23, 2020

  21. plbossart commented on Jun 10, 2021

    @plbossart
    plbossart
    on Jun 10, 2021
    Member

    @brentlu did your backports solve this issue? if yes can we close?

  22. brentlu commented on Oct 22, 2021

    @brentlu
    brentlu
    on Oct 22, 2021
    ContributorAuthor

    Since the FW has been deployed since March 2020 without issue feedback til today, we can close it.

  23. brentlu
    closed this as completedon Oct 22, 2021
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

    CMLApplies to Comet Lake platformDisplay AudioIssues with display audio (via external HDMI or DP display)P2Critical bugs or normal featuresbugSomething isn't working as expected

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions