| Summary: | Web Inspector: Confusingly nested events in the timeline for Mutation Observers | ||||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| Product: | WebKit | Reporter: | Simon Fraser (smfr) <simon.fraser> | ||||||||||||
| Component: | Web Inspector | Assignee: | Devin Rousso <hi> | ||||||||||||
| Status: | REOPENED --- | ||||||||||||||
| Severity: | Normal | CC: | commit-queue, hi, inspector-bugzilla-changes, joepeck, simon.fraser, webkit-bug-importer | ||||||||||||
| Priority: | P2 | Keywords: | InRadar | ||||||||||||
| Version: | WebKit Nightly Build | ||||||||||||||
| Hardware: | Unspecified | ||||||||||||||
| OS: | Unspecified | ||||||||||||||
| Bug Depends on: | 193918 | ||||||||||||||
| Bug Blocks: | |||||||||||||||
| Attachments: |
|
||||||||||||||
|
Description
Simon Fraser (smfr)
2018-12-19 15:12:46 PST
Created attachment 357735 [details]
Testcase
Created attachment 357736 [details]
Screenshot showing the issue
Created attachment 358725 [details]
Patch
Created attachment 358726 [details] [Image] After Patch is applied Captured on <https://devinrousso.com/demo/WebKit/192884.html>. I saw some bad nesting for AnimationFrame callbacks too. Comment on attachment 358725 [details] Patch View in context: https://bugs.webkit.org/attachment.cgi?id=358725&action=review > Source/WebInspectorUI/UserInterface/Controllers/TimelineManager.js:359 > + function fixMicrotaskPlacement(children) Can we instead fix the inspector instrumentation in the C++? Comment on attachment 358725 [details] Patch View in context: https://bugs.webkit.org/attachment.cgi?id=358725&action=review >> Source/WebInspectorUI/UserInterface/Controllers/TimelineManager.js:359 >> + function fixMicrotaskPlacement(children) > > Can we instead fix the inspector instrumentation in the C++? I agree with Simon. If this is the placement of events we want for display we should make the backend produce them appropriately. In fact we already have this problem with Microtasks. We detected it then and filed a bug. Here we are basically getting close to solving it, but only for observers. We should further solve the problem for microtasks and do so in the backend: // If there are more script profile records in the same time interval, add them // as individual script evaluated records with profiles. This can happen with // web microtask checkpoints that are technically inside of other web records. // FIXME: <https://webkit.org/b/152903> Web Inspector: Timeline Cleanup: Better Timeline Record for Microtask Checkpoints while (profilerRecord && recordEnclosesRecord(webRecord, profilerRecord)) { this._addRecord(profilerRecord); profilerRecord = nextScriptProfilerRecord(); } Basically there are two backends that provide data for the Scripts timeline. The generic "Timeline" domain (higher level web events like <script>, timer firing, event dispatch, ...) and ScriptProfiler domain (the most basic low level JS VM entry/exit, script, microtask, or API). The frontend merges these to produce the records seen. Also the samples taken by the sampling profiler will be put in the most appropriate bucket. For a case like this: <script> sleep(5); Promise.resolve().then(function m1() { sleep(2); }) Promise.resolve().then(function m2() { sleep(2); }) </script> We get Timeline / ScriptProfiler events like (or so I recall): Timeline Events: | [----------------- Evaluate Script -----------------] ScriptProfiler Events: | [----- Script ------] [-- Micro --] [-- Micro --] Samples: | * * * * * * * * * * * The existing FIXME/fixup in code says "hey, we got multiple ScriptProfiler events inside a single Timeline event, lets push our own records through to the UI". And in practice that ends up being entirely Microtask checkpoints and in other cases (mainly Observers!) it would be Script Evaluated. This looks fine but the top "Evaluate Script" still has the incorrect duration (it includes the microtasks which are broken out into their own record!!). An ideal world might look like this: Timeline Events: | [- Evaluate Script -][- Microtask -][- Microtask -] ScriptProfiler Events: | [---- Script -----] [-- Micro --] [-- Micro --] Samples: | * * * * * * * * * * * In this case everything would have its own duration and would be correct. --------------- So we've recently updated the backend for observers. In the case of a MutationObserver, which happens during a microtask checkpoint we get: Timeline Events: | [ ---------------- EvaluateScript ---------------- ] | [ --- Observer --- ] ScriptProfiler Events: | [----- Script ------] [-- Micro --] Samples: | * * * * * * * * Which you are mutating in the frontend to something like: Timeline Events: | [ --- EvaluateScript --- ] [ --- Observer --- ] ScriptProfiler Events: | [----- Script ------] [-- Micro --] Samples: | * * * * * * * * Maybe we should just do this in the backend, to fix both the Observer and Microtask cases? Or maybe we should continue to think about this some more. FWIW this is entirely because of a decision I made a long time ago to display Microtasks as their own block separate from (and not nested) inside of the general script evaluation. I think that is more useful to developers. FWIW, I generally try to fix issues in the frontend if possible so we have better backwards compatibility, but I get that MutationObserver is new so that's not really a concern here. Whether or not we should make the change in the backend boils down to one question in my mind: "are microtasks actually part of EvaluateScript (e.g. this is how it's defined in a spec somewhere), or do they only appear as part of one due to how we've implemented them in WebKit". If they are a part, then I think we should keep the backend as is and manipulate the data on the frontend (this protects us from a future footgun if we want to be more "accurate" instead of more friendly to the developer in how we organize the data). If the latter, we should decide how we want to organize this once and for all and change it everywhere to reflect that (probably both frontend and backend). Either way, I completely agree that we should show microtasks as separate records (e.g. on their own line) because that's what I'd expect to see as a developer. With that having been said, if it does turn out to be spec'd somewhere, I could also see a toggle where we'd nest microtasks underneath the associated EvaluateScript for literal accuracy. > Either way, I completely agree that we should show microtasks as separate > records (e.g. on their own line) because that's what I'd expect to see as a > developer. With that having been said, if it does turn out to be spec'd > somewhere, I could also see a toggle where we'd nest microtasks underneath > the associated EvaluateScript for literal accuracy. In that case can we do the same kind of `endTime` adjustment you are doing in your patch to this code: // FIXME: <https://webkit.org/b/152903> Web Inspector: Timeline Cleanup: Better Timeline Record for Microtask Checkpoints while (profilerRecord && recordEnclosesRecord(webRecord, profilerRecord)) { this._addRecord(profilerRecord); profilerRecord = nextScriptProfilerRecord(); } So that we actually reduce the time of the webRecord such that it doesn't double count the script profiler records? Something like: let didAdjustWebRecord = false; while (profilerRecord && recordEnclosesRecord(webRecord, profilerRecord)) { if (!didAdjustWebRecord) { webRecord.endTime = ...; didAdjustWebRecord = true; } this._addRecord(profilerRecord); profilerRecord = nextScriptProfilerRecord(); } That should fix the Promise example above. Then also include the FIXME bugzilla bug comment to your code. --- I'm fine with a frontend fix for this, as long as we've identified all the places it can happen and make them consistent. Because ultimately we are seeing the same kind of problem in both of these places (at least that is my understanding). Created attachment 359810 [details]
Patch
Comment on attachment 359810 [details]
Patch
r=me
Comment on attachment 359810 [details] Patch Clearing flags on attachment: 359810 Committed r240351: <https://trac.webkit.org/changeset/240351> All reviewed patches have been landed. Closing bug. Re-opened since this is blocked by bug 193918 |