Page MenuHomePhabricator
Create Task
Maniphest T193570

Why did first paint/fully loaded time drop (in a good way!) on mobile?
Closed, ResolvedPublic
Actions

Assigned To
• Gilles
Authored By
Jdlrobson
May 1 2018, 9:05 PM
Tags
Referenced Files
F17629470: Capture d'écran 2018-05-04 09.46.54.png
May 4 2018, 7:47 AM
F17622146: Screen Shot 2018-05-03 at 21.42.15.png
May 3 2018, 8:42 PM
F17622100: render-1.png
May 3 2018, 8:41 PM
F17622138: render-2.png
May 3 2018, 8:41 PM
F17622108: render.png
May 3 2018, 8:41 PM
F17592205: render.png
May 2 2018, 4:26 PM
F17553795: Screen Shot 2018-05-02 at 6.00.33 AM.png
May 2 2018, 4:11 AM
F17505360: Screen Shot 2018-05-01 at 2.05.24 PM.png
May 1 2018, 9:05 PM
View All 11 Files
Subscribers
Aklapper
• demon
gerritbot
• Gilles
• Imarlier
Jdlrobson
Krinkle
View All 10 Subscribers
Tokens
"Love" token, awarded by Jdlrobson.

Description

Moving median for first paint dropped on 26th/27th April as did total page load time for 95th and 99th percentile. CSS dropped for Barack Obama/Facebook around this time. Webpagetest runs showed no change in first paint.

Screen Shot 2018-05-01 at 1.54.18 PM.png (350×1 px, 84 KB)

Screen Shot 2018-05-01 at 1.55.24 PM.png (335×715 px, 53 KB)

Screen Shot 2018-05-01 at 1.55.53 PM.png (253×1 px, 78 KB)

Screen Shot 2018-05-01 at 2.05.24 PM.png (263×1 px, 79 KB)

Graphs: https://grafana-admin.wikimedia.org/dashboard/db/mobile-2g?orgId=1
Could the CSS drop be related to the real world device data or is this just relating to our instrumentation?

During this period there are several changes that may have caused this:

Any way we can work out what caused this and do more of it?

Details

SubjectRepoBranchLines +/-
ext.navigationTiming: Listen for window.onload, not document.onloadmediawiki/extensions/NavigationTimingwmf/1.32.0-wmf.1+1 -1
Restore NavigationTiming@1.32.0-wmf.1 back to its original branch pointsmediawiki/extensions/NavigationTimingwmf/1.32.0-wmf.1+13 -20
ext.navigationTiming: Listen for window.onload, not document.onloadmediawiki/extensions/NavigationTimingwmf/1.32.0-wmf.2+1 -1
ext.navigationTiming: Listen for window.onload, not document.onloadmediawiki/extensions/NavigationTimingmaster+1 -1
Don't trust loadEventEnd being set immediatelymediawiki/extensions/NavigationTimingmaster+18 -3
Reset NavigationTiming@1.32.0-wmf.1 to state of 1.31.0-wmf.30mediawiki/extensions/NavigationTimingwmf/1.32.0-wmf.1+20 -29
Don't trust loadEventEnd being set immediatelymediawiki/extensions/NavigationTimingwmf/1.32.0-wmf.1+18 -2
Don't trust loadEventEnd being set immediatelymediawiki/extensions/NavigationTimingmaster+18 -2
Customize query in gerrit

Related Objects

Event Timeline

Jdlrobson created this task.May 1 2018, 9:05 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptMay 1 2018, 9:05 PM
Jdlrobson updated the task description. (Show Details)May 1 2018, 9:05 PM
Jdlrobson added a project: Performance-Team.
Jdlrobson mentioned this in T182648: [EPIC] Review, rearrange and remove unnecessary CSS in the mobile site.
Jdlrobson updated the task description. (Show Details)
Volker_E subscribed.May 1 2018, 10:16 PM
Jdlrobson moved this task from Incoming to Needs Prioritization on the Web-Team-Backlog board.May 1 2018, 10:26 PM
Peter subscribed.May 2 2018, 3:51 AM
Peter added subscribers: • Imarlier, Krinkle.May 2 2018, 4:11 AM

We have the change on desktop too both median and p95 (first paint/loadEventEnd):
https://grafana.wikimedia.org/dashboard/db/navigation-timing-by-platform?refresh=5m&orgId=1&var-metric=firstPaint&var-platform=desktop&var-users=anonymous

Screen Shot 2018-05-02 at 6.00.33 AM.png (840×2 px, 427 KB)

I think it looks like something how we measure then, let us backtrack it. @Krinkle @Imarlier does it ring a bell what have been going out? We have a lower report rate too:
https://grafana.wikimedia.org/dashboard/db/navigation-timing-by-browser?refresh=5m&panelId=6&fullscreen&orgId=1&var-metric=firstPaint&var-browserFamily=All&var-browserVersion=all&var-m=median

• Gilles subscribed.May 2 2018, 8:31 AM

On late April 26th group 2 wikis moved to 1.32.0-wmf.1

This included the following NavigationTiming changes on the client side:

https://gerrit.wikimedia.org/r/#/c/428551/
https://gerrit.wikimedia.org/r/#/c/428549/
https://gerrit.wikimedia.org/r/#/c/427931/
https://gerrit.wikimedia.org/r/#/c/427460/

Tomorrow group 2 wikis are moving to 1.32.0-wmf.2 which will include a bunch more NavigationTiming changes...

• Gilles added a comment.May 2 2018, 8:52 AM

Of these changes https://gerrit.wikimedia.org/r/#/c/428551/ seems like the prime suspect to me. While the old code was quite agressive, it didn't trust the fact that the load event would happen on the document. The new code does trust that the document load event will happen if document.readyState != 'complete'. It also trusts that by the time the timeout runs in both situations, loadEventEnd will be set.

https://developer.mozilla.org/en-US/docs/Web/API/Document/readyState mentioned that the "complete" state indicates that the "load event is about to fire". I don't know if the browser has to fire it immediately, though.

Maybe we should start with a more cautious migration away from the old agressive setInterval, and only start doing the old agressive loop waiting on loadEventEnd once we've either caught the onload event or the readyState is "complete"? Kind of a middle ground compared to the current change. And if the assumptions of the new code are correct, it won't loop at all, as it will find loadEventEnd right away after the timeout. I'll write a patch doing that.

gerritbot subscribed.May 2 2018, 9:03 AM

Change 430302 had a related patch set uploaded (by Gilles; owner: Gilles):
[mediawiki/extensions/NavigationTiming@master] Don't trust loadEventEnd being set immediately

https://gerrit.wikimedia.org/r/430302

gerritbot added a project: Patch-For-Review.May 2 2018, 9:03 AM
Jdlrobson awarded a token.May 2 2018, 3:09 PM

Thanks all for digging into this!

Krinkle added a comment.May 2 2018, 4:26 PM
In T193570#4173812, @Gilles wrote:

[..] mentioned that the "complete" state indicates that the "load event is about to fire". I don't know if the browser has to fire it immediately, though.

As far as I understand it, there are no standardised steps for the browser to perform in-between there. They're two public interfaces coming from the same internal transition. There may be additional work going on internally of course, but there are no public events for them, which means no code can run there. The only code that can run after onreadystate-complete and before onload would be a promise handler for a promise that was resolved within the onreadystate handler (given the micro-task queue being cleared before ticking the outer event loop).

It's certainly possible for browsers to behave in non-standard ways though. So let's try it out, but if it doesn't change anything, I'd rather not keep it as defensive code in this case, as I'm afraid it'd do more harm than good (e.g. infinite polling for buggy performance.timing).

Regarding report rates, if loadEventEnd is missing, its report rate should be lower than e.g. responseStart and domComplete. Yet, it seems all our metric report rates went down ~equally on April 26/27:

https://graphite.wikimedia.org/render?width=1200&height=600&from=20180423&until=20180430&target=aliasByNode(frontend.navtiming2.{responseStart,domComplete,firstPaint,loadEventEnd}.overall.sample_rate,1,2)

render.png (600×1 px, 168 KB)

Jdlrobson moved this task from Needs Prioritization to Tracking on the Web-Team-Backlog board.May 2 2018, 5:01 PM
Jdlrobson edited projects, added Web-Team-Backlog (Tracking); removed Web-Team-Backlog.
• Gilles added a comment.May 2 2018, 5:11 PM

I agree that it's an unlikely cause, but worth ruling out. Have any changes on the backend/ingestion pipeline happened around that time?

gerritbot added a comment.May 2 2018, 6:04 PM

Change 430302 merged by jenkins-bot:
[mediawiki/extensions/NavigationTiming@master] Don't trust loadEventEnd being set immediately

https://gerrit.wikimedia.org/r/430302

gerritbot added a comment.May 2 2018, 6:11 PM

Change 430423 had a related patch set uploaded (by Gilles; owner: Gilles):
[mediawiki/extensions/NavigationTiming@master] Don't trust loadEventEnd being set immediately

https://gerrit.wikimedia.org/r/430423

gerritbot added a comment.May 2 2018, 6:12 PM

Change 430423 abandoned by Gilles:
Don't trust loadEventEnd being set immediately

https://gerrit.wikimedia.org/r/430423

gerritbot added a comment.May 2 2018, 6:15 PM

Change 430424 had a related patch set uploaded (by Gilles; owner: Gilles):
[mediawiki/extensions/NavigationTiming@wmf/1.32.0-wmf.1] Don't trust loadEventEnd being set immediately

https://gerrit.wikimedia.org/r/430424

ReleaseTaggerBot added a project: MW-1.32-notes (WMF-deploy-2018-05-08 (1.32.0-wmf.3)).May 2 2018, 7:00 PM
Krinkle triaged this task as Medium priority.May 3 2018, 12:14 AM
Krinkle removed projects: MW-1.32-notes (WMF-deploy-2018-05-08 (1.32.0-wmf.3)), Performance Issue.
gerritbot added a comment.May 3 2018, 12:20 AM

Change 430424 merged by jenkins-bot:
[mediawiki/extensions/NavigationTiming@wmf/1.32.0-wmf.1] Don't trust loadEventEnd being set immediately

https://gerrit.wikimedia.org/r/430424

Krinkle mentioned this in T193693: Exception in load-callback for schema.SaveTiming: "ext.navigationTiming.rumSpeedIndex" not loaded.May 3 2018, 12:37 AM
ReleaseTaggerBot added a project: MW-1.32-notes (WMF-deploy-2018-04-24 (1.32.0-wmf.1)).May 3 2018, 1:00 AM
• Gilles added a comment.May 3 2018, 12:42 PM

It's hard to say if the backported "fix" had an effect yet, since it was deployed around the lowest traffic point of the day. But so far at this time we have equivalent figures as yesterday, which are 1/3 lower than 7 days ago.

gerritbot added a comment.May 3 2018, 7:33 PM

Change 430651 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/extensions/NavigationTiming@wmf/1.32.0-wmf.1] Reset NavigationTiming@1.32.0-wmf.1 to state of 1.31.0-wmf.30

https://gerrit.wikimedia.org/r/430651

gerritbot added a comment.May 3 2018, 7:57 PM

Change 430651 merged by jenkins-bot:
[mediawiki/extensions/NavigationTiming@wmf/1.32.0-wmf.1] Reset NavigationTiming@1.32.0-wmf.1 to state of 1.31.0-wmf.30

https://gerrit.wikimedia.org/r/430651

Krinkle added a comment.EditedMay 3 2018, 8:41 PM

Seeing the report rate drop in both NavigationTiming and SaveTming events (from Statsd/Graphite perspective):

frontend.navtiming.domComplete.overall.sample_rate
render-1.png (600×1 px, 68 KB)
mw.performance.save.sample_rate
render.png (600×1 px, 71 KB)

We (@Gilles, @Imarlier and myself) went over different parts of the stack and ruled out various changes to the processing backends (navtimig, coal, their change of hardware and deployment methods; T159354, T186774, T191994).

That leaves: Kafka, EventLogging, Varnish, our client-code, and then actual devices/browsers.

Kafka metrics show the same drop for our schemas:

https://grafana.wikimedia.org/dashboard/db/eventlogging-schema?orgId=1&from=1524564000000&to=1525309200000

Screen Shot 2018-05-03 at 21.42.15.png (874×2 px, 150 KB)

And the above branch revert of NavigationTiming@1.32.0-wmf.1 restored the volume and typical median/p75 values so I guess it was our client code after all.

https://graphite.wikimedia.org/render?width=1200&height=600&from=00:0020180503&until=20:4020180503&target=frontend.navtiming.domComplete.overall.sample_rate

render-2.png (600×1 px, 69 KB)

gerritbot added a comment.May 3 2018, 9:06 PM

Change 430802 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/extensions/NavigationTiming@wmf/1.32.0-wmf.1] Restore NavigationTiming@1.32.0-wmf.1 back to its original branch points

https://gerrit.wikimedia.org/r/430802

• Chris407 subscribed.May 3 2018, 9:09 PM
This comment was removed by • demon.
gerritbot added a comment.May 3 2018, 9:11 PM

Change 430805 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/extensions/NavigationTiming@master] ext.navigationTiming: Listen for window.onload, not document.onload

https://gerrit.wikimedia.org/r/430805

• Chris407 renamed this task from Why did first paint/fully loaded time drop (in a good way!) on mobile? to Heyy.May 3 2018, 9:12 PM
gerritbot added a comment.May 3 2018, 9:12 PM

Change 430806 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/extensions/NavigationTiming@wmf/1.32.0-wmf.1] ext.navigationTiming: Listen for window.onload, not document.onload

https://gerrit.wikimedia.org/r/430806

• Gilles renamed this task from Heyy to Why did first paint/fully loaded time drop (in a good way!) on mobile?.May 3 2018, 9:13 PM
• Gilles changed the visibility from "Public (No Login Required)" to "Custom Policy".
• Gilles removed a subscriber: • Chris407.
gerritbot added a comment.May 3 2018, 9:27 PM

Change 430805 merged by jenkins-bot:
[mediawiki/extensions/NavigationTiming@master] ext.navigationTiming: Listen for window.onload, not document.onload

https://gerrit.wikimedia.org/r/430805

ReleaseTaggerBot edited projects, added MW-1.32-notes (WMF-deploy-2018-05-08 (1.32.0-wmf.3)); removed MW-1.32-notes (WMF-deploy-2018-04-24 (1.32.0-wmf.1)).May 3 2018, 10:01 PM
• demon subscribed.May 3 2018, 10:02 PM
gerritbot added a comment.May 3 2018, 10:09 PM

Change 430821 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/extensions/NavigationTiming@wmf/1.32.0-wmf.2] ext.navigationTiming: Listen for window.onload, not document.onload

https://gerrit.wikimedia.org/r/430821

Krinkle added a comment.May 3 2018, 10:12 PM

@demon At this point in time, wmf.1 is fine because earlier today I reverted NavigationTiming's wmf.1 branch back to the state of 1.31.0-wmf.30. That helped isolate the problem.

Master is fixed now, through https://gerrit.wikimedia.org/r/430805 (3abd83ff).

To apply to wmf.1:

To apply to wmf.2:

Aklapper changed the visibility from "Custom Policy" to "Public (No Login Required)".May 3 2018, 10:12 PM
gerritbot added a comment.May 3 2018, 11:01 PM

Change 430821 merged by jenkins-bot:
[mediawiki/extensions/NavigationTiming@wmf/1.32.0-wmf.2] ext.navigationTiming: Listen for window.onload, not document.onload

https://gerrit.wikimedia.org/r/430821

gerritbot added a comment.May 3 2018, 11:05 PM

Change 430802 merged by jenkins-bot:
[mediawiki/extensions/NavigationTiming@wmf/1.32.0-wmf.1] Restore NavigationTiming@1.32.0-wmf.1 back to its original branch points

https://gerrit.wikimedia.org/r/430802

gerritbot added a comment.May 3 2018, 11:05 PM

Change 430806 merged by jenkins-bot:
[mediawiki/extensions/NavigationTiming@wmf/1.32.0-wmf.1] ext.navigationTiming: Listen for window.onload, not document.onload

https://gerrit.wikimedia.org/r/430806

Stashbot subscribed.May 3 2018, 11:09 PM

Mentioned in SAL (#wikimedia-operations) [2018-05-03T23:09:32Z] <krinkle@tin> Synchronized php-1.32.0-wmf.1/extensions/NavigationTiming/: If293a156cac / T193570 (duration: 01m 17s)

Stashbot added a comment.May 3 2018, 11:12 PM

Mentioned in SAL (#wikimedia-operations) [2018-05-03T23:12:40Z] <krinkle@tin> Synchronized php-1.32.0-wmf.2/extensions/NavigationTiming/: If293a156ca / T193570 (duration: 01m 16s)

ReleaseTaggerBot edited projects, added MW-1.32-notes (WMF-deploy-2018-04-24 (1.32.0-wmf.1)); removed MW-1.32-notes (WMF-deploy-2018-05-08 (1.32.0-wmf.3)).May 4 2018, 12:00 AM
• Gilles closed this task as Resolved.May 4 2018, 7:47 AM
• Gilles claimed this task.

As expected, the metrics are back to their old values:

https://grafana.wikimedia.org/dashboard/db/navigation-timing-by-platform?refresh=5m&orgId=1&var-metric=firstPaint&var-platform=desktop&var-users=anonymous&from=now-30d&to=now

Capture d'écran 2018-05-04 09.46.54.png (439×1 px, 95 KB)

Krinkle edited projects, added NavigationTiming; removed Patch-For-Review.May 4 2018, 3:51 PM
Krinkle added a project: Wikimedia-Performance-publish.May 5 2018, 6:12 PM
Krinkle moved this task from Untriaged to Ready for write-up on the Wikimedia-Performance-publish board.
• Vvjjkkii renamed this task from Why did first paint/fully loaded time drop (in a good way!) on mobile? to dudaaaaaaa.Jul 1 2018, 1:13 AM
• Vvjjkkii reopened this task as Open.
• Vvjjkkii removed • Gilles as the assignee of this task.
• Vvjjkkii raised the priority of this task from Medium to High.
• Vvjjkkii added projects: CheckUser, Connected-Open-Heritage-Batch-uploads (RAÄ-KMB_1_2017-02), Tamil-Sites, Gamepress, Hashtags, Jade, KartoEditor, Language-2018-Apr-June, New-Editor-Experiences, Mail, TCB-Team (now WMDE-TechWish).
• Vvjjkkii updated the task description. (Show Details)
• Vvjjkkii removed subscribers: gerritbot, Aklapper.
CommunityTechBot renamed this task from dudaaaaaaa to Why did first paint/fully loaded time drop (in a good way!) on mobile?.Jul 2 2018, 2:52 PM
CommunityTechBot closed this task as Resolved.
CommunityTechBot assigned this task to • Gilles.
CommunityTechBot lowered the priority of this task from High to Medium.
CommunityTechBot updated the task description. (Show Details)
CommunityTechBot removed projects: TCB-Team (now WMDE-TechWish), Mail, New-Editor-Experiences, Language-2018-Apr-June, KartoEditor, Jade, Hashtags, Gamepress, Tamil-Sites, Connected-Open-Heritage-Batch-uploads (RAÄ-KMB_1_2017-02), CheckUser.
CommunityTechBot added subscribers: gerritbot, Aklapper.
Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL · Credits