Heads Up on Changes to INP Measurement When Interfered with JS Modal Dialogs

zuoaoyuan commented 3 months ago

With landing of EventTimingFallbackToModalDialogStart, event timing now will treat JS modal dialog showing time as an alternative end point of INP or event duration measurement.

It has following impact on WebVitals.js v4:

Events will have a short duration (when interfered with JS modal dialogs), which is good
The Event Timing processing is still large (this is a weirdness in event timing itself)

So now we can have a situation like: INP: 100ms, input delay: 20ms, processing: 10000ms, presentationDelay: 0ms This doesn't break web-vitals.js which is good, and it's also technically the truth:)

However, that huge event timing processing is also used to get a LoAF attribution, and it can be something that users will find surprising if it comes from field data, and we might want to signal it somehow. (Loaf ::Script will have a pauseDuration for dialogs, which could be one strategy to mitigate this)

mmocny commented 3 months ago

Steps to reproduce:

Open a page (e.g. the INP Demo page)

Using JS console:

Add an event handler that fires an alert, with less priority than the registered events on the page already:
```
document.documentElement.addEventListener('click', () => alert("hi"));
```

Add web-vitals.js v4 + attribution logging:

const { onLCP, onINP, onCLS } = await import('https://unpkg.com/web-vitals/attribution?module');
onINP((metric) => {
console.log('web-vitals.js', metric.value, metric);
}, { reportAllChanges: true });

Then interact with the page.

This results in the following:

First, you see a small jank which comes from the INP demo page itself (setInterval, pointerdown/up blocking events etc)
Then you see an alert popup, after that delay

The reported INP will show something like (specific numbers will vary):

{
    "name": "INP",
    "value": 376,
    "rating": "needs-improvement",
    "delta": 104,
    "entries": [
        {
            "name": "pointerdown",
            "entryType": "event",
            "startTime": 13763.100000023842,
            "duration": 376,
            "navigationId": "204030c4-b7ac-4c2c-a31d-5d15ef400627",
            "interactionId": 7303,
            "processingStart": 13820,
            "processingEnd": 13935.100000023842,
            "cancelable": true
        }
    ],
    "id": "v4-1717772209807-2007043867067",
    "navigationType": "back-forward",
    "attribution": {
        "interactionTarget": "#textarea",
        "interactionTargetElement": {},
        "interactionType": "pointer",
        "interactionTime": 13763.100000023842,
        "nextPaintTime": 16142.899999976158,
        "processedEventEntries": [
            {
                "name": "pointerdown",
                "entryType": "event",
                "startTime": 13763.100000023842,
                "duration": 376,
                "navigationId": "204030c4-b7ac-4c2c-a31d-5d15ef400627",
                "interactionId": 7303,
                "processingStart": 13820,
                "processingEnd": 13935.100000023842,
                "cancelable": true
            },
            {
                "name": "mousedown",
                "entryType": "event",
                "startTime": 13763.100000023842,
                "duration": 376,
                "navigationId": "204030c4-b7ac-4c2c-a31d-5d15ef400627",
                "interactionId": 0,
                "processingStart": 13935.100000023842,
                "processingEnd": 13935.100000023842,
                "cancelable": true
            },
            {
                "name": "pointerup",
                "entryType": "event",
                "startTime": 13769.199999928474,
                "duration": 368,
                "navigationId": "204030c4-b7ac-4c2c-a31d-5d15ef400627",
                "interactionId": 7303,
                "processingStart": 13936.299999952316,
                "processingEnd": 14136.299999952316,
                "cancelable": true
            },
            {
                "name": "mouseup",
                "entryType": "event",
                "startTime": 13769.199999928474,
                "duration": 368,
                "navigationId": "204030c4-b7ac-4c2c-a31d-5d15ef400627",
                "interactionId": 0,
                "processingStart": 14136.299999952316,
                "processingEnd": 14136.299999952316,
                "cancelable": true
            },
            {
                "name": "click",
                "entryType": "event",
                "startTime": 13769.199999928474,
                "duration": 368,
                "navigationId": "204030c4-b7ac-4c2c-a31d-5d15ef400627",
                "interactionId": 7303,
                "processingStart": 14136.299999952316,
                "processingEnd": 16142,
                "cancelable": true
            }
        ],
        "longAnimationFrameEntries": [
            {
                "name": "long-animation-frame",
                "entryType": "long-animation-frame",
                "startTime": 13745.899999976158,
                "duration": 2397,
                "navigationId": "204030c4-b7ac-4c2c-a31d-5d15ef400627",
                "renderStart": 16142.100000023842,
                "styleAndLayoutStart": 16142.299999952316,
                "firstUIEventTimestamp": 13763.100000023842,
                "blockingDuration": 2289,
                "scripts": [
                    {
                        "name": "script",
                        "entryType": "script",
                        "startTime": 13754.100000023842,
                        "duration": 65,
                        "navigationId": "204030c4-b7ac-4c2c-a31d-5d15ef400627",
                        "invoker": "TimerHandler:setTimeout",
                        "invokerType": "user-callback",
                        "windowAttribution": "self",
                        "executionStart": 13754.100000023842,
                        "forcedStyleAndLayoutDuration": 0,
                        "pauseDuration": 0,
                        "sourceURL": "https://inp-demo.glitch.me/main.js",
                        "sourceFunctionName": "periodicBlock",
                        "sourceCharPosition": 1410
                    },
                    {
                        "name": "script",
                        "entryType": "script",
                        "startTime": 13820,
                        "duration": 114,
                        "navigationId": "204030c4-b7ac-4c2c-a31d-5d15ef400627",
                        "invoker": "DOMWindow.onpointerdown",
                        "invokerType": "event-listener",
                        "windowAttribution": "self",
                        "executionStart": 13820,
                        "forcedStyleAndLayoutDuration": 0,
                        "pauseDuration": 0,
                        "sourceURL": "https://inp-demo.glitch.me/main.js",
                        "sourceFunctionName": "",
                        "sourceCharPosition": 4059
                    },
                    {
                        "name": "script",
                        "entryType": "script",
                        "startTime": 13936.299999952316,
                        "duration": 200,
                        "navigationId": "204030c4-b7ac-4c2c-a31d-5d15ef400627",
                        "invoker": "DOMWindow.onpointerup",
                        "invokerType": "event-listener",
                        "windowAttribution": "self",
                        "executionStart": 13936.299999952316,
                        "forcedStyleAndLayoutDuration": 0,
                        "pauseDuration": 0,
                        "sourceURL": "https://inp-demo.glitch.me/main.js",
                        "sourceFunctionName": "",
                        "sourceCharPosition": 4059
                    },
                    {
                        "name": "script",
                        "entryType": "script",
                        "startTime": 14136.699999928474,
                        "duration": 2005,
                        "navigationId": "204030c4-b7ac-4c2c-a31d-5d15ef400627",
                        "invoker": "HTML.onclick",
                        "invokerType": "event-listener",
                        "windowAttribution": "self",
                        "executionStart": 14136.699999928474,
                        "forcedStyleAndLayoutDuration": 0,
                        "pauseDuration": 0,
                        "sourceURL": "",
                        "sourceFunctionName": "",
                        "sourceCharPosition": -1
                    }
                ]
            }
        ],
        "inputDelay": 56.89999997615814,
        "processingDuration": 2322,
        "presentationDelay": 0.8999999761581421,
        "loadState": "complete"
    }
}

The value of 376 here represent the time it took to show the dialog-- which in this case did have observable UX delays. It does not include the time the dialog was opened.

However, the attribution data represents the entirely of the animation frame, including other events and the total time the js dialog was opened.

In particular, "processingDuration": 2322 is somewhat inconsistent with overall value of the metric, at first glance. (the last LoAF Script entry should have a "pauseDuration": value which is not 0, but seems not working on Canary for me...

In my opinion the attribution is FINE but there probably should be some obvious clue about WHY the numbers are the way they are. Maybe if the LoAF "pauseDuration" worked and the sum of all pauseDuration was split out from "processingDuration" (subtracted from and reported distinctly) this would be good enough?

rviscomi commented 1 month ago

To make testing this a bit easier, I've forked the INP demo to include a few buttons for triggering different dialogs and upgraded it to the latest attribution build: https://inp-demo-dialog.glitch.me/

rviscomi commented 1 month ago

Filed https://github.com/w3c/long-animation-frames/issues/17 to track the 0ms pauseDuration bug

tunetheweb commented 1 week ago

@mmocny / @zuoaoyuan this looks weird:

            {
                "name": "click",
                "entryType": "event",
                "startTime": 13769.199999928474,
                "duration": 368,
                "navigationId": "204030c4-b7ac-4c2c-a31d-5d15ef400627",
                "interactionId": 7303,
                "processingStart": 14136.299999952316,
                "processingEnd": 16142,
                "cancelable": true
            }

The processingEnd is > duration + startTime.

I guess that's technically correct since we're capping the duration but why not also cap processingEnd? Is the thought that people might still want to measure the full duration?

I guess web-vitals could similarly cap the processingDuration but it seems to me it's accurately reporting that based on the event timing details.

mmocny commented 1 week ago

why not also cap processingEnd?

Because the event is not done processing yet, and we thought that it would be best (i.e. for LoAF attribution with scripts) to leave the value accurate and "honest". Also, duration is capped because for INP we thought it made more sense-- but developers using Event Timing for other reasons might have different preferences.

I think we should expose MORE data to make this less confusing, such as making it obvious that the duration is based on an alternative fallback time, and to also still expose the presentation time alongside. We've started to do this in tracing but need to make a spec proposal to change public entry interface.

mmocny commented 1 week ago

One more note: when you have multiple events in one frame, the "fallback time" will be in the middle of exactly one of those events. For the other events, the fallback time can be before processingStart or after processingEnd.

The only reliable way to know if we're using a fallback time (at least today) I think is to compare with LoAF data and see if the end time of the event disagrees with the end time of the animation frame.

tunetheweb commented 1 week ago

Hmmm... so I guess from an INP point of view the duration has finished processing. So we could cap processingDuration (there precedence for this in #527 for example).

Would still look weird for LoAF-based bucketing, but guess we can deal with that, when we decide how that looks.

mmocny commented 1 week ago

the duration has finished processing

I would say:

The interaction has finished (there was visual feedback)
The event has not finished processing

I think capping processingDuration for the interaction as used for INP breakdowns for example, I think makes sense to me.

tunetheweb commented 1 week ago

That's why I said "from an INP point of view" 😁

OK will raise a PR similar to #527

GoogleChrome / web-vitals

Heads Up on Changes to INP Measurement When Interfered with JS Modal Dialogs #492