Add logging related to process assertions to help debug process suspe…

…nsion issues

https://bugs.webkit.org/show_bug.cgi?id=159001

Reviewed by Antti Koivisto.

Add logging related to process assertions to help debug process suspension issues.

* UIProcess/Cocoa/NavigationState.mm:
(WebKit::NavigationState::didChangeIsLoading):
* UIProcess/Network/NetworkProcessProxy.cpp:
(WebKit::NetworkProcessProxy::fetchWebsiteData):
(WebKit::NetworkProcessProxy::deleteWebsiteData):
(WebKit::NetworkProcessProxy::deleteWebsiteDataForOrigins):
(WebKit::NetworkProcessProxy::setIsHoldingLockedFiles):
* UIProcess/WebPageProxy.cpp:
(WebKit::WebPageProxy::updateActivityToken):
* UIProcess/WebProcessProxy.cpp:
(WebKit::WebProcessProxy::setIsHoldingLockedFiles):

Canonical link: https://commits.webkit.org/177098@main
git-svn-id: https://svn.webkit.org/repository/webkit/trunk@202331 268f45cc-cd09-0410-ab3c-d52691b4dbfc

Source/WebKit2/ChangeLog

@@ -1,3 +1,24 @@
+2016-06-22  Chris Dumez  <cdumez@apple.com>
+
+        Add logging related to process assertions to help debug process suspension issues
+        https://bugs.webkit.org/show_bug.cgi?id=159001
+
+        Reviewed by Antti Koivisto.
+
+        Add logging related to process assertions to help debug process suspension issues.
+
+        * UIProcess/Cocoa/NavigationState.mm:
+        (WebKit::NavigationState::didChangeIsLoading):
+        * UIProcess/Network/NetworkProcessProxy.cpp:
+        (WebKit::NetworkProcessProxy::fetchWebsiteData):
+        (WebKit::NetworkProcessProxy::deleteWebsiteData):
+        (WebKit::NetworkProcessProxy::deleteWebsiteDataForOrigins):
+        (WebKit::NetworkProcessProxy::setIsHoldingLockedFiles):
+        * UIProcess/WebPageProxy.cpp:
+        (WebKit::WebPageProxy::updateActivityToken):
+        * UIProcess/WebProcessProxy.cpp:
+        (WebKit::WebProcessProxy::setIsHoldingLockedFiles):
+
 2016-06-21  Sam Weinig  <sam@webkit.org>
 
         WKWebView with no WKNavigationDelegate does not follow universal links

Source/WebKit2/UIProcess/Cocoa/NavigationState.mm

@@ -821,10 +821,13 @@ static void tryAppLink(RefPtr<API::NavigationAction> navigationAction, const Str
 void NavigationState::didChangeIsLoading()
 {
 #if PLATFORM(IOS)
-    if (m_webView->_page->pageLoadState().isLoading())
+    if (m_webView->_page->pageLoadState().isLoading()) {
+        LOG_ALWAYS(m_webView->_page->isAlwaysOnLoggingAllowed(), "UIProcess is taking a background assertion because a page load started");
         m_activityToken = m_webView->_page->process().throttler().backgroundActivityToken();
-    else
+    } else {
+        LOG_ALWAYS(m_webView->_page->isAlwaysOnLoggingAllowed(), "UIProcess is releasing a background assertion because a page load completed");
         m_activityToken = nullptr;
+    }
 #endif
 
     [m_webView didChangeValueForKey:@"loading"];

Source/WebKit2/UIProcess/Network/NetworkProcessProxy.cpp

@@ -126,9 +126,11 @@ void NetworkProcessProxy::fetchWebsiteData(SessionID sessionID, OptionSet<Websit
 
     uint64_t callbackID = generateCallbackID();
     auto token = throttler().backgroundActivityToken();
+    LOG_ALWAYS(sessionID.isAlwaysOnLoggingAllowed(), "UIProcess is taking a background assertion because the Network process is fetching Website data");
 
-    m_pendingFetchWebsiteDataCallbacks.add(callbackID, [token, completionHandler](WebsiteData websiteData) {
+    m_pendingFetchWebsiteDataCallbacks.add(callbackID, [token, completionHandler, sessionID](WebsiteData websiteData) {
         completionHandler(WTFMove(websiteData));
+        LOG_ALWAYS(sessionID.isAlwaysOnLoggingAllowed(), "UIProcess is releasing a background assertion because the Network process is done fetching Website data");
     });
 
     send(Messages::NetworkProcess::FetchWebsiteData(sessionID, dataTypes, fetchOptions, callbackID), 0);
@@ -138,9 +140,11 @@ void NetworkProcessProxy::deleteWebsiteData(WebCore::SessionID sessionID, Option
 {
     auto callbackID = generateCallbackID();
     auto token = throttler().backgroundActivityToken();
+    LOG_ALWAYS(sessionID.isAlwaysOnLoggingAllowed(), "UIProcess is taking a background assertion because the Network process is deleting Website data");
 
-    m_pendingDeleteWebsiteDataCallbacks.add(callbackID, [token, completionHandler] {
+    m_pendingDeleteWebsiteDataCallbacks.add(callbackID, [token, completionHandler, sessionID] {
         completionHandler();
+        LOG_ALWAYS(sessionID.isAlwaysOnLoggingAllowed(), "UIProcess is releasing a background assertion because the Network process is done deleting Website data");
     });
     send(Messages::NetworkProcess::DeleteWebsiteData(sessionID, dataTypes, modifiedSince, callbackID), 0);
 }
@@ -151,9 +155,11 @@ void NetworkProcessProxy::deleteWebsiteDataForOrigins(SessionID sessionID, Optio
 
     uint64_t callbackID = generateCallbackID();
     auto token = throttler().backgroundActivityToken();
+    LOG_ALWAYS(sessionID.isAlwaysOnLoggingAllowed(), "UIProcess is taking a background assertion because the Network process is deleting Website data for several origins");
 
-    m_pendingDeleteWebsiteDataForOriginsCallbacks.add(callbackID, [token, completionHandler] {
+    m_pendingDeleteWebsiteDataForOriginsCallbacks.add(callbackID, [token, completionHandler, sessionID] {
         completionHandler();
+        LOG_ALWAYS(sessionID.isAlwaysOnLoggingAllowed(), "UIProcess is releasing a background assertion because the Network process is done deleting Website data for several origins");
     });
 
     Vector<SecurityOriginData> originData;
@@ -383,11 +389,14 @@ void NetworkProcessProxy::didSetAssertionState(AssertionState)
 void NetworkProcessProxy::setIsHoldingLockedFiles(bool isHoldingLockedFiles)
 {
     if (!isHoldingLockedFiles) {
+        LOG_ALWAYS(true, "UIProcess is releasing a background assertion because the Network process is no longer holding locked files");
         m_tokenForHoldingLockedFiles = nullptr;
         return;
     }
-    if (!m_tokenForHoldingLockedFiles)
+    if (!m_tokenForHoldingLockedFiles) {
+        LOG_ALWAYS(true, "UIProcess is taking a background assertion because the Network process is holding locked files");
         m_tokenForHoldingLockedFiles = m_throttler.backgroundActivityToken();
+    }
 }
 
 } // namespace WebKit

Source/WebKit2/UIProcess/WebPageProxy.cpp

@@ -180,6 +180,8 @@
 #define MESSAGE_CHECK(assertion) MESSAGE_CHECK_BASE(assertion, m_process->connection())
 #define MESSAGE_CHECK_URL(url) MESSAGE_CHECK_BASE(m_process->checkURLReceivedFromWebProcess(url), m_process->connection())
 
+#define WEBPAGEPROXY_LOG_ALWAYS(...) LOG_ALWAYS(isAlwaysOnLoggingAllowed(), __VA_ARGS__)
+
 using namespace WebCore;
 
 // Represents the number of wheel events we can hold in the queue before we start pushing them preemptively.
@@ -1485,6 +1487,11 @@ void WebPageProxy::dispatchViewStateChange()
     m_viewWasEverInWindow |= isNowInWindow;
 }
 
+bool WebPageProxy::isAlwaysOnLoggingAllowed() const
+{
+    return sessionID().isAlwaysOnLoggingAllowed();
+}
+
 void WebPageProxy::updateActivityToken()
 {
     if (m_viewState & ViewState::IsVisuallyIdle)
@@ -1493,10 +1500,16 @@ void WebPageProxy::updateActivityToken()
         m_pageIsUserObservableCount = m_process->processPool().userObservablePageCount();
 
 #if PLATFORM(IOS)
-    if (!isViewVisible() && !m_alwaysRunsAtForegroundPriority)
+    if (!isViewVisible() && !m_alwaysRunsAtForegroundPriority) {
+        WEBPAGEPROXY_LOG_ALWAYS("UIProcess is releasing a foreground assertion because the view is no longer visible");
         m_activityToken = nullptr;
-    else if (!m_activityToken)
+    } else if (!m_activityToken) {
+        if (isViewVisible())
+            WEBPAGEPROXY_LOG_ALWAYS("UIProcess is taking a foreground assertion because the view is visible");
+        else
+            WEBPAGEPROXY_LOG_ALWAYS("UIProcess is taking a foreground assertion even though the view is not visible because m_alwaysRunsAtForegroundPriority is true");
         m_activityToken = m_process->throttler().foregroundActivityToken();
+    }
 #endif
 }
 

Source/WebKit2/UIProcess/WebPageProxy.h

@@ -1116,6 +1116,8 @@ class WebPageProxy : public API::ObjectImpl<API::Object::Type::Page>
 
     bool hasHadSelectionChangesFromUserInteraction() const { return m_hasHadSelectionChangesFromUserInteraction; }
 
+    bool isAlwaysOnLoggingAllowed() const;
+
 private:
     WebPageProxy(PageClient&, WebProcessProxy&, uint64_t pageID, Ref<API::PageConfiguration>&&);
     void platformInitialize();

Source/WebKit2/UIProcess/WebProcessProxy.cpp

@@ -987,11 +987,14 @@ void WebProcessProxy::didSetAssertionState(AssertionState state)
 void WebProcessProxy::setIsHoldingLockedFiles(bool isHoldingLockedFiles)
 {
     if (!isHoldingLockedFiles) {
+        LOG_ALWAYS(true, "UIProcess is releasing a background assertion because the WebContent process is no longer holding locked files");
         m_tokenForHoldingLockedFiles = nullptr;
         return;
     }
-    if (!m_tokenForHoldingLockedFiles)
+    if (!m_tokenForHoldingLockedFiles) {
+        LOG_ALWAYS(true, "UIProcess is taking a background assertion because the WebContent process is holding locked files");
         m_tokenForHoldingLockedFiles = m_throttler.backgroundActivityToken();
+    }
 }
 
 void WebProcessProxy::isResponsive(std::function<void(bool isWebProcessResponsive)> callback)