Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

3rd party script's Main Thread Blocking Time does not match Long Task #15184

Closed
2 tasks done
samhDV opened this issue Jun 19, 2023 · 8 comments · Fixed by #16117
Closed
2 tasks done

3rd party script's Main Thread Blocking Time does not match Long Task #15184

samhDV opened this issue Jun 19, 2023 · 8 comments · Fixed by #16117
Assignees

Comments

@samhDV
Copy link

samhDV commented Jun 19, 2023

FAQ

URL

https://jsbin.com/rosesuluyi/9/edit?html,js,console

What happened?

tldr; It seems the Main Thread Blocking Time and the Long Main Thread Tasks duration don't correctly add up for external scripts.

I've learned the following definitions of the terms:
A Long Tasks is a task that takes longer that 50ms to complete. The part of the task that is longer than 50ms is called the 'blocking time'. If this is happening on the Main Thread, this is called "Main Thread Blocking Time".
This is not to be confused with Total Blocking Time (which isn't total at all, but the sum between FCP and TTI).

e.g. a task takes 250ms to complete will be a Long Task, and has a blocking time of 200ms.

I am trying to use lighthouse to asses the performance of a third-party script on a page.

Lighthouse outputs information about the Main-Thread Blocking Time in the "Reduce the impact of third-party code" category, and information about the Long Tasks in the "Avoid long main-thread tasks" section.

Given the above formula, I would have expected the sum of Long Tasks for a specific script - 50 * (amount) would be equal to the reported Main Thread Blocking Time.

However I did notice that the numbers were not matching.

On our real testpages, which I cannot disclose, the difference is bigger than on the sample page above. Possible also related to a lot more code running on the pages from different sources. If truly required I can see about setting up such a page for public.

What did you expect?

I would have expected the numbers to add up.

So that I could take the Total long task duration and the number of long tasks and use it to calculate the Main Thread Blocking time.

What have you tried?

I understand at some points lists are truncated to 20 entries, and because of that, it might be possible that the total numbers don't add up. But in this case there are always less than 20 entries.

I was also thinking that maybe lighthouse would do different passes to calculate the different data, and the data not matching being caused by variance, but as far as I can see, lighthouse only performs one pass.

To setup this linked test I managed to reproduce the behavior in Chrome Devtools, but I originally found the issue in Lighthouse-ci / cli

How were you running Lighthouse?

CLI, Chrome DevTools

Lighthouse Version

10.1.0

Chrome Version

116.0.5841.0 Canary

Node Version

18.16.0

OS

Mac

Relevant log output

No response

@adamraine
Copy link
Member

There are a lot of factors at play when we calculate TBT, including our throttling settings which I don't think you mentioned. When using simulate throttling (which is the default) the TBT value will be an estimate, so you probably can't get the exact TBT value from adding together all the tasks listed in the "Avoid long main-thread tasks" audit.

So that I could take the Total long task duration and the number of long tasks and use it to calculate the Main Thread Blocking time.

Where are you getting the "Main Thread Blocking time" and "Total long task duration" values that you are comparing here?

@samhDV
Copy link
Author

samhDV commented Jun 20, 2023

Thanks for looking into this.

Sorry for the potential confusion, all these terms look alike. I'm not talking about TBT (Total Blocking Time). I'm specifically talking about "Main Thread Blocking Time" and "Total long main-thread task duration"

The "Main Thread Blocking Time" can be found under the Diagnostic with the title "Minimize third-party usage". Link to source code

The "Long main-thread task duration" can be found under the diagnostic with the title "Avoid long main-thread tasks".
Link to source code

See below for some redacted screenshots of an internal test page.

lmtt-2

There are 4 long tasks for script 1, and one for script 2.

Based on these values we can calculate the respective blocking times, by subtracting them with 50ms. This is also done here

  • 140ms - 50ms = 90ms
  • 86ms - 50ms = 36ms
  • 86ms - 50ms = 36ms
  • 78ms - 50ms = 28ms
  • 58ms - 50ms = 8ms

And summing these up per script, I get a Main Thread Blocking Time of:

  • Script 1 : 90 + 36 + 36 + 28 = 190ms
  • Script 2 : 8ms
mtbt-2

Looking at the detailed output specifically listing the Main Thread Blocking Time (MTBT), I would have expected the numbers to align.

Instead it shows

  • Script 1 : 141ms (vs 190ms)
  • Script 2 : 0 ms (vs 8ms)

I'm curious as to why the numbers don't match. They come from the same single lighthouse run.

including our throttling settings which I don't think you mentioned.

I'm using the default settings: clear storage + simulated throttling.
lh-settings

@adamraine
Copy link
Member

I see what you are saying, thanks for clarifying!

In the long main thread tasks audit, we show tasks with their overall duration which is basically what you are expecting:

const results = longtasks.map(task => ({
url: getAttributableURLForTask(task, jsURLs),
duration: task.duration,
startTime: task.startTime,
}));

In the third-party summary audit, we show tasks with their "self time":

for (const task of mainThreadTasks) {
const attributableURL = getAttributableURLForTask(task, jsURLs);
const urlSummary = byURL.get(attributableURL) || {...defaultSummary};
const taskDuration = task.selfTime * cpuMultiplier;

"Self time" is the duration of the task minus the "self time" of any child tasks. I'm not sure exactly where this definition came from or why it was used in third-party summaries audit. I'm guessing it's because a child task could have a different third party entity than a parent task but not 100% sure yet. Marking for discussion.

@adamraine
Copy link
Member

Confirmed it is intended behavior to use selfTime instead of duration because child tasks can belong to a different entity than their parent task.

However, doing a - 50 operation on tasks that are not top level does not make much sense and is a problem I explored in #15175. Perhaps using the TBT impact number for blocking time would make more sense than selfTime in this scenario.

@samhDV
Copy link
Author

samhDV commented Jul 14, 2023

I'm still trying to wrap my head around this.

In order to simulate the call stack, trigger long tasks and make the selftime vs duration visible, I've set up the following experiment.

Script 1 will wait synchronously for 100ms, call exec on script 2 and then again wait 100ms, this starts in onload
Script 2, when called, will wait sync for 200ms, call exec on script 3 and then again wait 200ms
Script 3, when called, will wait for 300ms and return.

In my /etc/hosts I've added 4 domains all pointing to localhost. (domain1.com, domain2.com, domain3.com, domain4.com)

There's also an index.html page just loading those scripts. Each script is referenced from it's own domain to obtain separation.

Then I just started a simple server python -m http.server 8000 to host it all, and I'm testing it through http://domain4.com:8000

(I can share the code if relevant, pretty basic though)

This results in the following flamechart
Screenshot 2023-07-14 at 10 42 04

I would expect the following values
script 1
self time of 100+100 = 200ms, and a duration of 100+200+300+200+100 = 900ms
script 2
self time of 200+200 = 400ms, and a duration of 200+300+200 = 700ms
script 3
self time of 300ms, and a duration of 300ms as well

Obviously there can be some variance, but those are the ballpark numbers I'm expecting.

When running lighthouse on this page, I get the following results:

Screenshot 2023-07-14 at 10 43 44

The Long main-thread tasks reports 900ms for script1, which is what is expected given that it is based on duration.

For Main-Thread Blocking Time I cannot really explain the results. The number seems close to 900 - 50 = 850ms. But I can't really reconcile this with your statement about this being based on self time.

Self time of this script should be about 200ms?

@adamraine
Copy link
Member

(I can share the code if relevant, pretty basic though)

Can you share the code?

Lighthouse doesn't profile the JS as deeply as a normal performance panel flamechart, so it might be the case that Lighthouse simply attributes everything to script1.js because that's all the information we have.

These are all valid concerns which we should address and clarify before closing this issue.

@samhDV
Copy link
Author

samhDV commented Jul 19, 2023

Thank you for taking the time to look into this. I understand it is not trivial.

I've uploaded the code to this repo: https://github.com/samhDV/lighthouse-issue-15184

I also added some explanations to the readme, let me know if anything needs to be cleared up further.

Lighthouse doesn't profile the JS as deeply as a normal performance panel flamechart, so it might be the case that Lighthouse simply attributes everything to script1.js because that's all the information we have.

If that's the case, that's a valid reason. Just looking to understand the behavior. There's the concern of attribution, but there's also the concern of where the numbers are actually coming from (and their correctness).

I understand that 'correct' attribution is difficult here. I've also found https://docs.google.com/presentation/d/1sslnZi2MYyKlNb6LoS_vTlcvshkUR0IUekacq4mZMhs/edit#slide=id.ga0a742a0dc_0_21 contain valuable information.

@samhDV samhDV closed this as completed Jul 19, 2023
@samhDV samhDV reopened this Jul 19, 2023
@adamraine
Copy link
Member

If that's the case, that's a valid reason. Just looking to understand the behavior. There's the concern of attribution, but there's also the concern of where the numbers are actually coming from (and their correctness).

I recreated your example and this does look like the case. For reference, if you take a performance trace with "Disable Javascript Samples" checked then you will see what I mean. Lighthouse disables JS samples for it's tracing as well.

We will keep this issue to track possible improvements to the 3p blocking calculation mentioned in #15184 (comment).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants