After an evaluation, GNOME has moved from Bugzilla to GitLab. Learn more about GitLab.
No new issues can be reported in GNOME Bugzilla anymore.
To report an issue in a GNOME project, go to GNOME GitLab.
Do not go to GNOME Gitlab for: Bluefish, Doxygen, GnuCash, GStreamer, java-gnome, LDTP, NetworkManager, Tomboy.
Bug 142586 - alsasink resync is broken
alsasink resync is broken
Status: RESOLVED FIXED
Product: GStreamer
Classification: Platform
Component: gst-plugins
git master
Other Linux
: Normal normal
: 0.8.2
Assigned To: GStreamer Maintainers
GStreamer Maintainers
Depends on:
Blocks:
 
 
Reported: 2004-05-15 17:18 UTC by Ronald Bultje
Modified: 2004-12-22 21:47 UTC
See Also:
GNOME target: ---
GNOME version: ---


Attachments
Hack to work around snd_pcm_delay() bogus return values (873 bytes, patch)
2004-05-16 01:15 UTC, Ronald Bultje
none Details | Review

Description Ronald Bultje 2004-05-15 17:18:41 UTC
Just for my own memory, because I'll forget. Alsasink skips under extreme
conditions, which is normal. However, it skips too much. Osssink performs as
expected under the same conditions.

* disable DMA
* run a 2.4 kernel
* start openoffice
* run updatedb
* have a crappy soundcard
* compile three kernels plus the whole of the GNOME D&DP in parallel

That should be enough, or just a subpart of those (2,3,4,5 are enough for me).
Now look at the output of --gst-debug=alsa*:5. I also add a printf to the
_loop() function (patch below):

samplediff: 0 (maxdiscont=4410,buf=0,element=0
samplediff: -1 (maxdiscont=4410,buf=1151,element=0

Normal output, buffering...

DEBUG            alsa( 9464) gstalsa.c(1088):gst_alsa_start: Setting state to
RUNNING
samplediff: -1 (maxdiscont=4410,buf=17279,element=8249
samplediff: -1 (maxdiscont=4410,buf=18431,element=8257

Normal output, playback starts, note that sample_diff is very very low
(-2<=diff<=2). Then, suddenly:

samplediff: 0 (maxdiscont=4410,buf=2818944,element=2809876
samplediff: -1080883491 (maxdiscont=4410,buf=2820096,element=2809876
INFO             alsa( 9464) gstalsasink.c(418):gst_alsa_sink_loop:<alsasink0>
Skipping 1152 samples to resync (complete buffer): sample 2809876 expected, but
got 2820096
samplediff: 1080894863 (maxdiscont=4410,buf=2821248,element=2809876
INFO             alsa( 9464) gstalsasink.c(399):gst_alsa_sink_loop:<alsasink0>
Allocating 524288 bytes (131072 samples) now to resync: sample 2809876 expected,
but got 2821248
INFO             alsa( 9464) gstalsa.c(1136):gst_alsa_xrun_recovery:<alsasink0>
alsa: xrun of at least 2.368 msecs DEBUG            alsa( 9464)
gstalsa.c(1430):gst_alsa_stop_audio: stopping alsa, skipping pending frames

it just flows over to this value, for no good reason. Indeed, after this, it is
silent for a while. This seems like an signed/unsigned or 32it integer overflow
somewhere. Noet that 1e9 samples means 4e9 bytes, which is G_MAXUINT (format:
S16_LE 44100Hz, 2 channels). After the silence, alsa restarts and the clock is -
obviously - way behind and therefore it will skip several seconds of sound:

INFO             alsa( 9464) gstalsa.c(1282):gst_alsa_set_hw_params: Preparing
format: S16_LE 44100Hz, 2 channels
DEBUG            alsa( 9464) gstalsa.c(1088):gst_alsa_start: Setting state to
RUNNING
samplediff: -129920 (maxdiscont=4410,buf=2821248,element=2934812
INFO             alsa( 9464) gstalsasink.c(418):gst_alsa_sink_loop:<alsasink0>
Skipping 1152 samples to resync (complete buffer): sample 2934812 expected, but
got 2821248
samplediff: -128768 (maxdiscont=4410,buf=2822400,element=2934823
INFO             alsa( 9464) gstalsasink.c(418):gst_alsa_sink_loop:<alsasink0>
Skipping 1152 samples to resync (complete buffer): sample 2934823 expected, but
got 2822400
[..]
samplediff: -5504 (maxdiscont=4410,buf=2945663,element=2946823
INFO             alsa( 9464) gstalsasink.c(418):gst_alsa_sink_loop:<alsasink0>
Skipping 1152 samples to resync (complete buffer): sample 2946823 expected, but
got 2945663
samplediff: -4351 (maxdiscont=4410,buf=2946815,element=2946835
samplediff: -4352 (maxdiscont=4410,buf=2947967,element=2946848


After that, it resyncs correctly and plays back again for a while. This whole
procedure repeats several times in mp3 playback, but I've seen it for Ogg/Vorbis
files as well.

If wanted, I can attach the full log, although the idea must be clear now.

Patch for gstalsasink.c to get this output:

Index: gstalsasink.c
===================================================================
RCS file: /home/cvs/gstreamer/gst-plugins/ext/alsa/gstalsasink.c,v
retrieving revision 1.17
diff -u -r1.17 gstalsasink.c
--- a/gstalsasink.c     9 May 2004 00:02:26 -0000       1.17
+++ b/gstalsasink.c     15 May 2004 17:08:10 -0000
@@ -377,7 +377,8 @@
         snd_pcm_delay (this->handle, &sample_diff);
         /* actual diff = buffer samplestamp - played - to_play */
         sample_diff = samplestamp - time_sample - sample_diff;
-
+g_print ("samplediff: %ld (maxdiscont=%ld,buf=%lu,element=%lu\n", sample_diff,
+       max_discont, samplestamp, time_sample);
         if ((!GST_BUFFER_TIMESTAMP_IS_VALID (sink->buf[i])) ||
             (-max_discont <= sample_diff && sample_diff <= max_discont)) {
Comment 1 Ronald Bultje 2004-05-16 01:10:18 UTC
snd_pcm_delay() is returning bogus values. I've emailed alsa-devel and will
probably add an intermediate hack to work around it.
Comment 2 Ronald Bultje 2004-05-16 01:15:02 UTC
Created attachment 27745 [details] [review]
Hack to work around snd_pcm_delay() bogus return values
Comment 3 Benjamin Otte (Company) 2004-05-16 02:52:28 UTC
I believe this is fixed now.