| Summary: | Add more logging for process assertion in network process | ||||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| Product: | WebKit | Reporter: | Sihui Liu <sihui_liu> | ||||||||||||
| Component: | WebKit Misc. | Assignee: | Sihui Liu <sihui_liu> | ||||||||||||
| Status: | RESOLVED INVALID | ||||||||||||||
| Severity: | Normal | CC: | cdumez, ggaren, webkit-bug-importer | ||||||||||||
| Priority: | P2 | Keywords: | InRadar | ||||||||||||
| Version: | WebKit Nightly Build | ||||||||||||||
| Hardware: | Unspecified | ||||||||||||||
| OS: | Unspecified | ||||||||||||||
| Attachments: |
|
||||||||||||||
|
Description
Sihui Liu
2021-08-04 14:02:29 PDT
Created attachment 434932 [details]
Patch
Created attachment 434934 [details]
Patch
Created attachment 434937 [details]
Patch
Created attachment 434943 [details]
Patch
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? (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)? (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 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 (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. (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). (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. Created attachment 435027 [details]
Patch
|