Bug 99058

Summary:	combine-sink: Very high buffer latency (sometimes)
Product:	PulseAudio	Reporter:	Kristian Klausen <kristian>
Component:	modules	Assignee:	pulseaudio-bugs
Status:	RESOLVED MOVED	QA Contact:	pulseaudio-bugs
Severity:	normal
Priority:	medium	CC:	kristian, lennart
Version:	unspecified
Hardware:	x86-64 (AMD64)
OS:	Linux (All)
Whiteboard:
i915 platform:		i915 features:
Attachments:	custom /usr/share/pulseaudio/alsa-mixer/profile-sets/default.conf pactl list sink-input pacmd list-sinks Pulseaudio Debug log patch for alsa-sink.c, which give more information.. Pulseaudio Debug log with alsa-sink.patch and log-time true

Description Kristian Klausen 2016-12-11 21:54:37 UTC

Created attachment 128418 [details]
custom /usr/share/pulseaudio/alsa-mixer/profile-sets/default.conf

Hello

We sell digital signage boxes, and therefor have a Linux image which need to work on most hardware without the customer need to configure anything.

To ensure that, we have a custom default.conf profile-set, which ensure that: hdmi-stereo hdmi-stereo-extra1 hdmi-stereo-extra2 is split out as 3 different sinks, and we then use module-combine-sink to send audio to all the sinks.
It work most of the time, but sometimes (often the first time Pulseaudio is started after boot) the sound is "lagging"/sounding totally wrong (not sure how to explain it) and the module is printing errors like:

D: [pulseaudio] module-combine-sink.c: [alsa_output.pci-0000_00_03.0.hdmi-stereo] total=63902.33ms sink=367.18ms
W: [pulseaudio] module-combine-sink.c: [alsa_output.pci-0000_00_03.0.hdmi-stereo] Total latency of output is very high (63902.33ms), most likely the audio timing in one of your drivers is broken.
D: [pulseaudio] module-combine-sink.c: [alsa_output.pci-0000_00_03.0.hdmi-stereo-extra1] total=359.95ms sink=359.95ms
D: [pulseaudio] module-combine-sink.c: [alsa_output.pci-0000_00_03.0.hdmi-stereo-extra2] total=63902.00ms sink=366.72ms
W: [pulseaudio] module-combine-sink.c: [alsa_output.pci-0000_00_03.0.hdmi-stereo-extra2] Total latency of output is very high (63902.00ms), most likely the audio timing in one of your drivers is broken.
D: [pulseaudio] module-combine-sink.c: [alsa_output.pci-0000_00_1b.0.analog-stereo] total=63902.01ms sink=366.50ms
W: [pulseaudio] module-combine-sink.c: [alsa_output.pci-0000_00_1b.0.analog-stereo] Total latency of output is very high (63902.01ms), most likely the audio timing in one of your drivers is broken.
I: [pulseaudio] module-combine-sink.c: [combined] avg total latency is 48016.57 msec.
I: [pulseaudio] module-combine-sink.c: [combined] target latency is 367.18 msec.
W: [pulseaudio] module-combine-sink.c: [alsa_output.pci-0000_00_03.0.hdmi-stereo] sample rates too different, not adjusting (44100 vs. 324289).
I: [pulseaudio] module-combine-sink.c: [alsa_output.pci-0000_00_03.0.hdmi-stereo-extra1] new rate of 44069 Hz not within 2‰ of 43877 Hz, forcing smaller adjustment
I: [pulseaudio] module-combine-sink.c: [alsa_output.pci-0000_00_03.0.hdmi-stereo-extra1] new rate is 43964 Hz; ratio is 0.997; latency is 359.95 msec.
W: [pulseaudio] module-combine-sink.c: [alsa_output.pci-0000_00_03.0.hdmi-stereo-extra2] sample rates too different, not adjusting (44100 vs. 324288).
W: [pulseaudio] module-combine-sink.c: [alsa_output.pci-0000_00_1b.0.analog-stereo] sample rates too different, not adjusting (44100 vs. 324288).

This also cause Firefox (which is the only application running) videos to stutter.

If I open pavucontrol and switch default-sink to any of the other sinks the video start playing normally again as it should and the audio sounds normally.

I have debugged a little, and noticed that "pacmd list-sinks" only show a high (71350.68 ms) "current latency" for the combined sink, and "pactl list sink-inputs" show a very high (94875147 usec) "Buffer Latency" for any of the combine input.

alsa-info: http://www.alsa-project.org/db/?f=d31c9a34dcac7629a572d54c5affd3068074c8e2

Regards
Kristian Klausen

Comment 1 Kristian Klausen 2016-12-11 21:56:51 UTC

Created attachment 128419 [details]
pactl list sink-input

Comment 2 Kristian Klausen 2016-12-11 21:57:04 UTC

Created attachment 128420 [details]
pacmd list-sinks

Comment 3 Kristian Klausen 2016-12-11 22:00:07 UTC

Created attachment 128421 [details]
Pulseaudio Debug log

Pulseaudio log (-vv) until issue happens and some time after..

Comment 4 Tanu Kaskinen 2016-12-12 13:40:02 UTC

As one of the log messages says, "most likely the audio timing in one of your drivers is broken", so this might not be a pulseaudio bug.

The first HDMI sink is having underruns all the time, and when the first "total latency of output is very high" message is printed, the latency corresponds roughly to the time since the first underrun. My guess would be that the first HDMI sink is failing to consume almost any audio. The thread is not completely stuck, but I would guess that writing each chunk of audio takes way too long. Maybe it's the underrun recovery that's stalling?

To get any kind of certainty about what is happening, you could add more logging to the alsa sink to see what is taking time. To avoid more spam in the log than necessary, the extra logging could be enabled only once an underrun has happened for at least a couple of times.

Comment 5 Tanu Kaskinen 2016-12-12 17:26:31 UTC

I may have analysed the behaviour wrong. The situation is that the first HDMI sink, which is constantly underrunning, has a shorter buffer in module-combine-sink than the three other sinks. This would suggest that the first sink is actually consuming audio much faster than the three other sinks. Since the accumulated buffer size seems to grow roughly at the same rate as the system clock progresses (at least in the beginning), this can mean that either the first sink is running about twice the speed it should, or the three other sinks are more or less stopped. The first sink running too fast seems more likely.

Comment 6 Kristian Klausen 2016-12-12 20:59:33 UTC

Created attachment 128442 [details] [review]
patch for alsa-sink.c, which give more information..

before/after pa_sink_render_into_full and mmap_write

Comment 7 Kristian Klausen 2016-12-12 21:03:22 UTC

Created attachment 128443 [details]
Pulseaudio Debug log with alsa-sink.patch and log-time true

Tanu Kaskinen: Can you get anything from this?

Comment 8 Tanu Kaskinen 2016-12-12 21:36:07 UTC

This time it's HDMI 2 that is having problems. mmap_write() is getting called much more often for that sink. Most of the time nothing is written, though (pa_sink_render_full() isn't being called).

You could log u->write_count whenever something is written. Extra points for logging how much is expected to be written, based on the system clock. That should make it obvious if the write rate is too high or low.

Comment 9 GitLab Migration User 2018-07-30 09:38:47 UTC

-- GitLab Migration Automatic Message --

This bug has been migrated to freedesktop.org's GitLab instance and has been closed from further activity.

You can subscribe and participate further through the new bug through this link to our GitLab instance: https://gitlab.freedesktop.org/pulseaudio/pulseaudio/issues/70.

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.