Bug 112300

Summary: Opening the Web Inspector takes 5s (undocked)
Product: WebKit Reporter: Timothy Hatcher <timothy>
Component: WebKit2Assignee: Timothy Hatcher <timothy>
Status: RESOLVED FIXED    
Severity: Normal CC: andersca, ap, ggaren, graouts, joepeck, sam, timothy, webkit.review.bot
Priority: P2 Keywords: InRadar
Version: 528+ (Nightly build)   
Hardware: Unspecified   
OS: Unspecified   
Attachments:
Description Flags
Proposed Change
ggaren: review+
Proposed Additional Change ggaren: review+, timothy: commit-queue-

Description Timothy Hatcher 2013-03-13 16:53:18 PDT
In Safari 6, it only takes 2s. Ideally, it would take less than 200ms.

* STEPS TO REPRODUCE
1. Go to about:blank
2. Opt-Cmd-C to open the Web Inspector to the JS console.
--> Takes 5s

The first two seconds are spent waiting on sync IPC:

Samples	# Self		Symbol Name
64   22.9%	0	 	                        WebKit::WebInspector::createInspectorPage()
64   22.9%	0	 	                         bool CoreIPC::Connection::sendSync<Messages::WebInspectorProxy::CreateInspectorPage>(Messages::WebInspectorProxy::CreateInspectorPage const&, Messages::WebInspectorProxy::CreateInspectorPage::Reply const&, unsigned long long, double, unsigned int)
64   22.9%	0	 	                          CoreIPC::Connection::sendSyncMessage(unsigned long long, WTF::PassOwnPtr<CoreIPC::MessageEncoder>, double, unsigned int)
64   22.9%	0	 	                           CoreIPC::Connection::waitForSyncReply(unsigned long long, double, unsigned int)
64   22.9%	0	 	                            CoreIPC::BinarySemaphore::wait(double)
64   22.9%	0	 	                             WTF::ThreadCondition::timedWait(WTF::Mutex&, double)
64   22.9%	0	 	                              _pthread_cond_wait
64   22.9%	64	 	                               __psynch_cvwait

There seems to be a CoreIPC deadlock, caused by this in the UI process at the same time as the above backtrace:

Samples	# Self		Symbol Name
62   28.8%	0	 	                           WebKit::WebInspectorProxy::createInspectorWindow()
62   28.8%	0	 	                            -[NSWindow setFrameAutosaveName:]
62   28.8%	0	 	                             -[NSWindow _setFrameAutosaveName:changeFrame:]
62   28.8%	0	 	                              -[NSWindow setFrameUsingName:]
62   28.8%	0	 	                               -[NSWindow _setFrameUsingName:domain:force:]
62   28.8%	0	 	                                -[NSWindow _setFrameFromString:overrideTopLeft:constrainFullFrame:force:]
62   28.8%	0	 	                                 -[NSWindow _setFrameCommon:display:stashSize:]
61   28.3%	0	 	                                  -[NSThemeFrame handleSetFrameCommonRedisplay]
61   28.3%	0	 	                                   -[NSView displayIfNeeded]
60   27.9%	0	 	                                    -[NSView _displayRectIgnoringOpacity:isVisibleRect:rectIsVisibleRectForView:]
60   27.9%	0	 	                                     -[NSThemeFrame _recursiveDisplayRectIfNeededIgnoringOpacity:isVisibleRect:rectIsVisibleRectForView:topView:]
60   27.9%	0	 	                                      -[NSView _recursiveDisplayRectIfNeededIgnoringOpacity:isVisibleRect:rectIsVisibleRectForView:topView:]
60   27.9%	0	 	                                       -[NSView _recursiveDisplayAllDirtyWithLockFocus:visRect:]
58   26.9%	0	 	                                        -[NSView _recursiveDisplayAllDirtyWithLockFocus:visRect:]
58   26.9%	0	 	                                         -[NSView _recursiveDisplayAllDirtyWithLockFocus:visRect:]
58   26.9%	0	 	                                          -[NSView _drawRect:clip:]
58   26.9%	0	 	                                           -[NSView(NSLayerKitGlue) _drawRectAsLayerTree:]
58   26.9%	0	 	                                            CA::Transaction::commit()
58   26.9%	0	 	                                             CA::Context::commit_transaction(CA::Transaction*)
58   26.9%	0	 	                                              CA::Layer::layout_and_display_if_needed(CA::Transaction*)
58   26.9%	0	 	                                               CA::Layer::display_if_needed(CA::Transaction*)
58   26.9%	0	 	                                                CA::Layer::display()
58   26.9%	0	 	                                                 -[NSView(NSLayerKitGlue) _displayLayer:]
58   26.9%	0	 	                                                  +[NSView _performWithoutAnimation:]
58   26.9%	0	 	                                                   WebKit::TiledCoreAnimationDrawingAreaProxy::waitForPossibleGeometryUpdate()
58   26.9%	0	 	                                                    bool CoreIPC::Connection::waitForAndDispatchImmediately<Messages::DrawingAreaProxy::DidUpdateGeometry>(unsigned long long, double)
58   26.9%	0	 	                                                     CoreIPC::Connection::waitForMessage(CoreIPC::StringReference, CoreIPC::StringReference, unsigned long long, double)
58   26.9%	0	 	                                                      WTF::ThreadCondition::timedWait(WTF::Mutex&, double)
58   26.9%	0	 	                                                       _pthread_cond_wait
58   26.9%	58	 	                                                        __psynch_cvwait

<rdar://problem/13412219>
Comment 1 Timothy Hatcher 2013-03-13 17:18:46 PDT
Created attachment 193026 [details]
Proposed Change
Comment 2 WebKit Review Bot 2013-03-13 17:32:20 PDT
Attachment 193026 [details] did not pass style-queue:

Failed to run "['Tools/Scripts/check-webkit-style', '--diff-files', u'Source/WebKit2/ChangeLog', u'Source/WebKit2/Shared/WebPreferencesStore.cpp', u'Source/WebKit2/Shared/WebPreferencesStore.h', u'Source/WebKit2/UIProcess/WebInspectorProxy.cpp', u'Source/WebKit2/UIProcess/WebInspectorProxy.h', u'Source/WebKit2/UIProcess/mac/WebInspectorProxyMac.mm']" exit_code: 1
Source/WebKit2/ChangeLog:6:  Need whitespace between colon and description  [changelog/filechangedescriptionwhitespace] [5]
Source/WebKit2/ChangeLog:8:  Need whitespace between colon and description  [changelog/filechangedescriptionwhitespace] [5]
Source/WebKit2/ChangeLog:9:  Need whitespace between colon and description  [changelog/filechangedescriptionwhitespace] [5]
Total errors found: 3 in 6 files


If any of these errors are false positives, please file a bug against check-webkit-style.
Comment 3 Alexey Proskuryakov 2013-03-13 19:08:33 PDT
What is the reason for CreateInspectorPage to not be handled? Normally, sync messages are delivered even when waiting for a sync message response, to prevent deadlocks.
Comment 4 Timothy Hatcher 2013-03-13 21:40:38 PDT
I'm not sure. Either way this patch is a much better approach. We were just marking the WKView as hidden before anyway. So not trying to make the window until later is cleaner and safer.
Comment 5 Alexey Proskuryakov 2013-03-13 23:00:54 PDT
CC'ing Sam and Anders, who may know the answer.
Comment 6 Timothy Hatcher 2013-03-15 07:22:52 PDT
Created attachment 193304 [details]
Proposed Additional Change
Comment 7 Geoffrey Garen 2013-03-15 15:21:45 PDT
Comment on attachment 193304 [details]
Proposed Additional Change

View in context: https://bugs.webkit.org/attachment.cgi?id=193304&action=review

r=me

> Source/WebKit/mac/ChangeLog:26
> +2013-03-15  Timothy Hatcher  <timothy@apple.com>
> +
> +        Need a short description (OOPS!).
> +        Need the bug URL (OOPS!).
> +
> +        Reviewed by NOBODY (OOPS!).
> +
> +        * WebCoreSupport/WebInspectorClient.mm:
> +        (-[WebInspectorWindowController init]):

Oops!
Comment 8 Geoffrey Garen 2013-03-15 15:23:26 PDT
Comment on attachment 193026 [details]
Proposed Change

r=me
Comment 9 Alexey Proskuryakov 2013-03-15 16:08:14 PDT
As discussed on IRC, the root cause for the delay is that -[WKView updateLayers] makes UI process wait 0.5 seconds for a DidUpdateGeometry message, and this of course causes a temporary deadlock if WebProcess waits for some sync message response, and cannot send this message.
Comment 10 Timothy Hatcher 2013-03-15 16:32:49 PDT
r145961 and r145963