Bug 192884 – Web Inspector: Confusingly nested events in the timeline for Mutation Observers

• Component: Web Inspector
• Status: REOPENED

[Simon Fraser (smfr)]

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

[Simon Fraser (smfr)]

Created attachment 357735 [details]
Testcase

[Simon Fraser (smfr)]

Created attachment 357736 [details]
Screenshot showing the issue

[Radar WebKit Bug Importer]

<rdar://problem/46854178>

[Devin Rousso]

Created attachment 358725 [details]
Patch

[Devin Rousso]

Created attachment 358726 [details]
[Image] After Patch is applied

Captured on <https://devinrousso.com/demo/WebKit/192884.html>.

[Simon Fraser (smfr)]

I saw some bad nesting for AnimationFrame callbacks too.

[Simon Fraser (smfr)]

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++?

[Joseph Pecoraro]

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.

[Joseph Pecoraro]

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.

[Devin Rousso]

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.

[Joseph Pecoraro]

> 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).

[Devin Rousso]

Created attachment 359810 [details]
Patch

[Joseph Pecoraro]

Comment on attachment 359810 [details]
Patch

r=me

[WebKit Commit Bot]

Comment on attachment 359810 [details]
Patch

Clearing flags on attachment: 359810

Committed r240351: <https://trac.webkit.org/changeset/240351>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.

[WebKit Commit Bot]

Re-opened since this is blocked by bug 193918