Performance/Navigation Timing 2013 Experiment

The Navigation Timing API gets exact latency measurements from the browser.
== Experiment 1 ==
=== Goal ===
Identify a measurement for performance of client-side code which is not affected by network or server latency.
=== Method ===
* Create a ResourceLoader JavaScript module that creates N DOM elements in a loop, where N is the value of a URL parameter.
* Run it 10 times where N = 1, compute median
* Run it 10 times where N = 10000, compute median
* Compare medians across iterations. The values that change the most should be the ones that correlate with JS performance.
:* ..Because the page payload in bytes is the same
:* ..And the server performance is roughly the same
=== Script ===
( function ( mw, $ ) {
	var timing = performance.timing;
	var iters = mw.util.getParamValue('n') || 1;
	// do expensive busy work in a loop based on value of 'n' url param
 for ( var i = 0; i < iters; i++ ) {
		$( '', { text: + Math.random() } ).appendTo( 'body' );
	}
	function displayTiming() {
		var navStart = timing.navigationStart || timing.fetchStart; // all measurements will be relative to this
		var nt = JSON.parse( JSON.stringify( performance.timing ) ); // copy object
		for ( var k in nt ) {
			nt[k] = nt[k] - navStart; // take absolute timestamps, compute delta from navigationStart
			if ( nt[k] < 0 ) nt[k] = 0;
		}
		nt.iters = iters; // annotate with number of loop iterations executed
		// log
 var img = document.createElement('img');
		img.src = '//127.0.0.1:1337/?q=' + encodeURIComponent( JSON.stringify( nt ) ); // log somewhere
 // display
		$('#bodyContent').html( '<pre style="font-size: 22px;">' + JSON.stringify( nt, null, 4 ) + '</pre>' );
	}
	// make sure we capture navigationTiming data after the page has finished loading
 $( window ).load( function () {
		setTimeout( displayTiming, 0 );
	} );
} ( mediaWiki, jQuery ) );
=== Results ===
 Chrome 31
Key 	M (N=1)	M (N=10000)	Difference
navigationStart 	0 	0 	0
connectStart 	0 	0 	0
connectEnd 	0 	0 	0
requestStart 	7 	8 	1
responseStart 	793 	789 	-4
responseEnd 	796 	792 	-4
domLoading 	801 	806 	5
domInteractive 	2737 	2741 	4
domContentLoadedEventStart	2737 	2741 	4
domContentLoadedEventEnd 	2737 	2742 	5
loadEventStart 	3302 	6294 	2992
domComplete 	3302 	6294 	2992
loadEventEnd 	3303 	6295 	2992
 Firefox 24
Key 	M (N=1)	M (N=10000)	Difference
navigationStart 	0 	0 	0
connectStart 	0 	0 	0
connectEnd 	0 	0 	0
requestStart 	2 	2 	0
responseStart 	823 	808 	-15
responseEnd 	823 	808 	-15
domLoading 	823 	809 	-14
domInteractive 	2522 	2519 	-3
domContentLoadedEventStart	2526 	2525 	-1
domContentLoadedEventEnd 	2526 	2525 	-1
loadEventStart 	3018 	4525 	1507
domComplete 	3018 	4525 	1507
loadEventEnd 	3020 	4529 	1509
Tentative conclusion: we should measure the interval of time from domInteractive to loadEventStart.
== Variant 1: defer work to $(document).ready ==
What happens when we defer the work to a $(document).ready callback?
$( document ).ready( function () {
 for ( var i = 0; i < iters; i++ ) {
 $( '', { text: + Math.random() } ).appendTo( 'body' );
 }
} );
=== Results ===
 Chrome 31
Key 	M (N=1)	M (N=10000)	Difference
navigationStart 	0 	0 	0
connectStart 	0 	0 	0
connectEnd 	0 	0 	0
requestStart 	8 	9 	1
responseStart 	830 	777 	-53
responseEnd 	832 	782 	-50
domLoading 	841 	794 	-47
domInteractive 	2703 	2683 	-20
domContentLoadedEventStart	2703 	2683 	-20
domContentLoadedEventEnd 	2704 	2683 	-21
loadEventStart 	3278 	6207 	2929
domComplete 	3278 	6207 	2929
loadEventEnd 	3278 	6208 	2930
 Firefox 24
Key 	M (N=1)	M (N=10000)	Difference
navigationStart 	0 	0 	0
connectStart 	1 	1 	0
connectEnd 	1 	1 	0
requestStart 	9 	9 	0
responseStart 	800 	793 	-7
responseEnd 	800 	793 	-7
domLoading 	802 	801 	-1
domInteractive 	2571 	2558 	-13
domContentLoadedEventStart	2581 	2569 	-12
domContentLoadedEventEnd 	2582 	2570 	-12
loadEventStart 	3061 	4579 	1518
domComplete 	3061 	4579 	1518
loadEventEnd 	3064 	4583 	1519
== Variant 2: do busy work in sync script tag in head ==
Bypass ResourceLoader; inject script tag into head.
<script>
	var element, i, iters = parseInt(window.location.toString().split("=")[1], 10);
	for ( i = 0; i < iters; i++ ) {
		element = document.createElement("p");
		element.appendChild(document.createTextNode("" + Math.random()));
		document.getElementsByTagName("head")[0].appendChild(element);
	}
</script>
 Chrome 31
Key 	M (N=1)	M (N=10000)	Difference
navigationStart 	0 	0 	0
connectStart 	0 	0 	0
connectEnd 	0 	0 	0
requestStart 	8 	8 	0
responseStart 	788 	833 	45
responseEnd 	790 	836 	46
domLoading 	795 	842 	47
domInteractive 	2703 	2762 	59
domContentLoadedEventStart	2703 	2762 	59
domContentLoadedEventEnd 	2703 	2762 	59
loadEventStart 	3290 	3396 	106
domComplete 	3290 	3396 	106
loadEventEnd 	3291 	3398 	107
 Firefox 24
Key 	M (N=1)	M (N=10000)	Difference
navigationStart 	0 	0 	0
connectStart 	0 	0 	0
connectEnd 	0 	0 	0
requestStart 	2 	2 	0
responseStart 	786 	771 	-15
responseEnd 	786 	771 	-15
domLoading 	791 	772 	-19
domInteractive 	2548 	2556 	8
domContentLoadedEventStart	2551 	2565 	14
domContentLoadedEventEnd 	2552 	2565 	13
loadEventStart 	3036 	3023 	-13
domComplete 	3036 	3023 	-13
loadEventEnd 	3039 	3025 	-14
== Experiment 2: slow vs. fast network ==
OK, let's try taking the opposite approach: test the same JavaScript payload at two connection speeds (loopback vs. 128k ADSL, simulated using a proxy tool) and see what remains the same.
 Firefox 24
Key 	M (fast)	M (slow)	Difference
navigationStart 	0 	0 	0
connectStart 	0 	0 	0
connectEnd 	0 	0 	0
requestStart 	2 	2 	0
responseStart 	787 	866 	79
responseEnd 	787 	1175 	388
domLoading 	792 	958 	166
domInteractive 	2516 	17457 	14941
domContentLoadedEventStart 	2520 	17460 	14940
domContentLoadedEventEnd 	2520 	17461 	14941
loadEventStart 	2984 	23957 	20973
domComplete 	2984 	23957 	20973
loadEventEnd 	2986 	23959 	20973
loadEventEnd - domInteractive	470 	6502 	6032
The length of time between domInteractive to loadEventEnd still seems like the figure that is most responsive to code changes (vs. vagaries of network performance) but it looks like it too is highly sensitive to network latency. I guess that's the idea of "user-perceived latency" -- the user doesn't know or care why the page is slow; it only matters that it is slow.
loadEventEnd - domInteractive seems to track the cost of JS / CSS modules, but it compounds time spent fetching assets with time spent parsing and executing them.
== Experiment 3: ResourceLoader Timing ==
OK, let's use the User Timing API to measure the time from navigationStart to various key ResourceLoader moments. Because I'm hacking on my dev instance and I know my browser supports the API, I can just add performance.mark calls where I need them.
diff --git a/includes/OutputPage.php b/includes/OutputPage.php
index 83a7d3f..63ce7cd 100644
--- a/includes/OutputPage.php
+++ b/includes/OutputPage.php
@@ -2793,7 +2793,9 @@ $templates
 if ( $modules ) {
 $scripts .= Html::inlineScript(
 ResourceLoader::makeLoaderConditionalScript(
- Xml::encodeJsCall( 'mw.loader.load', array( $modules ) )
+ "performance.mark('topQueueStart');" .
+ Xml::encodeJsCall( 'mw.loader.load', array( $modules ) ) .
+ "performance.mark('topQueueStop');"
 )
 );
 }
@@ -2835,7 +2837,9 @@ $templates
 if ( $modules ) {
 $scripts .= Html::inlineScript(
 ResourceLoader::makeLoaderConditionalScript(
- Xml::encodeJsCall( 'mw.loader.load', array( $modules, null, true ) )
+ "performance.mark('bottomQueueStart');" .
+ Xml::encodeJsCall( 'mw.loader.load', array( $modules, null, true ) ) .
+ "performance.mark('bottomQueueStop');"
 )
 );
 }
diff --git a/includes/resourceloader/ResourceLoaderStartUpModule.php b/includes/resourceloader/ResourceLoaderStartUpModule.php
index 861ff18..7d777cb 100644
--- a/includes/resourceloader/ResourceLoaderStartUpModule.php
+++ b/includes/resourceloader/ResourceLoaderStartUpModule.php
@@ -227,7 +227,9 @@ class ResourceLoaderStartUpModule extends ResourceLoaderModule {
 // Conditional script injection
 $scriptTag = Html::linkedScript( wfAppendQuery( wfScript( 'load' ), $query ) );
 $out .= "if ( isCompatible() ) {\n" .
+ "\tperformance.mark('resourceLoaderDocumentWriteStart');\n" .
 "\t" . Xml::encodeJsCall( 'document.write', array( $scriptTag ) ) .
+ "\tperformance.mark('resourceLoaderDocumentWriteStop');\n" .
 "}\n" .
 "delete isCompatible;";
 }
diff --git a/resources/mediawiki/mediawiki.js b/resources/mediawiki/mediawiki.js
index 741e231..a93b86b 100644
--- a/resources/mediawiki/mediawiki.js
+++ b/resources/mediawiki/mediawiki.js
@@ -983,6 +983,7 @@ var mw = ( function ( $, undefined ) {
 script = registry[module].script;
 markModuleReady = function () {
 registry[module].state = 'ready';
+ performance.mark( module + 'ModuleStop' );
 handlePending( module );
 };
 nestedAddScript = function ( arr, callback, async, i ) {
@@ -1004,6 +1005,7 @@ var mw = ( function ( $, undefined ) {
 } else if ( $.isFunction( script ) ) {
 registry[module].state = 'ready';
 script( $ );
+ performance.mark( module + 'ModuleStop' );
 handlePending( module );
 }
 } catch ( e ) {
@@ -1020,6 +1022,7 @@ var mw = ( function ( $, undefined ) {
 // when execute() is called this is set synchronously, otherwise modules will get
 // executed multiple times as the registry will state that it isn't loading yet.
 registry[module].state = 'loading';
+ performance.mark( module + 'ModuleStart' );
 
 // Add localizations to message system
 if ( $.isPlainObject( registry[module].messages ) ) {
@@ -1904,6 +1907,8 @@ window.mw = window.mediaWiki = mw;
 
 // Auto-register from pre-loaded startup scripts
 if ( jQuery.isFunction( window.startUp ) ) {
+ performance.measure('startupStart');
 window.startUp();
+ performance.measure('startupEnd');
 window.startUp = undefined;
 }
Repeat of first experiment:
 Chrome 31
Key 	M (N=1)	M (N=10000)	Difference
navigationStart 	0 	0 	0
connectStart 	0 	0 	0
connectEnd 	0 	0 	0
requestStart 	8 	8 	0
responseStart 	789 	787 	-2
responseEnd 	803 	802 	-1
domLoading 	809 	811 	2
domInteractive 	2709 	2814 	105
domContentLoadedEventStart 	2709 	2814 	105
domContentLoadedEventEnd 	2710 	2814 	104
loadEventStart 	3270 	6406 	3136
domComplete 	3270 	6405 	3135
loadEventEnd 	3271 	6406 	3135
resourceLoaderDocumentWriteStart	2170 	2271 	101
resourceLoaderDocumentWriteStop 	2171 	2271 	100
firstModuleStart 	2406 	2509 	103
lastModuleStop 	2407 	2510 	103
topQueueStart 	2408 	2510 	102
topQueueStop 	2412 	2513 	101
bottomQueueStart 	2707 	2812 	105
bottomQueueStop 	2709 	2813 	104
Experiment 2 (network latency)
 Firefox 24.0
Key 	M (fast)	M (slow)	Difference
navigationStart 	0 	0 	0
connectStart 	1 	1 	0
connectEnd 	1 	1 	0
requestStart 	9 	9 	0
responseStart 	804 	895 	91
responseEnd 	804 	1205 	401
domLoading 	826 	987 	161
domInteractive 	2613 	17601 	14988
domContentLoadedEventStart 	2620 	17609 	14989
domContentLoadedEventEnd 	2621 	17610 	14989
loadEventStart 	3074 	24136 	21062
domComplete 	3074 	24136 	21062
loadEventEnd 	3076 	24138 	21062
resourceLoaderDocumentWriteStart	2068 	4552 	2484
resourceLoaderDocumentWriteStop 	2069 	4553 	2484
firstModuleStart 	2307 	15236 	12929
lastModuleStop 	2307 	15237 	12930
topQueueStart 	2308 	15237 	12929
topQueueStop 	2311 	15240 	12929
bottomQueueStart 	2611 	17599 	14988
bottomQueueStop 	2613 	17602 	14989