Ambiguous behaviour in Attribution data on Mobile device with no CPU Throttling
jinja12 opened this issue · 10 comments
I have a very simple page where I provide an option to add an item via 2 buttons: button-1 and button-2, the onClick handlers for both buttons have a small difference, one has an empty while loop running for 3s while the other runs for 4s.
The code for the page is below for reference. Now when I click any of the buttons and see the console, where I am interested in the Long Animation Frames entry inside the logged object, the source function and the source url is different from the expected output. The page can be found here (deployed on vercel, the image below shows output on localhost): Deployed Page Link
Code:
"use client";
import { useState, useEffect, useRef } from "react";
import { onINP, onCLS } from "web-vitals/attribution";
import { FadeInAnimation } from "./animation.js";
interface Item {
id: number;
name: string;
category: string;
}
export default function INPPage() {
const [items, setItems] = useState<Item[]>([]);
const [show, setShow] = useState(false);
function Welcome() {
const ref = useRef(null);
useEffect(() => {
const animation = new FadeInAnimation(ref.current);
animation.start(1000);
return () => {
animation.stop();
};
}, []);
return (
<h1
ref={ref}
style={{
opacity: 0,
color: "white",
padding: 50,
textAlign: "center",
fontSize: 50,
backgroundImage:
"radial-gradient(circle, rgba(63,94,251,1) 0%, rgba(252,70,107,1) 100%)",
}}
>
Welcome
</h1>
);
}
useEffect(() => {
const REPORTING_THRESHOLD_MS = 150;
const observer = new PerformanceObserver((list) => {
for (const entry of list.getEntries()) {
console.log("LKJHGFDSDFGHJKL ", entry)
if (
entry.duration > REPORTING_THRESHOLD_MS &&
entry.firstUIEventTimestamp > 0
) {
console.log("Long task detected:", entry)
}
}
});
observer.observe({ type: "long-animation-frame", buffered: true });
console.log("Printing something");
onINP(console.log, { reportAllChanges: true });
}, []);
const handleAddItem = () => {
const newItem = { id: items.length + 1, name: "", category: "" };
const start = Date.now();
while (Date.now() - start < 3000) {}
setItems([...items, newItem]);
};
const handleAddItem4s = () => {
const newItem = { id: items.length + 1, name: "", category: "" };
const start = Date.now();
while (Date.now() - start < 4000) {}
setItems([...items, newItem]);
};
const handleInputChange = (id: number, field: string, value: string) => {
setItems(
items.map((item) => (item.id === id ? { ...item, [field]: value } : item))
);
};
return (
<div className="min-h-screen bg-gray-100 p-4">
<div className="container mx-auto p-4 bg-gray-800 text-white rounded shadow-lg"> {/* Updated background color and text color */}
<h1 className="text-2xl font-bold mb-4">INP Test Page with LoAF</h1>
<button onClick={() => setShow(!show)}>
{show ? "Remove" : "Show"}
</button>
<hr />
{show && <Welcome />}
<br />
<br />
<button
onClick={handleAddItem}
className="mb-4 px-6 py-3 bg-blue-500 text-white rounded-lg hover:bg-blue-400"
>
Add Item (3s)
</button>
<button
onClick={handleAddItem4s}
className="mb-4 px-6 py-3 bg-green-500 text-white rounded-lg hover:bg-green-400"
>
Add Item (4s)
</button>
<div className="grid grid-cols-1 gap-4">
{items.map((item) => (
<div key={item.id} className="p-4 bg-gray-200 rounded-lg shadow-md">
<div className="mb-2">
<label className="block text-sm font-medium text-gray-700">
Name
</label>
<input
type="text"
value={item.name}
onChange={(e) =>
handleInputChange(item.id, "name", e.target.value)
}
className="mt-1 block w-full px-3 py-2 bg-white border border-gray-300 rounded-md shadow-sm focus:outline-none focus:ring-blue-500 focus:border-blue-500 sm:text-sm"
/>
</div>
<div>
<label className="block text-sm font-medium text-gray-700">
Category
</label>
<input
type="text"
value={item.category}
onChange={(e) =>
handleInputChange(item.id, "category", e.target.value)
}
className="mt-1 block w-full px-3 py-2 bg-white border border-gray-300 rounded-md shadow-sm focus:outline-none focus:ring-blue-500 focus:border-blue-500 sm:text-sm"
/>
</div>
</div>
))}
</div>
</div>
</div>
);
}Output Image:
Highlighted above is the sourceFunctionName and the sourceURL. In my application there is no such thing. I only clicked on the two buttons which you can see for which the function names which handle them are: handleAddItem and handleAddItem4s.
I went through the documentation for the same here: https://developer.mozilla.org/en-US/docs/Web/API/PerformanceScriptTiming/sourceFunctionName as well, but it does not provide a great idea into the attribute (expected behaviour and the result), if the output can't be changed, is there a way to get the exact function which is taking a lot of time/blocking the main single thread ? Similarly for the sourceURL attribute as well. Since this is a relatively new addition, I could not find much resources apart from the original docs to look into it.
It would be great if this could be please looked into once and some details be provided about how to go about getting the correct source functions and in a broader sense action items to understand the metric in depth.
Thanks!
The LoAF source attribution is based on the actual "entry point" that is registered with the browser for scheduling, and which is invoked to start this new task / loaf-script, rather than any code that might eventually be called as part of this task.
- The browser doesn't know you are using React or how React Components use event listeners
- You the developer know that you have a custom event listener defined inside a Component and this is attached a specific element and that this event does the "interesting bit" of work. However...
- React happens to do its own synthetic event dispatch (See caveats) which has some benefits and drawbacks (such as issues like this)
- In the case of LoAF attribution, because react is acting as a "wrapper" for your component code, LoAF can only attribute down to the React library.
- This is also common on pages that use library that wrap all native APIs, e.g. for measurement.
Generally, when using frameworks / compilers / bundlers / wrapper libraries... and especially for complex JS-apps using Component style development, it is often the case that the literal source location value returned by LoAF attribution links to a computer generated bundle and with a minified and unreadable name and inconsistent source locations.
For that reason, it is expected that you will likely need to rely on source maps (or other lookup methods) to actually show nice developer-readable attribution. This might require some assistance by frameworks themselves, and LoAF has not be available for very long. (Though some analytics providers are beginning to offer some of this as a product).
For local development, I would say this attribution is expected to be more useful if you use more Vanilla JS approaches to scheduling -- and over time, perhaps JS frameworks will be able to leverage more "vanilla" scheduling directly, as the reasons for wrappers are largely historic and for compatibility reasons at this point (and some frameworks already are more vanilla).
For attributing INP for a project like yours, I would probably:
- Use the fact that this is calling into ReactDOM as a signal that this is a Component listener that you explicitly added, rather than some 3p library code / global listeners.
- Instead of using the source location, use the
event.targetfrom the INP attribtion, as well as theevent.type. - Use this information (perhaps from RUM) to find the right UI element (likely testing in lab), then just inspect the DOM (or run a perf profile) to find the long event listener.
Thanks a tonne for the detailed response @mmocny @tunetheweb over the linked issue! I have been playing around with these metrics and was trying one specific case where some unexpected and interesting metrics were logged, and was hoping to get an insight from you on the same:
I am currently logging the interactionTargetElement node which we get from the attribution data of INP metric (added in v4), alongside this I have a PerformanceObserver which observes for type long-animation-frame, to get details about long tasks. The code snippet for the same:
// function logging relevant details to a performance entry
const analyzePerformanceEntry = (entry) => {
const { renderStart, firstUIEventTimestamp, blockingDuration, scripts } = entry;
console.log(`
Performance Analysis:
Render Start: ${renderStart}
First UI Event Timestamp: ${firstUIEventTimestamp}
Blocking Duration: ${blockingDuration}
Scripts:
`);
scripts.forEach((script) => {
const { duration, executionStart, sourceURL, sourceFunctionName, invoker, invokerType } = script;
console.log(`
Duration: ${duration}
Execution Start: ${executionStart}
Source URL: ${sourceURL}
Source Function: ${sourceFunctionName}
Invoker: ${invoker}
Invoker Type: ${invokerType}
`);
});
};
useEffect(() => {
const REPORTING_THRESHOLD_MS = 150;
// performance observer
const observer = new PerformanceObserver((list) => {
for (const entry of list.getEntries()) {
if (entry.duration > REPORTING_THRESHOLD_MS && (entry as any).firstUIEventTimestamp > 0) {
console.log("Long task detected:", entry);
analyzePerformanceEntry(entry);
}
}
});
observer.observe({ type: "long-animation-frame", buffered: true });
// callback function to be passed to the `onINP()` method
const handleINP = (metric) => {
const { attribution } = metric;
const { interactionTarget, interactionTargetElement } = attribution;
console.log('INP Attribution:');
console.log(`Interaction Type: ${interactionTarget}`);
if (interactionTargetElement) {
const reactPropsKey = Object.keys(interactionTargetElement).find(key => key.startsWith('__reactProps'));
const reactProps = reactPropsKey ? interactionTargetElement[reactPropsKey] : {};
console.log(`
Interaction Target Element:
Node Name: ${interactionTargetElement.nodeName}
Text Content: ${interactionTargetElement.textContent}
Parent Node Name: ${interactionTargetElement.parentNode?.nodeName}
Parent Text Content: ${interactionTargetElement.parentNode?.textContent}
React Props: ${reactProps ? JSON.stringify(reactProps) : 'N/A'}
`);
}
};
onINP(handleINP, { reportAllChanges: true });
return () => {
observer.disconnect();
onINP(null); // Ensure onINP callback is cleaned up
};
}, []);
// handler for click on button of 3s
const handleAddItem = () => {
const newItem = { id: items.length + 1, name: "", category: "" };
const start = Date.now();
while (Date.now() - start < 3000) {}
setItems([...items, newItem]);
};
// handler for click on button of 4s
const handleAddItem4s = () => {
const newItem = { id: items.length + 1, name: "", category: "" };
const start = Date.now();
while (Date.now() - start < 4000) {}
setItems([...items, newItem]);
};I was then testing around with some cases to get results from these logs. The page can be found here: https://webperf-alpha.vercel.app/dashboard/inp. On loading of this application page on localhost without any CPU Throttling and on Mobile dimensions, I tested for the input:
- Click on Add Item (4s) button
- Click on Add Item (3s) button immediately after clicking above
- Click on Add Item (4s) button again immediately after clicking above.
The output behaviour is rather interesting, and I am unable to explain them:
The first item is added after 4s, the second and third items are loaded together after 7s of the time the first item was loaded. The interactionTargetElement shows the 3s button for some reason. There are two doubts here: why is the 2nd and 3rd step above batched together and executed at once (combined delay of 7s?) and why is the target element pointing towards the 3s button and not the 4s button ? The interactionTarget docs say:
/**
* A selector identifying the element that the user first interacted with
* as part of the frame where the INP candidate interaction occurred.
* If this value is an empty string, that generally means the element was
* removed from the DOM after the interaction.
*/
So for instance in the case where I first select the 4s button and then immediately click the 3s button, the attribution should point out the element where the interaction started: i.e. the Add Item (4s) button, but it seems the reverse is happening. Am I missing anything here ? An insight into the same would be highly appreciated.
Output image:
I think I figured out the reason the performance metrics are reported together for the 2nd and the 3rd click: it is due to React batching the updates together, hence the metrics for the 2nd and 3rd click log together at once. I tested this logic for another case with 4 clicks, the last 3 updates are batched here again. So that is due to the latest React features, but again the doubt of which interactionTargetElement will be reported in such scenarios still stand, the perceived output is different from the expected one as specified in the docs.
alongside this I have a PerformanceObserver which observes for type long-animation-frame, to get details about long tasks.
v4 includes any long tasks overlapping the INP event in the INP callback to save you having to monitor that separately.
But it can be good to measure all LoAFs to also get long task outside the immediate INP event.
I think I figured out the reason the performance metrics are reported together for the 2nd and the 3rd click: it is due to React batching the updates together, hence the metrics for the 2nd and 3rd click log together at once. I tested this logic for another case with 4 clicks, the last 3 updates are batched here again. So that is due to the latest React features, but again the doubt of which interactionTargetElement will be reported in such scenarios still stand, the perceived output is different from the expected one as specified in the docs.
OK that's interesting. I would guess React is trying it's best to be responsive to the first click, but then batching the rest together to save having to do multiple layouts together?
Going back to the docs:
/**
* A selector identifying the element that the user first interacted with
* as part of the frame where the INP candidate interaction occurred.
* If this value is an empty string, that generally means the element was
* removed from the DOM after the interaction.
*/It would seem, that in that example, there would be two frames—the first with click 1, and the second with the remaining clicks that React has batched together.
In that case the frame with the longest one will be the "INP frame". All else being equal this would be the second frame (as it includes multiple clicks so will take multiple processing times to finish). And this is what you are seeing. The interactionTarget is set to the first interaction of the INP frame. The prior frame may well have been quite slow, but the subsequent one was slower still. Now I know you're running this with reportAllChanges: true but if all the Event Timings are reported together (as could often be the case in cases like this where the main thread is busy), then they will be processed together, but split into frames, so only the second one would be emitted as an INP event.
So I think the docs (and the implementation!) are right in this case. But certainly a confusing one if you're not aware how this all works!
OK that's interesting. I would guess React is trying it's best to be responsive to the first click, but then batching the rest together to save having to do multiple layouts together?
Yep exactly! I was not sure if we would should view this as separate frames (even if so how exactly though): one for the first click and the second for all the subsequent clicks. This logics fits perfectly and makes sense, checked on the following case of immediate clicks one after the another:
- 3s button
- 3s button
- 4s button
- 4s button
The interactionTargetElement is indeed reported as the 3s button (starting interaction of the 2nd frame).
Thanks for the clarification :)
I was not sure if we would should view this as separate frames (even if so how exactly though)
If you look at Event Timing entries I'd expect the first to finish (starttime + duration) at time 1, and the rest all at the same time 2 (or close enough minus some rounding and limits!), since the "starttime + duration" is approximately the frame paint time (rather than the end of event handler processing).
Should also be able to see in a performance trace.
Right, will see once with a performance trace as well.
OK so tried this.
Desktop
When I do this:
- Click on Add Item (4s) button
- Click on Add Item (3s) button immediately after clicking above
- Click on Add Item (4s) button again immediately after clicking above.
I see this:
- All 3 items are rendered together
- The INP target is the 4s click element
- The trace shows they were indeed split into two tasks, but both were rendered together, hence why the first interaction was the longest one from INP point of view.
Mobile
When enabling mobile emulation and repeating, it's slightly different:
- Two INP events are emitted, with the second being much longer (due to being delayed by the first), and overtaking the first. This second one is therefore the ultimate INP for the page. The first INP target is the 4s button, the second is the 3s button:
The trace shows two distinct interactions:
Weirdly the screenshot do not show two step render, but that's what I saw with my own eyes, and if you zoom in there is a paint and a commit between the two confirming a render happened then:
So it looks like on mobile Chrome prefers the early, separate paint, but on desktop it decides to wait and do them both together. Chrome does all sorts of heuristics to decide when to render a frame, especially when it knows there are more inputs to process, and it looks like the mobile and desktop heuristics are slightly different. Maybe @mmocny can explain why?
At the start of a BeginMainFrame task (i.e. rendering) Chrome will flush all UI events which are already queued in the event loop at the start of BMF, but won't flush any that are added during the BMF.
Therefore, if your first interaction is so long running that you have time to interact again, before BMF starts and the browser process actually sends these events to renderer in time, then you will effectively cluster those inputs into a single long animation frame.
I don't think the scheduling policy is any different on desktop or mobile-- but what changes is that as we change input types, we change how we send events from browser to renderer.
Touch is weirder than mouse input-- and DevTools touch emulation is weirdest of all. Sometimes you have to wait for Renderer to acknowledge feedback from previous events (i.e. IPC messages that start after processingEnd), and before browser can send new IPC about future events...
In this case these were distinct interactions, so I had expected it would work. I tried myself locally and could repro as Barry says. It wasn't just luck / races.
I traced with Perfetto and here is what I see:
- Indeed, the second and third events are stuck in browser process waiting for the first event to finish:
The 'flow' shows when the browser received the event and forwarded it to the renderer. You should see that it is first started after the first interactions ends-- weird, I definitely interacted earlier!
- If I follow that flow to the begging I see references to
RenderWidgetHostInputEventRouter::ForwardEmulatedGestureEvent, and I can find another flow event:
Following that flow to its start, I find the original RenderWidgetHostViewCocoa::mouseEvent.
Looks like the way Touch emulation works is:
- Browser receives mouse events, sends to renderer
- Renderer has to schedule the mouse events, before it can "reject them" and ask for touch simulation instead
- Goes back to Browser and back to renderer.
All this means that we are guaranteed to have a few process IPC between the end of the first interaction event and the start of BMF task and that is a very narrow window to race and rendering will win.
Net/net, don't rely on mobile emulation for very detailed scheduling test :D
Also -- more generally -- I have been advocating to make some scheduling changes to this scheduling policy, so I wouldn't rely on it too heavily.
Other browsers are already different. The mobile emulated behaviour today is likely to match the future behaviour more if I was to guess.
Got it, thanks a lot for the detailed explanation!