Merge "resourceloader: Implement mw.inspect 'time' report"
authorjenkins-bot <jenkins-bot@gerrit.wikimedia.org>
Thu, 23 Aug 2018 18:18:56 +0000 (18:18 +0000)
committerGerrit Code Review <gerrit@wikimedia.org>
Thu, 23 Aug 2018 18:18:56 +0000 (18:18 +0000)
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
+                       };
+               }
+       };
+
+}() );