pa_simple_drain() takes over 2 seconds to complete!

[Thomas Horsten]

Binary package hint: pulseaudio

The libpulse-simple API has a function, pa_simple_drain() which is supposed to "[w]ait until all data already written is played by the daemon".

However in Ubuntu 10.10, it waits a *fair* bit more than that, namely several seconds(!)

This means, that when I want to synchronize audio in my program ie. ensure that previously streamed audio has finished playing, e.g. before I start playing a new sound or just prior to exiting the program, there is a typically 2.2 second extra delay!

Without this call, at the end of playback before exiting, the final sound will be clipped off at the end, since there is still unbuffered audio waiting to be sent, so it is needed to call this at the end of the program, but now in 10.10, it causes an extra delay of several seconds before the program exits.

I have attached a program that demonstrates this behaviour. Compile with:

$ gcc `pkg-config --cflags --libs libpulse-simple` -o beep beep.c

Here is the output from the program:

$ ./beep
[0.039147] playing 440 hz tone volume 50 for 500 ms
[0.291107] play done
[0.291116] not calling pa_simple_drain()
[0.293467] playing 680 hz tone volume 50 for 500 ms
[0.855440] play done
[0.855459] not calling pa_simple_drain()
[0.857808] playing 440 hz tone volume 50 for 500 ms
[1.312107] play done
[3.544309] pa_simple_drain() done
[3.546687] playing 680 hz tone volume 50 for 500 ms
[3.798973] play done
[6.132183] pa_simple_drain() done
[6.134535] playing 440 hz tone volume 50 for 500 ms
[6.386808] play done
[6.386824] not calling pa_simple_drain()
[6.386851] playing 440 hz tone volume 0 for 500 ms
[6.951772] play done
[6.951789] not calling pa_simple_drain()
[6.956659] playing 880 hz tone volume 50 for 1000 ms
[7.912965] play done
[10.144917] pa_simple_drain() done

I am reporting this here rather than upstream, since I have observed it in latest Ubuntu, and I don't think it was in 10.04, but if it is determined to be a PulseAudio bug I will report it upstream as well...

ProblemType: Bug
DistroRelease: Ubuntu 10.10
Package: pulseaudio 1:0.9.22~0.9.21+stable-queue-32-g8478-0ubuntu21
ProcVersionSignature: Ubuntu 2.6.35-22.33-generic 2.6.35.4
Uname: Linux 2.6.35-22-generic x86_64
NonfreeKernelModules: nvidia
AlsaVersion: Advanced Linux Sound Architecture Driver Version 1.0.23.
AplayDevices:
 **** List of PLAYBACK Hardware Devices ****
 card 0: Intel [HDA Intel], device 0: AD198x Analog [AD198x Analog]
   Subdevices: 1/1
   Subdevice #0: subdevice #0
Architecture: amd64
ArecordDevices:
 **** List of CAPTURE Hardware Devices ****
 card 0: Intel [HDA Intel], device 0: AD198x Analog [AD198x Analog]
   Subdevices: 2/2
   Subdevice #0: subdevice #0
   Subdevice #1: subdevice #1
AudioDevicesInUse:
 USER PID ACCESS COMMAND
 /dev/snd/controlC0: th 10977 F.... pulseaudio
Card0.Amixer.info:
 Card hw:0 'Intel'/'HDA Intel at 0xfdffc000 irq 45'
   Mixer name : 'Analog Devices AD1984'
   Components : 'HDA:11d41984,10280214,00100400'
   Controls : 21
   Simple ctrls : 14
Date: Thu Oct 14 15:21:42 2010
InstallationMedia: Ubuntu 10.04 "Lucid Lynx" - Release Candidate amd64 (20100419.1)
ProcEnviron:
 PATH=(custom, user)
 LANG=en_GB.utf8
 SHELL=/bin/bash
SourcePackage: pulseaudio
dmi.bios.date: 08/14/2008
dmi.bios.vendor: Dell Inc.
dmi.bios.version: A08
dmi.board.name: 0TP412
dmi.board.vendor: Dell Inc.
dmi.chassis.type: 7
dmi.chassis.vendor: Dell Inc.
dmi.modalias: dmi:bvnDellInc.:bvrA08:bd08/14/2008:svnDellInc.:pnPrecisionWorkStationT3400:pvr:rvnDellInc.:rn0TP412:rvr:cvnDellInc.:ct7:cvr:
dmi.product.name: Precision WorkStation T3400
dmi.sys.vendor: Dell Inc.

[David Henningsson (diwic)]

Hi TH,
interesting. While there is no timing guarantee for these kinds of things, having to wait 3 s for a 500 ms note seems a little too much. Perhaps collecting a PulseAudio verbose log (as in https://wiki.ubuntu.com/PulseAudio/Log ) while you're running the test would be the first thing towards investigating where the time is spent.

[Thomas Horsten (thomas-horsten)]

Hi David

Here's the log. I ran it like this, so I could also see the pulseaudio log interspersed with the output of my test program:

 $ LANG=C pulseaudio -vvvv 2>&1 | tee ~/pulseverbose.log & (sleep 1 ; ../src/beep/beep )

Of course there is a lot of messages before playing the first tone, but after that pulse is quiet while playing until I call pa_simple_drain:

[0.343553] play done
[0.343609] not calling pa_simple_drain()
[0.357608] playing 680 hz tone volume 50 for 500 ms
[0.834818] play done
[0.834878] not calling pa_simple_drain()
[0.848907] playing 440 hz tone volume 50 for 500 ms
[1.302643] play done
(I call pa_simple_drain here)
D: protocol-native.c: Underrun on 'beep', 0 bytes in queue.
[3.504083] pa_simple_drain() done
[3.517146] playing 680 hz tone volume 50 for 500 ms
D: protocol-native.c: Requesting rewind due to end of underrun.
D: alsa-sink.c: Requested to rewind 9992 bytes.
D: alsa-sink.c: Limited to 9992 bytes.
D: alsa-sink.c: before: 2498
D: alsa-sink.c: after: 2498
D: alsa-sink.c: Rewound 9992 bytes.
D: sink.c: Processing rewind...
D: sink-input.c: Have to rewind 9992 bytes on render memblockq.
D: source.c: Processing rewind...

The only message pa_simple_drain() causes, is the underrun (which happens after the buffer runs out, but long before pa_simple_drain() returns - this is visible from observing it in real time, I could make a filter to put timestamps on the pulse log entries that would make this clearer). This underrun (and the subsequent recovery stanza) seems to be normal behaviour when the buffer runs out, as it also happens at the start of the program, and would be expected when calling pa_simple_drain(), but I would also expect pa_simple_drain() to return immediately when the underrun occurs.

[David Henningsson (diwic)]

Are you sure you remembered to run "pacmd set-log-time 1" according to the instructions for logging? Since you're debugging the timing, that would be useful. You could perhaps add that to your command line to run just before you start "beep".

[David Henningsson (diwic)]

Hmm, seems like upstream has seen this and is working on it. You might get more info by jumping into #pulseaudio on irc.freenode.net.

[Thomas Horsten (thomas-horsten)]

My bad, I didn't enable log-time. I have now and here is the log attached, and again the test program output interspersed with the log is as follows:

...
( 0.034| 0.000) D: source.c: Processing rewind...
[0.344269] play done
[0.344328] not calling pa_simple_drain()
[0.358380] playing 680 hz tone volume 50 for 500 ms
[0.829451] play done
[0.829489] not calling pa_simple_drain()
[0.840411] playing 440 hz tone volume 50 for 500 ms
[1.303775] play done
( 1.471| 1.437) D: protocol-native.c: Underrun on 'beep', 0 bytes in queue.
[3.505551] pa_simple_drain() done
[3.519491] playing 680 hz tone volume 50 for 500 ms
( 3.532| 2.060) D: protocol-native.c: Requesting rewind due to end of underrun.
( 3.532| 0.000) D: alsa-sink.c: Requested to rewind 10156 bytes.
( 3.532| 0.000) D: alsa-sink.c: Limited to 10156 bytes.
( 3.532| 0.000) D: alsa-sink.c: before: 2539
( 3.532| 0.000) D: alsa-sink.c: after: 2539
( 3.532| 0.000) D: alsa-sink.c: Rewound 10156 bytes.
( 3.532| 0.000) D: sink.c: Processing rewind...
( 3.532| 0.000) D: sink-input.c: Have to rewind 10156 bytes on render memblockq.
( 3.533| 0.000) D: source.c: Processing rewind...
[3.848197] play done
( 4.016| 0.483) D: protocol-native.c: Underrun on 'beep', 0 bytes in queue.
[6.050165] pa_simple_drain() done
[6.062775] playing 440 hz tone volume 50 for 500 ms
...

[Thomas Horsten (thomas-horsten)]

Thanks, I'm already in that IRC channel and also posted the upstream bug after an IRC user said it was also present in Fedora 14.

Anyway I think the logging is a dead end, since there is no log activity between the time where the buffer underruns until pa_simple_drain() completes and the next tone is played.

[Robert Siemer (robert-siemer-launchpad-net)]

I’m affected, too. E.g. an “ltrace aplay file” shows it hanging in snd_pcm_drain() at the end, when pulseaudio is running.I attach my log here as well, but probably nothing new in there...

[Robert Siemer (robert-siemer-launchpad-net)]

The package from natty (at the moment 1:0.9.22+stable-queue-18-geb966-0ubuntu2) has the same problem.

[Robert Siemer (robert-siemer-launchpad-net)]

Lucid, karmic-updates and karmic are also affected, I couldn’t get hardy-updates running... ;-)

[Robert Siemer (robert-siemer-launchpad-net)]

To make clear why this is annoying: applications like mplayer (which is used as media player by other applications like Anki) fail to reproduce gapless (or almost gapless) from their playlists.

Anki (flashcard learning program) tends to play voice snippets for short audio in a row, e.g. 3 files x1sec. Instead of the speaker saying “Hint. Question? Answer.” it’s more like “Hint. ------------ Question? ----------- Answer.” taking 7 seconds in total.

As a workaround I stop pulseaudio before using Anki (with respawn=off). -- When I use mplayer individually, I exploit a bug to skip “drain-less” forward in the playlist...

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Daniel van Vugt (vanvugt)]

Thank you for reporting this bug to Ubuntu.
Ubuntu 10.10 (maverick) reached end-of-life on April 10, 2012.

See this document for currently supported Ubuntu releases:
https://wiki.ubuntu.com/Releases

Please upgrade to the latest version and re-test.

[Launchpad Janitor (janitor)]

[Expired for pulseaudio (Ubuntu) because there has been no activity for 60 days.]