Bug 238082 – Add logging about process entering background to NetworkProcess::processDidResume

• Status: RESOLVED
• Resolution: FIXED
• Component: New Bugs

[Sihui Liu]

...

[Sihui Liu]

Created attachment 455112 [details]
Patch

[Sihui Liu]

Created attachment 455114 [details]
Patch

[Sihui Liu]

Created attachment 455118 [details]
Patch

[Sihui Liu]

Created attachment 455121 [details]
Patch

[Sihui Liu]

Created attachment 455124 [details]
Patch

[Chris Dumez]

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.

[Sihui Liu]

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.

[Chris Dumez]

(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.

[Sihui Liu]

Created attachment 455261 [details]
Patch

[Sihui Liu]

Created attachment 455262 [details]
Patch

[Sihui Liu]

Created attachment 455263 [details]
Patch

[Sihui Liu]

Created attachment 455272 [details]
Patch

[Sihui Liu]

Created attachment 455322 [details]
Patch

[Sihui Liu]

Created attachment 455323 [details]
Patch

[Chris Dumez]

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.

[Radar WebKit Bug Importer]

<rdar://problem/90844775>

[Sihui Liu]

Created attachment 455977 [details]
Patch

[EWS]

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].

[Sihui Liu]

Reopening to attach new patch.

[Sihui Liu]

Created attachment 456041 [details]
[fast-cq] Patch for landing

[EWS]

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].