Bug 197888

Summary:

The network process tries to take a process assertion when NetworkProcess::processWillSuspendImminently() is called

Product:

WebKit

Reporter:

Chris Dumez <cdumez>

Component:

WebKit2

Assignee:

Chris Dumez <cdumez>

Status:

RESOLVED FIXED

Severity:

Normal

CC:

achristensen, beidson, commit-queue, ggaren, sihui_liu, webkit-bug-importer

Priority:

Keywords:

InRadar

Version:

WebKit Nightly Build

Hardware:

Unspecified

OS:

Unspecified

Attachments:

Description	Flags
Patch	none

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>