Modified: branches/safari-608-branch/Source/WebKit/ChangeLog (250525 => 250526)
--- branches/safari-608-branch/Source/WebKit/ChangeLog 2019-09-30 20:16:00 UTC (rev 250525)
+++ branches/safari-608-branch/Source/WebKit/ChangeLog 2019-09-30 20:27:13 UTC (rev 250526)
@@ -1,3 +1,111 @@
+2019-09-30 Kocsen Chung <[email protected]>
+
+ Cherry-pick r250405. rdar://problem/55825353
+
+ Add some logging to help diagnose blank or stuck WKWebViews
+ https://bugs.webkit.org/show_bug.cgi?id=202297
+ <rdar://problem/55763610>
+
+ Reviewed by Wenson Hsieh.
+
+ Our current logging is insufficient to rule out some of the potential
+ causes of stuck/blank WKWebViews in <rdar://problem/53399054>. Add
+ some new logging, and improve some existing logging, to aid in diagnosis.
+
+ * UIProcess/API/Cocoa/WKWebView.mm:
+ (-[WKWebView _willInvokeUIScrollViewDelegateCallback]):
+ (-[WKWebView _didInvokeUIScrollViewDelegateCallback]):
+ Rename _delayUpdateVisibleContentRects to be more specific that it
+ was due to us being underneath a UIScrollView delegate callback.
+
+ (-[WKWebView _processWillSwapOrDidExit]):
+ (-[WKWebView _didCommitLayerTree:]):
+ Add a log when we receive an incoming commit while visible content rect
+ updates are being deferred. Also, include the current transaction ID
+ and the transaction ID that _needsResetViewState... is waiting for, to
+ help rule out a class of potential problems.
+
+ Add a log when we receive an incoming commit more than 5 seconds after
+ a visible content rect update.
+
+ (-[WKWebView _updateVisibleContentRects]):
+ Keep track of when we defer visual content rect updates for any reason,
+ and log the first time we do an update after deferring them. This will make
+ it MUCH easier at-a-glance to tell if one of the "bailing" messages
+ represents a long-term state (a problem), or is expected.
+
+ Keep track of how long it's been since we sent a visible content rect update
+ and didn't get a commit back from the Web Content process; if it's been
+ more than 5 seconds, start logging.
+
+ (-[WKWebView _cancelAnimatedResize]):
+ (-[WKWebView _didCompleteAnimatedResize]):
+ (-[WKWebView _beginAnimatedResizeWithUpdates:]):
+ (-[WKWebView _endAnimatedResize]):
+ (-[WKWebView _resizeWhileHidingContentWithUpdates:]):
+ Turn animated resize logging into release logging. It is a common culprit
+ for many kinds of bugs, while also not being high volume, so this is well worth it.
+
+ * WebProcess/WebPage/WebPage.cpp:
+ (WebKit::WebPage::freezeLayerTree):
+ (WebKit::WebPage::unfreezeLayerTree):
+ Show the current value of m_layerTreeFreezeReasons in addition to the old value and delta,
+ so you don't have to manually compute the current value when reading logs.
+
+ git-svn-id: https://svn.webkit.org/repository/webkit/trunk@250405 268f45cc-cd09-0410-ab3c-d52691b4dbfc
+
+ 2019-09-26 Tim Horton <[email protected]>
+
+ Add some logging to help diagnose blank or stuck WKWebViews
+ https://bugs.webkit.org/show_bug.cgi?id=202297
+ <rdar://problem/55763610>
+
+ Reviewed by Wenson Hsieh.
+
+ Our current logging is insufficient to rule out some of the potential
+ causes of stuck/blank WKWebViews in <rdar://problem/53399054>. Add
+ some new logging, and improve some existing logging, to aid in diagnosis.
+
+ * UIProcess/API/Cocoa/WKWebView.mm:
+ (-[WKWebView _willInvokeUIScrollViewDelegateCallback]):
+ (-[WKWebView _didInvokeUIScrollViewDelegateCallback]):
+ Rename _delayUpdateVisibleContentRects to be more specific that it
+ was due to us being underneath a UIScrollView delegate callback.
+
+ (-[WKWebView _processWillSwapOrDidExit]):
+ (-[WKWebView _didCommitLayerTree:]):
+ Add a log when we receive an incoming commit while visible content rect
+ updates are being deferred. Also, include the current transaction ID
+ and the transaction ID that _needsResetViewState... is waiting for, to
+ help rule out a class of potential problems.
+
+ Add a log when we receive an incoming commit more than 5 seconds after
+ a visible content rect update.
+
+ (-[WKWebView _updateVisibleContentRects]):
+ Keep track of when we defer visual content rect updates for any reason,
+ and log the first time we do an update after deferring them. This will make
+ it MUCH easier at-a-glance to tell if one of the "bailing" messages
+ represents a long-term state (a problem), or is expected.
+
+ Keep track of how long it's been since we sent a visible content rect update
+ and didn't get a commit back from the Web Content process; if it's been
+ more than 5 seconds, start logging.
+
+ (-[WKWebView _cancelAnimatedResize]):
+ (-[WKWebView _didCompleteAnimatedResize]):
+ (-[WKWebView _beginAnimatedResizeWithUpdates:]):
+ (-[WKWebView _endAnimatedResize]):
+ (-[WKWebView _resizeWhileHidingContentWithUpdates:]):
+ Turn animated resize logging into release logging. It is a common culprit
+ for many kinds of bugs, while also not being high volume, so this is well worth it.
+
+ * WebProcess/WebPage/WebPage.cpp:
+ (WebKit::WebPage::freezeLayerTree):
+ (WebKit::WebPage::unfreezeLayerTree):
+ Show the current value of m_layerTreeFreezeReasons in addition to the old value and delta,
+ so you don't have to manually compute the current value when reading logs.
+
2019-09-30 Babak Shafiei <[email protected]>
Cherry-pick r250394. rdar://problem/55826250
Modified: branches/safari-608-branch/Source/WebKit/UIProcess/API/Cocoa/WKWebView.mm (250525 => 250526)
--- branches/safari-608-branch/Source/WebKit/UIProcess/API/Cocoa/WKWebView.mm 2019-09-30 20:16:00 UTC (rev 250525)
+++ branches/safari-608-branch/Source/WebKit/UIProcess/API/Cocoa/WKWebView.mm 2019-09-30 20:27:13 UTC (rev 250526)
@@ -185,6 +185,7 @@
#if PLATFORM(IOS_FAMILY)
static const uint32_t firstSDKVersionWithLinkPreviewEnabledByDefault = 0xA0000;
static const Seconds delayBeforeNoVisibleContentsRectsLogging = 1_s;
+static const Seconds delayBeforeNoCommitsLogging = 5_s;
#endif
#if PLATFORM(MAC)
@@ -317,6 +318,7 @@
BOOL _hasCommittedLoadForMainFrame;
BOOL _needsResetViewStateAfterCommitLoadForMainFrame;
uint64_t _firstPaintAfterCommitLoadTransactionID;
+ uint64_t _lastTransactionID;
WebKit::DynamicViewportUpdateMode _dynamicViewportUpdateMode;
WebKit::DynamicViewportSizeUpdateID _currentDynamicViewportSizeUpdateID;
CATransform3D _resizeAnimationTransformAdjustments;
@@ -351,8 +353,10 @@
CGFloat _totalScrollViewBottomInsetAdjustmentForKeyboard;
BOOL _currentlyAdjustingScrollViewInsetsForKeyboard;
- BOOL _delayUpdateVisibleContentRects;
- BOOL _hadDelayedUpdateVisibleContentRects;
+ BOOL _invokingUIScrollViewDelegateCallback;
+ BOOL _didDeferUpdateVisibleContentRectsForUIScrollViewDelegateCallback;
+ BOOL _didDeferUpdateVisibleContentRectsForAnyReason;
+ BOOL _didDeferUpdateVisibleContentRectsForUnstableScrollView;
BOOL _waitingForEndAnimatedResize;
BOOL _waitingForCommitAfterAnimatedResize;
@@ -372,6 +376,8 @@
MonotonicTime _timeOfRequestForVisibleContentRectUpdate;
MonotonicTime _timeOfLastVisibleContentRectUpdate;
+ Optional<MonotonicTime> _timeOfFirstVisibleContentRectUpdateWithPendingCommit;
+
NSUInteger _focusPreservationCount;
NSUInteger _activeFocusedStateRetainCount;
@@ -795,8 +801,11 @@
#if PLATFORM(IOS_FAMILY)
_dragInteractionPolicy = _WKDragInteractionPolicyDefault;
- _timeOfRequestForVisibleContentRectUpdate = MonotonicTime::now();
- _timeOfLastVisibleContentRectUpdate = MonotonicTime::now();
+ auto timeNow = MonotonicTime::now();
+ _timeOfRequestForVisibleContentRectUpdate = timeNow;
+ _timeOfLastVisibleContentRectUpdate = timeNow;
+ _timeOfFirstVisibleContentRectUpdateWithPendingCommit = timeNow;
+
#if PLATFORM(WATCHOS)
_allowsViewportShrinkToFit = YES;
#else
@@ -1691,14 +1700,14 @@
- (void)_willInvokeUIScrollViewDelegateCallback
{
- _delayUpdateVisibleContentRects = YES;
+ _invokingUIScrollViewDelegateCallback = YES;
}
- (void)_didInvokeUIScrollViewDelegateCallback
{
- _delayUpdateVisibleContentRects = NO;
- if (_hadDelayedUpdateVisibleContentRects) {
- _hadDelayedUpdateVisibleContentRects = NO;
+ _invokingUIScrollViewDelegateCallback = NO;
+ if (_didDeferUpdateVisibleContentRectsForUIScrollViewDelegateCallback) {
+ _didDeferUpdateVisibleContentRectsForUIScrollViewDelegateCallback = NO;
[self _scheduleVisibleContentRectUpdate];
}
}
@@ -1881,8 +1890,10 @@
_scrollOffsetToRestore = WTF::nullopt;
_unobscuredCenterToRestore = WTF::nullopt;
_scrollViewBackgroundColor = WebCore::Color();
- _delayUpdateVisibleContentRects = NO;
- _hadDelayedUpdateVisibleContentRects = NO;
+ _invokingUIScrollViewDelegateCallback = NO;
+ _didDeferUpdateVisibleContentRectsForUIScrollViewDelegateCallback = NO;
+ _didDeferUpdateVisibleContentRectsForAnyReason = NO;
+ _didDeferUpdateVisibleContentRectsForUnstableScrollView = NO;
_currentlyAdjustingScrollViewInsetsForKeyboard = NO;
_lastSentViewLayoutSize = WTF::nullopt;
_lastSentMaximumUnobscuredSize = WTF::nullopt;
@@ -1894,6 +1905,8 @@
_firstPaintAfterCommitLoadTransactionID = 0;
_firstTransactionIDAfterPageRestore = WTF::nullopt;
+ _lastTransactionID = { };
+
_hasScheduledVisibleRectUpdate = NO;
_commitDidRestoreScrollPosition = NO;
@@ -2020,10 +2033,24 @@
- (void)_didCommitLayerTree:(const WebKit::RemoteLayerTreeTransaction&)layerTreeTransaction
{
+ if (_didDeferUpdateVisibleContentRectsForUnstableScrollView) {
+ RELEASE_LOG_IF_ALLOWED("%p (PageID=%llu) -[WKWebView _didCommitLayerTree:] - received a commit (%llu) while deferring visible content rect updates (_dynamicViewportUpdateMode %d, _needsResetViewStateAfterCommitLoadForMainFrame %d (wants commit %llu), sizeChangedSinceLastVisibleContentRectUpdate %d, [_scrollView isZoomBouncing] %d, _currentlyAdjustingScrollViewInsetsForKeyboard %d)",
+ self, _page->identifier().toUInt64(), layerTreeTransaction.transactionID().toUInt64(), _dynamicViewportUpdateMode, _needsResetViewStateAfterCommitLoadForMainFrame, _firstPaintAfterCommitLoadTransactionID.toUInt64(), [_contentView sizeChangedSinceLastVisibleContentRectUpdate], [_scrollView isZoomBouncing], _currentlyAdjustingScrollViewInsetsForKeyboard);
+ }
+
+ if (_timeOfFirstVisibleContentRectUpdateWithPendingCommit) {
+ auto timeSinceFirstRequestWithPendingCommit = MonotonicTime::now() - *_timeOfFirstVisibleContentRectUpdateWithPendingCommit;
+ if (timeSinceFirstRequestWithPendingCommit > delayBeforeNoCommitsLogging)
+ RELEASE_LOG_IF_ALLOWED("%p (PageID=%llu) -[WKWebView _didCommitLayerTree:] - finally received commit %.2fs after visible content rect update request; transactionID %llu", self, _page->identifier().toUInt64(), timeSinceFirstRequestWithPendingCommit.value(), layerTreeTransaction.transactionID().toUInt64());
+ _timeOfFirstVisibleContentRectUpdateWithPendingCommit = WTF::nullopt;
+ }
+
+ _lastTransactionID = layerTreeTransaction.transactionID();
+
if (![self usesStandardContentView])
return;
- LOG_WITH_STREAM(VisibleRects, stream << "-[WKWebView " << _page->pageID() << " _didCommitLayerTree:] transactionID " << layerTreeTransaction.transactionID() << " _dynamicViewportUpdateMode " << (int)_dynamicViewportUpdateMode);
+ LOG_WITH_STREAM(VisibleRects, stream << "-[WKWebView " << _page->pageID().toUInt64() << " _didCommitLayerTree:] transactionID " << layerTreeTransaction.transactionID() << " _dynamicViewportUpdateMode " << (int)_dynamicViewportUpdateMode);
bool needUpdateVisibleContentRects = _page->updateLayoutViewportParameters(layerTreeTransaction);
@@ -3115,13 +3142,22 @@
if (![self usesStandardContentView]) {
[_passwordView setFrame:self.bounds];
[_customContentView web_computedContentInsetDidChange];
- RELEASE_LOG_IF_ALLOWED("%p -[WKWebView _updateVisibleContentRects:] - usesStandardContentView is NO, bailing", self);
+ _didDeferUpdateVisibleContentRectsForAnyReason = YES;
+ RELEASE_LOG_IF_ALLOWED("%p (PageID=%llu) -[WKWebView _updateVisibleContentRects:] - usesStandardContentView is NO, bailing", self, _page->identifier().toUInt64());
return;
}
- if (_delayUpdateVisibleContentRects) {
- _hadDelayedUpdateVisibleContentRects = YES;
- RELEASE_LOG_IF_ALLOWED("%p -[WKWebView _updateVisibleContentRects:] - _delayUpdateVisibleContentRects is YES, bailing", self);
+ auto timeNow = MonotonicTime::now();
+ if (_timeOfFirstVisibleContentRectUpdateWithPendingCommit) {
+ auto timeSinceFirstRequestWithPendingCommit = timeNow - *_timeOfFirstVisibleContentRectUpdateWithPendingCommit;
+ if (timeSinceFirstRequestWithPendingCommit > delayBeforeNoCommitsLogging)
+ RELEASE_LOG_IF_ALLOWED("%p (PageID=%llu) -[WKWebView _updateVisibleContentRects:] - have not received a commit %.2fs after visible content rect update; lastTransactionID %llu", self, _page->identifier().toUInt64(), timeSinceFirstRequestWithPendingCommit.value(), _lastTransactionID.toUInt64());
+ }
+
+ if (_invokingUIScrollViewDelegateCallback) {
+ _didDeferUpdateVisibleContentRectsForUIScrollViewDelegateCallback = YES;
+ _didDeferUpdateVisibleContentRectsForAnyReason = YES;
+ RELEASE_LOG_IF_ALLOWED("%p (PageID=%llu) -[WKWebView _updateVisibleContentRects:] - _invokingUIScrollViewDelegateCallback is YES, bailing", self, _page->identifier().toUInt64());
return;
}
@@ -3129,11 +3165,20 @@
|| (_needsResetViewStateAfterCommitLoadForMainFrame && ![_contentView sizeChangedSinceLastVisibleContentRectUpdate])
|| [_scrollView isZoomBouncing]
|| _currentlyAdjustingScrollViewInsetsForKeyboard) {
- RELEASE_LOG_IF_ALLOWED("%p -[WKWebView _updateVisibleContentRects:] - scroll view state is non-stable, bailing (_dynamicViewportUpdateMode %d, _needsResetViewStateAfterCommitLoadForMainFrame %d, sizeChangedSinceLastVisibleContentRectUpdate %d, [_scrollView isZoomBouncing] %d, _currentlyAdjustingScrollViewInsetsForKeyboard %d)",
- self, _dynamicViewportUpdateMode, _needsResetViewStateAfterCommitLoadForMainFrame, [_contentView sizeChangedSinceLastVisibleContentRectUpdate], [_scrollView isZoomBouncing], _currentlyAdjustingScrollViewInsetsForKeyboard);
+ _didDeferUpdateVisibleContentRectsForAnyReason = YES;
+ _didDeferUpdateVisibleContentRectsForUnstableScrollView = YES;
+ RELEASE_LOG_IF_ALLOWED("%p (PageID=%llu) -[WKWebView _updateVisibleContentRects:] - scroll view state is non-stable, bailing (_dynamicViewportUpdateMode %d, _needsResetViewStateAfterCommitLoadForMainFrame %d, sizeChangedSinceLastVisibleContentRectUpdate %d, [_scrollView isZoomBouncing] %d, _currentlyAdjustingScrollViewInsetsForKeyboard %d)",
+ self, _page->identifier().toUInt64(), _dynamicViewportUpdateMode, _needsResetViewStateAfterCommitLoadForMainFrame, [_contentView sizeChangedSinceLastVisibleContentRectUpdate], [_scrollView isZoomBouncing], _currentlyAdjustingScrollViewInsetsForKeyboard);
return;
}
+ if (_didDeferUpdateVisibleContentRectsForAnyReason)
+ RELEASE_LOG_IF_ALLOWED("%p (PageID=%llu) -[WKWebView _updateVisibleContentRects:] - performing first visible content rect update after deferring updates", self, _page->identifier().toUInt64());
+
+ _didDeferUpdateVisibleContentRectsForUIScrollViewDelegateCallback = NO;
+ _didDeferUpdateVisibleContentRectsForUnstableScrollView = NO;
+ _didDeferUpdateVisibleContentRectsForAnyReason = NO;
+
CGRect visibleRectInContentCoordinates = [self _visibleContentRect];
UIEdgeInsets computedContentInsetUnadjustedForKeyboard = [self _computedObscuredInset];
@@ -3199,12 +3244,13 @@
auto callback = _visibleContentRectUpdateCallbacks.takeLast();
callback();
}
-
- auto timeNow = MonotonicTime::now();
+
if ((timeNow - _timeOfRequestForVisibleContentRectUpdate) > delayBeforeNoVisibleContentsRectsLogging)
RELEASE_LOG_IF_ALLOWED("%p -[WKWebView _updateVisibleContentRects:] finally ran %.2fs after being scheduled", self, (timeNow - _timeOfRequestForVisibleContentRectUpdate).value());
_timeOfLastVisibleContentRectUpdate = timeNow;
+ if (!_timeOfFirstVisibleContentRectUpdateWithPendingCommit)
+ _timeOfFirstVisibleContentRectUpdateWithPendingCommit = timeNow;
}
- (void)_didStartProvisionalLoadForMainFrame
@@ -3225,7 +3271,8 @@
- (void)_cancelAnimatedResize
{
- LOG_WITH_STREAM(VisibleRects, stream << "-[WKWebView " << _page->pageID() << " _cancelAnimatedResize:] " << " _dynamicViewportUpdateMode " << (int)_dynamicViewportUpdateMode);
+ RELEASE_LOG_IF_ALLOWED("%p (PageID=%llu) -[WKWebView _cancelAnimatedResize] _dynamicViewportUpdateMode %d", self, _page->pageID().toUInt64(), _dynamicViewportUpdateMode);
+
if (_dynamicViewportUpdateMode == WebKit::DynamicViewportUpdateMode::NotResizing)
return;
@@ -3260,6 +3307,8 @@
return;
}
+ RELEASE_LOG_IF_ALLOWED("%p (PageID=%llu) -[WKWebView _didCompleteAnimatedResize]", self, _page->identifier().toUInt64());
+
NSUInteger indexOfResizeAnimationView = [[_scrollView subviews] indexOfObject:_resizeAnimationView.get()];
[_scrollView insertSubview:_contentView.get() atIndex:indexOfResizeAnimationView];
[_scrollView insertSubview:[_contentView unscaledView] atIndex:indexOfResizeAnimationView + 1];
@@ -6137,6 +6186,8 @@
return;
}
+ RELEASE_LOG_IF_ALLOWED("%p (PageID=%llu) -[WKWebView _beginAnimatedResizeWithUpdates:]", self, _page->identifier().toUInt64());
+
_dynamicViewportUpdateMode = WebKit::DynamicViewportUpdateMode::ResizingWithAnimation;
auto oldViewLayoutSize = [self activeViewLayoutSize:self.bounds];
@@ -6249,7 +6300,7 @@
- (void)_endAnimatedResize
{
- LOG_WITH_STREAM(VisibleRects, stream << "-[WKWebView " << _page->pageID() << " _endAnimatedResize:] " << " _dynamicViewportUpdateMode " << (int)_dynamicViewportUpdateMode);
+ RELEASE_LOG_IF_ALLOWED("%p (PageID=%llu) -[WKWebView _endAnimatedResize] _dynamicViewportUpdateMode %d", self, _page->pageID().toUInt64(), _dynamicViewportUpdateMode);
// If we already have an up-to-date layer tree, immediately complete
// the resize. Otherwise, we will defer completion until we do.
@@ -6260,7 +6311,8 @@
- (void)_resizeWhileHidingContentWithUpdates:(void (^)(void))updateBlock
{
- LOG_WITH_STREAM(VisibleRects, stream << "-[WKWebView " << _page->pageID() << " _resizeWhileHidingContentWithUpdates:]");
+ RELEASE_LOG_IF_ALLOWED("%p (PageID=%llu) -[WKWebView _resizeWhileHidingContentWithUpdates:]", self, _page->pageID().toUInt64());
+
[self _beginAnimatedResizeWithUpdates:updateBlock];
if (_dynamicViewportUpdateMode == WebKit::DynamicViewportUpdateMode::ResizingWithAnimation) {
[_contentView setHidden:YES];
Modified: branches/safari-608-branch/Source/WebKit/WebProcess/WebPage/WebPage.cpp (250525 => 250526)
--- branches/safari-608-branch/Source/WebKit/WebProcess/WebPage/WebPage.cpp 2019-09-30 20:16:00 UTC (rev 250525)
+++ branches/safari-608-branch/Source/WebKit/WebProcess/WebPage/WebPage.cpp 2019-09-30 20:27:13 UTC (rev 250526)
@@ -2527,17 +2527,17 @@
void WebPage::freezeLayerTree(LayerTreeFreezeReason reason)
{
- RELEASE_LOG(ProcessSuspension, "%p - WebPage (PageID=%llu) - Adding a reason %d to freeze layer tree; current reasons are %d",
- this, m_pageID.toUInt64(), static_cast<unsigned>(reason), m_layerTreeFreezeReasons.toRaw());
+ auto oldReasons = m_layerTreeFreezeReasons.toRaw();
m_layerTreeFreezeReasons.add(reason);
+ RELEASE_LOG(ProcessSuspension, "%p - WebPage (PageID=%llu) - Adding a reason %d to freeze layer tree (now %d); old reasons were %d", this, pageID().toUInt64(), static_cast<unsigned>(reason), m_layerTreeFreezeReasons.toRaw(), oldReasons);
updateDrawingAreaLayerTreeFreezeState();
}
void WebPage::unfreezeLayerTree(LayerTreeFreezeReason reason)
{
- RELEASE_LOG(ProcessSuspension, "%p - WebPage (PageID=%llu) - Removing a reason %d to freeze layer tree; current reasons are %d",
- this, m_pageID.toUInt64(), static_cast<unsigned>(reason), m_layerTreeFreezeReasons.toRaw());
+ auto oldReasons = m_layerTreeFreezeReasons.toRaw();
m_layerTreeFreezeReasons.remove(reason);
+ RELEASE_LOG(ProcessSuspension, "%p - WebPage (PageID=%llu) - Removing a reason %d to freeze layer tree (now %d); old reasons were %d", this, pageID().toUInt64(), static_cast<unsigned>(reason), m_layerTreeFreezeReasons.toRaw(), oldReasons);
updateDrawingAreaLayerTreeFreezeState();
}
