I did this analysis to better understand how T142129: Source code eval should be async in mw.loader.work will change things (and to prevent certain regressions).
Critical path examination
Gathered with the DevTools in Chrome canary 52 on a MacBook Pro, running MediaWiki-Vagrant.
- CPU throttle: 2x slowdown.
- Network throttle: 100ms 750kb/s ("Regular 3G")
- Repeat view (local storage warmed up)
Simplified for brevity.
300ms:
- Receive Response (Main_Page)
- Send Request (Priority Highest; load.php?modules=... styles)
- Send Request (Priority Low; load.php?modules=startup)
- Send Request (Priority Highest; load.php?modules=site.styles)
- Evaluate Script. documentElement.className
- Evaluate Script. RLQ.push(config, state, implement, load top)
- HTML: Parse
- Send Request (poweredby_mediawiki)
- Receive Response (load.php?modules=site.styles)
600ms:
- Receive Response (load.php?modules=... styles)
- Evaluate Script. RLQ.push(load bottom, more config)
- HTML: Parse
- Paint: Calculate styles
- Send Request (mediawiki-vagrant.png logo)
- Paint: Layout
- Mark: DOMContentLoaded
This shows (as we know) that stylesheets block execution of inline scripts. The bottom inline script doesn't execute until the stylesheet is fully received and parsed.
See also:
This also shows (as we know) that the discovery of the logo resource is blocked on the arrival of the main stylesheet. While first paint usually waits for the main stylesheet, the logo will have only just started loading in the background at that time, and as such tends to show up later. See T100999.
800ms:
- Mark: firstPaint
- Finish Loading (poweredby_mediawiki)
- Finish Loading (mediawiki-vagrant.png logo)
1000ms:
- Finish Loading (load.php?modules=startup)
- Evaluate Script. isCompatible, getElementsByTagName('head'), appendChild
- Send Request (load.php?modules=jquery mediawiki)
1300ms:
- Finish Loading (load.php?modules=jquery mediawiki)
- Evaluate Script.
- (83ms) define jQuery, Sizzle and Major GC
- (0.5ms) define mw.now
- (0.3ms) define $j via mw.log.deprecate
- Event: load (load.php?modules=jquery mediawiki)
- Evaluate Script onreadystatechange/startUp from load.php?modules=startup
- (3ms) mw.loader.register
- (0.3ms) mw.config.set
- (120ms) run RLQ functions from HTML
- (0.1ms) mw.config.set from top
- (2ms) mw.loader.state from top
- (56ms) mw.loader.implement user.tokens and user.options
- (52ms) execute/runScript/using/work (most store.init and globalEval)
- (62ms) mw.loader.load top queue
- (21ms) mw.loader.load bottom queue (also pushed into RLQ already)
The slow mw.loader.implement statement is confusing at first because it's merely implementing two tiny private modules that have almost no execution time.
The reason for the slow down is that all modules must wait for legacy modules, which technically must include embedded private modules like these as well. So this is the first point where something requires the legacy modules, which we end up loading and evaluating from cache at this point. These legacy modules are removed in https://gerrit.wikimedia.org/r/282505. The general change to make cache-eval asynchronous would mitigate this as well by deferred it to later (T142129; https://gerrit.wikimedia.org/r/304158).
1500ms:
- Event: load; Function Call (jQuery.ready event fires)
- jquery.js (internal listeners)
- (19ms) mediawiki.js listener (code that'll emit mwLoadEnd)
- mediawiki.page.startup listener (for mw.hook#fire)
- (15ms) vector.js listener
- Mark: Load
For more details about mwLoadEnd and vector.js overhead, see https://gerrit.wikimedia.org/r/306871 and https://gerrit.wikimedia.org/r/306869 .
1800ms
- Timer Fired; Function Call (addEmbeddedCSS)
- newStyleTag
- (62ms) runScript
This timer marks the end of the CSS buffer for all top and bottom modules. Any modules with scripts but no styles will have executed already in the load() around 1300ms. Execution for modules with styles happens here.
A few notable scripts:
(62ms) runScript
- (3ms) mediawiki.action.view.postEdit (cookie.get, cookie.set, setTimeout)
- (2ms) ext.uls.common (mw.loader.using)
- (17ms) ext.uls.webfonts (mw.webfonts.setup, $(body).css, Recalculate Style Forced reflow)
- (5ms) ext.uls.interface (jQuery/querySelectorAll, Message#parser, jQuery#text, Store#get)
- (27ms) mediawiki.page.ready
- $.fn.makeCollapsible
- $.fn.checkboxShiftClick
- (25ms) $.fn.updateTooltipAccessKeys (Message#parser)
2900ms
- Timer Fired; Function Call (addEmbeddedCSS)
- newStyleTag
- (25ms) runScript
This timer marks the end of the first (and usually only) CSS buffer for modules lazy-loaded via mw.loader.using() by one of the previously executed scripts.
A few notable scripts:
(25ms) runScript
- (7ms) ext.visualEditor.desktopArticleTarget.init (cookie.get, DOM writes)
- (14ms) mediawiki.searchSuggest ($.fn.suggestions, $.fn.css, Recalculate Style Forced reflow, Minor GC)
2990ms
Timer Fired; Function Call ($.fn.webfonts, WebFonts#parse, $.fn.css, Recalculate Style Forced reflow, $.fn.is, $.fn.find)
Relevant open tasks and patches:
- T100999: Make the logo's loading priority higher
- T142129: Source code eval should be async in mw.loader.work
- https://gerrit.wikimedia.org/r/282505 (resourceloader: Avoid request overhead for legacy modules)
- https://gerrit.wikimedia.org/r/304158 (resourceloader: Make cache-eval asynchronous)
- https://gerrit.wikimedia.org/r/306871 (mw.loader: Make mwLoadEnd less expensive)
- https://gerrit.wikimedia.org/r/306869 (vector: Calculate #p-cactions width lazily)
- https://gerrit.wikimedia.org/r/307904 (mediawiki.util: Remove expensive tooltipAccessKeyPrefix assignment)
