PulseAudio underflows/audio drops on BYT/CHT #1285
Description
Strange behavior reported in #933
PulseAudio works well with paplay -vvv, but audio drops/underflows are experienced when playing with the speaker test UI (front left, front right). Also when using aplay there are duplicated sounds at the end of playback when using Control-C.
This is definitively a position reporting issue.
Activity
juimonen commentedon Oct 10, 2019
So when I play with "paplay" I get much bigger DAI position updates (altering between some 24k-32k):
PCM: stream 0 dir 0 DMA position 15120 DAI position 848064
PCM: stream 0 dir 0 DMA position 15120 DAI position 848064
PCM: stream 0 dir 0 DMA position 15120 DAI position 848064
PCM: stream 0 dir 0 DMA position 15120 DAI position 848064
PCM: stream 0 dir 0 DMA position 15120 DAI position 848064
PCM: stream 0 dir 0 DMA position 15120 DAI position 848064
PCM: stream 0 dir 0 DMA position 15072 DAI position 880704
PCM: stream 0 dir 0 DMA position 15072 DAI position 880704
PCM: stream 0 dir 0 DMA position 15072 DAI position 880704
PCM: stream 0 dir 0 DMA position 10944 DAI position 905184
PCM: stream 0 dir 0 DMA position 10944 DAI position 905184
PCM: stream 0 dir 0 DMA position 10944 DAI position 905184
PCM: stream 0 dir 0 DMA position 10896 DAI position 937824
PCM: stream 0 dir 0 DMA position 10896 DAI position 937824
PCM: stream 0 dir 0 DMA position 10896 DAI position 937824
PCM: stream 0 dir 0 DMA position 10848 DAI position 970464
PCM: stream 0 dir 0 DMA position 10848 DAI position 970464
PCM: stream 0 dir 0 DMA position 10848 DAI position 970464
PCM: stream 0 dir 0 DMA position 10800 DAI position 1003104
PCM: stream 0 dir 0 DMA position 10800 DAI position 1003104
PCM: stream 0 dir 0 DMA position 10800 DAI position 1003104
PCM: stream 0 dir 0 DMA position 6672 DAI position 1027584
PCM: stream 0 dir 0 DMA position 6672 DAI position 1027584
PCM: stream 0 dir 0 DMA position 6672 DAI position 1027584
PCM: stream 0 dir 0 DMA position 6624 DAI position 1060224
PCM: stream 0 dir 0 DMA position 6624 DAI position 1060224
PCM: stream 0 dir 0 DMA position 6624 DAI position 1060224
PCM: stream 0 dir 0 DMA position 6576 DAI position 1092864
PCM: stream 0 dir 0 DMA position 6576 DAI position 1092864
with "paplay -vvvv" i get steady 8160 DAI position updates (sound is clean):
CM: stream 0 dir 0 DMA position 12240 DAI position 23904
PCM: stream 0 dir 0 DMA position 12240 DAI position 23904
PCM: stream 0 dir 0 DMA position 12240 DAI position 23904
PCM: stream 0 dir 0 DMA position 12240 DAI position 23904
PCM: stream 0 dir 0 DMA position 16320 DAI position 32064
PCM: stream 0 dir 0 DMA position 16320 DAI position 32064
PCM: stream 0 dir 0 DMA position 16320 DAI position 32064
PCM: stream 0 dir 0 DMA position 16320 DAI position 32064
PCM: stream 0 dir 0 DMA position 16320 DAI position 32064
PCM: stream 0 dir 0 DMA position 16320 DAI position 32064
PCM: stream 0 dir 0 DMA position 16320 DAI position 32064
PCM: stream 0 dir 0 DMA position 16320 DAI position 32064
PCM: stream 0 dir 0 DMA position 4032 DAI position 40224
PCM: stream 0 dir 0 DMA position 4032 DAI position 40224
PCM: stream 0 dir 0 DMA position 8112 DAI position 48384
PCM: stream 0 dir 0 DMA position 8112 DAI position 48384
PCM: stream 0 dir 0 DMA position 8112 DAI position 48384
PCM: stream 0 dir 0 DMA position 8112 DAI position 48384
PCM: stream 0 dir 0 DMA position 8112 DAI position 48384
PCM: stream 0 dir 0 DMA position 8112 DAI position 48384
PCM: stream 0 dir 0 DMA position 8112 DAI position 48384
PCM: stream 0 dir 0 DMA position 8112 DAI position 48384
PCM: stream 0 dir 0 DMA position 12192 DAI position 56544
PCM: stream 0 dir 0 DMA position 12192 DAI position 56544
PCM: stream 0 dir 0 DMA position 12192 DAI position 56544
PCM: stream 0 dir 0 DMA position 12192 DAI position 56544
PCM: stream 0 dir 0 DMA position 16272 DAI position 64704
PCM: stream 0 dir 0 DMA position 16272 DAI position 64704
PCM: stream 0 dir 0 DMA position 16272 DAI position 64704
PCM: stream 0 dir 0 DMA position 16272 DAI position 64704
PCM: stream 0 dir 0 DMA position 16272 DAI position 64704
PCM: stream 0 dir 0 DMA position 16272 DAI position 64704
PCM: stream 0 dir 0 DMA position 16272 DAI position 64704
PCM: stream 0 dir 0 DMA position 16272 DAI position 64704
@tlauda any idea what would cause this? To me all parameters from pulseaudio to alsa seem the same in these 2 cases... also again dsp logs are somehow broken (I just get empty log...). Also in the broken case the music tempo seems to remain correct, so I don't hear "gaps" more like there's again some wrap around garbage in the buffer at some point...
tlauda commentedon Oct 10, 2019
@juimonen With the same parameters, we can't get so much discrepancy between DAI positions. Maybe time diffs between position logs are different?
juimonen commentedon Oct 10, 2019
@tlauda There has to be some difference in some parameter or initialization etc. I just can't see this currently from kernel side...(and no dsp logs) It is very much 100% reproducible that in dmesg when the sound is clean the position updates come much faster than with broken case (8k vs 30k dai updates). Just if you would know any hints where to look for? So I'm actually puzzled is this driver or firmware issue? Actually I have not played too much with pulseaudio in mb-byt, so this feature could have been there always...
Anyway as aplay is clean, so it has to be something how pulseaudio plays to alsa
plbossart commentedon Oct 10, 2019
the PulseAudio -vvv option should only change the verbosity level at the PulseAudio level. But it'd be interesting to see if we have the same hw_params and if the latency settings are correct.
If yes, one possibility is that the extra verbosity increases the time between calls to snd_pcm_status() and maybe hides abrupt transitions reported by the firmware (or DMA).
juimonen commentedon Oct 10, 2019
@plbossart so the difference is with "paplay" and "paplay -vvvv"... I tried to debug and pcm params in driver side seems to be the same. So you don't have to play from ui, you get the same stuttering with paplay from command line.
BTW byt logging got fixed also when checking this stuttering issue: thesofproject/sof#1918. Probably bug in logging was hidden because byt tests in CI we're passing, so nobody was looking at logs.
I'm trying to figure out now is there some difference in firmware parameters, but so far haven't found anything. Only difference I can see in pulse log is that in correctly working case Pulseaudio rewinds about 40kB, in non-working case rewind is around 60kB. It could be it has nothing to do with this.
But will continue to debug.
plbossart commentedon Oct 14, 2019
@juimonen I am seeing underflows with the system UI, which doesn't change the verbosity of the error logs, so wondering if you are chasing the wrong issue.
juimonen commentedon Oct 14, 2019
@plbossart my suspicion is that "paplay -vvvv" does something extra, uses more cpu ticks or something that makes it work correctly. And all "normal" playback through pulseaudio is borked. For me the system ui has the same stuttering as bare "paplay".
Do you mean you actually see some logs with underrun?
Only difference I see with correctly playing paplay to erroneous is that the correctly playing starts playing earlier with smaller chunks and converges to same dma size as broken one later, like 32k. So with correct one the first DAI position is in around 7k (with 8k hops) as in erroneous in 32k (with 32k hops), but later the sizes/hops converge. I would assume that "-vvvvv" would make it other way around... otherwise the logs look the same.
plbossart commentedon Oct 14, 2019
@juimonen no I don't see any logs, and I suspect another reason really.
I just ran the Chrome conformance tests and I get a fail. Instructions at:
https://chromium.googlesource.com/chromiumos/platform/audiotest/+/master/alsa_conformance_test.md
we should try to disable the timer-based scheduling with PulseAudio to see if indeed this is the rate of progress that's borked.
plbossart commentedon Oct 15, 2019
@juimonen if I disable the timer-based scheduling I don't have issues with the system UI
The default.pa "load-module module-udev-detect" does not work well, using "load-module module-udev-detect tsched=0" removes the repeated buffers.
Another possibility is the 3-period shenanigan in the topology file. I don't see any BYT file that was modified, but I don't know if it's required either.
juimonen commentedon Oct 15, 2019
@plbossart ok, good finding. If I put pulseaudio alsa timing debugs on I see that in "bad" case pulseaudio is sleeping 3 periods without writing because snd_pcm_avail gives 0 in then it sleeps almost 300ms and in 4th period it tries to write some 65k (so the total dma buffer). With "good" case pulseaudio sleeps steadily like 50ms and writes some 16k bytes. Pulseaudio also reports that before writing the big buffer, alsa has only 1ms data to play. So writing the total dma buffer at once just doesn't work.
it seems that in both cases dsp is writing the position updates similar way, same amounts with same pace, but for some reason pulse is sleeping more (and writing more rarely) . I still don't know what is causing this in alsa... So that pulse doesn't get some decent values with snd_pcm_avail.
juimonen commentedon Oct 16, 2019
@plbossart so what happens here is that pulseaudio timer scheduling waits until last moment to fill the buffer (which is the mmapped dma buffer between user space, kernel and dsp). Now timer scheduling disables the alsa period_elapsed calls and I think we are not in any way tracking dma writes/reads between kernel and dsp. So dsp period sized transfer is just happily running while pulseaudio is copying full buffer length. Pulseaudio would adjust its wake up earlier with xrun, but nobody is sending xrun to it. I think only xrun we send is fw internal, not if it happens in dma transfer.
So I think dsp dma is already transferring first period while pulseaudio is still writing to it.
I'm not sure how to solve this, should we somehow mark the dma buffers so that we would know not to read/write over them and get proper underrun to userspace...
plbossart commentedon Oct 16, 2019
well if the position is only valid at the period_elapsed, then we should use the INFO_BATCH to make pulseaudio work. If we don't then we lie and PulseAudio will not work at all. Ironically we had this issue on Moorestown 10 years ago...
However, we do have timestamp information in the shared SRAM/memory windows so we could get a better time estimate than at every IPC.
I guess @keyonjie and @lgirdwood need to chime in here, since this dates from the time they initially contributed SOF...
juimonen commentedon Oct 18, 2019
https://github.com/orgs/thesofproject/teams/sof-developers/discussions/25