582513 - ended event may be delayed up to two seconds on platforms using PulseAudio

Status: RESOLVED FIXED

(Core :: Audio/Video, defect)

Description

[Dale Harvey (:daleharvey)]

User-Agent:       Mozilla/5.0 (X11; U; Linux i686; en-GB; rv:1.9.2.8) Gecko/20100723 Ubuntu/10.04 (lucid) Firefox/3.6.8
Build Identifier: Mozilla/5.0 (X11; U; Linux i686; en-GB; rv:1.9.2.8) Gecko/20100723 Ubuntu/10.04 (lucid) Firefox/3.6.8

When listening on for the "ended" event on an audio object, it is triggered 2/3 seconds after the audio has finished, Affects ubuntu (lucid)

Reproducible: Always

Steps to Reproduce:
1. visit http://pastebin.me/a0146e64ed386da270e51eb7a0893615
2. play song and wait for ended event alert
3.
Actual Results:  
Ended event is 2 seconds later

Comment 1

[Matthew Gregan [:kinetik]]

I can't reproduce this with your testcase (there's a delay between the end of sound and the alert appearing, but it seems like 500ms at most), but I do see it with http://flim.org/~kinetik/tests/bug581321/test.html.  Each of the files play back to back on OS X, but there's a two second or so delay between each file on Linux.

Comment 2

[Matthew Gregan [:kinetik]]

I happened to catch this in the debugger.  It turns out that we're waiting in sa_stream_drain for an unusually long time.  While playing back a 1 second audio file, I recorded sa_stream_drain taking 2.5s.  Adding debug logging to the alsa-pulse plugin, the pulse_wait_operation on the operation returned by pa_stream_drain is what's taking all the time, so we're stuck waiting on the PA server to respond here.

Comment 3

[Matthew Gregan [:kinetik]]

Attachment: reproducer

Simple reproducer using the PulseAudio client API.

So, now I'm really confused:

Write a second of audio, then immediately call drain and wait for completion:
% time ./a.out 1
write 48000 samples
drain
./a.out 1  0.00s user 0.01s system 0% cpu 2.539 total

Write a second of audio, sleep for 500ms, then call drain and wait:
% time ./a.out 1 sleep
write 48000 samples
sleep
drain
./a.out 1 sleep  0.00s user 0.01s system 1% cpu 0.516 total

% time ./a.out 10
write 480000 samples
drain
./a.out 10  0.01s user 0.01s system 0% cpu 7.118 total

% time ./a.out 10 sleep
write 48000 samples
sleep
drain
./a.out 10 sleep  0.00s user 0.01s system 1% cpu 0.511 total

Comment 4

[Matthew Gregan [:kinetik]]

Emailed pulseaudio-discuss about this: https://tango.0pointer.de/pipermail/pulseaudio-discuss/2010-November/008189.html

Comment 5

[Matthew Gregan [:kinetik]]

Oh, the sleep cases in comment 3 are bogus, my testcase had a bug in the argument parsing, so that part is a red herring.

Comment 6

[Matthew Gregan [:kinetik]]

Existing PA bug: http://pulseaudio.org/ticket/866

Comment 7

[Matthew Gregan [:kinetik]]

Fixed by bug 623444.