Bug 54629

Summary: [webkitwebsrc] locks randomly fetching an uri
Product: WebKit Reporter: Andoni <ylatuya>
Component: WebCore Misc.Assignee: Nobody <webkit-unassigned>
Status: RESOLVED FIXED    
Severity: Normal CC: mrobinson, pnormand, sh919.park, svillar
Priority: P2    
Version: 528+ (Nightly build)   
Hardware: All   
OS: All   
Bug Depends on: 58318    
Bug Blocks:    
Attachments:
Description Flags
proposed patch xan.lopez: review-

Description Andoni 2011-02-17 02:24:41 PST
I have noticed a random lock in the webkit source fetching an uri. It looks like no buffers are pushed into the appsrc

(gdb) thread apply all bt

Hilo 8 (Thread 0xb64f2b70 (LWP 22603)):
#0  0x00774416 in __kernel_vsyscall ()
#1  0x04ebadf6 in __poll (fds=0x4f51ff4, nfds=1, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:87
#2  0x04d08a1b in g_poll () from /lib/libglib-2.0.so.0
#3  0x04cfb43c in ?? () from /lib/libglib-2.0.so.0
#4  0x04cfbba7 in g_main_loop_run () from /lib/libglib-2.0.so.0
#5  0x02d996b4 in ?? () from /usr/lib/libgio-2.0.so.0
#6  0x04d2248f in ?? () from /lib/libglib-2.0.so.0
#7  0x0061fcc9 in start_thread (arg=0xb64f2b70) at pthread_create.c:304
#8  0x04ec969e in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130

Hilo 7 (Thread 0xb5affb70 (LWP 22604)):
#0  0x00774416 in __kernel_vsyscall ()
#1  0x006244dc in pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/pthread_cond_wait.S:169
#2  0x011065f7 in WTF::TCMalloc_PageHeap::scavengerThread() () from /usr/local/lib/libwebkit-1.0.so
#3  0x01106631 in WTF::TCMalloc_PageHeap::runScavengerThread(void*) () from /usr/local/lib/libwebkit-1.0.so
#4  0x0061fcc9 in start_thread (arg=0xb5affb70) at pthread_create.c:304
#5  0x04ec969e in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130

Hilo 6 (Thread 0xb51feb70 (LWP 22605)):
#0  0x00774416 in __kernel_vsyscall ()
#1  0x006244dc in pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/pthread_cond_wait.S:169
#2  0x01042754 in WTF::ThreadCondition::wait(WTF::Mutex&) () from /usr/local/lib/libwebkit-1.0.so
#3  0x00dd165f in WebCore::IconDatabase::syncThreadMainLoop() () from /usr/local/lib/libwebkit-1.0.so
#4  0x00dd1734 in WebCore::IconDatabase::iconDatabaseSyncThread() () from /usr/local/lib/libwebkit-1.0.so
#5  0x010426bf in WTF::threadEntryPoint(void*) () from /usr/local/lib/libwebkit-1.0.so
#6  0x0061fcc9 in start_thread (arg=0xb51feb70) at pthread_create.c:304
#7  0x04ec969e in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130

Hilo 5 (Thread 0xb1ca4b70 (LWP 22606)):
#0  0x00774416 in __kernel_vsyscall ()
#1  0x006244dc in pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/pthread_cond_wait.S:169
#2  0x01634f5a in gst_task_func (task=0x87f48f8) at gsttask.c:303
#3  0x01636487 in default_func (tdata=0x8e4f8a0, pool=0x8ce3720) at gsttaskpool.c:70
#4  0x04d243d4 in ?? () from /lib/libglib-2.0.so.0
#5  0x04d2248f in ?? () from /lib/libglib-2.0.so.0
#6  0x0061fcc9 in start_thread (arg=0xb1ca4b70) at pthread_create.c:304
#7  0x04ec969e in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130

Hilo 4 (Thread 0xafd0cb70 (LWP 22608)):
#0  0x00774416 in __kernel_vsyscall ()
#1  0x006244dc in pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/pthread_cond_wait.S:169
#2  0x01634f5a in gst_task_func (task=0x87f4f58) at gsttask.c:303
#3  0x01636487 in default_func (tdata=0x8d064e0, pool=0x8ce3720) at gsttaskpool.c:70
#4  0x04d243d4 in ?? () from /lib/libglib-2.0.so.0
#5  0x04d2248f in ?? () from /lib/libglib-2.0.so.0
#6  0x0061fcc9 in start_thread (arg=0xafd0cb70) at pthread_create.c:304
#7  0x04ec969e in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130

Hilo 3 (Thread 0xaf50bb70 (LWP 22609)):
#0  0x00774416 in __kernel_vsyscall ()
#1  0x006244dc in pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/pthread_cond_wait.S:169
#2  0x01b230e9 in gst_hls_src_fetch_location (src=0x8ece008, uri=<value optimized out>) at gsthlssrc.c:752
#3  0x01b2372d in gst_hls_src_get_next_fragment (src=0x8ece008, retry=<value optimized out>) at gsthlssrc.c:924
#4  0x01b23d5b in gst_hls_src_cache_fragments (src=0x8ece008) at gsthlssrc.c:718
#5  gst_hls_src_loop (src=0x8ece008) at gsthlssrc.c:478
---Type <return> to continue, or q <return> to quit---
#6  0x01634d62 in gst_task_func (task=0x87f4ed0) at gsttask.c:318
#7  0x01636487 in default_func (tdata=0xb5b0f220, pool=0x8ce3720) at gsttaskpool.c:70
#8  0x04d243d4 in ?? () from /lib/libglib-2.0.so.0
#9  0x04d2248f in ?? () from /lib/libglib-2.0.so.0
#10 0x0061fcc9 in start_thread (arg=0xaf50bb70) at pthread_create.c:304
#11 0x04ec969e in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130

Hilo 2 (Thread 0xaed0ab70 (LWP 22610)):
#0  0x00774416 in __kernel_vsyscall ()
#1  0x006244dc in pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/pthread_cond_wait.S:169
#2  0x005ce3fd in gst_app_src_create (bsrc=0x8e50c20, offset=0, size=4096, buf=0xaed0a05c) at gstappsrc.c:1040
#3  0x00732ab1 in gst_base_src_get_range (src=<value optimized out>, offset=0, length=4096, buf=0xaed0a05c) at gstbasesrc.c:2137
#4  0x0073583f in gst_base_src_loop (pad=0x8ea2650) at gstbasesrc.c:2394
#5  0x01634d62 in gst_task_func (task=0x8ed0de8) at gsttask.c:318
#6  0x01636487 in default_func (tdata=0xb5b1ab38, pool=0x8ce3720) at gsttaskpool.c:70
#7  0x04d243d4 in ?? () from /lib/libglib-2.0.so.0
#8  0x04d2248f in ?? () from /lib/libglib-2.0.so.0
#9  0x0061fcc9 in start_thread (arg=0xaed0ab70) at pthread_create.c:304
#10 0x04ec969e in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130

Hilo 1 (Thread 0xb689b860 (LWP 22602)):
#0  0x00774416 in __kernel_vsyscall ()
#1  0x04ebadf6 in __poll (fds=0x4f51ff4, nfds=13, timeout=188) at ../sysdeps/unix/sysv/linux/poll.c:87
#2  0x04d08a1b in g_poll () from /lib/libglib-2.0.so.0
#3  0x04cfb43c in ?? () from /lib/libglib-2.0.so.0
#4  0x04cfbba7 in g_main_loop_run () from /lib/libglib-2.0.so.0
#5  0x031a51d9 in gtk_main () from /usr/lib/libgtk-x11-2.0.so.0
#6  0x0806e793 in main ()

0:00:00.712582110 22847 0xb4b29b38 INFO                  hlssrc gsthlssrc.c:935:gst_hls_src_get_next_fragment:<hlssrc0> Input source caps: video/mpegts, systemstream=(boolean)true, packetsize=(int)188
0:00:00.712616505 22847 0xb4b29b38 INFO                  hlssrc gsthlssrc.c:922:gst_hls_src_get_next_fragment:<hlssrc0> Fetching next fragment http://devimages.apple.com/iphone/samples/bipbop/gear4/fileSequence1.ts
0:00:00.712626160 22847 0xb4b29b38 DEBUG                 hlssrc gsthlssrc.c:547:gst_hls_src_make_fetcher:<hlssrc0> Creating fetcher for the URI:http://devimages.apple.com/iphone/samples/bipbop/gear4/fileSequence1.ts
0:00:00.712798044 22847 0xb4b29b38 DEBUG                basesrc gstbasesrc.c:416:gst_base_src_init:<GstBaseSrc@0x99b8c98> creating src pad
0:00:00.712820943 22847 0xb4b29b38 DEBUG                basesrc gstbasesrc.c:419:gst_base_src_init:<GstBaseSrc@0x99b8c98> setting functions on src pad
0:00:00.712832177 22847 0xb4b29b38 DEBUG                basesrc gstbasesrc.c:432:gst_base_src_init:<GstBaseSrc@0x99b8c98> adding src pad
0:00:00.712842266 22847 0xb4b29b38 DEBUG                basesrc gstbasesrc.c:446:gst_base_src_init:<GstBaseSrc@0x99b8c98> init done
0:00:00.712891634 22847 0xb4b29b38 DEBUG                 appsrc gstappsrc.c:1217:gst_app_src_set_stream_type:<appsrc2> setting stream_type of 1
0:00:00.712901972 22847 0xb4b29b38 DEBUG                 appsrc gstappsrc.c:1273:gst_app_src_set_max_bytes:<appsrc2> setting max-bytes to 524288
0:00:00.712916897 22847 0xb4b29b38 DEBUG                 appsrc gstappsrc.c:1100:gst_app_src_set_caps:<appsrc2> setting caps to (NULL)
0:00:00.712926522 22847 0xb4b29b38 DEBUG                 appsrc gstappsrc.c:1161:gst_app_src_set_size:<appsrc2> setting size of -1
0:00:00.712934845 22847 0xb4b29b38 DEBUG           webkitwebsrc WebCore/platform/graphics/gstreamer/WebKitWebSourceGStreamer.cpp:392:webKitWebSrcStop:<WebKitWebSrc@0xb4b083b0> Stopped request
0:00:00.713008143 22847 0xb4b29b38 DEBUG                basesrc gstbasesrc.c:2928:gst_base_src_activate_push:<appsrc2> Activating in push mode
0:00:00.713018099 22847 0xb4b29b38 DEBUG                basesrc gstbasesrc.c:2694:gst_base_src_start:<appsrc2> starting source
0:00:00.713025877 22847 0xb4b29b38 DEBUG                 appsrc gstappsrc.c:735:gst_app_src_start:<appsrc2> starting
0:00:00.713033707 22847 0xb4b29b38 DEBUG                 appsrc gstappsrc.c:1189:gst_app_src_get_size:<appsrc2> getting size of -1
0:00:00.713041485 22847 0xb4b29b38 DEBUG                basesrc gstbasesrc.c:2727:gst_base_src_start:<appsrc2> setting size 18446744073709551615
0:00:00.713050485 22847 0xb4b29b38 DEBUG                basesrc gstbasesrc.c:2740:gst_base_src_start:<appsrc2> format: bytes, have size: 1, size: 18446744073709551615, duration: -1
0:00:00.713059559 22847 0xb4b29b38 DEBUG                basesrc gstbasesrc.c:2743:gst_base_src_start:<appsrc2> is seekable: 1
0:00:00.713067142 22847 0xb4b29b38 DEBUG                basesrc gstbasesrc.c:2748:gst_base_src_start:<appsrc2> is random_access: 1
0:00:00.713075940 22847 0xb4b29b38 DEBUG                basesrc gstbasesrc.c:2604:gst_base_src_default_negotiate:<appsrc2> caps of src: ANY
0:00:00.713085286 22847 0xb4b29b38 DEBUG                basesrc gstbasesrc.c:2652:gst_base_src_default_negotiate:<appsrc2> no negotiation needed
0:00:00.713093428 22847 0xb4b29b38 DEBUG                basesrc gstbasesrc.c:1308:gst_base_src_perform_seek:<appsrc2> doing seek: (NULL)
0:00:00.713102930 22847 0xb4b29b38 DEBUG                 appsrc gstappsrc.c:720:gst_app_src_unlock_stop:<appsrc2> unlock stop
0:00:00.713110804 22847 0xb4b29b38 DEBUG                basesrc gstbasesrc.c:1363:gst_base_src_perform_seek:<appsrc2> seek with seqnum 108
0:00:00.713118910 22847 0xb4b29b38 DEBUG                basesrc gstbasesrc.c:1399:gst_base_src_perform_seek:<appsrc2> segment configured from 0 to -1, position 0
0:00:00.713127549 22847 0xb4b29b38 DEBUG                 appsrc gstappsrc.c:858:gst_app_src_do_seek:<appsrc2> seeking to 0, format bytes
0:00:00.713135917 22847 0xb4b29b38 DEBUG           webkitwebsrc WebCore/platform/graphics/gstreamer/WebKitWebSourceGStreamer.cpp:639:webKitWebSrcSeekDataCb:<webkitwebsrc1> Seeking to offset: 0
0:00:00.713143939 22847 0xb4b29b38 DEBUG                 appsrc gstappsrc.c:879:gst_app_src_do_seek:<appsrc2> flushing queue
0:00:00.713151780 22847 0xb4b29b38 DEBUG                basesrc gstbasesrc.c:1459:gst_base_src_perform_seek:<appsrc2> Sending newsegment from 0 to -1
0:00:00.713218853 22847  0x9879fc0 LOG                  basesrc gstbasesrc.c:2392:gst_base_src_loop:<appsrc2> next_ts 0:00:00.000000000 size 4096
0:00:00.713229533 22847  0x9879fc0 DEBUG                basesrc gstbasesrc.c:2045:gst_base_src_update_length:<appsrc2> reading offset 0, length 4096, size -1, segment.stop -1, maxsize -1
0:00:00.713238873 22847  0x9879fc0 DEBUG                basesrc gstbasesrc.c:2135:gst_base_src_get_range:<appsrc2> calling create offset 0 length 4096, time 0
0:00:00.713247635 22847  0x9879fc0 DEBUG           webkitwebsrc WebCore/platform/graphics/gstreamer/WebKitWebSourceGStreamer.cpp:595:webKitWebSrcNeedDataCb:<webkitwebsrc1> Need more data: 4096
0:00:00.713267883 22847 0xb4b29b38 DEBUG           webkitwebsrc WebCore/platform/graphics/gstreamer/WebKitWebSourceGStreamer.cpp:475:webKitWebSrcChangeState:<webkitwebsrc1> READY->PAUSED
0:00:00.725116845 22847 0xb4b29b38 DEBUG           webkitwebsrc WebCore/platform/graphics/gstreamer/WebKitWebSourceGStreamer.cpp:443:webKitWebSrcStart:<webkitwebsrc1> Started request
0:00:00.725159135 22847 0xb4b29b38 DEBUG                basesrc gstbasesrc.c:3065:gst_base_src_change_state:<appsrc2> PAUSED->PLAYING
0:00:00.725180771 22847 0xb4b29b38 DEBUG                 hlssrc gsthlssrc.c:751:gst_hls_src_fetch_location:<hlssrc0> Waiting to fetch the URI
Comment 1 Philippe Normand 2011-02-28 01:31:22 PST
Hi Andoni, have you had time to investigate this issue further?

If not, I can help maybe? The issue is reproducible with your hls element, right?
Comment 2 Andoni 2011-02-28 02:02:47 PST
I am on vacations and I couldn't debug it further but it can be reproduced with the hls element.
Comment 3 Philippe Normand 2011-04-12 06:53:59 PDT
With patch in Bug 58318 the player starts loading the stream but a segfault is triggered in ResourceHandleSoup :P Will investigate that issue...

Then I can check this deadlock!
Comment 4 Philippe Normand 2011-04-13 05:50:37 PDT
I can't reproduce that exact deadlock here. However I found some issues related to multi-threading in ResourceHandleSoup.

The hlsdemux element runs a thread which creates a WebKitWebSrc element (and that chains into WebKit's resource loader) for each fragment to get from the server.

It seems that using a GRefPtr in the libsoup read/close callbacks triggers some threadsafety crashes like this one:


(gdb) bt
#0  0x00007f5446fd6579 in WebCore::TimerBase::stop (this=0x7f5430099e38)
    at ../../Source/WebCore/platform/Timer.cpp:189
#1  0x00007f5446fd641c in WebCore::TimerBase::~TimerBase (this=0x7f5430099e38, 
    __in_chrg=<value optimized out>) at ../../Source/WebCore/platform/Timer.cpp:175
#2  0x00007f54467e8bc6 in WebCore::Timer<WebCore::ResourceHandle>::~Timer (this=0x7f5430099e38, 
    __in_chrg=<value optimized out>) at ../../Source/WebCore/platform/network/ResourceHandle.h:94
#3  0x00007f54467e4da6 in WebCore::ResourceHandleInternal::~ResourceHandleInternal (this=0x7f5430099a00, 
    __in_chrg=<value optimized out>) at ../../Source/WebCore/platform/network/soup/ResourceHandleSoup.cpp:134
#4  0x00007f54467ea3ad in WTF::deleteOwnedPtr<WebCore::ResourceHandleInternal> (ptr=0x7f5430099a00)
    at ../../Source/JavaScriptCore/wtf/OwnPtrCommon.h:59
#5  0x00007f54467e973b in WTF::OwnPtr<WebCore::ResourceHandleInternal>::~OwnPtr (this=0x7f54300a79f0, 
    __in_chrg=<value optimized out>) at ../../Source/JavaScriptCore/wtf/OwnPtr.h:57
#6  0x00007f54467e4ebd in WebCore::ResourceHandle::~ResourceHandle (this=0x7f54300a79e0, 
    __in_chrg=<value optimized out>) at ../../Source/WebCore/platform/network/soup/ResourceHandleSoup.cpp:140
#7  0x00007f54467e4f00 in WebCore::ResourceHandle::~ResourceHandle (this=0x7f54300a79e0, 
    __in_chrg=<value optimized out>) at ../../Source/WebCore/platform/network/soup/ResourceHandleSoup.cpp:143
#8  0x00007f54467a6f46 in WTF::RefCounted<WebCore::ResourceHandle>::deref (this=0x7f54300a79e8)
    at ../../Source/JavaScriptCore/wtf/RefCounted.h:141
#9  0x00007f54467a726d in WTF::derefIfNotNull<WebCore::ResourceHandle> (ptr=0x7f54300a79e0)
    at ../../Source/JavaScriptCore/wtf/PassRefPtr.h:59
#10 0x00007f54467e97d7 in WTF::RefPtr<WebCore::ResourceHandle>::~RefPtr (this=0x7fff73778440, 
    __in_chrg=<value optimized out>) at ../../Source/JavaScriptCore/wtf/RefPtr.h:58
#11 0x00007f54467e7ff5 in WebCore::readCallback (source=0x7f53d4005340, asyncResult=0x1d35de0, data=0x0)
    at ../../Source/WebCore/platform/network/soup/ResourceHandleSoup.cpp:753
#12 0x00007f5444fecf15 in async_ready_callback_wrapper (source_object=0x7f53d4005340, res=0x1d35de0, 
    user_data=0x0) at ginputstream.c:470
#13 0x00007f5440f2110d in read_async_done (stream=0x7f53d4005340) at soup-http-input-stream.c:723
#14 0x00007f5443a49d8e in g_closure_invoke (closure=0x7f54300fba90, return_value=0x0, n_param_values=1, 
    param_values=0x7f543034e480, invocation_hint=0x7fff73778690) at gclosure.c:767
#15 0x00007f5443a5c6da in signal_emit_unlocked_R (node=<value optimized out>, detail=0, instance=0x1c09c00, 
    emission_return=0x0, instance_and_params=0x7f543034e480) at gsignal.c:3256
#16 0x00007f5443a65d3a in g_signal_emit_valist (instance=<value optimized out>, 
    signal_id=<value optimized out>, detail=<value optimized out>, var_args=0x7fff73778880) at gsignal.c:2987
#17 0x00007f5443a65ee3 in g_signal_emit (instance=<value optimized out>, signal_id=<value optimized out>, 
    detail=<value optimized out>) at gsignal.c:3044
#18 0x00007f5440f343b3 in process_queue_item (item=0x1d29e00, should_prune=0x7fff737789bc, loop=1)
    at soup-session-async.c:376
#19 0x00007f5440f34705 in run_queue (sa=<value optimized out>) at soup-session-async.c:418
#20 0x00007f5440f34d53 in idle_run_queue (sa=0x13f0830) at soup-session-async.c:441
#21 0x00007f54431575c3 in g_main_dispatch (context=0x13b82d0) at gmain.c:2447
#22 g_main_context_dispatch (context=0x13b82d0) at gmain.c:3020
#23 0x00007f5443157da0 in g_main_context_iterate (context=0x13b82d0, block=1, dispatch=1, 
    self=<value optimized out>) at gmain.c:3098
#24 0x00007f5443158412 in g_main_loop_run (loop=0x1a46b00) at gmain.c:3306
#25 0x00007f54458da557 in IA__gtk_main () at gtkmain.c:1255
#26 0x0000000000402af9 in main (argc=2, argv=0x7fff73778cd8) at ../../Tools/GtkLauncher/main.c:274

Would it make sense to not use GRefPtr in those callbacks? Sergio? Martin?
Comment 5 Philippe Normand 2011-04-13 07:24:48 PDT
Created attachment 89372 [details]
proposed patch
Comment 6 Martin Robinson 2011-04-13 08:31:31 PDT
(In reply to comment #5)
> Created an attachment (id=89372) [details]
> proposed patch

It seems dangerous to remove the RefPtr here. What happens if the ResourceHandle is dereffed out of existence on another thread?
Comment 7 Philippe Normand 2011-04-13 08:37:31 PDT
(In reply to comment #6)
> (In reply to comment #5)
> > Created an attachment (id=89372) [details] [details]
> > proposed patch
> 
> It seems dangerous to remove the RefPtr here. What happens if the ResourceHandle is dereffed out of existence on another thread?

The crash in comment 4. The destructor of Timer checks the thread where it was created with the current thread and ASSERTs if they differ.
Comment 8 Xan Lopez 2011-04-26 16:33:06 PDT
Comment on attachment 89372 [details]
proposed patch

There must be a bette way to handle this than not using RefPtr because some of its side effects.
Comment 9 Philippe Normand 2014-03-04 23:48:13 PST
http://devimages.apple.com/iphone/samples/bipbop/bipbopall.m3u8 plays fine here. Our HTTP src element got some attention about locks recently. I'm going to close this issue but feel free to reopen if needed!