Bug 238082

Summary: Add logging about process entering background to NetworkProcess::processDidResume
Product: WebKit Reporter: Sihui Liu <sihui_liu>
Component: New BugsAssignee: Sihui Liu <sihui_liu>
Status: RESOLVED FIXED    
Severity: Normal CC: cdumez, ews-watchlist, pascoe, webkit-bug-importer
Priority: P2 Keywords: InRadar
Version: WebKit Nightly Build   
Hardware: Unspecified   
OS: Unspecified   
Attachments:
Description Flags
Patch
ews-feeder: commit-queue-
Patch
ews-feeder: commit-queue-
Patch
ews-feeder: commit-queue-
Patch
ews-feeder: commit-queue-
Patch
none
Patch
none
Patch
ews-feeder: commit-queue-
Patch
none
Patch
none
Patch
ews-feeder: commit-queue-
Patch
none
Patch
none
[fast-cq] Patch for landing none

Description Sihui Liu 2022-03-18 10:31:31 PDT
...
Comment 1 Sihui Liu 2022-03-18 11:07:09 PDT
Created attachment 455112 [details]
Patch
Comment 2 Sihui Liu 2022-03-18 11:12:06 PDT
Created attachment 455114 [details]
Patch
Comment 3 Sihui Liu 2022-03-18 11:46:30 PDT
Created attachment 455118 [details]
Patch
Comment 4 Sihui Liu 2022-03-18 11:55:01 PDT
Created attachment 455121 [details]
Patch
Comment 5 Sihui Liu 2022-03-18 12:09:10 PDT
Created attachment 455124 [details]
Patch
Comment 6 Chris Dumez 2022-03-18 15:53:01 PDT
Comment on attachment 455124 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=455124&action=review

> Source/WebKit/ChangeLog:9
> +        For network porcess, processDidResume means process is not suspended and it is safe to perform database 

typo: porcess

> Source/WebKit/NetworkProcess/NetworkProcess.cpp:2117
> +    RELEASE_LOG(ProcessSuspension, "%p - NetworkProcess::prepareToSuspend(), isSuspensionImminent=%d Process is %s in background", this, isSuspensionImminent, m_enterBackgroundTimestamp ? "" : "not");

There is going to be a extra space between "is" and "in": "Process is  in background"

> Source/WebKit/NetworkProcess/NetworkProcess.cpp:2151
> +    m_enterBackgroundTimestamp = WallTime::now();

We want to be using MonotonicTime, not WallTime. If the timezone changes (or daylight savings) while suspended for e.g., you'd get unexpected results.

> Source/WebKit/NetworkProcess/NetworkProcess.cpp:2168
> +        auto interval = WallTime::now() - m_enterBackgroundTimestamp.value();

MonotonicTime

> Source/WebKit/NetworkProcess/NetworkProcess.cpp:2169
> +        RELEASE_LOG_ERROR(ProcessSuspension, "%p - NetworkProcess::processDidResume() Process is in background for %f ms", this, interval.value());

How is that an error?

Also, I have a feeling interval.value() is seconds and the logging claims it is milliseconds?

> Source/WebKit/UIProcess/API/Cocoa/WKWebViewTesting.mm:216
> +        _page->process().sendProcessDidResume(true);

This is the reason we use enum classes for parameters and not booleans, the reader has no idea what true means here.

> Source/WebKit/UIProcess/ios/ProcessAssertionIOS.mm:97
> +        WebKit::WebsiteDataStore::forEachWebsiteDataStore([] (WebKit::WebsiteDataStore& dataStore) {

Seems like a layer violation to be using WebsiteDataStore inside ProcessAssertionIOS.mm (as a ProcessAssertion could theoretically be taken in any process).
Odds are we want to set a new listener inside NetworkProcessCocoa.mm instead.

> Source/WebKit/UIProcess/ios/ProcessAssertionIOS.mm:99
> +                networkProcess->applicationWillEnterForeground();

Looks like this will send duplicate IPCs if several data stores share the same network process (which is always the case on Cocoa)_

> Source/WebKit/UIProcess/ios/ProcessAssertionIOS.mm:109
> +                networkProcess->applicationDidEnterBackground();

ditto.
Comment 7 Sihui Liu 2022-03-18 16:37:21 PDT
Comment on attachment 455124 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=455124&action=review

>> Source/WebKit/ChangeLog:9
>> +        For network porcess, processDidResume means process is not suspended and it is safe to perform database 
> 
> typo: porcess

Will change.

>> Source/WebKit/NetworkProcess/NetworkProcess.cpp:2117
>> +    RELEASE_LOG(ProcessSuspension, "%p - NetworkProcess::prepareToSuspend(), isSuspensionImminent=%d Process is %s in background", this, isSuspensionImminent, m_enterBackgroundTimestamp ? "" : "not");
> 
> There is going to be a extra space between "is" and "in": "Process is  in background"

oh, will move to a space to "not"

>> Source/WebKit/NetworkProcess/NetworkProcess.cpp:2151
>> +    m_enterBackgroundTimestamp = WallTime::now();
> 
> We want to be using MonotonicTime, not WallTime. If the timezone changes (or daylight savings) while suspended for e.g., you'd get unexpected results.

Sure.

>> Source/WebKit/NetworkProcess/NetworkProcess.cpp:2168
>> +        auto interval = WallTime::now() - m_enterBackgroundTimestamp.value();
> 
> MonotonicTime

Sure.

>> Source/WebKit/NetworkProcess/NetworkProcess.cpp:2169
>> +        RELEASE_LOG_ERROR(ProcessSuspension, "%p - NetworkProcess::processDidResume() Process is in background for %f ms", this, interval.value());
> 
> How is that an error?
> 
> Also, I have a feeling interval.value() is seconds and the logging claims it is milliseconds?

Yes, should be milliseconds() not value().

>> Source/WebKit/UIProcess/API/Cocoa/WKWebViewTesting.mm:216
>> +        _page->process().sendProcessDidResume(true);
> 
> This is the reason we use enum classes for parameters and not booleans, the reader has no idea what true means here.

Okay will change to enum.

>> Source/WebKit/UIProcess/ios/ProcessAssertionIOS.mm:97
>> +        WebKit::WebsiteDataStore::forEachWebsiteDataStore([] (WebKit::WebsiteDataStore& dataStore) {
> 
> Seems like a layer violation to be using WebsiteDataStore inside ProcessAssertionIOS.mm (as a ProcessAssertion could theoretically be taken in any process).
> Odds are we want to set a new listener inside NetworkProcessCocoa.mm instead.

I will try adding to NetworkProcessCocoa.mm and see if it works

>> Source/WebKit/UIProcess/ios/ProcessAssertionIOS.mm:99
>> +                networkProcess->applicationWillEnterForeground();
> 
> Looks like this will send duplicate IPCs if several data stores share the same network process (which is always the case on Cocoa)_

If network process can receive the notification, we don't need the message I guess.
Comment 8 Chris Dumez 2022-03-18 16:41:26 PDT
(In reply to Sihui Liu from comment #7)
> Comment on attachment 455124 [details]
> Patch
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=455124&action=review
> 
> >> Source/WebKit/ChangeLog:9
> >> +        For network porcess, processDidResume means process is not suspended and it is safe to perform database 
> > 
> > typo: porcess
> 
> Will change.
> 
> >> Source/WebKit/NetworkProcess/NetworkProcess.cpp:2117
> >> +    RELEASE_LOG(ProcessSuspension, "%p - NetworkProcess::prepareToSuspend(), isSuspensionImminent=%d Process is %s in background", this, isSuspensionImminent, m_enterBackgroundTimestamp ? "" : "not");
> > 
> > There is going to be a extra space between "is" and "in": "Process is  in background"
> 
> oh, will move to a space to "not"
> 
> >> Source/WebKit/NetworkProcess/NetworkProcess.cpp:2151
> >> +    m_enterBackgroundTimestamp = WallTime::now();
> > 
> > We want to be using MonotonicTime, not WallTime. If the timezone changes (or daylight savings) while suspended for e.g., you'd get unexpected results.
> 
> Sure.
> 
> >> Source/WebKit/NetworkProcess/NetworkProcess.cpp:2168
> >> +        auto interval = WallTime::now() - m_enterBackgroundTimestamp.value();
> > 
> > MonotonicTime
> 
> Sure.
> 
> >> Source/WebKit/NetworkProcess/NetworkProcess.cpp:2169
> >> +        RELEASE_LOG_ERROR(ProcessSuspension, "%p - NetworkProcess::processDidResume() Process is in background for %f ms", this, interval.value());
> > 
> > How is that an error?
> > 
> > Also, I have a feeling interval.value() is seconds and the logging claims it is milliseconds?
> 
> Yes, should be milliseconds() not value().
> 
> >> Source/WebKit/UIProcess/API/Cocoa/WKWebViewTesting.mm:216
> >> +        _page->process().sendProcessDidResume(true);
> > 
> > This is the reason we use enum classes for parameters and not booleans, the reader has no idea what true means here.
> 
> Okay will change to enum.
> 
> >> Source/WebKit/UIProcess/ios/ProcessAssertionIOS.mm:97
> >> +        WebKit::WebsiteDataStore::forEachWebsiteDataStore([] (WebKit::WebsiteDataStore& dataStore) {
> > 
> > Seems like a layer violation to be using WebsiteDataStore inside ProcessAssertionIOS.mm (as a ProcessAssertion could theoretically be taken in any process).
> > Odds are we want to set a new listener inside NetworkProcessCocoa.mm instead.
> 
> I will try adding to NetworkProcessCocoa.mm and see if it works
> 
> >> Source/WebKit/UIProcess/ios/ProcessAssertionIOS.mm:99
> >> +                networkProcess->applicationWillEnterForeground();
> > 
> > Looks like this will send duplicate IPCs if several data stores share the same network process (which is always the case on Cocoa)_
> 
> If network process can receive the notification, we don't need the message I
> guess.

Sorry, I meant NetworkProcessProxyCocoa.mm, in the UIProcess. I don't think the NetworkProcess will be able to listener for this.
Comment 9 Sihui Liu 2022-03-21 12:05:50 PDT
Created attachment 455261 [details]
Patch
Comment 10 Sihui Liu 2022-03-21 12:06:41 PDT
Created attachment 455262 [details]
Patch
Comment 11 Sihui Liu 2022-03-21 12:20:08 PDT
Created attachment 455263 [details]
Patch
Comment 12 Sihui Liu 2022-03-21 13:49:16 PDT
Created attachment 455272 [details]
Patch
Comment 13 Sihui Liu 2022-03-21 20:26:17 PDT
Created attachment 455322 [details]
Patch
Comment 14 Sihui Liu 2022-03-21 20:37:31 PDT
Created attachment 455323 [details]
Patch
Comment 15 Chris Dumez 2022-03-23 15:56:50 PDT
Comment on attachment 455323 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=455323&action=review

r=me with changes.

> Source/WebKit/ChangeLog:8
> +        In rdar://82412733, we found network process can be suspended right after it receives processDidResume message. 

Sure, RunningBoard can suspend us at any point once we're no longer visible. If something takes a process assertion (causing the processDidResume IPC to get sent) and then the 30 second timeout in the background hits shortly after. We may or may not get notified by Runningboard that our assertion has expired before forced suspension and if we do get notified, we may or may not have time to send the ProcessDidSuspend IPC (or the child process may or may not have time to process it). This is a know issue.

This is why we should do our best not to wake up new processes while backgrounded (technically while the RunningBoard timer has started, which is slightly different).

> Source/WebKit/ChangeLog:9
> +        For network porcess, processDidResume means process is not suspended and it is safe to perform database 

typo: porcess.

> Source/WebKit/NetworkProcess/NetworkProcess.cpp:2132
> +    RELEASE_LOG(ProcessSuspension, "%p - NetworkProcess::prepareToSuspend(), isSuspensionImminent=%d Process is %sin background", this, isSuspensionImminent, m_enterBackgroundTimestamp ? "" : "not ");

%{public}s

> Source/WebKit/NetworkProcess/NetworkProcess.cpp:2179
> +    String backgroundIntervalString = "";

emptyString()

> Source/WebKit/NetworkProcess/NetworkProcess.cpp:2181
> +        backgroundIntervalString = makeString(" Process is in background for ", (MonotonicTime::now() - m_enterBackgroundTimestamp.value()).value(), " seconds");

is -> has been

> Source/WebKit/NetworkProcess/NetworkProcess.cpp:2182
> +    RELEASE_LOG(ProcessSuspension, "%p - NetworkProcess::processDidResume() forForegroundActivity=%d%s", this, forForegroundActivity, backgroundIntervalString.utf8().data());

This %s won't print on public builds. We could use %{public}s but I would just suggest using branching:
if (m_enterBackgroundTimestamp)
    RELEASE_LOG(...)
else
    RELEASE_LOG(...)

> Source/WebKit/UIProcess/Network/NetworkProcessProxy.h:239
> +    void sendProcessDidResume(ResumeReason = ResumeReason::ForegroundActivity) final;

Can we avoid having a default parameter on a virtual function?
Seems also error prone to not force the caller to specify it.

> Source/WebKit/UIProcess/Network/NetworkProcessProxy.h:305
> +    void applicationDidEnterBackground();

Can these be private?

> Source/WebKit/UIProcess/Network/NetworkProcessProxy.h:308
> +    void addBackgroundStateObservers();

Can these be private?

> Source/WebKit/UIProcess/Network/NetworkProcessProxyCocoa.mm:101
> +            return;

nit: Early returns for one liners seem overly verbose.

> Source/WebKit/UIProcess/Network/NetworkProcessProxyCocoa.mm:106
> +            return;

ditto.

> Source/WebKit/UIProcess/ProcessThrottlerClient.h:41
> +    virtual void sendProcessDidResume(ResumeReason = ForegroundActivity) = 0;

Ideally we wouldn't have a default parameter value.
Comment 16 Radar WebKit Bug Importer 2022-03-25 10:32:15 PDT
<rdar://problem/90844775>
Comment 17 Sihui Liu 2022-03-28 18:27:15 PDT
Created attachment 455977 [details]
Patch
Comment 18 EWS 2022-03-28 22:56:07 PDT
Committed r292024 (248967@main): <https://commits.webkit.org/248967@main>

All reviewed patches have been landed. Closing bug and clearing flags on attachment 455977 [details].
Comment 19 Sihui Liu 2022-03-29 10:33:12 PDT
Reopening to attach new patch.
Comment 20 Sihui Liu 2022-03-29 10:33:14 PDT
Created attachment 456041 [details]
[fast-cq] Patch for landing
Comment 21 EWS 2022-03-29 11:34:48 PDT
Committed r292051 (248988@main): <https://commits.webkit.org/248988@main>

All reviewed patches have been landed. Closing bug and clearing flags on attachment 456041 [details].