GNOME Bugzilla – Bug 164069
[clocking] Hang when playing audio file (.wav) with visualization
Last modified: 2005-01-17 12:46:01 UTC
$ ./metadata-test /home/data/Documents/Movie\ Samples/brave_robinsong.wav (metadata-test:18390): GLib-GObject-WARNING **: gsignal.c:1716: signal `group-switch' is invalid for instance `0x982e540' (metadata-test:18390): GLib-GObject-WARNING **: IA__g_object_set_valist: object class `GstPlayBin' has no property named `suburi' ** (metadata-test:18390): CRITICAL **: file multichannel.c: line 168 (gst_audio_get_channel_positions): assertion `pos_val_arr != NULL' failed ** (metadata-test:18390): CRITICAL **: internal negotiation error ** (metadata-test:18390): WARNING **: could not link audio/x-raw-int, endianness=(int)1234, width=(int)16, depth=(int)16, signed=(boolean)true, rate=(int)11025, channels=(int)1 File at: http://files.hadess.net/redhat/tmp/brave_robinsong.wav
Which version of gst-plugins is this? If it's CVS, what version? I can play it with osssink, alsasink and dmix, and I don't get errors. I have fixed one of the above warnings a few weeks ago. In totem, it actually does hang, but only with visualization enabled:
+ Trace 54599
Thread 5 (Thread 33622960 (LWP 988))
Thread 3 (Thread 45476784 (LWP 986))
Thread 4 is the video, thread 5 is the visualization thread (plus audio) and thread 3 is the decoder. Seems like a deadlock, probably wrong timestamps. LOG (0x9a79a50 - 307211:47:39.543223000) xvimagesink( 1024) xvimagesink.c(1405):gst_xvimagesink_chain:<xvimagesink0> clock wait: 0:00:00.100000000 DEBUG (0x9a79a50 - 307211:47:39.543674000) alsa( 1024) gstalsaclock.c(193):gst_alsa_clock_wait:<alsasinkclock> real_target 307211:47:39.335004000 target 307211:47:39.335004000 now 307211:47:39.235004000 LOG (0x9fa18d8 - 307211:47:39.583367000) alsa( 1024) gstalsasink.c(384):gst_alsa_sink_loop:<alsasink0> pulled data 0x98d66a0 from pad 0 DEBUG (0x9fa18d8 - 307211:47:39.583645000) alsa( 1024) gstalsasink.c(163):gst_alsa_sink_flush_one_pad:<alsasink0> flushing pad 0 DEBUG (0x9fa18d8 - 307211:47:39.583751000) alsa( 1024) gstalsasink.c(167):gst_alsa_sink_flush_one_pad:<alsasink0> unreffing gst data 0x98d66a0 LOG (0x9fa18d8 - 307211:47:39.827302000) alsa( 1024) gstalsasink.c(384):gst_alsa_sink_loop:<alsasink0> pulled data 0x98d66a0 from pad 0 DEBUG (0x9fa18d8 - 307211:47:39.919839000) alsa( 1024) gstalsasink.c(163):gst_alsa_sink_flush_one_pad:<alsasink0> flushing pad 0 DEBUG (0x9fa18d8 - 307211:47:39.920196000) alsa( 1024) gstalsasink.c(167):gst_alsa_sink_flush_one_pad:<alsasink0> unreffing gst data 0x98d66a0 LOG (0x9fa18d8 - 307211:47:40.037103000) alsa( 1024) gstalsasink.c(384):gst_alsa_sink_loop:<alsasink0> pulled data 0x98d66a0 from pad 0 DEBUG (0x9fa18d8 - 307211:47:40.037706000) alsa( 1024) gstalsasink.c(163):gst_alsa_sink_flush_one_pad:<alsasink0> flushing pad 0 DEBUG (0x9fa18d8 - 307211:47:40.038033000) alsa( 1024) gstalsasink.c(167):gst_alsa_sink_flush_one_pad:<alsasink0> unreffing gst data 0x98d66a0 LOG (0x9fa18d8 - 307211:47:40.167486000) alsa( 1024) gstalsasink.c(384):gst_alsa_sink_loop:<alsasink0> pulled data 0x98d66a0 from pad 0 DEBUG (0x9fa18d8 - 307211:47:40.250631000) alsa( 1024) gstalsasink.c(163):gst_alsa_sink_flush_one_pad:<alsasink0> flushing pad 0 DEBUG (0x9fa18d8 - 307211:47:40.251013000) alsa( 1024) gstalsasink.c(167):gst_alsa_sink_flush_one_pad:<alsasink0> unreffing gst data 0x98d66a0 This is inside alsa's context. This basically means that alsa's gst_pad_pull triggered a push in tee on the other pad, which waits on an update in alsa. Making audio a thread doesn't solve it, since the deadlock is still there, but on a queue boundary (I actually tested that...). It gets stuck in the wait loop in gstalsaclock.c:gst_alsa_clock_wait, with: LOG (0x9546a50 - 307212:09:40.752929000) alsa( 3471) gstalsaclock.c(200):gst_alsa_clock_wait: 1105963772770298000 < 1105963772870298000, 0 < 1105963772770298000 The weird thing is that the audio clock is actually already at 0.9s, while we're still waiting for 0.1s. I don't know why that happens. I think alsaclock should have a max. wait time of maybe 1.5 * diff, because this is a deadlock. Besides that, we (I) should figure out why the clock is not updated properly... GStreamer bug, so re-assigning
alsasink:get_time() gives this on the hang: Delay: 12288, played: 12288 which implies that alsa isn't actually running yet... Probably an alsasink bug after all?
Created attachment 36129 [details] [review] workaround Adds a maximum of 1.5 times the request/current diff as waiting time. This fixes the issue in this bug for me. The fact that alsa doesn't run yet is probably alsa buffering, and therefore not a GStreamer bug. The proper workaround would actually be to implement this behaviour.
Applied, but using the GST_TIMEVAL_TO_TIME() macro instead.
*** Bug 164160 has been marked as a duplicate of this bug. ***
*** Bug 162548 has been marked as a duplicate of this bug. ***