Adds new performance metrics

- duration between early click and replayed click
- duration between replayed/post-replay click and first image display
- duration between replayed/post-replay click and first metadata display

Change-Id: Ia308db7580fd89538b9a9c8b0fea89fa2a4c77d2
Mingle: https://wikimedia.mingle.thoughtworks.com/projects/multimedia/cards/515
Mingle: https://wikimedia.mingle.thoughtworks.com/projects/multimedia/cards/508

MultimediaViewer.php

@@ -730,6 +730,7 @@ $wgResourceModules += array(
 			'mmv.lightboxinterface',
 			'mmv.provider',
 			'mmv.routing',
+			'mmv.DurationLogger',
 			'jquery.fullscreen',
 			'jquery.hidpi',
 			'jquery.scrollTo',
@@ -760,6 +761,7 @@ $wgResourceModules += array(
 			'mediawiki.Title',
 			'mmv.logger',
 			'mmv.HtmlUtils',
+			'mmv.DurationLogger',
 			'jquery.scrollTo',
 		),
 
@@ -779,6 +781,16 @@ $wgResourceModules += array(
 		),
 	),
 
+	'mmv.DurationLogger' => $wgMediaViewerResourceTemplate + array(
+		'scripts' => array(
+			'mmv/mmv.DurationLogger.js',
+		),
+
+		'dependencies' => array(
+			'mmv.base'
+		)
+	),
+
 	'mmv.head' => $wgMediaViewerResourceTemplate + array(
 		'scripts' => array(
 			'mmv/mmv.head.js',
@@ -786,6 +798,7 @@ $wgResourceModules += array(
 
 		'dependencies' => array(
 			'mmv.base',
+			'mmv.DurationLogger'
 		),
 
 		'position' => 'top',
@@ -820,11 +833,20 @@ $wgExtensionFunctions[] = function () {
 			'revision' => 7917896,
 		);
 
+		$wgResourceModules['schema.MultimediaViewerDuration'] = array(
+			'class' => 'ResourceLoaderSchemaModule',
+			'schema' => 'MultimediaViewerDuration',
+			'revision' => 8318615,
+		);
+
 		$wgResourceModules['mmv.logger']['dependencies'][] = 'ext.eventLogging';
 		$wgResourceModules['mmv.logger']['dependencies'][] = 'schema.MediaViewer';
 
 		$wgResourceModules['mmv.performance']['dependencies'][] = 'ext.eventLogging';
 		$wgResourceModules['mmv.performance']['dependencies'][] = 'schema.MultimediaViewerNetworkPerformance';
+
+		$wgResourceModules['mmv.DurationLogger']['dependencies'][] = 'ext.eventLogging';
+		$wgResourceModules['mmv.DurationLogger']['dependencies'][] = 'schema.MultimediaViewerDuration';
 	}
 };
 

MultimediaViewerHooks.php

@@ -181,6 +181,7 @@ class MultimediaViewerHooks {
 			'scripts' => array(
 				'tests/qunit/mmv/mmv.bootstrap.test.js',
 				'tests/qunit/mmv/mmv.test.js',
+				'tests/qunit/mmv/mmv.DurationLogger.test.js',
 				'tests/qunit/mmv/mmv.lightboxinterface.test.js',
 				'tests/qunit/mmv/mmv.lightboximage.test.js',
 				'tests/qunit/mmv/mmv.ThumbnailWidthCalculator.test.js',

docs/categories.json

@@ -6,6 +6,7 @@
 				"name": "Base",
 				"classes": [
 					"mw.mmv.Api",
+					"mw.mmv.DurationLogger",
 					"mw.mmv.EmbedFileFormatter",
 					"mw.mmv.HtmlUtils",
 					"mw.mmv.LightboxImage",

resources/mmv/mmv.DurationLogger.js

@@ -0,0 +1,87 @@
+/*
+ * This file is part of the MediaWiki extension MultimediaViewer.
+ *
+ * MultimediaViewer is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation, either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * MultimediaViewer is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with MultimediaViewer.  If not, see <http://www.gnu.org/licenses/>.
+ */
+
+( function ( mw, $ ) {
+	var L;
+
+	/**
+	 * Writes Event Logging entries for duration measurements
+	 * @class mw.mmv.DurationLogger
+	 */
+	function DurationLogger() {
+		this.starts = {};
+	}
+
+	L = DurationLogger.prototype;
+
+	/**
+	 * Saves the start of a duration
+	 * @param {string|string[]} type_or_types Type(s) of duration being measured.
+	 */
+	L.start = function ( typeOrTypes ) {
+		var i,
+			start = $.now();
+
+		if ( $.isArray( typeOrTypes ) ) {
+			for ( i = 0; i < typeOrTypes.length; i++ ) {
+				// Don't overwrite an existing value
+				if ( !this.starts.hasOwnProperty( typeOrTypes[ i ] ) ) {
+					this.starts[ typeOrTypes[ i ] ] = start;
+				}
+			}
+		// Don't overwrite an existing value
+		} else if ( typeOrTypes && !this.starts.hasOwnProperty( typeOrTypes ) ) {
+			this.starts[ typeOrTypes ] = start;
+		}
+	};
+
+	/**
+	 * Logs a duration if a start was recorded first
+	 * @param {string} type Type of duration being measured.
+	 */
+	L.stop = function ( type ) {
+		var e, duration;
+
+		if ( this.starts.hasOwnProperty( type ) ) {
+			duration = $.now() - this.starts[ type ];
+
+			e = {
+				type : type,
+				duration : duration,
+				loggedIn : !mw.user.isAnon()
+			};
+
+			if ( $.isPlainObject( window.Geo ) && typeof window.Geo.country === 'string' ) {
+				e.country = window.Geo.country;
+			}
+
+			if ( mw.eventLog ) {
+				mw.eventLog.logEvent( 'MultimediaViewerDuration', e );
+			}
+
+			if ( window.console && window.console.log ) {
+				window.console.log( type + ': ' + duration + 'ms' );
+			}
+		}
+
+		if ( this.starts.hasOwnProperty( type ) ) {
+			delete this.starts[ type ];
+		}
+	};
+
+	mw.mmv.DurationLogger = new DurationLogger();
+}( mediaWiki, jQuery ) );

resources/mmv/mmv.bootstrap.js

@@ -250,6 +250,8 @@
 			return;
 		}
 
+		mw.mmv.DurationLogger.start( [ 'click-to-first-image', 'click-to-first-metadata' ] );
+
 		if ( $element.is( 'a.image' ) ) {
 			mw.mmv.logger.log( 'thumbnail' );
 		} else if ( $element.is( '.magnify a' ) ) {

resources/mmv/mmv.head.js

@@ -35,11 +35,15 @@
 			return;
 		}
 
+		mw.mmv.DurationLogger.start( 'early-click-to-replay-click' );
+
 		// We wait for document readiness because mw.loader.using writes to the DOM
 		// which can cause a blank page if it happens before DOM readiness
 		$document.ready( function () {
 			mw.loader.using( 'mmv.bootstrap.autostart', function() {
 				mw.mmv.bootstrap.whenThumbsReady().then( function () {
+					mw.mmv.DurationLogger.stop( 'early-click-to-replay-click' );
+
 					// We have to copy the properties, passing e doesn't work. Probably because of preventDefault()
 					$( e.target ).trigger( { type : 'click', which: 1, replayed: true } );
 				} );

resources/mmv/mmv.js

@@ -110,6 +110,18 @@
 		 * @private
 		 */
 		this.ui = new mw.mmv.LightboxInterface();
+
+		/**
+		 * How many sharp images have been displayed in Media Viewer since the pageload
+		 * @property {number}
+		 */
+		this.imageDisplayedCount = 0;
+
+		/**
+		 * How many data-filled metadata panels have been displayed in Media Viewer since the pageload
+		 * @property {number}
+		 */
+		this.metadataDisplayedCount = 0;
 	}
 
 	MMVP = MultimediaViewer.prototype;
@@ -282,6 +294,9 @@
 				return;
 			}
 
+			if ( viewer.imageDisplayedCount++ === 0 ) {
+				mw.mmv.DurationLogger.stop( 'click-to-first-image' );
+			}
 			viewer.displayRealThumbnail( thumbnail, imageElement, imageWidths, $.now() - start );
 		} ).fail( function ( error ) {
 			viewer.ui.canvas.showError( error );
@@ -294,6 +309,9 @@
 				return;
 			}
 
+			if ( viewer.metadataDisplayedCount++ === 0 ) {
+				mw.mmv.DurationLogger.stop( 'click-to-first-metadata' );
+			}
 			viewer.ui.panel.setImageInfo( image, imageInfo, repoInfo, localUsage, globalUsage, userInfo );
 		} ).fail( function ( error ) {
 			if ( viewer.currentIndex !== image.index ) {

tests/qunit/mmv/mmv.DurationLogger.test.js

@@ -0,0 +1,74 @@
+( function ( mw, $ ) {
+	QUnit.module( 'mmv.DurationLogger', QUnit.newMwEnvironment({
+		setup: function () {
+			this.clock = this.sandbox.useFakeTimers();
+		}
+	} ) );
+
+	QUnit.test( 'start()', 7, function ( assert ) {
+		var durationLogger = new mw.mmv.DurationLogger.constructor();
+
+		durationLogger.start();
+		assert.ok( $.isEmptyObject( durationLogger.starts ), 'No events saved by DurationLogger' );
+
+		durationLogger.start( 'foo' );
+		assert.strictEqual( durationLogger.starts.foo, 0, 'Event start saved' );
+
+		this.clock.tick( 1000 );
+		durationLogger.start( 'bar' );
+		assert.strictEqual( durationLogger.starts.bar, 1000, 'Later event start saved' );
+
+		durationLogger.start( 'foo' );
+		assert.strictEqual( durationLogger.starts.foo, 0, 'Event start not overritten' );
+
+		this.clock.tick( 666 );
+		durationLogger.start( [ 'baz', 'bob', 'bar' ] );
+		assert.strictEqual( durationLogger.starts.baz, 1666, 'First simultaneous event start saved' );
+		assert.strictEqual( durationLogger.starts.bob, 1666, 'Second simultaneous event start saved' );
+		assert.strictEqual( durationLogger.starts.bar, 1000, 'Third simultaneous event start not overwritten' );
+	} );
+
+	QUnit.test( 'stop()', 6, function ( assert ) {
+		var logEvent,
+			durationLogger = new mw.mmv.DurationLogger.constructor(),
+			fakeEventLogging = false,
+			fakeGeo = false;
+
+		if ( window.Geo === undefined ) {
+			window.Geo = { country : 'FR' };
+			fakeGeo = true;
+		}
+
+		if ( mw.eventLog === undefined ) {
+			mw.eventLog = { logEvent : $.noop };
+			fakeEventLogging = true;
+		}
+
+		this.sandbox.stub( mw.user, 'isAnon', function() { return false; } );
+		this.sandbox.stub( window.Geo, 'country', 'FR' );
+
+		logEvent = this.sandbox.stub( mw.eventLog, 'logEvent', function( schema, e ) {
+				assert.strictEqual( e.type, 'bar', 'Type passed to EventLogging is correct' );
+				assert.strictEqual( e.duration, 1000, 'Duration passed to EventLogging is correct' );
+				assert.strictEqual( e.loggedIn, true, 'Loggedin information passed to EventLogging is correct' );
+				assert.strictEqual( e.country, 'FR', 'Country passed to EventLogging is correct' );
+			} );
+
+		durationLogger.stop( 'foo' );
+		assert.ok( !logEvent.called, 'Stop without a start doesn\'t get logged' );
+
+		durationLogger.start( 'bar' );
+		this.clock.tick( 1000 );
+		durationLogger.stop( 'bar' );
+
+		assert.strictEqual( durationLogger.starts.bar, undefined, 'Start value deleted after stop' );
+
+		if ( fakeGeo ) {
+			delete window.Geo;
+		}
+
+		if ( fakeEventLogging ) {
+			delete mw.eventLog;
+		}
+	} );
+}( mediaWiki, jQuery ) );