Page MenuHomePhabricator
Create Task
Maniphest T160315

Remove mwLoadStart/mediaWikiLoadStart and track mwLoadEnd relative to fetchStart
Closed, ResolvedPublic
Actions

Assigned To
Krinkle
Authored By
Peter
Mar 13 2017, 7:52 AM
Tags
Referenced Files
F17776542: render-2.png
May 5 2018, 12:24 AM
F17770996: render.png
May 4 2018, 11:56 PM
F17771081: render-1.png
May 4 2018, 11:56 PM
F17333663: render-2.png
Apr 27 2018, 3:39 AM
F8808903: Screen Shot 2017-07-21 at 19.45.52.png
Jul 22 2017, 2:51 AM
F8808906: Screen Shot 2017-07-21 at 19.46.05.png
Jul 22 2017, 2:51 AM
F8808901: Screen Shot 2017-07-21 at 19.46.22.png
Jul 22 2017, 2:51 AM
F6548323: 1330-mwLoadStart.json.gz
Mar 14 2017, 5:31 AM
View All 12 Files
Subscribers
Aklapper
gerritbot
Krinkle
Peter
Stashbot

Description

Ever since we moved to 100% async JS, mwLoadStart stopped being useful, since it races with other things (causing the variation in described in the original description of this task).

References to mediaWikiLoadStart variable:

  • mediawiki/extensions/NavigationTiming: Used to compute the mediaWikiLoadComplete delta. Let's remove and report mediaWikiLoadEnd instead.
  • mediawiki/extensions/VisualEditor: Removed.
  • puppet: navtiming.py – Unused. (We only report mediaWikiLoadComplete). Safe to remove.
  • puppet: coal.py – Unused. (We only report mediaWikiLoadComplete). Safe to remove.

References to mwLoadStart mark:

  • mediawiki/core - Definition. Unused. Safe to remove. Maybe rename to mwStartup?

Details

Show related patches Customize query in gerrit

Related Objects

Event Timeline

Peter created this task.Mar 13 2017, 7:52 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptMar 13 2017, 7:52 AM
Peter added a comment.Mar 14 2017, 5:31 AM

I've started to collect some example tracelogs from Chrome. Drag and drop it into your devtools timeline (unpack it first), Taking two exteremes first: One with mwLoadStart 550 ms and one 1330 ms.

550ms-mwLoadStart.json.gz812 KBDownload

1330-mwLoadStart.json.gz825 KBDownload

• Gilles moved this task from Inbox, needs triage to Backlog: Maintenance, non-prioritized on the Performance-Team board.Mar 15 2017, 7:10 PM
Peter triaged this task as Medium priority.May 30 2017, 9:40 AM
Krinkle subscribed.EditedJul 22 2017, 2:51 AM

Looking at it again, looks like it has gotten a fair bit more stable.

BrowserGraphVariance in last 5-10 days
Firefox
Screen Shot 2017-07-21 at 19.45.52.png (944×2 px, 462 KB)
mwLoadStart/mwLoadEnd: ± 0.2s
Chrome
Screen Shot 2017-07-21 at 19.46.05.png (942×2 px, 246 KB)
mwLoadStart/mwLoadEnd: ± 0.1s
IE
Screen Shot 2017-07-21 at 19.46.22.png (964×2 px, 333 KB)
mwLoadStart: ± 0.1s, mwLoadEnd: Alternates between ~1.7s and ~2.6s (± 0.1s). But a gap of around 1s. It seems to consistently alternate between 2 scenarios.
Krinkle moved this task from Backlog: Maintenance, non-prioritized to To-do: Goals prioritized current Quarter on the Performance-Team board.Jul 22 2017, 2:52 AM
Peter moved this task from To-do: Goals prioritized current Quarter to Backlog: Maintenance, non-prioritized on the Performance-Team board.Sep 12 2017, 9:42 AM
Peter added a project: MediaWiki-ResourceLoader.Sep 12 2017, 1:33 PM

The mwLoadStart doesn't gives us an extra value since we made the loading async. Instead we should change the mwLoadEnd to be relative when the page starts to load. Let me update the description later.

• Gilles renamed this task from Investigate the big difference in mwLoadStart to Remove mwLoadStart and track mwLoadEnd relative to fetchStart.Sep 12 2017, 1:36 PM
• Gilles updated the task description. (Show Details)
Krinkle moved this task from Inbox to Accepted Enhancement on the MediaWiki-ResourceLoader board.Sep 20 2017, 6:53 PM
gerritbot subscribed.Oct 31 2017, 2:57 AM

Change 387510 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/extensions/ImageMetrics@master] Remove use of 'mediaWikiLoadStart'

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

gerritbot added a project: Patch-For-Review.Oct 31 2017, 2:57 AM
Krinkle updated the task description. (Show Details)Oct 31 2017, 3:01 AM
Krinkle updated the task description. (Show Details)
Krinkle updated the task description. (Show Details)Nov 1 2017, 12:36 AM
Krinkle removed a project: Patch-For-Review.
gerritbot added a comment.Nov 1 2017, 12:48 AM

Change 387510 merged by jenkins-bot:
[mediawiki/extensions/ImageMetrics@master] Remove use of 'mediaWikiLoadStart'

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

Krinkle mentioned this in T104902: Refactor Navigation Timing gathering to produce reliable stackable measures (aka "frontend.navtiming2").Nov 7 2017, 10:22 PM
Krinkle mentioned this in T180598: NavigationTimingv2 misses mediaWikiLoadComplete.Nov 17 2017, 8:12 PM
Krinkle moved this task from Backlog: Maintenance, non-prioritized to To-do: Goals, prioritized next 4 Quarters on the Performance-Team board.Jan 18 2018, 9:41 AM
Krinkle added a project: NavigationTiming.Feb 2 2018, 3:03 AM
Krinkle mentioned this in T186295: Slim down Navigation Timing schema.Feb 2 2018, 3:15 AM
Krinkle moved this task from To-do: Goals, prioritized next 4 Quarters to To-do: Goals prioritized current Quarter on the Performance-Team board.Apr 19 2018, 11:50 PM
gerritbot added a comment.Apr 20 2018, 12:52 AM

Change 427838 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@master] resourceloader: Remove unused mwLoadStart mark

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

gerritbot added a project: Patch-For-Review.Apr 20 2018, 12:52 AM
Krinkle mentioned this in T192623: ResourceLoader 2018 Review.Apr 20 2018, 12:53 AM
gerritbot added a comment.Apr 20 2018, 5:00 PM

Change 427931 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/extensions/NavigationTiming@master] Add mediaWikiLoadEnd, remove mediaWikiLoadComplete

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

gerritbot added a comment.Apr 20 2018, 5:38 PM

Change 427936 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[performance/navtiming@master] Remove reporting for mediaWikiLoadStart and mediaWikiLoadComplete

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

gerritbot added a comment.Apr 20 2018, 5:38 PM

Change 427937 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[performance/navtiming@master] Add tests for 'mediaWikiLoadEnd' metric

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

Krinkle claimed this task.Apr 20 2018, 5:51 PM

@Peter This has been in the backlog for a while, but to get metric in-place for T192623, I've written the patches for now. Was quite straight-forward because you already did most of the work in 2015 when we first introduced the mediaWikiLoadEnd metric :)

Krinkle updated the task description. (Show Details)Apr 20 2018, 5:51 PM
Peter added a comment.Apr 23 2018, 8:17 AM

I kind of like the mwLoadStart metric :) I've been looking into the problem we have with the unstable metrics for Firefox on synthetic T185186 and I think I see a pattern and the mwLoadStart helped me.

Here a summary for 11 runs on Firefox:
http://webpagereplay-wikimedia.s3.us-east-1.amazonaws.com/enwiki/desktop/firefox/100/Facebook/2018-04-23-05-53/browsertime.json

The firstPaint (we use both the one from the video but also the "hidden" one in Firefox that seems to work ok for Wikipedia, you enable it with dom.performance.time_to_non_blank_paint.enabled). It doesn't mattern which metric we use, the pattern is the same.

We have two kind of buckets when first paint happens here: One 1.5 seconds and one 2.5 seconds roughly. For the ones when first paint happens at 1.5 seconds the mwLoadStart match first paint, it happens around 1.5 seconds. So we start to render the screen and parse the JavaScript.

The other bucket start to render at 2.5 seconds and mwLoadStarts happens earlier 800-900 ms and block the rendering. It's seems to correlate for the other pages two where we have the two bucket scenarios: Early mwLoadStarts gives us a slow first paint on Firefox.

Without the mwLoadStart I've wouldn't been able to see that, the other metrics gives me no idea what's going on (missing HAR doesn't help either).

gerritbot added a comment.Apr 23 2018, 11:17 AM

Change 427931 merged by jenkins-bot:
[mediawiki/extensions/NavigationTiming@master] Add mediaWikiLoadEnd, remove mediaWikiLoadComplete

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

ReleaseTaggerBot added a project: MW-1.32-notes (WMF-deploy-2018-04-24 (1.32.0-wmf.1)).Apr 23 2018, 12:00 PM
Krinkle updated the task description. (Show Details)Apr 23 2018, 2:54 PM
gerritbot added a comment.Apr 23 2018, 2:58 PM

Change 427936 merged by jenkins-bot:
[performance/navtiming@master] Remove reporting for mediaWikiLoadStart and mediaWikiLoadComplete

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

gerritbot added a comment.Apr 23 2018, 2:58 PM

Change 427937 merged by jenkins-bot:
[performance/navtiming@master] Add tests for 'mediaWikiLoadEnd' metric

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

Krinkle added a comment.Apr 23 2018, 5:55 PM
In T160315#4148868, @Peter wrote:

The other bucket start to render at 2.5 seconds and mwLoadStarts happens earlier 800-900 ms and block the rendering. It's seems to correlate for the other pages two where we have the two bucket scenarios: Early mwLoadStarts gives us a slow first paint on Firefox.

Without the mwLoadStart I've wouldn't been able to see that, the other metrics gives me no idea what's going on (missing HAR doesn't help either).

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

I think the mwLoadStart still could help us, checkout https://phabricator.wikimedia.org/T160315#4148868 where it helped me to understand the slow first paint for Firefox. Even though the JavaScript is async the user have different experience depending in when the script is parsed right?

Yes, it is useful to see when the request happened, but we also have other requests that are useful to track in that way.I am not sure whether we should metrics for them, however, because they will vary a lot and (I believe) they are okay to vary.

The end-result matters more, which metrics like firstPaint and mwLoadEnd measure. When we find an issue there, or high variance, we can investigate based on other metrics, but also based on the timeline, right? For example, another problem we found in Firefox recently related to image size and load time.

Maybe we can check if the startup module request shows in the timeline and correlates the same way as mwLoadStart? Anyway, we can keep it for now, but perhaps without polyfill and with a slightly different name to fix the confusion of it relating to mwLoadEnd (which is a problem, per this task). Maybe mwStartup.

gerritbot added a comment.Apr 23 2018, 6:10 PM

Change 428397 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/extensions/VisualEditor@master] init: Use navStart directly in mw.trackSubscriber

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

gerritbot added a comment.Apr 24 2018, 1:20 AM

Change 428549 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/extensions/NavigationTiming@master] Actually update schema revision

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

gerritbot added a comment.Apr 24 2018, 2:32 AM

Change 428553 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[performance/coal@master] coal: Remove reporting for mediaWikiLoadStart and mediaWikiLoadComplete

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

gerritbot added a comment.Apr 24 2018, 7:10 AM

Change 428549 merged by jenkins-bot:
[mediawiki/extensions/NavigationTiming@master] Actually update schema revision

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

Krinkle updated the task description. (Show Details)Apr 25 2018, 10:47 PM
gerritbot added a comment.Apr 26 2018, 4:20 AM

Change 428553 merged by Krinkle:
[performance/coal@master] coal: Remove reporting for mediaWikiLoadStart and mediaWikiLoadComplete

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

Krinkle removed a project: MW-1.32-notes (WMF-deploy-2018-04-24 (1.32.0-wmf.1)).Apr 26 2018, 4:25 AM
Krinkle updated the task description. (Show Details)
gerritbot added a comment.Apr 27 2018, 3:15 AM

Change 429371 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/extensions/NavigationTiming@master] ext.navigationTiming: Don't send beacon without basic NavTiming support

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

gerritbot added a comment.Apr 27 2018, 3:15 AM

Change 429372 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/extensions/NavigationTiming@master] ext.navigationTiming: Fix mediaWikiLoadEnd metric (offset, not timestamp)

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

Krinkle added a comment.EditedApr 27 2018, 3:39 AM

https://graphite.wikimedia.org/render?target=coal.mediaWikiLoadEnd&from=20180424&until=20180502&width=800&height=400&yMin=1524000000000

Time increasing, one minute every minute
render-2.png (600×1 px, 27 KB)
                          ¯\_(ツ)_/¯
gerritbot added a comment.Apr 28 2018, 12:04 PM

Change 427838 merged by jenkins-bot:
[mediawiki/core@master] resourceloader: Remove mwPerformance stub and rename mwLoadStart mark

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

gerritbot added a comment.Apr 30 2018, 7:54 AM

Change 429371 merged by jenkins-bot:
[mediawiki/extensions/NavigationTiming@master] ext.navigationTiming: Don't send beacon without basic NavTiming support

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

gerritbot added a comment.Apr 30 2018, 7:54 AM

Change 429372 merged by jenkins-bot:
[mediawiki/extensions/NavigationTiming@master] ext.navigationTiming: Fix mediaWikiLoadEnd metric (offset, not timestamp)

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

ReleaseTaggerBot added a project: MW-1.32-notes (WMF-deploy-2018-05-01 (1.32.0-wmf.2)).Apr 30 2018, 8:00 AM
Krinkle mentioned this in T185077: Add User-Timing mark for base-modules execution.May 4 2018, 3:15 AM
Krinkle removed a project: Patch-For-Review.May 4 2018, 3:30 AM
Krinkle added a comment.EditedMay 4 2018, 11:56 PM

Looks better now with the above fix in wmf.2 having gone to all wikis.

https://graphite.wikimedia.org/render?target=frontend.navtiming2.mediaWikiLoadEnd.overall.median&from=20:00_20180504&until=00:00_20180505&width=800&height=400

render-2.png (400×800 px, 48 KB)

Stashbot subscribed.May 5 2018, 12:26 AM

Mentioned in SAL (#wikimedia-operations) [2018-05-05T00:26:17Z] <Krinkle> Purging values for navtiming 'mediaWikiLoadEnd' sub-properties from 2018-04-21 to 2018-05-04T04:40:00 (T160315)

Stashbot added a comment.May 5 2018, 12:35 AM

Mentioned in SAL (#wikimedia-operations) [2018-05-05T00:35:46Z] <Krinkle> Delete navtiming 'mediaWikiLoadComplete' metrics (T160315)

Krinkle added a comment.May 5 2018, 12:54 AM

Purged timing metrics ('count', 'mean', 'p50', 'p95', 'p999', 'sample_rate', 'upper', 'lower', 'median', 'p75', 'p99', 'rate') on following base names between the point where we added the metric (1 week ago) and when the fix went out to all wikis (yesterday) – during which it was accidentally was recording timestamps instead of durations:

frontend.navtiming.mediaWikiLoadEnd.overall.%
frontend.navtiming2.mediaWikiLoadEnd.overall.%

frontend.navtiming.mediaWikiLoadEnd.mobile.overall.%
frontend.navtiming2.mediaWikiLoadEnd.mobile.overall.%
frontend.navtiming.mediaWikiLoadEnd.desktop.overall.%
frontend.navtiming2.mediaWikiLoadEnd.desktop.overall.%

frontend.navtiming_oversample.mediaWikiLoadEnd.overall.%
frontend.navtiming2_oversample.mediaWikiLoadEnd.overall.%

(using the ugly hack that is graphite_wipe.py)

Krinkle closed this task as Resolved.May 5 2018, 12:54 AM
gerritbot added a comment.May 31 2018, 7:16 PM

Change 428397 merged by jenkins-bot:
[mediawiki/extensions/VisualEditor@master] mw.trackSubscriber: Remove action.init.timing value

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

ReleaseTaggerBot edited projects, added MW-1.32-notes (WMF-deploy-2018-06-05 (1.32.0-wmf.7)); removed MW-1.32-notes (WMF-deploy-2018-05-01 (1.32.0-wmf.2)).May 31 2018, 8:00 PM
gerritbot added a comment.Jun 5 2018, 11:31 PM

Change 437647 had a related patch set uploaded (by Aaron Schulz; owner: Aaron Schulz):
[mediawiki/core@master] resourceloader: remove "mediaWikiLoadStart" and move mwNow() to mediawiki.js

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

gerritbot added a project: Patch-For-Review.Jun 5 2018, 11:31 PM
Krinkle renamed this task from Remove mwLoadStart and track mwLoadEnd relative to fetchStart to Remove mwLoadStart mark() and track mwLoadEnd relative to fetchStart.Jun 5 2018, 11:36 PM
Krinkle renamed this task from Remove mwLoadStart mark() and track mwLoadEnd relative to fetchStart to Remove mwLoadStart/mediaWikiLoadStart and track mwLoadEnd relative to fetchStart.
Krinkle updated the task description. (Show Details)
gerritbot added a comment.Jun 6 2018, 3:43 PM

Change 437647 merged by jenkins-bot:
[mediawiki/core@master] resourceloader: remove "mediaWikiLoadStart" and move mwNow() to mediawiki.js

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

ReleaseTaggerBot edited projects, added MW-1.32-notes (WMF-deploy-2018-06-12 (1.32.0-wmf.8)); removed MW-1.32-notes (WMF-deploy-2018-06-05 (1.32.0-wmf.7)).Jun 6 2018, 4:01 PM
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