Jump to content

Performance/Navigation Timing 2013 Experiment

From Wikitech
This page contains historical information. It may be outdated or unreliable.

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++ ) {
		$( '<p>', { 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
KeyM (N=1)M (N=10000)Difference
navigationStart000
connectStart000
connectEnd000
requestStart781
responseStart793789-4
responseEnd796792-4
domLoading8018065
domInteractive273727414
domContentLoadedEventStart273727414
domContentLoadedEventEnd273727425
loadEventStart330262942992
domComplete330262942992
loadEventEnd330362952992
Firefox 24
KeyM (N=1)M (N=10000)Difference
navigationStart000
connectStart000
connectEnd000
requestStart220
responseStart823808-15
responseEnd823808-15
domLoading823809-14
domInteractive25222519-3
domContentLoadedEventStart25262525-1
domContentLoadedEventEnd25262525-1
loadEventStart301845251507
domComplete301845251507
loadEventEnd302045291509

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++ ) {
        $( '<p>', { text: '' + Math.random() } ).appendTo( 'body' );
    }
} );

Results

Chrome 31
KeyM (N=1)M (N=10000)Difference
navigationStart000
connectStart000
connectEnd000
requestStart891
responseStart830777-53
responseEnd832782-50
domLoading841794-47
domInteractive27032683-20
domContentLoadedEventStart27032683-20
domContentLoadedEventEnd27042683-21
loadEventStart327862072929
domComplete327862072929
loadEventEnd327862082930
Firefox 24
KeyM (N=1)M (N=10000)Difference
navigationStart000
connectStart110
connectEnd110
requestStart990
responseStart800793-7
responseEnd800793-7
domLoading802801-1
domInteractive25712558-13
domContentLoadedEventStart25812569-12
domContentLoadedEventEnd25822570-12
loadEventStart306145791518
domComplete306145791518
loadEventEnd306445831519

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
KeyM (N=1)M (N=10000)Difference
navigationStart000
connectStart000
connectEnd000
requestStart880
responseStart78883345
responseEnd79083646
domLoading79584247
domInteractive2703276259
domContentLoadedEventStart2703276259
domContentLoadedEventEnd2703276259
loadEventStart32903396106
domComplete32903396106
loadEventEnd32913398107
Firefox 24
KeyM (N=1)M (N=10000)Difference
navigationStart000
connectStart000
connectEnd000
requestStart220
responseStart786771-15
responseEnd786771-15
domLoading791772-19
domInteractive254825568
domContentLoadedEventStart2551256514
domContentLoadedEventEnd2552256513
loadEventStart30363023-13
domComplete30363023-13
loadEventEnd30393025-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
KeyM (fast)M (slow)Difference
navigationStart000
connectStart000
connectEnd000
requestStart220
responseStart78786679
responseEnd7871175388
domLoading792958166
domInteractive25161745714941
domContentLoadedEventStart25201746014940
domContentLoadedEventEnd25201746114941
loadEventStart29842395720973
domComplete29842395720973
loadEventEnd29862395920973
loadEventEnd - domInteractive47065026032

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
KeyM (N=1)M (N=10000)Difference
navigationStart000
connectStart000
connectEnd000
requestStart880
responseStart789787-2
responseEnd803802-1
domLoading8098112
domInteractive27092814105
domContentLoadedEventStart27092814105
domContentLoadedEventEnd27102814104
loadEventStart327064063136
domComplete327064053135
loadEventEnd327164063135
resourceLoaderDocumentWriteStart21702271101
resourceLoaderDocumentWriteStop21712271100
firstModuleStart24062509103
lastModuleStop24072510103
topQueueStart24082510102
topQueueStop24122513101
bottomQueueStart27072812105
bottomQueueStop27092813104

Experiment 2 (network latency)

Firefox 24.0
KeyM (fast)M (slow)Difference
navigationStart000
connectStart110
connectEnd110
requestStart990
responseStart80489591
responseEnd8041205401
domLoading826987161
domInteractive26131760114988
domContentLoadedEventStart26201760914989
domContentLoadedEventEnd26211761014989
loadEventStart30742413621062
domComplete30742413621062
loadEventEnd30762413821062
resourceLoaderDocumentWriteStart206845522484
resourceLoaderDocumentWriteStop206945532484
firstModuleStart23071523612929
lastModuleStop23071523712930
topQueueStart23081523712929
topQueueStop23111524012929
bottomQueueStart26111759914988
bottomQueueStop26131760214989
Retrieved from "https://wikitech.wikimedia.org/w/index.php?title=Performance/Navigation_Timing_2013_Experiment&oldid=2023059"