Performance/Navigation Timing 2013 Experiment

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

For current information about Navigation Timing at Wikimedia, see Webperf#navtiming and Extension:NavigationTiming.

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
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++ ) {
        $( '<p>', { 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
Retrieved from "https://wikitech.wikimedia.org/w/index.php?title=Performance/Navigation_Timing_2013_Experiment&oldid=2023059"