resourceloader: Implement mw.inspect 'time' report
authorTimo Tijhof <krinklemail@gmail.com>
Tue, 10 Jul 2018 00:28:55 +0000 (17:28 -0700)
committerRoan Kattouw <roan.kattouw@gmail.com>
Thu, 23 Aug 2018 17:54:55 +0000 (10:54 -0700)
When enabling $wgResourceLoaderEnableJSProfiler, mw.loader gets instrumented
with the following timing values for each of the modules loaded on the page:

* 'total' - This measures the time spent in mw.loader#execute(), and
  represents the initialisation of the module's implementation, including
  the registration of messages, templates, and the execution of the 'script'
  closure received from load.php.

* 'script' – This measures only the subset of time spent in the internal
  runScript() function, and represents just the execution of the module's
  JavaScript code as received through mw.loader.implement() from load.php.

  For user scripts and site scripts, this measures the call to domEval
  (formerly known as "globalEval").

* 'execute' - This measures the self time of mw.loader#execute(), which is
  effectively `total - script`.

To view the report, enable the feature, then run `mw.inspect( 'time' )` from
the browser console, which will render a table with the initialisation
overhead from each module used on the page.

Bug: T133646
Change-Id: I68d1193b62c93c97cf09b7d344c896afb437c5ac

includes/DefaultSettings.php
includes/resourceloader/ResourceLoaderStartUpModule.php
maintenance/jsduck/categories.json
resources/src/mediawiki.inspect.js
resources/src/startup/mediawiki.js
resources/src/startup/profiler.js [new file with mode: 0644]

index fdac10a..164eb46 100644 (file)
@@ -3792,6 +3792,16 @@ $wgResourceLoaderMaxQueryLength = false;
  */
 $wgResourceLoaderValidateJS = true;
 
+/**
+ * When enabled, execution of JavaScript modules is profiled client-side.
+ *
+ * Instrumentation happens in mw.loader.profiler.
+ * Use `mw.inspect('time')` from the browser console to display the data.
+ *
+ * @since 1.32
+ */
+$wgResourceLoaderEnableJSProfiler = false;
+
 /**
  * Whether ResourceLoader should attempt to persist modules in localStorage on
  * browsers that support the Web Storage API.
index 2457fe8..99ffcd2 100644 (file)
@@ -388,6 +388,9 @@ class ResourceLoaderStartUpModule extends ResourceLoaderModule {
                if ( $context->getDebug() ) {
                        $mwLoaderCode .= file_get_contents( "$IP/resources/src/startup/mediawiki.log.js" );
                }
+               if ( $this->getConfig()->get( 'ResourceLoaderEnableJSProfiler' ) ) {
+                       $mwLoaderCode .= file_get_contents( "$IP/resources/src/startup/profiler.js" );
+               }
 
                $mapToJson = function ( $value ) {
                        $value = FormatJson::encode( $value, ResourceLoader::inDebugMode(), FormatJson::ALL_OK );
@@ -397,9 +400,23 @@ class ResourceLoaderStartUpModule extends ResourceLoaderModule {
                };
 
                // Perform replacements for mediawiki.js
-               $mwLoaderCode = strtr( $mwLoaderCode, [
+               $mwLoaderPairs = [
                        '$VARS.baseModules' => $mapToJson( $this->getBaseModules() ),
-               ] );
+               ];
+               $profilerStubs = [
+                       '$CODE.profileExecuteStart();' => 'mw.loader.profiler.onExecuteStart( module );',
+                       '$CODE.profileExecuteEnd();' => 'mw.loader.profiler.onExecuteEnd( module );',
+                       '$CODE.profileScriptStart();' => 'mw.loader.profiler.onScriptStart( module );',
+                       '$CODE.profileScriptEnd();' => 'mw.loader.profiler.onScriptEnd( module );',
+               ];
+               if ( $this->getConfig()->get( 'ResourceLoaderEnableJSProfiler' ) ) {
+                       // When profiling is enabled, insert the calls.
+                       $mwLoaderPairs += $profilerStubs;
+               } else {
+                       // When disabled (by default), insert nothing.
+                       $mwLoaderPairs += array_fill_keys( array_keys( $profilerStubs ), '' );
+               }
+               $mwLoaderCode = strtr( $mwLoaderCode, $mwLoaderPairs );
 
                // Perform replacements for startup.js
                $pairs = array_map( $mapToJson, [
@@ -434,13 +451,15 @@ class ResourceLoaderStartUpModule extends ResourceLoaderModule {
        public function getDefinitionSummary( ResourceLoaderContext $context ) {
                global $IP;
                $summary = parent::getDefinitionSummary( $context );
-               $summary[] = [
-                       // Detect changes to variables exposed in mw.config (T30899).
+               $startup = [
+                       // getScript() exposes these variables to mw.config (T30899).
                        'vars' => $this->getConfigSettings( $context ),
-                       // Changes how getScript() creates mw.Map for mw.config
+                       // getScript() uses this to decide how configure mw.Map for mw.config.
                        'wgLegacyJavaScriptGlobals' => $this->getConfig()->get( 'LegacyJavaScriptGlobals' ),
-                       // Detect changes to the module registrations
+                       // Detect changes to the module registrations output by getScript().
                        'moduleHashes' => $this->getAllModuleHashes( $context ),
+                       // Detect changes to base modules listed by getScript().
+                       'baseModules' => $this->getBaseModules(),
 
                        'fileHashes' => [
                                $this->safeFileHash( "$IP/resources/src/startup/startup.js" ),
@@ -448,6 +467,13 @@ class ResourceLoaderStartUpModule extends ResourceLoaderModule {
                                $this->safeFileHash( "$IP/resources/src/startup/mediawiki.requestIdleCallback.js" ),
                        ],
                ];
+               if ( $context->getDebug() ) {
+                       $startup['fileHashes'][] = $this->safeFileHash( "$IP/resources/src/startup/mediawiki.log.js" );
+               }
+               if ( $this->getConfig()->get( 'ResourceLoaderEnableJSProfiler' ) ) {
+                       $startup['fileHashes'][] = $this->safeFileHash( "$IP/resources/src/startup/profiling.js" );
+               }
+               $summary[] = $startup;
                return $summary;
        }
 
index bebee85..6f922a0 100644 (file)
@@ -83,7 +83,6 @@
                                "classes": [
                                        "mw.log",
                                        "mw.inspect",
-                                       "mw.inspect.reports",
                                        "mw.Debug"
                                ]
                        }
index 6c4b80d..f4545de 100644 (file)
        function sortByProperty( array, prop, descending ) {
                var order = descending ? -1 : 1;
                return array.sort( function ( a, b ) {
+                       if ( a[ prop ] === undefined || b[ prop ] === undefined ) {
+                               // Sort undefined to the end, regardless of direction
+                               return a[ prop ] !== undefined ? -1 : b[ prop ] !== undefined ? 1 : 0;
+                       }
                        return a[ prop ] > b[ prop ] ? order : a[ prop ] < b[ prop ] ? -order : 0;
                } );
        }
         *
         * When invoked without arguments, prints all available reports.
         *
-        * @param {...string} [reports] One or more of "size", "css", or "store".
+        * @param {...string} [reports] One or more of "size", "css", "store", or "time".
         */
        inspect.runReports = function () {
                var reports = arguments.length > 0 ?
        };
 
        /**
+        * @private
         * @class mw.inspect.reports
         * @singleton
         */
                                } catch ( e ) {}
                        }
                        return [ stats ];
+               },
+
+               /**
+                * Generate a breakdown of all loaded modules and their time
+                * spent during initialisation (measured in milliseconds).
+                *
+                * This timing data is collected by mw.loader.profiler.
+                *
+                * @return {Object[]} Table rows
+                */
+               time: function () {
+                       var modules;
+
+                       if ( !mw.loader.profiler ) {
+                               mw.log.warn( 'mw.inspect: The time report requires $wgResourceLoaderEnableJSProfiler.' );
+                               return [];
+                       }
+
+                       modules = inspect.getLoadedModules()
+                               .map( function ( moduleName ) {
+                                       return mw.loader.profiler.getProfile( moduleName );
+                               } )
+                               .filter( function ( perf ) {
+                                       // Exclude modules that reached "ready" state without involvement from mw.loader.
+                                       // This is primarily styles-only as loaded via <link rel="stylesheet">.
+                                       return perf !== null;
+                               } );
+
+                       // Sort by total time spent, highest first.
+                       sortByProperty( modules, 'total', true );
+
+                       // Add human-readable strings
+                       modules.forEach( function ( module ) {
+                               module.totalInMs = module.total;
+                               module.total = module.totalInMs.toLocaleString() + ' ms';
+                       } );
+
+                       return modules;
                }
        };
 
index f9a69b8..6ed226c 100644 (file)
@@ -7,7 +7,7 @@
  * @alternateClassName mediaWiki
  * @singleton
  */
-/* global $VARS */
+/* global $VARS, $CODE */
 
 ( function () {
        'use strict';
                                }
 
                                registry[ module ].state = 'executing';
+                               $CODE.profileExecuteStart();
 
                                runScript = function () {
                                        var script, markModuleReady, nestedAddScript;
 
+                                       $CODE.profileScriptStart();
                                        script = registry[ module ].script;
                                        markModuleReady = function () {
+                                               $CODE.profileScriptEnd();
                                                registry[ module ].state = 'ready';
                                                handlePending( module );
                                        };
                                                // Use mw.track instead of mw.log because these errors are common in production mode
                                                // (e.g. undefined variable), and mw.log is only enabled in debug mode.
                                                registry[ module ].state = 'error';
+                                               $CODE.profileScriptEnd();
                                                mw.trackError( 'resourceloader.exception', {
                                                        exception: e, module:
                                                        module, source: 'module-execute'
                                        }
                                }
 
+                               // End profiling of execute()-self before we call checkCssHandles(),
+                               // which (sometimes asynchronously) calls runScript(), which we want
+                               // to measure separately without overlap.
+                               $CODE.profileExecuteEnd();
+
                                // Kick off.
                                cssHandlesRegistered = true;
                                checkCssHandles();
diff --git a/resources/src/startup/profiler.js b/resources/src/startup/profiler.js
new file mode 100644 (file)
index 0000000..5e9b6ab
--- /dev/null
@@ -0,0 +1,81 @@
+/*!
+ * Augment mw.loader to facilitate module-level profiling.
+ *
+ * @author Timo Tijhof
+ * @since 1.32
+ */
+/* global mw */
+( function () {
+       'use strict';
+
+       var moduleTimes = Object.create( null );
+
+       /**
+        * Private hooks inserted into mw.loader code if MediaWiki configuration
+        * `$wgResourceLoaderEnableJSProfiler` is `true`.
+        *
+        * To use this data, run `mw.inspect( 'time' )` from the browser console.
+        * See mw#inspect().
+        *
+        * @private
+        * @class
+        * @singleton
+        */
+       mw.loader.profiler = {
+               onExecuteStart: function ( moduleName ) {
+                       var time = performance.now();
+                       if ( moduleTimes[ moduleName ] ) {
+                               throw new Error( 'Unexpected perf record for "' + moduleName + '".' );
+                       }
+                       moduleTimes[ moduleName ] = {
+                               executeStart: time,
+                               executeEnd: null,
+                               scriptStart: null,
+                               scriptEnd: null
+                       };
+               },
+               onExecuteEnd: function ( moduleName ) {
+                       var time = performance.now();
+                       moduleTimes[ moduleName ].executeEnd = time;
+               },
+               onScriptStart: function ( moduleName ) {
+                       var time = performance.now();
+                       moduleTimes[ moduleName ].scriptStart = time;
+               },
+               onScriptEnd: function ( moduleName ) {
+                       var time = performance.now();
+                       moduleTimes[ moduleName ].scriptEnd = time;
+               },
+
+               /**
+                * For internal use by inspect.reports#time.
+                *
+                * @private
+                * @param {string} moduleName
+                * @return {Object|null}
+                * @throws {Error} If the perf record is incomplete.
+                */
+               getProfile: function ( moduleName ) {
+                       var times, key, execute, script, total;
+                       times = moduleTimes[ moduleName ];
+                       if ( !times ) {
+                               return null;
+                       }
+                       for ( key in times ) {
+                               if ( times[ key ] === null ) {
+                                       throw new Error( 'Incomplete perf record for "' + moduleName + '".', times );
+                               }
+                       }
+                       execute = times.executeEnd - times.executeStart;
+                       script = times.scriptEnd - times.scriptStart;
+                       total = execute + script;
+                       return {
+                               name: moduleName,
+                               execute: execute,
+                               script: script,
+                               total: total
+                       };
+               }
+       };
+
+}() );