Skip to content
Permalink
Browse files
Add some more UIProcess-side logging related to process assertions
https://bugs.webkit.org/show_bug.cgi?id=159188

Reviewed by Andreas Kling.

Add some more UIProcess-side logging related to process assertions
to help debug process suspension issues.

* UIProcess/Network/NetworkProcessProxy.cpp:
(WebKit::NetworkProcessProxy::fetchWebsiteData):
(WebKit::NetworkProcessProxy::deleteWebsiteData):
(WebKit::NetworkProcessProxy::deleteWebsiteDataForOrigins):
* UIProcess/ProcessThrottler.cpp:
(WebKit::ProcessThrottler::updateAssertionNow):
(WebKit::ProcessThrottler::updateAssertion):
* UIProcess/WebPageProxy.cpp:
(WebKit::WebPageProxy::updateActivityToken):
* UIProcess/WebProcessProxy.cpp:
(WebKit::WebProcessProxy::fetchWebsiteData):
(WebKit::WebProcessProxy::deleteWebsiteData):
(WebKit::WebProcessProxy::deleteWebsiteDataForOrigins):
(WebKit::WebProcessProxy::didSetAssertionState):


Canonical link: https://commits.webkit.org/177322@main
git-svn-id: https://svn.webkit.org/repository/webkit/trunk@202575 268f45cc-cd09-0410-ab3c-d52691b4dbfc
  • Loading branch information
cdumez committed Jun 28, 2016
1 parent 674dfde commit 9b06c678253605bb8f70cda459a60d41fe06ccdb
@@ -1,3 +1,28 @@
2016-06-28 Chris Dumez <cdumez@apple.com>

Add some more UIProcess-side logging related to process assertions
https://bugs.webkit.org/show_bug.cgi?id=159188

Reviewed by Andreas Kling.

Add some more UIProcess-side logging related to process assertions
to help debug process suspension issues.

* UIProcess/Network/NetworkProcessProxy.cpp:
(WebKit::NetworkProcessProxy::fetchWebsiteData):
(WebKit::NetworkProcessProxy::deleteWebsiteData):
(WebKit::NetworkProcessProxy::deleteWebsiteDataForOrigins):
* UIProcess/ProcessThrottler.cpp:
(WebKit::ProcessThrottler::updateAssertionNow):
(WebKit::ProcessThrottler::updateAssertion):
* UIProcess/WebPageProxy.cpp:
(WebKit::WebPageProxy::updateActivityToken):
* UIProcess/WebProcessProxy.cpp:
(WebKit::WebProcessProxy::fetchWebsiteData):
(WebKit::WebProcessProxy::deleteWebsiteData):
(WebKit::WebProcessProxy::deleteWebsiteDataForOrigins):
(WebKit::WebProcessProxy::didSetAssertionState):

2016-06-28 Chris Dumez <cdumez@apple.com>

[WK2] Do not suppress navigation snapshotting on session restore if we are not navigating right away
@@ -126,11 +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");
LOG_ALWAYS(sessionID.isAlwaysOnLoggingAllowed(), "%p - NetworkProcessProxy is taking a background assertion because the Network process is fetching Website data", this);

m_pendingFetchWebsiteDataCallbacks.add(callbackID, [token, completionHandler, sessionID](WebsiteData websiteData) {
m_pendingFetchWebsiteDataCallbacks.add(callbackID, [this, 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");
LOG_ALWAYS(sessionID.isAlwaysOnLoggingAllowed(), "%p - NetworkProcessProxy is releasing a background assertion because the Network process is done fetching Website data", this);
});

send(Messages::NetworkProcess::FetchWebsiteData(sessionID, dataTypes, fetchOptions, callbackID), 0);
@@ -140,11 +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");
LOG_ALWAYS(sessionID.isAlwaysOnLoggingAllowed(), "%p - NetworkProcessProxy is taking a background assertion because the Network process is deleting Website data", this);

m_pendingDeleteWebsiteDataCallbacks.add(callbackID, [token, completionHandler, sessionID] {
m_pendingDeleteWebsiteDataCallbacks.add(callbackID, [this, token, completionHandler, sessionID] {
completionHandler();
LOG_ALWAYS(sessionID.isAlwaysOnLoggingAllowed(), "UIProcess is releasing a background assertion because the Network process is done deleting Website data");
LOG_ALWAYS(sessionID.isAlwaysOnLoggingAllowed(), "%p - NetworkProcessProxy is releasing a background assertion because the Network process is done deleting Website data", this);
});
send(Messages::NetworkProcess::DeleteWebsiteData(sessionID, dataTypes, modifiedSince, callbackID), 0);
}
@@ -155,11 +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");
LOG_ALWAYS(sessionID.isAlwaysOnLoggingAllowed(), "%p - NetworkProcessProxy is taking a background assertion because the Network process is deleting Website data for several origins", this);

m_pendingDeleteWebsiteDataForOriginsCallbacks.add(callbackID, [token, completionHandler, sessionID] {
m_pendingDeleteWebsiteDataForOriginsCallbacks.add(callbackID, [this, 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");
LOG_ALWAYS(sessionID.isAlwaysOnLoggingAllowed(), "%p - NetworkProcessProxy is releasing a background assertion because the Network process is done deleting Website data for several origins", this);
});

Vector<SecurityOriginData> originData;
@@ -56,6 +56,8 @@ void ProcessThrottler::updateAssertionNow()
{
m_suspendTimer.stop();
if (m_assertion) {
if (m_assertion->state() != assertionState())
LOG_ALWAYS(true, "%p - ProcessThrottler::updateAssertionNow() updating process assertion state to %u (foregroundActivities: %lu, backgroundActivities: %lu)", this, assertionState(), m_foregroundCounter.value(), m_backgroundCounter.value());
m_assertion->setState(assertionState());
m_process.didSetAssertionState(assertionState());
}
@@ -68,13 +70,14 @@ void ProcessThrottler::updateAssertion()
// in the background for too long.
if (m_assertion && m_assertion->state() != AssertionState::Suspended && !m_foregroundCounter.value() && !m_backgroundCounter.value()) {
++m_suspendMessageCount;
LOG_ALWAYS(true, "%p - ProcessThrottler::updateAssertion() sending PrepareToSuspend IPC", this);
m_process.sendPrepareToSuspend();
m_suspendTimer.startOneShot(processSuspensionTimeout);
m_assertion->setState(AssertionState::Background);
m_process.didSetAssertionState(AssertionState::Background);
return;
}

bool shouldBeRunnable = m_foregroundCounter.value() || m_backgroundCounter.value();

// If we're currently waiting for the Web process to do suspension cleanup, but no longer need to be suspended, tell the Web process to cancel the cleanup.
@@ -1507,13 +1507,15 @@ void WebPageProxy::updateActivityToken()

#if PLATFORM(IOS)
if (!isViewVisible() && !m_alwaysRunsAtForegroundPriority) {
WEBPAGEPROXY_LOG_ALWAYS("UIProcess is releasing a foreground assertion because the view is no longer visible");
m_activityToken = nullptr;
if (m_activityToken) {
WEBPAGEPROXY_LOG_ALWAYS("%p - UIProcess is releasing a foreground assertion because the view is no longer visible", this);
m_activityToken = nullptr;
}
} else if (!m_activityToken) {
if (isViewVisible())
WEBPAGEPROXY_LOG_ALWAYS("UIProcess is taking a foreground assertion because the view is visible");
WEBPAGEPROXY_LOG_ALWAYS("%p - UIProcess is taking a foreground assertion because the view is visible", this);
else
WEBPAGEPROXY_LOG_ALWAYS("UIProcess is taking a foreground assertion even though the view is not visible because m_alwaysRunsAtForegroundPriority is true");
WEBPAGEPROXY_LOG_ALWAYS("%p - UIProcess is taking a foreground assertion even though the view is not visible because m_alwaysRunsAtForegroundPriority is true", this);
m_activityToken = m_process->throttler().foregroundActivityToken();
}
#endif
@@ -727,9 +727,11 @@ void WebProcessProxy::fetchWebsiteData(SessionID sessionID, OptionSet<WebsiteDat

uint64_t callbackID = generateCallbackID();
auto token = throttler().backgroundActivityToken();
LOG_ALWAYS(sessionID.isAlwaysOnLoggingAllowed(), "%p - WebProcessProxy is taking a background assertion because the Web process is fetching Website data", this);

m_pendingFetchWebsiteDataCallbacks.add(callbackID, [token, completionHandler](WebsiteData websiteData) {
m_pendingFetchWebsiteDataCallbacks.add(callbackID, [this, token, completionHandler, sessionID](WebsiteData websiteData) {
completionHandler(WTFMove(websiteData));
LOG_ALWAYS(sessionID.isAlwaysOnLoggingAllowed(), "%p - WebProcessProxy is releasing a background assertion because the Web process is done fetching Website data", this);
});

send(Messages::WebProcess::FetchWebsiteData(sessionID, dataTypes, callbackID), 0);
@@ -741,9 +743,11 @@ void WebProcessProxy::deleteWebsiteData(SessionID sessionID, OptionSet<WebsiteDa

uint64_t callbackID = generateCallbackID();
auto token = throttler().backgroundActivityToken();
LOG_ALWAYS(sessionID.isAlwaysOnLoggingAllowed(), "%p - WebProcessProxy is taking a background assertion because the Web process is deleting Website data", this);

m_pendingDeleteWebsiteDataCallbacks.add(callbackID, [token, completionHandler] {
m_pendingDeleteWebsiteDataCallbacks.add(callbackID, [this, token, completionHandler, sessionID] {
completionHandler();
LOG_ALWAYS(sessionID.isAlwaysOnLoggingAllowed(), "%p - WebProcessProxy is releasing a background assertion because the Web process is done deleting Website data", this);
});
send(Messages::WebProcess::DeleteWebsiteData(sessionID, dataTypes, modifiedSince, callbackID), 0);
}
@@ -754,9 +758,11 @@ void WebProcessProxy::deleteWebsiteDataForOrigins(SessionID sessionID, OptionSet

uint64_t callbackID = generateCallbackID();
auto token = throttler().backgroundActivityToken();
LOG_ALWAYS(sessionID.isAlwaysOnLoggingAllowed(), "%p - WebProcessProxy is taking a background assertion because the Web process is deleting Website data for several origins", this);

m_pendingDeleteWebsiteDataForOriginsCallbacks.add(callbackID, [token, completionHandler] {
m_pendingDeleteWebsiteDataForOriginsCallbacks.add(callbackID, [this, token, completionHandler, sessionID] {
completionHandler();
LOG_ALWAYS(sessionID.isAlwaysOnLoggingAllowed(), "%p - WebProcessProxy is releasing a background assertion because the Web process is done deleting Website data for several origins", this);
});

Vector<SecurityOriginData> originData;
@@ -959,18 +965,21 @@ void WebProcessProxy::didSetAssertionState(AssertionState state)

switch (state) {
case AssertionState::Suspended:
LOG_ALWAYS(true, "%p - WebProcessProxy::didSetAssertionState(Suspended) release all assertions for network process", this);
m_foregroundTokenForNetworkProcess = nullptr;
m_backgroundTokenForNetworkProcess = nullptr;
for (auto& page : m_pageMap.values())
page->processWillBecomeSuspended();
break;

case AssertionState::Background:
LOG_ALWAYS(true, "%p - WebProcessProxy::didSetAssertionState(Background) taking background assertion for network process", this);
m_backgroundTokenForNetworkProcess = processPool().ensureNetworkProcess().throttler().backgroundActivityToken();
m_foregroundTokenForNetworkProcess = nullptr;
break;

case AssertionState::Foreground:
LOG_ALWAYS(true, "%p - WebProcessProxy::didSetAssertionState(Foreground) taking foreground assertion for network process", this);
m_foregroundTokenForNetworkProcess = processPool().ensureNetworkProcess().throttler().foregroundActivityToken();
m_backgroundTokenForNetworkProcess = nullptr;
for (auto& page : m_pageMap.values())

0 comments on commit 9b06c67

Please sign in to comment.