Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

PulseAudio underflows/audio drops on BYT/CHT #1285

Closed
plbossart opened this issue Oct 8, 2019 · 13 comments
Closed

PulseAudio underflows/audio drops on BYT/CHT #1285

plbossart opened this issue Oct 8, 2019 · 13 comments
Labels
BYT Applies to Baytrail platform

Comments

@plbossart
Copy link
Member

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.

@plbossart plbossart added the BYT Applies to Baytrail platform label Oct 8, 2019
@juimonen
Copy link

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
Copy link

tlauda commented 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
Copy link

@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
Copy link
Member Author

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
Copy link

@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
Copy link
Member Author

@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
Copy link

@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
Copy link
Member Author

plbossart commented 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.

root@plb-T00TA:~/script# ./alsa_conformance_test.py  hw:0,0 PLAYBACK
5 passed, 4 failed
Device Information
	Name: hw:0,0
	Stream: PLAYBACK
	Format: ['S16_LE', 'S24_LE', 'S32_LE']
	Channels: [2]
	Rate: [48000]
	Period_size range: [24, 4080]
	Buffer_size range: [48, 16368]
Test Params
	Set channels 2: pass
	Set format S16_LE: pass
	Set format S24_LE: pass
	Set format S32_LE: pass
	Set rate 48000: pass
Test Rates
	Set rate 48000: fail - Expected rate is 48000.000000, measure 47990.462409, difference 9.537591 > threshold 4.800000
Test All Pairs
	Set channels 2, format S16_LE, rate 48000: fail - Expected rate is 48000.000000, measure 47988.981516, difference 11.018484 > threshold 4.800000
	Set channels 2, format S24_LE, rate 48000: fail - Expected rate is 48000.000000, measure 47991.421268, difference 8.578732 > threshold 4.800000
	Set channels 2, format S32_LE, rate 48000: fail - Expected rate is 48000.000000, measure 47989.285688, difference 10.714312 > threshold 4.800000

@plbossart
Copy link
Member Author

@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
Copy link

@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
Copy link

@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
Copy link
Member Author

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...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
BYT Applies to Baytrail platform
Projects
None yet
Development

No branches or pull requests

3 participants