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 736969 - queue2: dead lock when buffering
queue2: dead lock when buffering
Status: RESOLVED FIXED
Product: GStreamer
Classification: Platform
Component: gstreamer (core)
1.x
Other All
: Normal blocker
: 1.4.5
Assigned To: GStreamer Maintainers
GStreamer Maintainers
Depends on:
Blocks:
 
 
Reported: 2014-09-19 12:22 UTC by Guillaume Desmottes
Modified: 2014-11-23 14:12 UTC
See Also:
GNOME target: ---
GNOME version: ---


Attachments
GST_DEBUG=5 (567.42 KB, application/gzip)
2014-09-19 12:22 UTC, Guillaume Desmottes
  Details
log with core updated to master (578.51 KB, application/gzip)
2014-09-19 13:11 UTC, Guillaume Desmottes
  Details
queue2: do not post buffering messages holding the lock (7.44 KB, patch)
2014-09-19 15:04 UTC, Thiago Sousa Santos
committed Details | Review

Description Guillaume Desmottes 2014-09-19 12:22:54 UTC
Created attachment 286620 [details]
GST_DEBUG=5

The fix for bug #727255 seems to have introduced a regression when playing buffered stream. Here is a log when trying to play from a DLNA server. gst-launch is stuck at "Buffering 10%".

It doesn't happen all the time so I guess there is a race or something but after lots of testing and bisecting I'm pretty confident that the regression has been introduced with http://cgit.freedesktop.org/gstreamer/gst-plugins-base/commit/?id=a2122f04ec6305a1393e73eb8e7fccb291f36ccb
Comment 1 Guillaume Desmottes 2014-09-19 13:09:28 UTC


Thread 4 (Thread 0x7fb8dfdd4700 (LWP 22737))

  • #0 __lll_lock_wait
    at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S line 135
  • #1 _L_lock_1022
    from /lib64/libpthread.so.0
  • #2 __GI___pthread_mutex_lock
    at ../nptl/pthread_mutex_lock.c line 134
  • #3 g_mutex_lock
    at gthread-posix.c line 213
  • #4 gst_queue2_handle_src_event
    at gstqueue2.c line 2823
  • #5 gst_pad_send_event_unchecked
    at gstpad.c line 5155
  • #6 gst_pad_push_event_unchecked
    at gstpad.c line 4842
  • #7 gst_pad_push_event
    at gstpad.c line 4973
  • #8 event_forward_func
    at gstpad.c line 2842
  • #9 gst_pad_forward
    at gstpad.c line 2796
  • #10 gst_pad_event_default
    at gstpad.c line 2893
  • #11 gst_pad_send_event_unchecked
    at gstpad.c line 5155
  • #12 gst_pad_push_event_unchecked
    at gstpad.c line 4842
  • #13 gst_pad_push_event
    at gstpad.c line 4973
  • #14 gst_type_find_element_src_event
    at gsttypefindelement.c line 515
  • #15 gst_pad_send_event_unchecked
    at gstpad.c line 5155
  • #16 gst_pad_push_event_unchecked
    at gstpad.c line 4842
  • #17 gst_pad_push_event
    at gstpad.c line 4973
  • #18 event_forward_func
    at gstpad.c line 2842
  • #19 gst_pad_forward
    at gstpad.c line 2796
  • #20 gst_pad_event_default
    at gstpad.c line 2893
  • #21 gst_pad_send_event_unchecked
    at gstpad.c line 5155
  • #22 gst_pad_push_event_unchecked
    at gstpad.c line 4842
  • #23 gst_pad_push_event
    at gstpad.c line 4973
  • #24 gst_pad_send_event_unchecked
    at gstpad.c line 5155
  • #25 gst_pad_push_event_unchecked
    at gstpad.c line 4842
  • #26 gst_pad_push_event
    at gstpad.c line 4973
  • #27 event_forward_func
    at gstpad.c line 2842
  • #28 gst_pad_forward
    at gstpad.c line 2796
  • #29 gst_pad_event_default
    at gstpad.c line 2893
  • #30 gst_base_parse_src_event_default
    at gstbaseparse.c line 1409
  • #31 gst_pad_send_event_unchecked
    at gstpad.c line 5155
  • #32 gst_pad_push_event_unchecked
    at gstpad.c line 4842
  • #33 gst_pad_push_event
    at gstpad.c line 4973
  • #34 gst_base_transform_src_eventfunc
    at gstbasetransform.c line 1954
  • #35 gst_pad_send_event_unchecked
    at gstpad.c line 5155
  • #36 gst_pad_push_event_unchecked
    at gstpad.c line 4842
  • #37 gst_pad_push_event
    at gstpad.c line 4973
  • #38 event_forward_func
    at gstpad.c line 2842
  • #39 gst_pad_forward
    at gstpad.c line 2796
  • #40 gst_pad_event_default
    at gstpad.c line 2893
  • #41 gst_audio_decoder_src_eventfunc
    at gstaudiodecoder.c line 2270
  • #42 gst_pad_send_event_unchecked
    at gstpad.c line 5155
  • #43 gst_pad_push_event_unchecked
    at gstpad.c line 4842
  • #44 gst_pad_push_event
    at gstpad.c line 4973
  • #45 event_forward_func
    at gstpad.c line 2842
  • #46 gst_pad_forward
    at gstpad.c line 2796
  • #47 gst_pad_event_default
    at gstpad.c line 2893
  • #48 gst_pad_send_event_unchecked
    at gstpad.c line 5155
  • #49 gst_pad_push_event_unchecked
    at gstpad.c line 4842
  • #50 gst_pad_push_event
    at gstpad.c line 4973
  • #51 event_forward_func
    at gstpad.c line 2842
  • #52 gst_pad_forward
    at gstpad.c line 2796
  • #53 gst_pad_event_default
    at gstpad.c line 2893
  • #54 gst_pad_send_event_unchecked
    at gstpad.c line 5155
  • #55 gst_pad_push_event_unchecked
    at gstpad.c line 4842
  • #56 gst_pad_push_event
    at gstpad.c line 4973
  • #57 gst_input_selector_event
    at gstinputselector.c line 1528
  • #58 gst_pad_send_event_unchecked
    at gstpad.c line 5155
  • #59 gst_pad_send_event
    at gstpad.c line 5322
  • #60 gst_pad_link_full
    at gstpad.c line 2390
  • #61 gst_pad_link
    at gstpad.c line 2445
  • #62 no_more_pads_cb
    at gstplaybin2.c line 3517
  • #63 _g_closure_invoke_va
    at gclosure.c line 840
  • #64 g_signal_emit_valist
    at gsignal.c line 3238
  • #65 g_signal_emit
    at gsignal.c line 3386
  • #66 gst_element_no_more_pads
    at gstelement.c line 845
  • #67 no_more_pads_full
    at gsturidecodebin.c line 1014
  • #68 _g_closure_invoke_va
    at gclosure.c line 840
  • #69 g_signal_emit_valist
    at gsignal.c line 3238
  • #70 g_signal_emit
    at gsignal.c line 3386
  • #71 gst_element_no_more_pads
    at gstelement.c line 845
  • #72 gst_decode_bin_expose
    at gstdecodebin2.c line 4272
  • #73 source_pad_blocked_cb
    at gstdecodebin2.c line 4452
  • #74 probe_hook_marshal
    at gstpad.c line 3174
  • #75 g_hook_list_marshal
    at ghook.c line 676
  • #76 do_probe_callbacks
    at gstpad.c line 3268
  • #77 gst_pad_push_event_unchecked
    at gstpad.c line 4809
  • #78 push_sticky
    at gstpad.c line 3443
  • #79 events_foreach
    at gstpad.c line 570
  • #80 check_sticky
    at gstpad.c line 3499
  • #81 gst_pad_push_event
    at gstpad.c line 4967
  • #82 gst_pad_set_caps
    at /home/cassidy/dev/gst/master/gstreamer/gst/gstcompat.h line 55
  • #83 gst_audio_decoder_negotiate_default
    at gstaudiodecoder.c line 669
  • #84 gst_audio_decoder_negotiate_unlocked
    at gstaudiodecoder.c line 728
  • #85 check_pending_reconfigure
    at gstaudiodecoder.c line 1092
  • #86 gst_audio_decoder_finish_frame
    at gstaudiodecoder.c line 1156
  • #87 gst_a52dec_handle_frame
    at gsta52dec.c line 640
  • #88 gst_audio_decoder_push_buffers
    at gstaudiodecoder.c line 1414
  • #89 gst_audio_decoder_chain_forward
    at gstaudiodecoder.c line 1517
  • #90 gst_audio_decoder_chain
    at gstaudiodecoder.c line 1775
  • #91 gst_a52dec_chain
    at gsta52dec.c line 734
  • #92 gst_pad_chain_data_unchecked
    at gstpad.c line 3836
  • #93 gst_pad_push_data
    at gstpad.c line 4069
  • #94 gst_pad_push
    at gstpad.c line 4180
  • #95 gst_base_transform_chain
    at gstbasetransform.c line 2260
  • #96 gst_pad_chain_data_unchecked
    at gstpad.c line 3836
  • #97 gst_pad_push_data
    at gstpad.c line 4069
  • #98 gst_pad_push
    at gstpad.c line 4180
  • #99 gst_base_parse_push_frame
    at gstbaseparse.c line 2307
  • #100 gst_base_parse_handle_and_push_frame
    at gstbaseparse.c line 2139
  • #101 gst_base_parse_finish_frame
    at gstbaseparse.c line 2464
  • #102 gst_ac3_parse_handle_frame
    at gstac3parse.c line 669
  • #103 gst_base_parse_handle_buffer
    at gstbaseparse.c line 1966
  • #104 gst_base_parse_chain
    at gstbaseparse.c line 2963
  • #105 gst_pad_chain_data_unchecked
    at gstpad.c line 3836
  • #106 gst_pad_push_data
    at gstpad.c line 4069
  • #107 gst_pad_push
    at gstpad.c line 4180
  • #108 gst_single_queue_push_one
    at gstmultiqueue.c line 1200
  • #109 gst_multi_queue_loop
    at gstmultiqueue.c line 1449
  • #110 gst_task_func
    at gsttask.c line 317
  • #111 g_thread_pool_thread_proxy
    at gthreadpool.c line 309
  • #112 g_thread_proxy
    at gthread.c line 798
  • #113 start_thread
    at pthread_create.c line 309
  • #114 clone
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S line 111

Comment 2 Guillaume Desmottes 2014-09-19 13:11:08 UTC
Created attachment 286625 [details]
log with core updated to master
Comment 3 Thiago Sousa Santos 2014-09-19 13:14:56 UTC
From a quick glance it seems the same case as with multiqueue -> posting buffering messages holding the lock.
Comment 4 Thiago Sousa Santos 2014-09-19 15:04:27 UTC
Created attachment 286633 [details] [review]
queue2: do not post buffering messages holding the lock

Assembled this patch quickly here from the multiqueue one. Still going
to do a better review of it myself. But could be tested already by the
reporter.

Thanks
Comment 5 Guillaume Desmottes 2014-09-19 15:09:36 UTC
Yep this patches does fix my bug; thanks!
Comment 6 Thiago Sousa Santos 2014-09-20 00:12:48 UTC
Pushed to master.

commit ecf479e3d1885c41208ca0df7c7d4b6d3e2d2af7
Author: Thiago Santos <thiagoss@osg.samsung.com>
Date:   Fri Sep 19 12:02:46 2014 -0300

    queue2: do not post buffering messages holding the lock
    
    It might cause deadlocks to post messages while holding the queue2
    lock. To avoid this a new boolean flag is set whenever a new
    buffering percent is found. The message is posted after the lock
    is released.
    
    To make sure the buffering messages are posted in the right order, messages
    are posted holding another lock. This prevents 2 threads trying to post
    messages at the same time.
    
    https://bugzilla.gnome.org/show_bug.cgi?id=736969


Waiting for 1.4 freeze period to be over before pushing for 1.4.3 and closing this bug.
Comment 7 Guillaume Desmottes 2014-09-22 10:22:09 UTC
Thanks a lot for the fix. I can confirm this does work fine now with master.
Comment 8 Abhimanyu V 2014-10-21 08:38:19 UTC
Hello,
The following diff (which is in proposed fix)
+    percent = percent * 100 / queue->high_percent;
+    /* clip */
+    if (percent > 100)
+      percent = 100;

is not present in actual commit http://cgit.freedesktop.org/gstreamer/gstreamer/commit/?h=1.4&id=7630ada89a6360b7bc8304e5e08de43c36f1226f.

What could be reason to omit this?

The problem i am facing is that it queue2 never posting 100% buffering:
$ gst-launch-1.0 souphttpsrc location=http://205.164.36.135:80 ! icydemux ! queue2 use-buffering=1 low-percent=10 high-percent=50 ! decodebin ! pulsesink 
Setting pipeline to PAUSED ...
Pipeline is PREROLLING ...
Prerolled, waiting for buffering to finish...
buffering... 50% 

With the above changes it works fine. i am testing with 1.4.3 release
Comment 9 Thiago Sousa Santos 2014-11-23 08:57:24 UTC
commit 8d835ec400819140e5fc8532a90010c694e1212b
Author: Thiago Santos <thiagoss@osg.samsung.com>
Date:   Sun Nov 23 05:45:24 2014 -0300

    queue2: percentage is relative to high-percent
    
    When comparing percentage values, compare with 0-100 scale as it
    has already been made relative to 0-high_percent, otherwise we mark
    the queue as not buffering and report a 50% to the user. This leads to
    a buffering stall as the user assumes the queue is still buffering but
    it thinks it isn't.
    
    https://bugzilla.gnome.org/show_bug.cgi?id=736969
Comment 10 Thiago Sousa Santos 2014-11-23 09:20:53 UTC
1.4 branch:

commit cafe1f2fc90acccd7aceb6d3c09bee6496396672
Author: Thiago Santos <thiagoss@osg.samsung.com>
Date:   Sun Nov 23 05:45:24 2014 -0300

    queue2: percentage is relative to high-percent
    
    When comparing percentage values, compare with 0-100 scale as it
    has already been made relative to 0-high_percent, otherwise we mark
    the queue as not buffering and report a 50% to the user. This leads to
    a buffering stall as the user assumes the queue is still buffering but
    it thinks it isn't.
    
    https://bugzilla.gnome.org/show_bug.cgi?id=736969