LoAF missed for some INP events

[brendankenny]

I ran across this issue while playing with the demo for the Measuring INP codelab. After trying to find a minimal repro, it still depends on a number of very specific circumstances, but

• I ran into it while doing typical INP debugging of a fairly normal page and
• it's possible my repro is only locally minimal and there are more common ways to induce the behavior

so it still seems worth fixing.

tl;dr

LoAFs can sometimes arrive from the PerfObserver before the interaction events they contain. If a requestIdleCallback fires between the PerfObserver callbacks, a LoAF can be discarded and won't be able to be paired with the interaction events when they come in later.

From out-of-band discussion, a reasonable fix would be to not discard any LoAFs that have a startTime after any existing event's processingEnd (or startTime + duration?). I'll open a PR to address this.

---

This turned out to be relatively simple, but I spent a decent amount of time debugging because it didn't appear to be simple at first, so I'm going to write down way too much about it for posterity. Feel free to skip the rest :)

To reproduce

• Visit https://nosy-first-plaster.glitch.me/
• As mentioned on the page, enable mobile device emulation and 4x CPU slowdown
• Click on the hamburger button

The demo does two things:

• when the hamburger button is clicked it gets a :hover style (since this is emulated mobile) and the hamburger SVG stroke starts a CSS color transition
• the click event triggers a 400ms busy task in a requestAnimationFrame callback

Things that are necessary but I don't totally understand:

• the hamburger button needs touch-action: manipulation (originally included because I had copy/pasted some Adam Argyle styles into the page). I thought that was just useful for preventing DTZ, but the page also has a proper mobile viewport set so that shouldn't be a factor regardless. Does that property interact with mobile :hover in some way? Speaking to @mmocny, setting this may affect the timing/order of event dispatch, so it may just be a matter of PerfObserver timing, not a difference in behavior
• 4x CPU slowdown appears necessary. I assume because it affects the requestIdleCallback underlying whenIdle triggering LoAF cleanup, but it's unclear if it just makes it easier to repro and isn't necessary, or if there's other task ordering/triggering that could have the same effect without DevTools.

Behavior

Usually two INP events will be logged to console (reportAllChanges is set to true). On my machine:

• Sometimes there will be two identical INPs logged.

  What's actually happening is two different INPs are reported from the unattributed onINP, but the whenIdle on the callback in the attributed onINP is causing the first report to not be made (and logged to console) until after the metric has been updated for the second report callback. Since it's the same object being updated and passed to the two callbacks, the same values are logged twice. In this case the attribution will have a LoAF, though, so everything is good (I don't know if it's worth doing anything about the slightly confusing apparent double logging...maybe debounce when reportAllChanges is true? Abort the idle task when a new report comes in? Or is that not "report all changes" anymore?)

• Much more often, a short INP is logged with just a pointerdown event in entries, then a little later a longer INP comes in with the ~400ms click event. Neither of these INP values will have an attributed LoAF attached.

I can very reliably reproduce the second case, which is why I noticed this in the first place.

Looking into what's happening, it appears that

• the pointerdown comes in
• a LoAF comes in that starts after the pointerdown
• queueCleanup's whenIdle fires. The LoAF doesn't overlap with the pointerdown, so is discarded
• the click event comes in, which would have overlapped with the LoAF
• With no overlapping LoAF for attribution now, longAnimationFrameEntries is left empty.

Example run of bug

This can be difficult to debug because recording via the performance panel and even console logging seem to affect when the whenIdle callbacks fire. I ended up using a global array to push log messages to and then logged everything at once at the end.

Here's a trace with the different PerformanceObserver callbacks added as performance marks and the LoAF as a measure:

https://trace.cafe/t/Q3usrDo9C7

Console output:

• new events (at 1930.9):

  name	startTime	processingStart	processingEnd	end	duration
  'pointerdown'	1813.5	1834.6	1834.6	1837.5	24

• new LoAFs (at 2354.3):

  startTime	end	duration
  1935.3	2347.3	412

• LoAFs discarded (at 2356.9):

  startTime	end	duration
  1935.3	2347.3	412

• web-vitals: INP of 24ms

• new events (at 2371.8):

  name	startTime	processingStart	processingEnd	end	duration
  'mouseover'	1909.4	1941.1	1941.1	2357.4	448
  'mousedown'	1909.4	1942.1	1942.1	2357.4	448
  'mouseup'	1909.4	1943	1943	2357.4	448
  'click'	1909.4	1943	1943.9	2357.4	448

• web-vitals: INP of 448ms

[mmocny]

Update: we discovered that touch emulation in DevTools on desktop requires some extra IPC hops between Renderer and Browser, and that this can lead to events being processed in a different LoAF frame than if it were real input processing (essentially: the browser adds an extra yield() point which then often schedules after-next-paint).

We wanted to check if that could be related to this issue -- did you have a chance?

[mmocny]

Re-reading the initial description, I thought I should point out:

• LoAF entries end measurement at main-thread-paint, while Event Timings end measurement at presentation time.
  • For this reason, it is expected that LoAF will often arrive first, before Event Timings, even when the processing time of the events is nested.
  • However-- if we ever have both entries in the same PO buffer at the same time, I believe we will report Event Timing entries first, just due to the way we sort things.
  • I think the v4 release did account for this, though.
• Some Event Timings require additional buffering (whenever we are waiting to generate interactionID).
  • This means some event timings might be reported, and then later more event timings are added into the same LoAF. In theory this can happen multiple times (for each active overlapping interaction)
  • So, flushing LoAF is more complex than just comparing to the most recent event timings. Again, I thought the v4 release did account for this-- though maybe imperfectly

(After the feedback we got from the folks working on v4 + attribution, we are working towards cleaning up the event timing stream to remove the out-of-order reporting complexity)

[mmocny]

I was finally able to reproduce your test page by NOT turning on 4x throttling (and now its fairly reliable).

I did it many times with 4x throttling enabled and kept getting the other case you mentioned, with 2x events each with a 1 LoAF. (I also at least once was a single event entry). My machine is pretty slow already so I guess too much throttling is as bad as none at all ? ;)

[philipwalton]

(After the feedback we got from the folks working on v4 + attribution, we are working towards cleaning up the event timing stream to remove the out-of-order reporting complexity)

🎉

[philipwalton]

• Sometimes there will be two identical INPs logged.
  What's actually happening is two different INPs are reported from the unattributed onINP, but the whenIdle on the callback in the attributed onINP is causing the first report to not be made (and logged to console) until after the metric has been updated for the second report callback. Since it's the same object being updated and passed to the two callbacks, the same values are logged twice. In this case the attribution will have a LoAF, though, so everything is good (I don't know if it's worth doing anything about the slightly confusing apparent double logging...maybe debounce when reportAllChanges is true? Abort the idle task when a new report comes in? Or is that not "report all changes" anymore?)

I thought about this a bit, and I think that's not "report all changes" anymore (as you say).

One way to handle this would be to not report until after all entries in a given PerformanceObserver callback were processed, and that would work well for the INP case where you're observing as the user is interacting. But it would NOT work well for the buffered case where the library is loaded late and processes a bunch of entries at the same time (like is common with LCP). In those cases you'd lose the changes, so I think it's best to be consistent.

[tunetheweb]

I thought about this a bit, and I think that's not "report all changes" anymore (as you say).

Hmmm… not entirely sure about that. For a start it’s not "report all changes" anyway, it’s “report all metric changes”. I.e. it doesn’t report candidates that are smaller than the current metric (a point of confusion often raised).

To me this isn’t a change either since it’s reporting the same value. So it’s kinda pointless and confusing. I’ve seen this issue with web-vitals extension and been meaning to figure it out. I presumed it was an issue with the extension.

So ideally we wouldn’t do this. Maybe by noting when reporting a value that’s already been reported (and losing the “change”). Or by cloning the metric at observation time if it’s liable to change.

Them again I think reportAllChanges is kinda niche anyway, so wouldn’t want to introduce too much more complexity

[philipwalton]

Hmmm… not entirely sure about that. For a start it’s not "report all changes" anyway, it’s “report all metric changes”. I.e. it doesn’t report candidates that are smaller than the current metric (a point of confusion often raised).

My understanding of the situation is that there IS a metric change, but by the time the attribution callback is run (since it's behind an idle callback) the values on the respective metric objects have updated and now appear to be the same when they're reported.

My comment above was meant to say that if there actually is a metric value change, then (to be consistent with how this work for other metrics) we should fire two callbacks, even if they're part of the same interaction.

My hope is that we can eventually remove the idle callback once Michal and team implement the buffering behavior he describes, and so then this would no longer be an issue.

[ekremney]

could be related: #491

[philipwalton]

My hope is that we can eventually remove the idle callback once Michal and team implement the buffering behavior he describes, and so then this would no longer be an issue.

Another option would be to move the whenIdle() call into the main onINP() function so that attribution logic all still happens sync. This should remove any double reporting. @tunetheweb WDYT?