Bug 192884 - Web Inspector: Confusingly nested events in the timeline for Mutation Observers
Summary: Web Inspector: Confusingly nested events in the timeline for Mutation Observers
Status: REOPENED
Alias: None
Product: WebKit
Classification: Unclassified
Component: Web Inspector (show other bugs)
Version: WebKit Nightly Build
Hardware: Unspecified Unspecified
: P2 Normal
Assignee: Devin Rousso
URL:
Keywords: InRadar
Depends on: 193918
Blocks:
  Show dependency treegraph
 
Reported: 2018-12-19 15:12 PST by Simon Fraser (smfr)
Modified: 2019-01-28 12:15 PST (History)
6 users (show)

See Also:


Attachments
Testcase (1.52 KB, text/html)
2018-12-19 15:13 PST, Simon Fraser (smfr)
no flags Details
Screenshot showing the issue (43.64 KB, image/png)
2018-12-19 15:13 PST, Simon Fraser (smfr)
no flags Details
Patch (3.12 KB, patch)
2019-01-09 12:35 PST, Devin Rousso
no flags Details | Formatted Diff | Diff
[Image] After Patch is applied (1.14 MB, image/png)
2019-01-09 12:37 PST, Devin Rousso
no flags Details
Patch (4.59 KB, patch)
2019-01-22 16:56 PST, Devin Rousso
no flags Details | Formatted Diff | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Simon Fraser (smfr) 2018-12-19 15:12:46 PST
With the fix for bug 192669, MutationObserver callbacks fail to wrap their "script evaluated" record, which makes the event nesting look broken.

This happens because TimelineManager.js makes assumptions about the nesting of TimelineAgent.EventType.ObserverCallback events. MutationObserver callbacks are called inside of performMicrotaskCheckpoint(), but this is nested inside the instrumentation inside ScriptController::evaluateInWorld(), which makes the records look like:


{
    "method": "Timeline.eventRecorded",
    "params": {
        "record": {
            "startTime": 126.1153933230089,
            "data": {},
            "children": [{
                "startTime": 126.13111369599937,
                "frameId": "0.1",
                "data": {},
                "children": [],
                "endTime": 126.13206217900733,
                "type": "RecalculateStyles"
            }, {
                "startTime": 126.15065376498387,
                "frameId": "0.1",
                "data": {},
                "children": [],
                "endTime": 126.15083438300644,
                "type": "RecalculateStyles"
            }, {
                "startTime": 126.1510179519828,
                "data": {},
                "frameId": "0.1",
                "type": "ScheduleStyleRecalculation"
            }, {
                "startTime": 126.15147269400768,
                "frameId": "0.1",
                "data": {
                    "url": "file:///Volumes/Data/Development/media/testcontent/DOM API/callback-types.html",
                    "lineNumber": 11
                },
                "children": [{
                    "startTime": 126.15439619901008,
                    "frameId": "0.1",
                    "data": {
                        "type": "MutationObserver"
                    },
                    "children": [{
                        "startTime": 126.15448315799586,
                        "frameId": "0.1",
                        "data": {
                            "scriptName": "file:///Volumes/Data/Development/media/testcontent/DOM API/callback-types.html",
                            "scriptLine": 28
                        },
                        "children": [],
                        "endTime": 126.17735613300465,
                        "type": "FunctionCall"
                    }],
                    "endTime": 126.17736832599621,
                    "type": "ObserverCallback"
                }],
                "endTime": 126.17738567499327,
                "type": "EvaluateScript"
            }],
            "endTime": 126.17764653699123,
            "type": "RenderingFrame"
        }
    }
}

I think we need to close the "ScriptController::evaluateInWorld" block before we open the block in JSExecState::didLeaveScriptContext().

Stack for MutationObserver callbacks:

  * frame #0: 0x00000003da414918 WebCore`WebCore::MutationObserver::deliver(this=0x00000003f96001e0) at MutationObserver.cpp:249
    frame #1: 0x00000003da415490 WebCore`WebCore::MutationObserver::notifyMutationObservers() at MutationObserver.cpp:301
    frame #2: 0x00000003da41a611 WebCore`WebCore::MutationObserverMicrotask::run(this=0x00000003fba2dbb8) at MutationObserver.cpp:168
    frame #3: 0x00000003da3f9ab3 WebCore`WebCore::MicrotaskQueue::performMicrotaskCheckpoint(this=0x00000003dd623190) at Microtasks.cpp:94
    frame #4: 0x00000003d9ddbe0a WebCore`WebCore::JSExecState::didLeaveScriptContext(exec=0x00000003f74e0048) at JSExecState.cpp:42
    frame #5: 0x00000003d9d90d05 WebCore`WebCore::JSExecState::~JSExecState(this=0x00007ffee6c16e40) at JSExecState.h:145
    frame #6: 0x00000003d9d90b25 WebCore`WebCore::JSExecState::~JSExecState(this=0x00007ffee6c16e40) at JSExecState.h:134
    frame #7: 0x00000003d9e22a35 WebCore`WebCore::JSExecState::profiledEvaluate(exec=0x00000003f74e0048, reason=Other, source=0x00007ffee6c170d0, thisValue=JSValue @ 0x00007ffee6c16e70, returnedException=0x00007ffee6c16ed8) at JSExecState.h:81
    frame #8: 0x00000003d9e22786 WebCore`WebCore::ScriptController::evaluateInWorld(this=0x00000003f67e93c0, sourceCode=0x00007ffee6c170c8, world=0x00000003f67c11a0, exceptionDetails=0x0000000000000000) at ScriptController.cpp:131
    frame #9: 0x00000003d9e22afd WebCore`WebCore::ScriptController::evaluate(this=0x00000003f67e93c0, sourceCode=0x00007ffee6c170c8, exceptionDetails=0x0000000000000000) at ScriptController.cpp:147
    frame #10: 0x00000003da4913e1 WebCore`WebCore::ScriptElement::executeClassicScript(this=0x00000003f95002a0, sourceCode=0x00007ffee6c170c8) at ScriptElement.cpp:387
    frame #11: 0x00000003da48f6f0 WebCore`WebCore::ScriptElement::prepareScript(this=0x00000003f95002a0, scriptStartPosition=0x00007ffee6c173b8, supportLegacyTypes=DisallowLegacyTypeInTypeAttribute) at ScriptElement.cpp:267
    frame #12: 0x00000003da91aef4 WebCore`WebCore::HTMLScriptRunner::runScript(this=0x00000003fbad2cf0, scriptElement=0x00000003f95002a0, scriptStartPosition=0x00007ffee6c173b8) at HTMLScriptRunner.cpp:250
    frame #13: 0x00000003da91ad1f WebCore`WebCore::HTMLScriptRunner::execute(this=0x00000003fbad2cf0, element=0x00007ffee6c173a8, scriptStartPosition=0x00007ffee6c173b8) at HTMLScriptRunner.cpp:140
Comment 1 Simon Fraser (smfr) 2018-12-19 15:13:03 PST
Created attachment 357735 [details]
Testcase
Comment 2 Simon Fraser (smfr) 2018-12-19 15:13:25 PST
Created attachment 357736 [details]
Screenshot showing the issue
Comment 3 Radar WebKit Bug Importer 2018-12-19 15:13:53 PST
<rdar://problem/46854178>
Comment 4 Devin Rousso 2019-01-09 12:35:56 PST
Created attachment 358725 [details]
Patch
Comment 5 Devin Rousso 2019-01-09 12:37:24 PST
Created attachment 358726 [details]
[Image] After Patch is applied

Captured on <https://devinrousso.com/demo/WebKit/192884.html>.
Comment 6 Simon Fraser (smfr) 2019-01-09 13:01:46 PST
I saw some bad nesting for AnimationFrame callbacks too.
Comment 7 Simon Fraser (smfr) 2019-01-09 13:02:39 PST
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 8 Joseph Pecoraro 2019-01-09 13:59:31 PST
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.
Comment 9 Joseph Pecoraro 2019-01-09 14:06:49 PST
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.
Comment 10 Devin Rousso 2019-01-09 14:42:17 PST
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.
Comment 11 Joseph Pecoraro 2019-01-11 14:01:38 PST
> 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).
Comment 12 Devin Rousso 2019-01-22 16:56:08 PST
Created attachment 359810 [details]
Patch
Comment 13 Joseph Pecoraro 2019-01-23 10:43:37 PST
Comment on attachment 359810 [details]
Patch

r=me
Comment 14 WebKit Commit Bot 2019-01-23 11:29:23 PST
Comment on attachment 359810 [details]
Patch

Clearing flags on attachment: 359810

Committed r240351: <https://trac.webkit.org/changeset/240351>
Comment 15 WebKit Commit Bot 2019-01-23 11:29:25 PST
All reviewed patches have been landed.  Closing bug.
Comment 16 WebKit Commit Bot 2019-01-28 12:15:45 PST
Re-opened since this is blocked by bug 193918