Bug 228797 - Add more logging for process assertion in network process
Summary: Add more logging for process assertion in network process
Status: RESOLVED INVALID
Alias: None
Product: WebKit
Classification: Unclassified
Component: WebKit Misc. (show other bugs)
Version: WebKit Nightly Build
Hardware: Unspecified Unspecified
: P2 Normal
Assignee: Sihui Liu
URL:
Keywords: InRadar
Depends on:
Blocks:
 
Reported: 2021-08-04 14:02 PDT by Sihui Liu
Modified: 2022-05-24 13:17 PDT (History)
3 users (show)

See Also:


Attachments
Patch (18.05 KB, patch)
2021-08-04 14:09 PDT, Sihui Liu
ews-feeder: commit-queue-
Details | Formatted Diff | Diff
Patch (18.19 KB, patch)
2021-08-04 14:25 PDT, Sihui Liu
ews-feeder: commit-queue-
Details | Formatted Diff | Diff
Patch (18.32 KB, patch)
2021-08-04 14:30 PDT, Sihui Liu
ews-feeder: commit-queue-
Details | Formatted Diff | Diff
Patch (18.33 KB, patch)
2021-08-04 15:31 PDT, Sihui Liu
no flags Details | Formatted Diff | Diff
Patch (3.67 KB, text/plain)
2021-08-05 14:55 PDT, Sihui Liu
ews-feeder: commit-queue-
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Sihui Liu 2021-08-04 14:02:29 PDT
...
Comment 1 Sihui Liu 2021-08-04 14:09:01 PDT
Created attachment 434932 [details]
Patch
Comment 2 Sihui Liu 2021-08-04 14:25:01 PDT
Created attachment 434934 [details]
Patch
Comment 3 Sihui Liu 2021-08-04 14:30:49 PDT
Created attachment 434937 [details]
Patch
Comment 4 Sihui Liu 2021-08-04 15:31:19 PDT
Created attachment 434943 [details]
Patch
Comment 5 Chris Dumez 2021-08-05 09:39:10 PDT
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?
Comment 6 Sihui Liu 2021-08-05 10:06:32 PDT
(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)?
Comment 7 Chris Dumez 2021-08-05 10:21:08 PDT
(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).
Comment 8 Sihui Liu 2021-08-05 10:33:13 PDT
(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
Comment 9 Chris Dumez 2021-08-05 10:47:27 PDT
(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.
Comment 10 Chris Dumez 2021-08-05 10:49:08 PDT
(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).
Comment 11 Sihui Liu 2021-08-05 13:14:17 PDT
(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.
Comment 12 Sihui Liu 2021-08-05 14:55:19 PDT
Created attachment 435027 [details]
Patch
Comment 13 Radar WebKit Bug Importer 2021-08-11 14:03:17 PDT
<rdar://problem/81812331>