From: Timo Tijhof Date: Tue, 10 Jul 2018 00:28:55 +0000 (-0700) Subject: resourceloader: Implement mw.inspect 'time' report X-Git-Tag: 1.34.0-rc.0~4323^2 X-Git-Url: http://git.cyclocoop.org/data/Fool?a=commitdiff_plain;h=7f3c102a3bcbc1a8c6576a1bebf3bfd3c5053200;p=lhc%2Fweb%2Fwiklou.git resourceloader: Implement mw.inspect 'time' report 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 --- diff --git a/includes/DefaultSettings.php b/includes/DefaultSettings.php index fdac10a53e..164eb462f9 100644 --- a/includes/DefaultSettings.php +++ b/includes/DefaultSettings.php @@ -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. diff --git a/includes/resourceloader/ResourceLoaderStartUpModule.php b/includes/resourceloader/ResourceLoaderStartUpModule.php index 2457fe8c72..99ffcd2a94 100644 --- a/includes/resourceloader/ResourceLoaderStartUpModule.php +++ b/includes/resourceloader/ResourceLoaderStartUpModule.php @@ -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; } diff --git a/maintenance/jsduck/categories.json b/maintenance/jsduck/categories.json index bebee85f3f..6f922a0a2e 100644 --- a/maintenance/jsduck/categories.json +++ b/maintenance/jsduck/categories.json @@ -83,7 +83,6 @@ "classes": [ "mw.log", "mw.inspect", - "mw.inspect.reports", "mw.Debug" ] } diff --git a/resources/src/mediawiki.inspect.js b/resources/src/mediawiki.inspect.js index 6c4b80d2ae..f4545dee0f 100644 --- a/resources/src/mediawiki.inspect.js +++ b/resources/src/mediawiki.inspect.js @@ -28,6 +28,10 @@ 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; } ); } @@ -202,7 +206,7 @@ * * 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 ? @@ -257,6 +261,7 @@ }; /** + * @private * @class mw.inspect.reports * @singleton */ @@ -335,6 +340,44 @@ } 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 . + 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; } }; diff --git a/resources/src/startup/mediawiki.js b/resources/src/startup/mediawiki.js index f9a69b82ce..6ed226cf38 100644 --- a/resources/src/startup/mediawiki.js +++ b/resources/src/startup/mediawiki.js @@ -7,7 +7,7 @@ * @alternateClassName mediaWiki * @singleton */ -/* global $VARS */ +/* global $VARS, $CODE */ ( function () { 'use strict'; @@ -1166,12 +1166,15 @@ } 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 ); }; @@ -1224,6 +1227,7 @@ // 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' @@ -1335,6 +1339,11 @@ } } + // 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 index 0000000000..5e9b6ab2a6 --- /dev/null +++ b/resources/src/startup/profiler.js @@ -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 + }; + } + }; + +}() );