Add some logging to help diagnose blank or stuck WKWebViews
authortimothy_horton@apple.com <timothy_horton@apple.com@268f45cc-cd09-0410-ab3c-d52691b4dbfc>
Fri, 27 Sep 2019 00:59:37 +0000 (00:59 +0000)
committertimothy_horton@apple.com <timothy_horton@apple.com@268f45cc-cd09-0410-ab3c-d52691b4dbfc>
Fri, 27 Sep 2019 00:59:37 +0000 (00:59 +0000)
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

Source/WebKit/ChangeLog
Source/WebKit/UIProcess/API/Cocoa/WKWebView.mm
Source/WebKit/WebProcess/WebPage/WebPage.cpp

index 5a86862..d5c3159 100644 (file)
@@ -1,3 +1,55 @@
+2019-09-26  Tim Horton  <timothy_horton@apple.com>
+
+        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-26  Dean Jackson  <dino@apple.com>
 
         ContextMenu on a link in an email no longer shows web preview
index b497135..cee3faf 100644 (file)
 #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 @@ static Optional<WebCore::ScrollbarOverlayStyle> toCoreScrollbarStyle(_WKOverlayS
     BOOL _hasCommittedLoadForMainFrame;
     BOOL _needsResetViewStateAfterCommitLoadForMainFrame;
     WebKit::TransactionID _firstPaintAfterCommitLoadTransactionID;
+    WebKit::TransactionID _lastTransactionID;
     WebKit::DynamicViewportUpdateMode _dynamicViewportUpdateMode;
     WebKit::DynamicViewportSizeUpdateID _currentDynamicViewportSizeUpdateID;
     CATransform3D _resizeAnimationTransformAdjustments;
@@ -351,8 +353,10 @@ static Optional<WebCore::ScrollbarOverlayStyle> toCoreScrollbarStyle(_WKOverlayS
     CGFloat _totalScrollViewBottomInsetAdjustmentForKeyboard;
     BOOL _currentlyAdjustingScrollViewInsetsForKeyboard;
 
-    BOOL _delayUpdateVisibleContentRects;
-    BOOL _hadDelayedUpdateVisibleContentRects;
+    BOOL _invokingUIScrollViewDelegateCallback;
+    BOOL _didDeferUpdateVisibleContentRectsForUIScrollViewDelegateCallback;
+    BOOL _didDeferUpdateVisibleContentRectsForAnyReason;
+    BOOL _didDeferUpdateVisibleContentRectsForUnstableScrollView;
 
     BOOL _waitingForEndAnimatedResize;
     BOOL _waitingForCommitAfterAnimatedResize;
@@ -372,6 +376,8 @@ static Optional<WebCore::ScrollbarOverlayStyle> toCoreScrollbarStyle(_WKOverlayS
     MonotonicTime _timeOfRequestForVisibleContentRectUpdate;
     MonotonicTime _timeOfLastVisibleContentRectUpdate;
 
+    Optional<MonotonicTime> _timeOfFirstVisibleContentRectUpdateWithPendingCommit;
+
     NSUInteger _focusPreservationCount;
     NSUInteger _activeFocusedStateRetainCount;
 
@@ -795,8 +801,11 @@ static void validate(WKWebViewConfiguration *configuration)
 #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 @@ static CGSize roundScrollViewContentSize(const WebKit::WebPageProxy& page, CGSiz
 
 - (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 @@ static WebCore::Color scrollViewBackgroundColor(WKWebView *webView)
     _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 @@ static WebCore::Color scrollViewBackgroundColor(WKWebView *webView)
     _firstPaintAfterCommitLoadTransactionID = { };
     _firstTransactionIDAfterPageRestore = WTF::nullopt;
 
+    _lastTransactionID = { };
+
     _hasScheduledVisibleRectUpdate = NO;
     _commitDidRestoreScrollPosition = NO;
 
@@ -2020,10 +2033,24 @@ static inline bool areEssentiallyEqualAsFloat(float a, float b)
 
 - (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->identifier() << " _didCommitLayerTree:] transactionID " <<  layerTreeTransaction.transactionID() << " _dynamicViewportUpdateMode " << (int)_dynamicViewportUpdateMode);
+    LOG_WITH_STREAM(VisibleRects, stream << "-[WKWebView " << _page->identifier() << " _didCommitLayerTree:] transactionID " << layerTreeTransaction.transactionID() << " _dynamicViewportUpdateMode " << (int)_dynamicViewportUpdateMode);
 
     bool needUpdateVisibleContentRects = _page->updateLayoutViewportParameters(layerTreeTransaction);
 
@@ -3115,13 +3142,22 @@ static bool scrollViewCanScroll(UIScrollView *scrollView)
     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 @@ static bool scrollViewCanScroll(UIScrollView *scrollView)
         || (_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 @@ static bool scrollViewCanScroll(UIScrollView *scrollView)
         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 @@ static int32_t activeOrientation(WKWebView *webView)
 
 - (void)_cancelAnimatedResize
 {
-    LOG_WITH_STREAM(VisibleRects, stream << "-[WKWebView " << _page->identifier() << " _cancelAnimatedResize:] " << " _dynamicViewportUpdateMode " << (int)_dynamicViewportUpdateMode);
+    RELEASE_LOG_IF_ALLOWED("%p (PageID=%llu) -[WKWebView _cancelAnimatedResize] _dynamicViewportUpdateMode %d", self, _page->identifier().toUInt64(), _dynamicViewportUpdateMode);
+
     if (_dynamicViewportUpdateMode == WebKit::DynamicViewportUpdateMode::NotResizing)
         return;
 
@@ -3260,6 +3307,8 @@ static int32_t activeOrientation(WKWebView *webView)
         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];
@@ -6163,6 +6212,8 @@ static inline WebKit::FindOptions toFindOptions(_WKFindOptions wkFindOptions)
         return;
     }
 
+    RELEASE_LOG_IF_ALLOWED("%p (PageID=%llu) -[WKWebView _beginAnimatedResizeWithUpdates:]", self, _page->identifier().toUInt64());
+
     _dynamicViewportUpdateMode = WebKit::DynamicViewportUpdateMode::ResizingWithAnimation;
 
     auto oldViewLayoutSize = [self activeViewLayoutSize:self.bounds];
@@ -6275,7 +6326,7 @@ static inline WebKit::FindOptions toFindOptions(_WKFindOptions wkFindOptions)
 
 - (void)_endAnimatedResize
 {
-    LOG_WITH_STREAM(VisibleRects, stream << "-[WKWebView " << _page->identifier() << " _endAnimatedResize:] " << " _dynamicViewportUpdateMode " << (int)_dynamicViewportUpdateMode);
+    RELEASE_LOG_IF_ALLOWED("%p (PageID=%llu) -[WKWebView _endAnimatedResize] _dynamicViewportUpdateMode %d", self, _page->identifier().toUInt64(), _dynamicViewportUpdateMode);
 
     // If we already have an up-to-date layer tree, immediately complete
     // the resize. Otherwise, we will defer completion until we do.
@@ -6286,7 +6337,8 @@ static inline WebKit::FindOptions toFindOptions(_WKFindOptions wkFindOptions)
 
 - (void)_resizeWhileHidingContentWithUpdates:(void (^)(void))updateBlock
 {
-    LOG_WITH_STREAM(VisibleRects, stream << "-[WKWebView " << _page->identifier() << " _resizeWhileHidingContentWithUpdates:]");
+    RELEASE_LOG_IF_ALLOWED("%p (PageID=%llu) -[WKWebView _resizeWhileHidingContentWithUpdates:]", self, _page->identifier().toUInt64());
+
     [self _beginAnimatedResizeWithUpdates:updateBlock];
     if (_dynamicViewportUpdateMode == WebKit::DynamicViewportUpdateMode::ResizingWithAnimation) {
         [_contentView setHidden:YES];
index 9675c2c..881f778 100644 (file)
@@ -2497,17 +2497,17 @@ const WebEvent* WebPage::currentEvent()
 
 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_identifier.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, m_identifier.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_identifier.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, m_identifier.toUInt64(), static_cast<unsigned>(reason), m_layerTreeFreezeReasons.toRaw(), oldReasons);
     updateDrawingAreaLayerTreeFreezeState();
 }