Bug 228797 – Add more logging for process assertion in network process

• Component: WebKit Misc.
• Status: RESOLVED INVALID

[Sihui Liu]

...

[Sihui Liu]

Created attachment 434932 [details]
Patch

[Sihui Liu]

Created attachment 434934 [details]
Patch

[Sihui Liu]

Created attachment 434937 [details]
Patch

[Sihui Liu]

Created attachment 434943 [details]
Patch

[Chris Dumez]

Comment on attachment 434943 [details]
Patch

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

> Source/WebKit/ChangeLog:10
> +        information from UI process to network process and log it.

What's the purpose? The UIProcess is already doing the logging for these, why do we need the network process to do the exact same logging again?

[Sihui Liu]

(In reply to Chris Dumez from comment #5)
> Comment on attachment 434943 [details]
> Patch
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=434943&action=review
> 
> > Source/WebKit/ChangeLog:10
> > +        information from UI process to network process and log it.
> 
> What's the purpose? The UIProcess is already doing the logging for these,
> why do we need the network process to do the exact same logging again?

The UI process logging does not show up in the network process crash log.
From recent crash logs, we know network process sometimes suspends soon after processDidResume.

Or do you have any idea of what should be logged in this case (to figure out why network process is suspended after processDidResume)?

[Chris Dumez]

(In reply to Sihui Liu from comment #6)
> (In reply to Chris Dumez from comment #5)
> > Comment on attachment 434943 [details]
> > Patch
> > 
> > View in context:
> > https://bugs.webkit.org/attachment.cgi?id=434943&action=review
> > 
> > > Source/WebKit/ChangeLog:10
> > > +        information from UI process to network process and log it.
> > 
> > What's the purpose? The UIProcess is already doing the logging for these,
> > why do we need the network process to do the exact same logging again?
> 
> The UI process logging does not show up in the network process crash log.
> From recent crash logs, we know network process sometimes suspends soon
> after processDidResume.
> 
> Or do you have any idea of what should be logged in this case (to figure out
> why network process is suspended after processDidResume)?

Why does it matter what assertion the UIProcess is holding? The NetworkProcess should be holding its own assertion if holding locked files (and thus not suspend).

[Sihui Liu]

(In reply to Chris Dumez from comment #7)
> (In reply to Sihui Liu from comment #6)
> > (In reply to Chris Dumez from comment #5)
> > > Comment on attachment 434943 [details]
> > > Patch
> > > 
> > > View in context:
> > > https://bugs.webkit.org/attachment.cgi?id=434943&action=review
> > > 
> > > > Source/WebKit/ChangeLog:10
> > > > +        information from UI process to network process and log it.
> > > 
> > > What's the purpose? The UIProcess is already doing the logging for these,
> > > why do we need the network process to do the exact same logging again?
> > 
> > The UI process logging does not show up in the network process crash log.
> > From recent crash logs, we know network process sometimes suspends soon
> > after processDidResume.
> > 
> > Or do you have any idea of what should be logged in this case (to figure out
> > why network process is suspended after processDidResume)?
> 
> Why does it matter what assertion the UIProcess is holding? The
> NetworkProcess should be holding its own assertion if holding locked files
> (and thus not suspend).

In some crash, network process assertion is acquired after processDidResume, and process is still suspended. Something like:

com.apple.WebKit.Networking[440] (WebKit): 0x1da2db5c0 - NetworkProcess::processDidResume()
com.apple.WebKit.Networking[440] (RunningBoardServices): Acquiring assertion: <RBSAssertionDescriptor| "Network Process is holding locked files" ID:(null) target:440>
com.apple.WebKit.Networking[440] (WebKit): 0x104618318 - ProcessAssertion: Successfully took RBS assertion 'Network Process is holding locked files' for process with PID=440

[Chris Dumez]

(In reply to Sihui Liu from comment #8)
> (In reply to Chris Dumez from comment #7)
> > (In reply to Sihui Liu from comment #6)
> > > (In reply to Chris Dumez from comment #5)
> > > > Comment on attachment 434943 [details]
> > > > Patch
> > > > 
> > > > View in context:
> > > > https://bugs.webkit.org/attachment.cgi?id=434943&action=review
> > > > 
> > > > > Source/WebKit/ChangeLog:10
> > > > > +        information from UI process to network process and log it.
> > > > 
> > > > What's the purpose? The UIProcess is already doing the logging for these,
> > > > why do we need the network process to do the exact same logging again?
> > > 
> > > The UI process logging does not show up in the network process crash log.
> > > From recent crash logs, we know network process sometimes suspends soon
> > > after processDidResume.
> > > 
> > > Or do you have any idea of what should be logged in this case (to figure out
> > > why network process is suspended after processDidResume)?
> > 
> > Why does it matter what assertion the UIProcess is holding? The
> > NetworkProcess should be holding its own assertion if holding locked files
> > (and thus not suspend).
> 
> In some crash, network process assertion is acquired after processDidResume,
> and process is still suspended. Something like:
> 
> com.apple.WebKit.Networking[440] (WebKit): 0x1da2db5c0 -
> NetworkProcess::processDidResume()
> com.apple.WebKit.Networking[440] (RunningBoardServices): Acquiring
> assertion: <RBSAssertionDescriptor| "Network Process is holding locked
> files" ID:(null) target:440>
> com.apple.WebKit.Networking[440] (WebKit): 0x104618318 - ProcessAssertion:
> Successfully took RBS assertion 'Network Process is holding locked files'
> for process with PID=440

Yes, this is likely to happen if:
1. Someone take a background assertion for the network process (from the UIProcess) after the app has been in the background for a while (e.g. ~29 seconds)
2. The UIProcess then tells the network process to resume
3. But RunningBoard expires the assertion almost right away (and may or may not have time to tell us, or we may or may not have time to notify the child process) because we were so close to the 30s timer when we took the assertion.

[Chris Dumez]

(In reply to Chris Dumez from comment #9)
> (In reply to Sihui Liu from comment #8)
> > (In reply to Chris Dumez from comment #7)
> > > (In reply to Sihui Liu from comment #6)
> > > > (In reply to Chris Dumez from comment #5)
> > > > > Comment on attachment 434943 [details]
> > > > > Patch
> > > > > 
> > > > > View in context:
> > > > > https://bugs.webkit.org/attachment.cgi?id=434943&action=review
> > > > > 
> > > > > > Source/WebKit/ChangeLog:10
> > > > > > +        information from UI process to network process and log it.
> > > > > 
> > > > > What's the purpose? The UIProcess is already doing the logging for these,
> > > > > why do we need the network process to do the exact same logging again?
> > > > 
> > > > The UI process logging does not show up in the network process crash log.
> > > > From recent crash logs, we know network process sometimes suspends soon
> > > > after processDidResume.
> > > > 
> > > > Or do you have any idea of what should be logged in this case (to figure out
> > > > why network process is suspended after processDidResume)?
> > > 
> > > Why does it matter what assertion the UIProcess is holding? The
> > > NetworkProcess should be holding its own assertion if holding locked files
> > > (and thus not suspend).
> > 
> > In some crash, network process assertion is acquired after processDidResume,
> > and process is still suspended. Something like:
> > 
> > com.apple.WebKit.Networking[440] (WebKit): 0x1da2db5c0 -
> > NetworkProcess::processDidResume()
> > com.apple.WebKit.Networking[440] (RunningBoardServices): Acquiring
> > assertion: <RBSAssertionDescriptor| "Network Process is holding locked
> > files" ID:(null) target:440>
> > com.apple.WebKit.Networking[440] (WebKit): 0x104618318 - ProcessAssertion:
> > Successfully took RBS assertion 'Network Process is holding locked files'
> > for process with PID=440
> 
> Yes, this is likely to happen if:
> 1. Someone take a background assertion for the network process (from the
> UIProcess) after the app has been in the background for a while (e.g. ~29
> seconds)
> 2. The UIProcess then tells the network process to resume
> 3. But RunningBoard expires the assertion almost right away (and may or may
> not have time to tell us, or we may or may not have time to notify the child
> process) because we were so close to the 30s timer when we took the
> assertion.

FYI, this tells us how much time is left on the RunningBoard timer:
`auto remainingTime = [RBSProcessHandle currentProcess].activeLimitations.runTime;` 

and may return RBSProcessTimeLimitationNone if there is no timer (i.e. app is foreground or allowed to run indefinitely in the background, e.g. due to media playback).

[Sihui Liu]

(In reply to Chris Dumez from comment #10)
> (In reply to Chris Dumez from comment #9)
> > (In reply to Sihui Liu from comment #8)
> > > (In reply to Chris Dumez from comment #7)
> > > > (In reply to Sihui Liu from comment #6)
> > > > > (In reply to Chris Dumez from comment #5)
> > > > > > Comment on attachment 434943 [details]
> > > > > > Patch
> > > > > > 
> > > > > > View in context:
> > > > > > https://bugs.webkit.org/attachment.cgi?id=434943&action=review
> > > > > > 
> > > > > > > Source/WebKit/ChangeLog:10
> > > > > > > +        information from UI process to network process and log it.
> > > > > > 
> > > > > > What's the purpose? The UIProcess is already doing the logging for these,
> > > > > > why do we need the network process to do the exact same logging again?
> > > > > 
> > > > > The UI process logging does not show up in the network process crash log.
> > > > > From recent crash logs, we know network process sometimes suspends soon
> > > > > after processDidResume.
> > > > > 
> > > > > Or do you have any idea of what should be logged in this case (to figure out
> > > > > why network process is suspended after processDidResume)?
> > > > 
> > > > Why does it matter what assertion the UIProcess is holding? The
> > > > NetworkProcess should be holding its own assertion if holding locked files
> > > > (and thus not suspend).
> > > 
> > > In some crash, network process assertion is acquired after processDidResume,
> > > and process is still suspended. Something like:
> > > 
> > > com.apple.WebKit.Networking[440] (WebKit): 0x1da2db5c0 -
> > > NetworkProcess::processDidResume()
> > > com.apple.WebKit.Networking[440] (RunningBoardServices): Acquiring
> > > assertion: <RBSAssertionDescriptor| "Network Process is holding locked
> > > files" ID:(null) target:440>
> > > com.apple.WebKit.Networking[440] (WebKit): 0x104618318 - ProcessAssertion:
> > > Successfully took RBS assertion 'Network Process is holding locked files'
> > > for process with PID=440
> > 
> > Yes, this is likely to happen if:
> > 1. Someone take a background assertion for the network process (from the
> > UIProcess) after the app has been in the background for a while (e.g. ~29
> > seconds)
> > 2. The UIProcess then tells the network process to resume
> > 3. But RunningBoard expires the assertion almost right away (and may or may
> > not have time to tell us, or we may or may not have time to notify the child
> > process) because we were so close to the 30s timer when we took the
> > assertion.
> 
> FYI, this tells us how much time is left on the RunningBoard timer:
> `auto remainingTime = [RBSProcessHandle
> currentProcess].activeLimitations.runTime;` 
> 
> and may return RBSProcessTimeLimitationNone if there is no timer (i.e. app
> is foreground or allowed to run indefinitely in the background, e.g. due to
> media playback).

I see. I didn't know new assertion can be acquired in UI process when it's close to timeout. I guess we can add timing information in the logging of processDidResume to check how often that happens and causes crashes.

[Sihui Liu]

Created attachment 435027 [details]
Patch

[Radar WebKit Bug Importer]

<rdar://problem/81812331>