Closed Bug 1564569 Opened 5 years ago Closed 5 years ago

Resources added to root url load group via setTimeout can cause significant load time noise

Categories

(Core :: Performance, enhancement, P3)

enhancement

Tracking

()

RESOLVED WONTFIX
Tracking Status
firefox70 --- affected

People

(Reporter: acreskey, Unassigned)

References

(Blocks 1 open bug)

Details

Attachments

(2 files, 1 obsolete file)

I was investigating page load performance noise, specifically large outliers.

The test was raptor-tp6m-amazon-geckoview-cold on the Moto G5.

The most common load time (onLoad event) was around 1300ms.
But I would frequently see load times of close to 2000ms.

By looking into what was loaded in the slow cases I noticed that a batch of images were added to the root resource loadgroup prior to the load event firing.
In the fast case, these images were loaded after the load event firing.

So we are measuring the load timing for a superset of resources in the slow load case.
i.e. not comparing apples to apples.

The first resource in this batch is https://images-na.ssl-images-amazon.com/images/G/01/gateway/grid/test/all_beauty2x._CB518612027_.png
You can see it in the load group that's a child of the root url's loadgroup here:
With changes that I intend to land to the logging of LoadGroups, this will be easier to spot going forward.

[0x8732d780]: Adding request 0x873be844 https://www.amazon.com/ (count=0).

07-09 13:18:25.628 18116 18131 V AJC - loadgroup: LOADGROUP [0x86189480]: rootLoadGroup 0x8732d780  Adding request 0x86e90044 https://images-na.ssl-images-amazon.com/images/G/01/gateway/grid/test/all_beauty2x._CB518612027_.png (count=0).

Profiles:

Slow (all_beauty2x and related images loaded before onload)
https://perfht.ml/2JfCaOQ

Fast (all_beauty2x and related images loaded after onload)
https://perfht.ml/2JfbDku

smaug was able to pinpoint this down to a setTimeout call using innerHTML to create the image element, thus triggering the early load:
https://perfht.ml/2NJTv6v

Logging this so we can discuss.

Can we defer all setTimeouts until after pageload? (that would probably hurt some pages?)

By spec, do these new resources have to go in the loadgroup of the root url?

Bugbug thinks this bug is a enhancement, but please change it back in case of error.

Type: defect → enhancement

I believe this is spec behavior for loads; these are dependent resources of the document (once the setTimeout fires and tries to add them). smaug: correct?

If so it's likely just the same sort of variability that the timeout deferral attacked, but if we get idle time we will run the timeouts, and that can add things to the load group. We could tweak the definition of "idle" during load, to require a longer idle period than normal; but at some point there will be negative consequences to doing so (perhaps not seen in load time, but in other ways)

Flags: needinfo?(bugs)

Yes :)

"Fetching the image must delay the load event of the element's node document until the task that is queued by the networking task source once the resource has been fetched (defined below) has been run. "

https://html.spec.whatwg.org/#the-end see step 6 (currently step 6)
"Spin the event loop until there is nothing that delays the load event in the Document."
Clicking that 'delays the load event ' tells what all delays load event that way.

Flags: needinfo?(bugs)
Attached image amazon-innerHTML images.png (obsolete) —

Thanks guys.

Right - if we delay the setTimeout() then we delay the requests for the images.

And this could regress visual completeness.

For this page those images happen to be way, way below the fold (attached).
Although there is also some JS that's requested.

More for curiosity, I'll try to attach Chrome on android to this recording to see what it does with that setTimeout() and those images.

Attachment #9077416 - Attachment is obsolete: true
Attached image amazon-images.png

InnerHTML images added via setTimeout().

So if I'm reading the Chrome profiler correctly, those images are loaded way after the load event. (Moto G5, Chrome 75).

But that's not telling me too much -- gecko does the same thing, roughly 9 times out of 10.

Blocks: 1502138
See Also: → 1565325
Priority: -- → P3

To see how many sites are affected by this behavior I made a comparison:
Left-hand-side is baseline (with the idle detection tweak from Bug 1541229)
Right-hand-side doesn't run the setTimeout() in the idle cue (commented out). So the setTimeouts() run at onload.

Main comparison view (some jobs still running):
https://treeherder.mozilla.org/perf.html#/compare?originalProject=try&originalRevision=190b8f87707ac2e16c9d94003310fec1700a14ad&newProject=try&newRevision=8cd358ef99bf055bd288661057d37ebcae9185b5&framework=10

Some interesting results:

• You can see the removal of most of the bimodal amazon loads here

• Removal of big outliers on ebay

• Did not remove all the outliers on instagram

• A 25% 'improvement' on amazon loadtime and a 35% 'improvement' on google loadtime on pixel 2 (no idea what the visual impact is). And makes sense since we push off more work till after.

Of the first five tp6 cold pages (G5), three of them have a bimodal loading pattern.
Deferring the setTimeout() execution "fixes" all three.

I've attached a screenshot of the replicates compare for google, but amazon and instagram are similar (baseline on top, experiment on the bottom).

tp6m-amazon-geckoview-cold
In the amazon case, images are added to the DOM via a setTimeout.
Deferring the setTimeouts causes these images to be added after the load and we get rid of the longer ~1500ms load times.

tp6m-google-geckoview-cold
On google, the setTimeout() adds a script node, so more network resources are added to the load group.
Deferring the addition of the script removes the 2x loadtime loads.

tp6m-instagram-geckoview-cold
In this case it’s a notification screen that’s triggered by a setTimeout.
If this setTimeout runs before load then about a half dozen images are added to the load group.

Instagram is interesting in that it’s one case were deferring all the setTimeouts() actually delays the load event.

I haven’t run this test on every site. It does appear to remove most of the bimodal load event behaviour, but not all.
e.g.
tp6m-ebay-kleinanzeigen-search-geckoview-cold
Here something else is causing the occasional faster loads.

For curiosity's sake, :denispal ran a visual metrics test of the deferred time execution:
https://pastebin.com/raw/VFZSJpjm

Major improvements in loadtime, major regressions in visual metrics.

I'm thinking that this be closed as "wont-fix" -- any thoughts?

Closing as won't fix for now.

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → WONTFIX
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: