Track the most recent upload time for duration events

This will allow us to see if images uploaded recently, which have been
subjected to thumbnail prerendering, load faster.

Change-Id: I4ce358ff54e4ca4e290349aa3ff4810ad4714d24
Mingle: https://wikimedia.mingle.thoughtworks.com/projects/multimedia/cards/975

MultimediaViewer.php

@@ -1015,7 +1015,7 @@ $wgHooks['EventLoggingRegisterSchemas'][] = function( array &$schemas ) {
 	$schemas += array(
 		'MediaViewer' => 10308479,
 		'MultimediaViewerNetworkPerformance' => 7917896,
-		'MultimediaViewerDuration' => 8572641,
+		'MultimediaViewerDuration' => 10427980,
 		'MultimediaViewerAttribution' => 9758179,
 		'MultimediaViewerDimensions' => 10014238,
 	);

resources/mmv/logging/mmv.logging.DurationLogger.js

@@ -26,6 +26,7 @@
 	 */
 	function DurationLogger() {
 		this.starts = {};
+		this.stops = {};
 	}
 
 	oo.inheritClass( DurationLogger, mw.mmv.logging.Logger );
@@ -66,42 +67,78 @@
 				this.starts[ typeOrTypes[ i ] ] = start;
 			}
 		}
+
+		return this;
 	};
 
 	/**
-	 * Logs a duration if a start was recorded first
+	 * Saves the stop of a duration
 	 * @param {string} type Type of duration being measured.
-	 * @param {number} start Start timestamp that to substitute the one coming from start()
+	 * @param {number} start Start timestamp to substitute the one coming from start()
 	 */
 	L.stop = function ( type, start ) {
-		var e, duration, message, startTimestamp;
+		var stop = $.now();
 
 		if ( !type ) {
 			throw 'Must specify type';
 		}
 
-		startTimestamp = this.starts.hasOwnProperty( type ) ? this.starts[ type ] : start;
-
-		if ( startTimestamp !== undefined ) {
-			duration = $.now() - startTimestamp;
-
-			e = {
-				type : type,
-				duration : duration,
-				loggedIn : !mw.user.isAnon(),
-				samplingFactor : this.samplingFactor
-			};
-
-			message = type + ': ' + duration + 'ms';
-
-			mw.log( message );
-
-			this.log( e );
+		// Don't overwrite an existing value
+		if ( !this.stops.hasOwnProperty( type ) ) {
+			this.stops[ type ] = stop;
 		}
 
-		if ( this.starts.hasOwnProperty( type ) ) {
-			delete this.starts[ type ];
+		// Don't overwrite an existing value
+		if ( start !== undefined && !this.starts.hasOwnProperty( type ) ) {
+			this.starts[ type ] = start;
 		}
+
+		return this;
+	};
+
+	/**
+	 * Records the duration log event
+	 * @param {string} type Type of duration being measured.
+	 * @param {Object} extraData Extra information to add to the log event data
+	 */
+	L.record = function ( type, extraData ) {
+		var e, duration;
+
+		if ( !type ) {
+			throw 'Must specify type';
+		}
+
+		if ( !this.starts.hasOwnProperty( type ) || this.starts[ type ] === undefined ) {
+			return;
+		}
+
+		if ( !this.stops.hasOwnProperty( type ) || this.stops[ type ] === undefined ) {
+			return;
+		}
+
+		duration = this.stops[ type ] - this.starts[ type ];
+
+		e = {
+			type : type,
+			duration : duration,
+			loggedIn : !mw.user.isAnon(),
+			samplingFactor : this.samplingFactor
+		};
+
+		if ( extraData ) {
+			$.each( extraData, function ( key, value ) {
+				e[ key ] = value;
+			} );
+		}
+
+		mw.log( 'mw.mmw.logger.DurationLogger', e );
+
+		this.log( e );
+
+		delete this.starts[ type ];
+		delete this.stops[ type ];
+
+		return this;
 	};
 
 	mw.mmv.durationLogger = new DurationLogger();

resources/mmv/mmv.head.js

@@ -46,7 +46,7 @@
 		$document.ready( function () {
 			mw.loader.using( [ 'mmv.bootstrap.autostart', 'mmv.logging.DurationLogger' ] , function() {
 				mw.mmv.bootstrap.whenThumbsReady().then( function () {
-					mw.mmv.durationLogger.stop( 'early-click-to-replay-click', start );
+					mw.mmv.durationLogger.stop( 'early-click-to-replay-click', start ).record( '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

@@ -237,6 +237,7 @@
 			imagePromise,
 			metadataPromise,
 			start,
+			uploadTimestamp,
 			viewer = this,
 			$initialImage = $( initialImage );
 
@@ -278,6 +279,8 @@
 
 		this.setupProgressBar( image, imagePromise, imageWidths.real );
 
+		metadataPromise = this.fetchSizeIndependentLightboxInfo( image.filePageTitle );
+
 		imagePromise.done( function ( thumbnail, imageElement ) {
 			if ( viewer.currentIndex !== image.index ) {
 				return;
@@ -285,22 +288,38 @@
 
 			if ( viewer.imageDisplayedCount++ === 0 ) {
 				mw.mmv.durationLogger.stop( 'click-to-first-image' );
+
+				metadataPromise.done( function ( imageInfo ) {
+					if ( !imageInfo || !imageInfo.uploadDateTime ) {
+						return;
+					}
+
+					uploadTimestamp = imageInfo.uploadDateTime.toString();
+					// Convert to "timestamp" format commonly used in EventLogging
+					uploadTimestamp = uploadTimestamp.replace( /[:\s]/g, '' );
+					// Anonymise the timestamp to avoid making the file identifiable
+					// We only need to know the day
+					uploadTimestamp = uploadTimestamp.substr( 0, uploadTimestamp.length - 6 ) + '000000';
+
+					mw.mmv.durationLogger.record( 'click-to-first-image', {
+						uploadTimestamp: uploadTimestamp
+					} );
+				} );
 			}
 			viewer.displayRealThumbnail( thumbnail, imageElement, imageWidths, $.now() - start );
 		} ).fail( function ( error ) {
 			viewer.ui.canvas.showError( error );
 		} );
 
-		metadataPromise = this.fetchSizeIndependentLightboxInfo(
-			image.filePageTitle
-		).done( function ( imageInfo, repoInfo, userInfo ) {
+		metadataPromise.done( function ( imageInfo, repoInfo, userInfo ) {
 			if ( viewer.currentIndex !== image.index ) {
 				return;
 			}
 
 			if ( viewer.metadataDisplayedCount++ === 0 ) {
-				mw.mmv.durationLogger.stop( 'click-to-first-metadata' );
+				mw.mmv.durationLogger.stop( 'click-to-first-metadata' ).record( 'click-to-first-metadata' );
 			}
+
 			viewer.ui.panel.setImageInfo( image, imageInfo, repoInfo, userInfo );
 
 			// File reuse steals a bunch of information from the DOM, so do it last

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

@@ -33,7 +33,34 @@
 		assert.strictEqual( durationLogger.starts.bar, 1000, 'Third simultaneous event start not overwritten' );
 	} );
 
-	QUnit.test( 'stop()', 17, function ( assert ) {
+	QUnit.test( 'stop()', 5, function ( assert ) {
+		var durationLogger = new mw.mmv.durationLogger.constructor();
+
+		try {
+			durationLogger.stop();
+		} catch ( e ) {
+			assert.ok( true, 'Exception raised when calling stop() without parameters' );
+		}
+
+		durationLogger.stop( 'foo' );
+
+		assert.strictEqual( durationLogger.stops.foo, 0, 'Event stop saved' );
+
+		this.clock.tick( 1000 );
+		durationLogger.stop( 'foo' );
+
+		assert.strictEqual( durationLogger.stops.foo, 0, 'Event stop not overwritten' );
+
+		durationLogger.stop( 'foo', 1 );
+
+		assert.strictEqual( durationLogger.starts.foo, 1, 'Event start saved' );
+
+		durationLogger.stop( 'foo', 2 );
+
+		assert.strictEqual( durationLogger.starts.foo, 1, 'Event start not overwritten' );
+	} );
+
+	QUnit.test( 'record()', 21, function ( assert ) {
 		var dependenciesDeferred = $.Deferred(),
 			fakeEventLog = { logEvent : this.sandbox.stub() },
 			durationLogger = new mw.mmv.durationLogger.constructor();
@@ -45,9 +72,9 @@
 		this.sandbox.stub( durationLogger, 'loadDependencies' ).returns( dependenciesDeferred.promise() );
 
 		try {
-			durationLogger.stop();
+			durationLogger.record();
 		} catch ( e ) {
-			assert.ok( true, 'Exception raised when calling stop() without parameters' );
+			assert.ok( true, 'Exception raised when calling record() without parameters' );
 		}
 
 		durationLogger.setEventLog( fakeEventLog );
@@ -55,6 +82,7 @@
 		durationLogger.start( 'bar' );
 		this.clock.tick( 1000 );
 		durationLogger.stop( 'bar' );
+		durationLogger.record( 'bar' );
 
 		assert.ok( !fakeEventLog.logEvent.called, 'Event queued if dependencies not loaded' );
 
@@ -63,6 +91,7 @@
 		durationLogger.start( 'bob' );
 		this.clock.tick( 4000 );
 		durationLogger.stop( 'bob' );
+		durationLogger.record( 'bob' );
 
 		assert.ok( !fakeEventLog.logEvent.called, 'Event queued if dependencies not loaded' );
 
@@ -81,12 +110,14 @@
 		durationLogger.start( 'foo' );
 		this.clock.tick( 3000 );
 		durationLogger.stop( 'foo' );
+		durationLogger.record( 'foo' );
 
 		assert.strictEqual( fakeEventLog.logEvent.getCall( 2 ).args[ 0 ], 'MultimediaViewerDuration', 'EventLogging schema is correct' );
 		assert.deepEqual( fakeEventLog.logEvent.getCall( 2 ).args[ 1 ], { type : 'foo', duration : 3000, loggedIn : true, samplingFactor : 1 },
 			'EventLogging data is correct' );
 
-		assert.strictEqual( durationLogger.starts.bar, undefined, 'Start value deleted after stop' );
+		assert.strictEqual( durationLogger.starts.bar, undefined, 'Start value deleted after record' );
+		assert.strictEqual( durationLogger.stops.bar, undefined, 'Stop value deleted after record' );
 
 		durationLogger.setGeo( { country : 'FR' } );
 		mw.user.isAnon.returns( true );
@@ -94,14 +125,17 @@
 		durationLogger.start( 'baz' );
 		this.clock.tick( 2000 );
 		durationLogger.stop( 'baz' );
+		durationLogger.record( 'baz' );
 
 		assert.strictEqual( fakeEventLog.logEvent.getCall( 3 ).args[ 0 ], 'MultimediaViewerDuration', 'EventLogging schema is correct' );
 		assert.deepEqual( fakeEventLog.logEvent.getCall( 3 ).args[ 1 ], { type : 'baz', duration : 2000, loggedIn : false, country : 'FR', samplingFactor : 1 },
 			'EventLogging data is correct' );
 
-		assert.strictEqual( durationLogger.starts.bar, undefined, 'Start value deleted after stop' );
+		assert.strictEqual( durationLogger.starts.bar, undefined, 'Start value deleted after record' );
+		assert.strictEqual( durationLogger.stops.bar, undefined, 'Stop value deleted after record' );
 
 		durationLogger.stop( 'fooz', $.now() - 9000 );
+		durationLogger.record( 'fooz' );
 
 		assert.deepEqual( fakeEventLog.logEvent.getCall( 4 ).args[ 1 ], { type : 'fooz', duration : 9000, loggedIn : false, country : 'FR', samplingFactor : 1 },
 			'EventLogging data is correct' );
@@ -109,8 +143,22 @@
 		assert.strictEqual( fakeEventLog.logEvent.callCount, 5, 'logEvent has been called fives times at this point in the test' );
 
 		durationLogger.stop( 'foo' );
+		durationLogger.record( 'foo' );
 
-		assert.strictEqual( fakeEventLog.logEvent.callCount, 5, 'Stop without a start doesn\'t get logged' );
+		assert.strictEqual( fakeEventLog.logEvent.callCount, 5, 'Record without a start doesn\'t get logged' );
+
+		durationLogger.start( 'foofoo' );
+		durationLogger.record( 'foofoo' );
+
+		assert.strictEqual( fakeEventLog.logEvent.callCount, 5, 'Record without a stop doesn\'t get logged' );
+
+		durationLogger.start( 'extra' );
+		this.clock.tick( 5000 );
+		durationLogger.stop( 'extra' );
+		durationLogger.record( 'extra', { bim: 'bam' } );
+
+		assert.deepEqual( fakeEventLog.logEvent.getCall( 5 ).args[ 1 ], { type : 'extra', duration : 5000, loggedIn : false, country : 'FR', samplingFactor : 1, bim : 'bam' },
+			'EventLogging data is correct' );
 	} );
 
 	QUnit.test( 'loadDependencies()', 3, function ( assert ) {