[BUG] start/stop floods with applications using start threshold, e.g. with aplay+S3

Describe the bug
There seems to be an issue with handling a TRIG_START when following conditions apply:

stream has been previously running and then restarted (1) S3 suspend+resume, 2) application stopped with SIGSUSPEND, 3) XRUN, or 4) applications which start/stop the stream with snd_pcm_drop() + snd_pcm_prepare() + snd_pcm_start()))
application has set the "start_threshold" SW parameter to any lower value than the maximum, or explicitly starts the stream with snd_pcm_start()

With these conditions met, FW is not able to start the stream succesfully, but either ends up in a short start/stop loop causing dozens of XRUNs lasting multiple milliseconds (and making a pretty awful nosie), or in infinite loop (application must be terminated to recover).

This problem is at least a contributing factor to Pulseaudio issues tracked in linux#1000

To Reproduce
To simplify testing, I figured out following way to reproduce this with aplay (but this will impact a wide range of other ALSA applications):

aplay -R 21000 -Dhw:0 -vv -i testfile.wav
suspend aplay with 'ctrl-Z'
resume aplay with 'fg'
go back to (2) until error occurs

The error happens with 21ms start threshdold in this example, but notably
higher values (-R 200000) also cause the issue. Clearly DSP should have plenty of time to resume the stream with this much buffering in place.

Reproduction Rate
5/10

Expected behavior
Playback should resume succesfully.

Impact
Marked is as P2 as DSP should under no circumstance go into a state machine loop like this.

Environment

Branches
SOF: 0dd6c23 (master)
Linux: 2712289 (sof-dev head)

Note: attached log file has some additional patches (prints with "KV:"), but the bug is reproduced without these patches with the unmodified version above. The additional patches are to explain the problem better.

Name of the topology file: sof-hda-generic-2ch.tplg
Platform: WHL laptop with HDA codec
Reproducibility Rate: 5/10

Screenshots or console output

Sof-logger file attached.
20190617-soflog.txt

Annotating the attached log 20190617-soflog.txt:

The succesful playback of stream ends in the log with this:

    0      2          DMA         2496208914.010417        33.802082 intel/cavs/hda-dma.c:418 	hda-dmac: 5 channel 0 -> copy 0xc0 bytes
    0      1         PIPE         2496210130.260417      1216.250000 src/audio/pipeline.c:752 	pipeline_copy() preload=0
    0      2          DMA         2496210164.635417        34.375000 intel/cavs/hda-dma.c:418 	hda-dmac: 5 channel 0 -> copy 0xc0 bytes
    0      1         PIPE         2496211380.364583      1215.729126 src/audio/pipeline.c:752 	pipeline_copy() preload=0
    0      2          DMA         2496211414.322917        33.958332 intel/cavs/hda-dma.c:418 	hda-dmac: 5 channel 0 -> copy 0xc0 bytes
    0      2          IPC         2496212125.052083       710.729187    src/ipc/handler.c:439 	ipc: comp 1 -> trigger cmd 0x50000
    0      2         PIPE 1.6     2496212129.479167         4.427083 src/audio/pipeline.c:604 	pipeline_trigger()
    0      2         HOST         2496212133.489583         4.010417     src/audio/host.c:263 	host_trigger()
    0      2          DMA         2496212137.968750         4.479167 intel/cavs/hda-dma.c:647 	hda-dmac: 5 channel 0 -> stop
    0      2       VOLUME         2496212142.395833         4.427083 udio/volume/volume.c:521 	volume_trigger()
    0      2          DAI 1.5     2496212146.354167         3.958333      src/audio/dai.c:470 	dai_comp_trigger(), command = 0
    0      2          DAI 1.5     2496212150.208333         3.854167      src/audio/dai.c:534 	dai_comp_trigger(), PAUSE/STOP

Then starts a repeated sequence where host trying to restart the stream, it doesn't work, it stops it again (xrun handling), and tries to start again. This happens many times:

    0      2         PIPE 1.6     2496212129.479167         4.427083 src/audio/pipeline.c:604 	pipeline_trigger()
    0      2         HOST         2496212133.489583         4.010417     src/audio/host.c:263 	host_trigger()
    0      2          DMA         2496212137.968750         4.479167 intel/cavs/hda-dma.c:647 	hda-dmac: 5 channel 0 -> stop
    0      2       VOLUME         2496212142.395833         4.427083 udio/volume/volume.c:521 	volume_trigger()
    0      2          DAI 1.5     2496212146.354167         3.958333      src/audio/dai.c:470 	dai_comp_trigger(), command = 0
    0      2          DAI 1.5     2496212150.208333         3.854167      src/audio/dai.c:534 	dai_comp_trigger(), PAUSE/STOP
    0      2          DMA         2496212153.854167         3.645833 intel/cavs/hda-dma.c:647 	hda-dmac: 7 channel 0 -> stop
    0      2          DMA         2496822633.750000    610479.875000 intel/cavs/hda-dma.c:418 	hda-dmac: 4 channel 0 -> copy 0x2c0 bytes
    0      2          IPC         2497303274.687500    480640.937500    src/ipc/handler.c:439 	ipc: comp 1 -> trigger cmd 0x40000
    0      2         PIPE 1.6     2497303279.375000         4.687500 src/audio/pipeline.c:604 	pipeline_trigger()
    0      2         HOST         2497303283.437500         4.062500     src/audio/host.c:263 	host_trigger()
    0      2          DMA         2497303288.072917         4.635417 intel/cavs/hda-dma.c:552 	hda-dmac: 5 channel 0 -> start
    0      2          DMA         2497303291.927083         3.854167 intel/cavs/hda-dma.c:362 	hda-dmac: 5 channel 0 -> enable
    0      2          DMA         2497303295.468750         3.541667 intel/cavs/hda-dma.c:363 	hda-dmac: desc count 2
    0      2       VOLUME         2497303353.385417        57.916668 udio/volume/volume.c:521 	volume_trigger()
    0      2          DAI 1.5     2497303357.395833         4.010417      src/audio/dai.c:470 	dai_comp_trigger(), command = 1
    0      2          DAI 1.5     2497303361.406250         4.010417      src/audio/dai.c:481 	dai_comp_trigger(), START
    0      2          DMA         2497303365.416667         4.010417 intel/cavs/hda-dma.c:552 	hda-dmac: 7 channel 0 -> start
    0      2          DMA         2497303369.270833         3.854167 intel/cavs/hda-dma.c:362 	hda-dmac: 7 channel 0 -> enable
    0      2          DMA         2497303372.968750         3.697917 intel/cavs/hda-dma.c:363 	hda-dmac: desc count 2
    0      1         PIPE         2497303880.833333       507.864594 src/audio/pipeline.c:752 	pipeline_copy() preload=0
    0      2          DMA         2497303909.739583        28.906250 intel/cavs/hda-dma.c:418 	hda-dmac: 5 channel 0 -> copy 0x88 bytes
    0      2          IPC         2497304660.000000       750.260437    src/ipc/handler.c:439 	ipc: comp 1 -> trigger cmd 0x50000
    0      2         PIPE 1.6     2497304664.427083         4.427083 src/audio/pipeline.c:604 	pipeline_trigger()
    0      2         HOST         2497304668.489583         4.062500     src/audio/host.c:263 	host_trigger()
    0      2          DMA         2497304673.072917         4.583333 intel/cavs/hda-dma.c:647 	hda-dmac: 5 channel 0 -> stop
    0      2       VOLUME         2497304677.291667         4.218750 udio/volume/volume.c:521 	volume_trigger()
    0      2          DAI 1.5     2497304681.354167         4.062500      src/audio/dai.c:470 	dai_comp_trigger(), command = 0
    0      2          DAI 1.5     2497304685.312500         3.958333      src/audio/dai.c:534 	dai_comp_trigger(), PAUSE/STOP

Sometime we get into FW XRUN handling:

    0      2          DAI 1.5     2497323920.156250         4.062500      src/audio/dai.c:481 	dai_comp_trigger(), START
    0      2          DMA         2497323924.166667         4.010417 intel/cavs/hda-dma.c:552 	hda-dmac: 7 channel 0 -> start
    0      2          DMA         2497323928.072917         3.906250 intel/cavs/hda-dma.c:362 	hda-dmac: 7 channel 0 -> enable
    0      2          DMA         2497323931.770833         3.697917 intel/cavs/hda-dma.c:363 	hda-dmac: desc count 2
    0      1         PIPE         2497323946.927083        15.156250 src/audio/pipeline.c:752 	pipeline_copy() preload=0
    0      1          DAI 1.5     2497323954.635417         7.708333      src/audio/dai.c:562 	dai_check_for_xrun() error: underrun due to no data available
    0      1         COMP         2497323960.260417         5.625000 of/audio/component.h:732 	comp_underrun() error: dev->comp.id = 5, source->avail = 768,

And yet one case in the start/loop is failure to start up in preload state:

    0      2          IPC         2497443846.093750       759.479187    src/ipc/handler.c:439 	ipc: comp 1 -> trigger cmd 0x40000
    0      2         PIPE 1.6     2497443850.416667         4.322917 src/audio/pipeline.c:604 	pipeline_trigger()
    0      2         HOST         2497443854.427083         4.010417     src/audio/host.c:263 	host_trigger()
    0      2          DMA         2497443858.697917         4.270833 intel/cavs/hda-dma.c:552 	hda-dmac: 5 channel 0 -> start
    0      2          DMA         2497443862.708333         4.010417 intel/cavs/hda-dma.c:362 	hda-dmac: 5 channel 0 -> enable
    0      2          DMA         2497443866.250000         3.541667 intel/cavs/hda-dma.c:363 	hda-dmac: desc count 2
    0      2       VOLUME         2497443923.854167        57.604168 udio/volume/volume.c:521 	volume_trigger()
    0      2          DAI 1.5     2497443927.968750         4.114583      src/audio/dai.c:470 	dai_comp_trigger(), command = 1
    0      2          DAI 1.5     2497443931.770833         3.802083      src/audio/dai.c:481 	dai_comp_trigger(), START
    0      1         PIPE         2497443945.989583        14.218750 src/audio/pipeline.c:752 	pipeline_copy() preload=1
    0      1         HOST         2497443953.281250         7.291667     src/audio/host.c:753 	KV: host_params(): calling dma_copy with size 384
    0      2          DMA         2497443959.531250         6.250000 intel/cavs/hda-dma.c:418 	hda-dmac: 5 channel 0 -> copy 0x180 bytes
    0      2          DMA         2497443963.489583         3.958333 intel/cavs/hda-dma.c:437 	KV: after wait in hd_dma_copy(): full:0 empty:0
    0      1         HOST         2497443967.500000         4.010417     src/audio/host.c:765 	KV: host_params() error: dma_set_config() failed 384
    0      2         HOST         2497443973.229167         5.729167     src/audio/host.c:768 	host_copy(), preload not yet finished

In host side, aplay output looks like this:

##################                               + | 96%underrun!!! (at least 0,002 ms long)
Status:
  state       : XRUN
  trigger_time: 1998.149562659
  tstamp      : 0.000000
  delay       : 0
  avail       : 16672
  avail_max   : 16672
###################                              + | 96%underrun!!! (at least 0,002 ms long)
Status:
  state       : XRUN
  trigger_time: 1998.150581616
  tstamp      : 0.000000
  delay       : 0
  avail       : 16672
  avail_max   : 16672
###############                                  + | 96%underrun!!! (at least 0,002 ms long)
Status:
  state       : XRUN
  trigger_time: 1998.151584974
  tstamp      : 0.000000
  delay       : 0
  avail       : 16672
  avail_max   : 16672
################                                 + | 96%^C

Status update: The root of the problem seems to be the first DMA position that is visible to driver. Not clear yet whether this is FW or Linux driver bug (could be the latter as well, based on today's debug).

Log file showing the problem (driver log):

[ 1758.669701] sof-audio-pci 0000:00:1f.3: D: trig-ptr0 12408
[ 1758.669713] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 1758.669864] sof-audio-pci 0000:00:1f.3: D: stream_check
[ 1758.669976] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 1758.669986] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=1
[ 1758.670000] skl_hda_dsp_generic skl_hda_dsp_generic: D: avail = 12288, state 3, buffer size = 16368, period size = 4080
[ 1758.670087] sof-audio-pci 0000:00:1f.3: D: PCM: position 49792 (hdareg), position 0 (ipc)
NOTE: First driver checks for DMA position, half of the buffer is already consumed.
[ 1758.670092] skl_hda_dsp_generic skl_hda_dsp_generic: D: ptr0 12448 (old 0)
[ 1758.670099] skl_hda_dsp_generic skl_hda_dsp_generic: D: avail = 24736, state 3, buffer size = 16368, period size = 4080
NOTE: But this is even more suspicious, avail>buffer_size indicating an XRUN, which should not yet be the case.

Debug continues...

@tlauda

The root cause seems to be mis-synchronization of the host DMA pointer.

When Linux application goes through the STOP/XRUN->PREPARE->START transitions, at PREPARE the DMA position should be reset to 0. This is however not done. FW does not do this in host.c TRIG_START, and Linux driver does not do this in sof/pcm.c:prepare(). What follows is this (success case first, then failure case):

Success case:
[ 421.704543] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 421.704546] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=1
[ 421.704556] skl_hda_dsp_generic skl_hda_dsp_generic: D: avail = 12288 (hw_ptr=0/appl_ptr=4080), state 3, buffer size = 16368, period size = 4080
[ 421.704603] sof-audio-pci 0000:00:1f.3: D: PCM: position 384 (hdareg), position 0 (ipc)
[ 421.704604] skl_hda_dsp_generic skl_hda_dsp_generic: D: ptr0 96 (old 0)
[ 421.704605] skl_hda_dsp_generic skl_hda_dsp_generic: D: avail = 12384 (hw_ptr=96/appl_ptr=4080), state 3, buffer size = 16368, period size = 4080
[ 421.704607] skl_hda_dsp_generic skl_hda_dsp_generic: D: avail = 8304 (hw_ptr=96/appl_ptr=8160), state 3, buffer size = 16368, period size = 4080
[ 421.704641] sof-audio-pci 0000:00:1f.3: D: PCM: position 384 (hdareg), position 0 (ipc)
[ 421.704641] skl_hda_dsp_generic skl_hda_dsp_generic: D: ptr0 96 (old 96)
[ 421.704643] skl_hda_dsp_generic skl_hda_dsp_generic: D: avail = 4224 (hw_ptr=96/appl_ptr=12240), state 3, buffer size = 16368, period size = 4080
[ 421.704735] sof-audio-pci 0000:00:1f.3: D: PCM: position 384 (hdareg), position 0 (ipc)

As you can note, DMA starts consuming the buffer from zero (96frames==384bytes), as reported by
DGBRP and DGBWP registers. So this is ok. But then:

Failure case (when aplay is resumed in the bug scenario):
[ 428.462266] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 428.462279] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=1
[ 428.462296] skl_hda_dsp_generic skl_hda_dsp_generic: D: avail = 12968 (hw_ptr=0/appl_ptr=3400), state 3, buffer size = 16368, period size = 4080
[ 428.462376] sof-audio-pci 0000:00:1f.3: D: PCM: position 32672 (hdareg), position 0 (ipc)
[ 428.462379] skl_hda_dsp_generic skl_hda_dsp_generic: D: ptr0 8168 (old 0)
[ 428.462385] skl_hda_dsp_generic skl_hda_dsp_generic: D: avail = 21136 (hw_ptr=8168/appl_ptr=3400), state 3, buffer size = 16368, period size = 4080
-> avail>buffer_size means XRUN condition and stream will stop

... the DMA is not correctly reset in TRIG_START, so Linux side will get random values and in the original use-case of this bug, leads to an immediate XRUN condition. This sequence repeats infinitely. Confirmed to be the rootcause also for Linux bug thesofproject/linux#1000 .

@tlauda @jajanusz : can you confirm the expected behaviour of the FW? Is TRIG_START expected to continue from same position? And if yes, what is the right IPC sequence to reset DMA position in the ring buffer?

@ranj063 FYI

@kv2019i

@kv2019i If we are talking about DMA position read from stream HW registers, then it can only be reset on kernel side by resetting Host DMA.

@tlauda

@tlauda wrote:

@kv2019i If we are talking about DMA position read from stream HW registers, then it can only be reset on kernel side by resetting Host DMA.

Hmm, thanks, so it seems to be. And if host resets the DMA, it needs to let FW know about it and currently this means IPC_STREAM_PCM_PARAMS.

@lgirdwood Any historical reasons why IPC interface does not have IPC_STREAM_PREPARE()? Both ALSA PCM and ASOC ops interface have a separate prepare() method, but SOF IPC does not have. In SOF side IPC implementation, handler.c seems to implement both hw_params and prepare logic, so the split is there as well, just wrapped into a single IPC.

For now, this bug seems to be a driver side issue, moving to driver -> thesofproject/linux#1062

Addition of new prepare IPC is a separate topic and will be handled as an enhancement if other solutions to solve this issue prove out to be problematic.

Navigation Menu

Repository navigation

[BUG] start/stop floods with applications using start threshold, e.g. with aplay+S3 #1572

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[BUG] start/stop floods with applications using start threshold, e.g. with aplay+S3 #1572

Description

Activity

kv2019i commented on Jun 17, 2019

kv2019i commented on Jun 18, 2019

kv2019i commented on Jun 19, 2019

tlauda commented on Jun 25, 2019

kv2019i commented on Jun 25, 2019

kv2019i commented on Jun 27, 2019

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions