GoogleChrome / GoogleChrome/lighthouse
Lighthouse misattributing Main-Thread Blocking Time in Run Microtasks
- Dominant language
- JavaScript
- Stars
- 30.8k
- Forks
- 9.8k
- Avg merge
- 1d 14h
- Merged PRs (30d)
- 20
Description
### FAQ
- [X] Yes, my issue is not about [variability](https://github.com/GoogleChrome/lighthouse/blob/main/docs/variability.md) or [throttling](https://github.com/GoogleChrome/lighthouse/blob/main/docs/throttling.md).
- [X] Yes, my issue is not about a specific accessibility audit (file with [axe-core](https://github.com/dequelabs/axe-core) instead).
### URL
https://nicj.net
### What happened?
(submitted URL is a placeholder URL, not the site I've reproduced this issue on)
As a [third party RUM provider](https://www.akamai.com/products/mpulse-real-user-monitoring), my team provides a JavaScript RUM library called [boomerang.js](https://github.com/akamai/boomerang) that is included in our customer's websites. boomerang.js is loaded on every page load and beacons performance analytics information.
Our customers, who are paying for RUM or CDN services, are usually very motivated and proactive in monitoring their site's performance, as you would expect. They will utilize tools like Lighthouse and want to ensure that boomerang.js is not causing any performance side-effects on their sites. We sometimes get Lighthouse reports that highlight boomerang.js in some of the audits. Being a RUM provider, our development team is very interested in ensuring boomerang.js is as [performant and non-invasive as possible](https://nicj.net/an-audit-of-boomerangs-performance/).
We recently were sent a Lighthouse report by a customer that highlighted boomerang.js as one of the top hits under the _Reduce the impact of third-party code_ audit. I was surprised to see boomerang.js highlighted there, as we haven't seen occurrences of blocking time in our own self-audits of our boomerang.js runtime. Their report showed 989ms of _Main-Thread Blocking Time_ (though my screenshots below will show a smaller amount (286ms) with my local repro).
Here's an example screenshot from my development machine:

(the rest of the third-parties in this audit have been chopped off for brevity and the privacy of our customer)
I started to dig into what was causing the _Main-Thread Blocking Time_ being 286ms in this trace. In other examples, when running Lighthouse locally, I would potentially see it even higher, 500-1000ms or more.
I had a hard time correlating those 286ms to anything within the Trace itself. Once loaded in the _Performance_ tab, I could see our script executing infrequently, but most tasks were 0.1ms or smaller, and added up (even at the microsecond granularity) the total `FunctionCall` time was only around ~23ms. Even taking the mobile `.cpuMultiplier` 4x into account that would be just 92ms.
We have a few 100ms-interval timers and a rAF callback, most of which complete in under 0.1ms. The below list is filtered to just our URL:

I additionally took several JavaScript Profiler traces, and generally found the same results: 25-50ms maximum spent via sampled profiles [under our JavaScript library](https://github.com/nicjansma/cpuprofile-filter).
I eventually dug into the Lighthouse source to understand how the _Main-Thread Blocking Time_ was calculated, and came across `third-party-summary.js`:
https://github.com/GoogleChrome/lighthouse/blob/516d32c7f66a0ffcfe7fbfc8bb40849699f769dc/core/audits/third-party-summary.js#L102-L114
So for each task, find its source URL and sum `.blockingTime` if it's over 50ms.
This function gets the source URL from `getAttributeableURLForTask`:
https://github.com/GoogleChrome/lighthouse/blob/516d32c7f66a0ffcfe7fbfc8bb40849699f769dc/core/lib/tracehouse/task-summary.js#L45-L58
The above function looks for any matching 3P script URLs, and falls back to the "first" URL of the task if it can't determine a cause.
When I looked back at the trace, I think I found the actual cause of the "blocking" task -- a _Run Microtasks_ which has ~80 items. This looks possibly like the DCL event, and all related tasks executed:

The _only_ time our boomerang.js is in that _Run Microtasks_ of 80 sub-tasks is the _very last_ `FunctionCall`, of 0.1ms:

In the trace JSON, we see that `RunMicrotasks` w/ 80 subtasks:
```
{
"args": {
"microtask_count": 80
},
"cat": "v8.execute",
"dur": 104382,
"name": "RunMicrotasks",
"ph": "X",
"pid": 41000,
"tdur": 102588,
"tid": 13620,
"ts": 1112473559258,
"tts": 1451432
},
```
And the previous `FunctionCall` happened to be our script appearing once:
```
{
"args": {
"data": {
"columnNumber": 10854,
"frame": "9D1A3DB0E9E508834136FE2E28B89B67",
"functionName": "l",
"lineNumber": 10,
"scriptId": "41",
"url": "https://s2.go-mpulse.net/boomerang/KX3GJ..."
}
},
"cat": "devtools.timeline",
"dur": 347,
"name": "FunctionCall",
"ph": "X",
"pid": 41000,
"tdur": 339,
"tid": 13620,
"ts": 1112473558883,
"tts": 1451065
},
```
Debugging this in Node also confirmed that it's just a big bunch of tasks, and our boomerang.js just happens to be the first in the `attributableURLs` list:
```
{
event: {
args: {},
cat: 'v8',
dur: 104379,
name: 'V8.RunMicrotasks',
ph: 'X',
pid: 41000,
tdur: 102586,
tid: 13620,
ts: 1112473559259,
tts: 1451433
},
endEvent: undefined,
startTime: 1326.394,
endTime: 1430.773,
duration: 104.379,
unbounded: false,
...
attributableURLs: [
'https://s2.go-mpulse.net/boomerang/KX3GJ...',
'https://customer.com/xyz.html',
'https://customer.com/assets/index.js',
'https://customer.com/assets/PDP.js',
'https://customer.com/assets/ImageGallery.js',
'https://customer.com/assets/vendor.js',
'https://customer.com/gtm.js?id=GTM-XXX,
'https://customer.com/gtag/js?id=G-XXX
],
group: {
id: 'scriptEvaluation',
label: 'Script Evaluation',
traceEventNames: [
'EventDispatch',
'EvaluateScript',
'v8.evaluateModule',
'FunctionCall',
'TimerFire',
'FireIdleCallback',
'FireAnimationFrame',
'RunMicrotasks',
'V8.Execute'
]
},
selfTime: 83.955
}
```
If we take that 83.955 `selfTime` and multiply by 4 (cpuMultiplier) minus 50ms we get the _Main-Thread Blocking Time_ reported in the original audit of 286ms.
So unfortunately because our boomerang.js script has one task executing at DCL that took ~0.1ms, we're unluckily being blamed for a 83.955ms Microtask chunk that gets shown as 286ms of _Main-Thread Blocking Time_ time.
d'oh!
I've run Lighthouse a bunch of times on the same URL, and some times the _Main-Thread Blocking Time_ is 0ms, and other times it's that much higher value. It's up to luck of the draw. I suspect the times it's 0ms, it's not the `[0]`th entry in `attributableURLs` or 3P URLs list.
### What did you expect?
Ultimately I think the question is how we should deal with a microtask-execution chunk when there are many microtasks from various sources involved. Task attribution is hard, and I'm not sure how to "assign blame" to a _Run Microtasks_ that has a lot of sub-calls to various other scripts/handlers/callbacks/timeouts.
In the above examples where boomerang.js was unlucky, it's ~0.1ms task(s) happen to get blamed for the whole chunk of microtask time.
Since this audit's purpose is to highlight third-party scripts that are behaving badly, I'd like to suggest we make a change to the calculation to ensure it's more accurate and repeatable.
I'm not a Chrome or Lighthouse expert so I may be missing some context on how this all works, but with my understanding here are some possible ideas for how we could deal with microtask chunks:
0. Do nothing! Sometimes 3P scripts will be involved in a chonky microtasks run and may be blamed for the whole thing
1. Don't include Microtask execution chunks in any consideration for `.blockingTime` calculation for 3P URLs (this may hide real problems)
2. Dive a level deeper into the Microtask execution time's children, and treat each child `FunctionCall`s independently for `.blockingTime` consideration.
3. Dive a level deeper into the Microtask execution time's children, and accumulate time in child `FunctionCall`s grouped by URL. Consider the sum() for each URL for `.blockingTime` calculation.
4. Dive a level deeper into the Microtask execution time's children, and only accumulate time in child `FunctionCall`s etc that are related to that specific URL. Combine all related ones for that URL in that _Run Microtasks_, and if it's > 50(?)% of the total _Run Microtasks_ execution time, declare that URL to be blamed for the whole _Run Microtasks_.
Personally, I think (3) sounds the most logical -- essentially, group each execution of Microtasks by the 3P URLs and treat their weight of runtime independently, to see if they cross the `.blockingTime` threshold (50ms).
I'm happy to take a stab at the code changes for this, if there's agreement on the approach.
### What have you tried?
_No response_
### How were you running Lighthouse?
CLI, Chrome DevTools
### Lighthouse Version
10.0.1
### Chrome Version
113.0.0.0
### Node Version
16.19.1
### OS
Windows
### Relevant log output
_No response_
Contributor guide
Assessment
This issue has not been assessed yet.