Bug 197888 - The network process tries to take a process assertion when NetworkProcess::processWillSuspendImminently() is called
Summary: The network process tries to take a process assertion when NetworkProcess::pr...
Status: RESOLVED FIXED
Alias: None
Product: WebKit
Classification: Unclassified
Component: WebKit2 (show other bugs)
Version: WebKit Nightly Build
Hardware: Unspecified Unspecified
: P2 Normal
Assignee: Chris Dumez
URL:
Keywords: InRadar
Depends on:
Blocks:
 
Reported: 2019-05-14 11:29 PDT by Chris Dumez
Modified: 2019-05-14 12:35 PDT (History)
6 users (show)

See Also:


Attachments
Patch (2.70 KB, patch)
2019-05-14 11:35 PDT, Chris Dumez
no flags Details | Formatted Diff | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Chris Dumez 2019-05-14 11:29:51 PDT
The network process tries to take a process assertion when NetworkProcess::processWillSuspendImminently() is called:
2019-05-14 10:59:36.691261-0700 0x29035    Error       0x6f0c5              3660   0    MobileSafari: (WebKit) [com.apple.WebKit:ProcessSuspension] Background task expired while holding WebKit ProcessAssertion (isMainThread? 1).
2019-05-14 10:59:36.695504-0700 0x2906d    Default     0x0                  3663   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x15bd10c80 - WebProcess::processWillSuspendImminently()
2019-05-14 10:59:36.729903-0700 0x2906d    Default     0x0                  3663   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] WebProcess 3663 is freezing all layer trees
2019-05-14 10:59:36.729999-0700 0x2906d    Default     0x0                  3663   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x15bd10c80 - WebProcess::destroyRenderingResources() took 0.01ms
2019-05-14 10:59:36.732330-0700 0x2906d    Default     0x0                  3663   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x15bd10c80 - WebProcess::updateFreezerStatus() isFreezable: 0, success
2019-05-14 10:59:36.732431-0700 0x2906d    Default     0x0                  3663   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x15bd10c80 - WebProcess::markAllLayersVolatile()
2019-05-14 10:59:36.732513-0700 0x2906d    Default     0x0                  3663   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x15bd10c80 - WebProcess::markAllLayersVolatile() Successfuly marked all layers as volatile
2019-05-14 10:59:36.734947-0700 0x29060    Default     0x0                  3662   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x109712f40 - WebProcess::processWillSuspendImminently()
2019-05-14 10:59:36.776027-0700 0x29060    Default     0x0                  3662   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] WebProcess 3662 is freezing all layer trees
2019-05-14 10:59:36.776091-0700 0x29060    Default     0x0                  3662   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x109800808 - WebPage (PageID=1) - Adding a reason 4 to freeze layer tree; current reasons are 2
2019-05-14 10:59:36.776163-0700 0x29060    Default     0x0                  3662   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x109712f40 - WebProcess::destroyRenderingResources() took 0.01ms
2019-05-14 10:59:36.778930-0700 0x29060    Default     0x0                  3662   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x109712f40 - WebProcess::updateFreezerStatus() isFreezable: 1, success
2019-05-14 10:59:36.779024-0700 0x29060    Default     0x0                  3662   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x109712f40 - WebProcess::markAllLayersVolatile()
2019-05-14 10:59:36.781429-0700 0x29058    Default     0x0                  3661   0    com.apple.WebKit.Networking: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x1039e47f8 - NetworkProcess::processWillSuspendImminently()
2019-05-14 10:59:36.794408-0700 0x29035    Default     0x6f0c5              3660   0    MobileSafari: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x116b2ac10 - WKProcessAssertionBackgroundTaskManager - endBackgroundTask
2019-05-14 10:59:36.796161-0700 0x29035    Default     0x0                  3660   0    MobileSafari: (WebKit) [com.apple.WebKit:ProcessSuspension] UIProcess is taking a background assertion because the Network process is holding locked files
2019-05-14 10:59:36.797298-0700 0x29058    Default     0x0                  3661   0    com.apple.WebKit.Networking: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x1039e47f8 - NetworkProcess::processDidResume()

This last 2 lines are bad. The UIProcess is being forcibly suspended and is telling its child process via ProcessWillSuspendImminently IPC. The Network process tries to keep itself alive at that point due to locked files, due to activity it does as a result of NetworkProcess::processWillSuspendImminently() getting called.

This should be:
2019-05-14 11:26:24.859087-0700 0x2a612    Error       0x72e96              4056   0    MobileSafari: (WebKit) [com.apple.WebKit:ProcessSuspension] Background task expired while holding WebKit ProcessAssertion (isMainThread? 1).
2019-05-14 11:26:24.861170-0700 0x2a63f    Default     0x0                  4057   0    com.apple.WebKit.Networking: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x1053807f8 - NetworkProcess::processWillSuspendImminently()
2019-05-14 11:26:24.896799-0700 0x2a659    Default     0x0                  4059   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x14de111e0 - WebProcess::processWillSuspendImminently()
2019-05-14 11:26:24.927195-0700 0x2a659    Default     0x0                  4059   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] WebProcess 4059 is freezing all layer trees
2019-05-14 11:26:24.927266-0700 0x2a659    Default     0x0                  4059   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x14de111e0 - WebProcess::destroyRenderingResources() took 0.01ms
2019-05-14 11:26:24.928392-0700 0x2a659    Default     0x0                  4059   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x14de111e0 - WebProcess::updateFreezerStatus() isFreezable: 0, success
2019-05-14 11:26:24.929522-0700 0x2a659    Default     0x0                  4059   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x14de111e0 - WebProcess::markAllLayersVolatile()
2019-05-14 11:26:24.930031-0700 0x2a659    Default     0x0                  4059   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x14de111e0 - WebProcess::markAllLayersVolatile() Successfuly marked all layers as volatile
2019-05-14 11:26:24.931142-0700 0x2a64c    Default     0x0                  4058   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x12bd170f0 - WebProcess::processWillSuspendImminently()
2019-05-14 11:26:24.969973-0700 0x2a64c    Default     0x0                  4058   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] WebProcess 4058 is freezing all layer trees
2019-05-14 11:26:24.970020-0700 0x2a64c    Default     0x0                  4058   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x12c806008 - WebPage (PageID=1) - Adding a reason 4 to freeze layer tree; current reasons are 2
2019-05-14 11:26:24.970588-0700 0x2a64c    Default     0x0                  4058   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x12bd170f0 - WebProcess::destroyRenderingResources() took 0.52ms
2019-05-14 11:26:24.972108-0700 0x2a64c    Default     0x0                  4058   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x12bd170f0 - WebProcess::updateFreezerStatus() isFreezable: 1, success
2019-05-14 11:26:24.972638-0700 0x2a64c    Default     0x0                  4058   0    com.apple.WebKit.WebContent: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x12bd170f0 - WebProcess::markAllLayersVolatile()
2019-05-14 11:26:24.974009-0700 0x2a612    Default     0x72e96              4056   0    MobileSafari: (WebKit) [com.apple.WebKit:ProcessSuspension] 0x1147a8fa0 - WKProcessAssertionBackgroundTaskManager - endBackgroundTask
Comment 1 Chris Dumez 2019-05-14 11:35:44 PDT
Created attachment 369875 [details]
Patch
Comment 2 Geoffrey Garen 2019-05-14 11:46:16 PDT
Comment on attachment 369875 [details]
Patch

r=me
Comment 3 Chris Dumez 2019-05-14 12:27:16 PDT
This is the database activity that's happening as a result of preparing to suspend:
	com.apple.WebKit.Networking	default	12:25:54.299839-0700	5333	0x10154c7f8 - NetworkProcess::processWillSuspendImminently()
	com.apple.WebKit.Networking	default	12:25:54.311009-0700	5333	1   0x101022338 WebKit::WebSQLiteDatabaseTracker::willBeginFirstTransaction()
	com.apple.WebKit.Networking	default	12:25:54.314454-0700	5333	2   0x10596e760 WebCore::SQLiteDatabase::close()
	com.apple.WebKit.Networking	default	12:25:54.317950-0700	5333	3   0x10596e52c WebCore::SQLiteDatabase::~SQLiteDatabase()
	com.apple.WebKit.Networking	default	12:25:54.321923-0700	5333	4   0x105e11f3c WTF::Detail::CallableWrapper<WebCore::RegistrationDatabase::close(WTF::CompletionHandler<void ()>&&)::$_24, void>::call()

So we're closing a registration database.
Comment 4 Chris Dumez 2019-05-14 12:30:00 PDT
(In reply to Chris Dumez from comment #3)
> This is the database activity that's happening as a result of preparing to
> suspend:
> 	com.apple.WebKit.Networking	default	12:25:54.299839-0700	5333	0x10154c7f8 -
> NetworkProcess::processWillSuspendImminently()
> 	com.apple.WebKit.Networking	default	12:25:54.311009-0700	5333	1  
> 0x101022338 WebKit::WebSQLiteDatabaseTracker::willBeginFirstTransaction()
> 	com.apple.WebKit.Networking	default	12:25:54.314454-0700	5333	2  
> 0x10596e760 WebCore::SQLiteDatabase::close()
> 	com.apple.WebKit.Networking	default	12:25:54.317950-0700	5333	3  
> 0x10596e52c WebCore::SQLiteDatabase::~SQLiteDatabase()
> 	com.apple.WebKit.Networking	default	12:25:54.321923-0700	5333	4  
> 0x105e11f3c
> WTF::Detail::CallableWrapper<WebCore::RegistrationDatabase::close(WTF::
> CompletionHandler<void ()>&&)::$_24, void>::call()
> 
> So we're closing a registration database.

Because of this code in actualPrepareToSuspend():
#if ENABLE(SERVICE_WORKER)
    for (auto& server : m_swServers.values())
        server->startSuspension([delayedTaskCounter] { });
#endif

which ends up calling:
void RegistrationStore::startSuspension(WTF::CompletionHandler<void()>&& completionHandler)
{
    m_isSuspended = true;
    m_database->close(WTFMove(completionHandler));
}

And closing our service worker registrations database.
Comment 5 Chris Dumez 2019-05-14 12:32:21 PDT
Comment on attachment 369875 [details]
Patch

Clearing flags on attachment: 369875

Committed r245297: <https://trac.webkit.org/changeset/245297>
Comment 6 Chris Dumez 2019-05-14 12:32:23 PDT
All reviewed patches have been landed.  Closing bug.
Comment 7 Radar WebKit Bug Importer 2019-05-14 12:35:17 PDT
<rdar://problem/50777823>