Add performance logging

Change-Id: If6e3aec4b2547fa9768eaaf5387729ed2b427ab1

MultimediaViewer.php

@@ -199,7 +199,13 @@ $wgExtensionFunctions[] = function () {
 		$wgResourceModules['schema.MediaViewer'] = array(
 			'class' => 'ResourceLoaderSchemaModule',
 			'schema' => 'MediaViewer',
-			'revision' => 6066908,
+			'revision' => 6636420,
+		);
+
+		$wgResourceModules['schema.MediaViewerPerf'] = array(
+			'class' => 'ResourceLoaderSchemaModule',
+			'schema' => 'MediaViewerPerf',
+			'revision' => 6636500,
 		);
 
 		$wgResourceModules['ext.multimediaViewer']['dependencies'][] = 'ext.eventLogging';

resources/ext.multimediaViewer/ext.multimediaViewer.js

@@ -52,7 +52,19 @@
 			'fullscreen-link-click': 'User clicked on fullscreen button in lightbox.',
 			'defullscreen-link-click': 'User clicked on button to return to normal lightbox view.',
 			'close-link-click': 'User clicked on the lightbox close button.',
-			'site-link-click': 'User clicked on the link to the file description page.'
+			'site-link-click': 'User clicked on the link to the file description page.',
+
+			// Profiling events start messages, $1 replaced with profile ID
+			'profile-image-load-start': 'Profiling image load with ID $1',
+			'profile-image-resize-start': 'Profiling image resize with ID $1',
+			'profile-metadata-fetch-start': 'Profiling image metadata fetch with ID $1',
+			'profile-gender-fetch-start': 'Profiling uploader gender fetch with ID $1',
+
+			// Profiling events end messages, $1 replaced with profile ID, $2 replaced with time it took in ms
+			'profile-image-load-end': 'Finished image load with ID $1 in $2 milliseconds',
+			'profile-image-resize-end': 'Finished image resize with ID $1 in $2 milliseconds',
+			'profile-metadata-fetch-end': 'Finished image metadata fetch with ID $1 in $2 milliseconds',
+			'profile-gender-fetch-end': 'Finished uploader gender fetch with ID $1 in $2 milliseconds'
 		};
 
 	/**
@@ -261,9 +273,11 @@
 	 * @param {Object} data information regarding the new resized image
 	 */
 	MMVP.loadResizedImage = function ( ui, data ) {
+		var imageInfo, innerInfo, rpid, viewer, image;
+
 		// Replace image only if data was returned.
 		if ( data && data.query && data.query.pages ) {
-			var imageInfo, innerInfo,
+			viewer = this;
 			image = new Image();
 
 			$.each( data.query.pages, function ( i, page ) {
@@ -274,10 +288,17 @@
 			innerInfo = imageInfo.imageinfo[0];
 
 			image.onload = function () {
+				viewer.profileEnd( rpid );
 				ui.replaceImageWith( image );
 				this.updateControls();
 			};
 
+			rpid = this.profileStart( 'image-resize', {
+				width: innerInfo.width,
+				height: innerInfo.height,
+				fileSize: innerInfo.size
+			}, innerInfo.mime );
+
 			image.src = innerInfo.thumburl || innerInfo.url;
 		}
 	};
@@ -462,13 +483,14 @@
 			ui.$usernameLi.toggleClass( 'empty', !username );
 		}
 
-		var extmeta,
+		var extmeta, gfpid,
 			repoInfo, articlePath, linkToRepo,
 			desc,
 			datetime, dtmsg,
 			license, msgname,
 			username,
 			source, author,
+			viewer = this,
 			ui = this.lightbox.iface,
 			innerInfo = imageInfo.imageinfo[0] || {};
 
@@ -515,6 +537,8 @@
 		username = innerInfo.user;
 
 		if ( username ) {
+			gfpid = this.profileStart( 'gender-fetch' );
+
 			// TODO: Reuse the api member, fix everywhere.
 			// Fetch the gender from the uploader's home wiki
 			// TODO this is ugly as hell, let's fix this in core.
@@ -529,8 +553,12 @@
 				usprop: 'gender'
 			} ).done( function ( data ) {
 				var gender = data.query.users[0].gender;
+
+				viewer.profileEnd( gfpid );
+
 				setUserpageLink( username, gender );
 			} ).fail( function () {
+				mw.log( 'Gender fetch with ID ' + gfpid + ' failed, probably due to cross-domain API request.' );
 				setUserpageLink( username, 'unknown' );
 			} );
 		}
@@ -625,7 +653,8 @@
 	};
 
 	MMVP.loadImage = function ( image, initialSrc ) {
-		var viewer = this;
+		var mdpid,
+			viewer = this;
 
 		this.lightbox.currentIndex = image.index;
 
@@ -643,10 +672,17 @@
 			size: 'large'
 		} ) );
 
+		mdpid = this.profileStart( 'metadata-fetch' );
+
 		this.fetchImageInfo( image.filePageTitle, function ( imageInfo ) {
-			var imageEle = new Image();
+			var pid,
+				innerInfo = imageInfo.imageinfo[0],
+				imageEle = new Image();
+
+			viewer.profileEnd( mdpid );
 
 			imageEle.onload = function () {
+				viewer.profileEnd( pid );
 				viewer.lightbox.iface.replaceImageWith( imageEle );
 				viewer.lightbox.iface.$imageDiv.removeClass( 'empty' );
 				viewer.updateControls();
@@ -655,6 +691,12 @@
 			};
 
 			imageEle.src = imageInfo.imageinfo[0].thumburl || imageInfo.imageinfo[0].url;
+
+			pid = viewer.profileStart( 'image-load', {
+				width: innerInfo.width,
+				height: innerInfo.height,
+				fileSize: innerInfo.size
+			}, innerInfo.mime );
 		} );
 
 		comingFromPopstate = false;
@@ -761,14 +803,81 @@
 
 		if ( mw.eventLog ) {
 			mw.eventLog.logEvent( 'MediaViewer', {
-				version: '1.0',
+				version: '1.1',
-				action: action,
+				action: action
-				userId: mw.user.getId(),
-				editCount: mw.config.get( 'wgUserEditCount', 0 )
 			} );
 		}
 	};
 
+	( function () {
+		var profiling = {},
+			nonce = 0;
+
+		/**
+		 * Start profiling an event
+		 * @param {string} type Can be image-load, image-resize, metadata-fetch, gender-fetch
+		 * @param {object} [imgSize] Size of image (for image related events)
+		 * @param {number} [imgSize.width] In pixels
+		 * @param {number} [imgSize.height] In pixels
+		 * @param {number} [imgSize.filesize] In bytes
+		 * @param {string} [fileType] File type (for image related events)
+		 * @param {number} [timeout] Optional timeout for the event.
+		 * @returns {number} The id used to finish the profiling
+		 */
+		MMVP.profileStart = function ( type, imgSize, fileType, timeout ) {
+			var thisid = nonce++;
+
+			imgSize = imgSize || {};
+
+			profiling[thisid] = {
+				version: '1.0',
+				action: type,
+				imageWidth: imgSize.width,
+				imageHeight: imgSize.height,
+				fileSize: imgSize.filesize,
+				fileType: fileType,
+				userAgent: navigator.userAgent,
+				start: Date.now()
+			};
+
+			mw.log( mmvLogActions['profile-' + type + '-start'].replace( /\$1/g, thisid ) );
+
+			if ( timeout ) {
+				window.setTimeout( function () {
+					profiling[thisid] = undefined;
+				}, timeout );
+			}
+
+			return thisid;
+		};
+
+		/**
+		 * Signal the end of an event being profiled and send the
+		 * eventlogging message.
+		 * @param {number} id Should be the value returned from profileStart
+		 * @param {boolean} [includeTime] For testing, whether to include the time in the message. Time is zero otherwise.
+		 */
+		MMVP.profileEnd = function ( id, includeTime ) {
+			var msg;
+
+			if ( profiling[id] ) {
+				msg = profiling[id];
+				msg.milliseconds = includeTime ? Date.now() - msg.start : 0;
+				delete msg.start;
+
+				mw.log(
+					mmvLogActions['profile-' + msg.action + '-end']
+						.replace( /\$1/g, id )
+						.replace( /\$2/g, msg.milliseconds )
+				);
+
+				if ( mw.eventLog ) {
+					mw.eventLog.logEvent( 'MediaViewerPerf', msg );
+				}
+			}
+		};
+	}() );
+
 	/**
 	 * Transforms a date string into localized, human-readable format.
 	 * Unrecognized strings are returned unchanged.

tests/qunit/ext.multimediaViewer.test.js

@@ -1,4 +1,22 @@
 ( function ( mw, $ ) {
+	var logTests = [
+			[ 'thumbnail-link-click', 'User clicked on thumbnail to open lightbox.' ],
+			[ 'enlarge-link-click', 'User clicked on enlarge link to open lightbox.' ],
+			[ 'fullscreen-link-click', 'User clicked on fullscreen button in lightbox.' ],
+			[ 'defullscreen-link-click', 'User clicked on button to return to normal lightbox view.' ],
+			[ 'close-link-click', 'User clicked on the lightbox close button.' ],
+			[ 'site-link-click', 'User clicked on the link to the file description page.' ],
+			[ 'Something happened', 'Something happened' ]
+		],
+
+		profileTests = [
+			[ 'image-load', 'Profiling image load with ID $1', 'Finished image load with ID $1 in $2 milliseconds', 200, 200, 120348, 'jpg' ],
+			[ 'image-resize', 'Profiling image resize with ID $1', 'Finished image resize with ID $1 in $2 milliseconds', 400, 400, 500000, 'png' ],
+			[ 'metadata-fetch', 'Profiling image metadata fetch with ID $1', 'Finished image metadata fetch with ID $1 in $2 milliseconds' ],
+			[ 'gender-fetch', 'Profiling uploader gender fetch with ID $1', 'Finished uploader gender fetch with ID $1 in $2 milliseconds' ]
+		];
+
+
 	QUnit.module( 'ext.multimediaViewer', QUnit.newMwEnvironment() );
 
 	function createGallery( imageSrc ) {
@@ -120,4 +138,82 @@
 		assert.ok( true, 'Resized image is not replaced since we have not data.' );
 	} );
 
+	QUnit.test( 'Logging works as expected', 4 * logTests.length, function ( assert ) {
+		var i, test, msgName, expectedMsg,
+			viewer = new mw.MultimediaViewer(),
+			backupLog = mw.log,
+			backupEventLog = mw.eventLog;
+
+		function checkLogging( msg ) {
+			assert.strictEqual( msg, expectedMsg, 'Message ' + msgName + ' is logged correctly.' );
+		}
+
+		function checkLoggingEventLog( type, event ) {
+			assert.strictEqual( type, 'MediaViewer', 'Eventlogging gets the right event type for message ' + msgName + '.' );
+			assert.strictEqual( event.version, '1.1', 'Eventlogging gets the right version number for message ' + msgName + '.' );
+			assert.strictEqual( event.action, msgName, 'Eventlogging gets the right action name for message ' + msgName + '.' );
+		}
+
+		mw.log = checkLogging;
+		mw.eventLog = mw.eventLog || {};
+		mw.eventLog.logEvent = checkLoggingEventLog;
+
+		for ( i = 0; i < logTests.length; i++ ) {
+			test = logTests[i];
+			msgName = test[0];
+			expectedMsg = test[1];
+			viewer.log( msgName );
+		}
+
+		mw.log = backupLog;
+		mw.eventLog = backupEventLog;
+	} );
+
+	QUnit.test( 'Profiling works as expected', ( 12 * profileTests.length ), function ( assert ) {
+		var i, pid, test, msgName, expectedMsg, expectedImageWidth,
+			expectedFileSize, expectedFileType, expectedImageHeight,
+			viewer = new mw.MultimediaViewer(),
+			backupLog = mw.log,
+			backupEventLog = mw.eventLog;
+
+		function checkLogging( msg ) {
+			assert.strictEqual( msg, expectedMsg, 'Message ' + msgName + ' is logged correctly.' );
+		}
+
+		function checkProfileEventLog( type, msg ) {
+			assert.strictEqual( type, 'MediaViewerPerf', 'EventLogging gets the right event type for profile message ' + msgName + '.' );
+			assert.strictEqual( msg.version, '1.0', 'EventLogging gets the right version number for profile message ' + msgName + '.' );
+			assert.strictEqual( msg.action, msgName, 'EventLogging gets the right action name for message ' + msgName + '.' );
+			assert.strictEqual( msg.start, undefined, 'MultimediaViewer#profileEnd deletes the event start time from ' + msgName + ' profiles sent to EventLogging.' );
+			assert.strictEqual( msg.fileSize, expectedFileSize, 'EventLogging sees the correct file size for ' + msgName + ' profiles.' );
+			assert.strictEqual( msg.fileType, expectedFileType, 'EventLogging sees the correct filetype for ' + msgName + ' profiles.' );
+			assert.strictEqual( msg.imageHeight, expectedImageHeight, 'EventLogging sees the correct image height for ' + msgName + ' profiles.' );
+			assert.strictEqual( msg.imageWidth, expectedImageWidth, 'EventLogging sees the correct image width for ' + msgName + ' profiles.' );
+			assert.strictEqual( msg.userAgent, navigator.userAgent, 'EventLogging logs the browser user-agent string for ' + msgName + ' profiles.' );
+		}
+
+		mw.log = checkLogging;
+		mw.eventLog = mw.eventLog || {};
+		mw.eventLog.logEvent = checkProfileEventLog;
+
+		for ( i = 0; i < profileTests.length; i++ ) {
+			test = profileTests[i];
+			msgName = test[0];
+
+			expectedMsg = test[1].replace( /\$1/g, i );
+			expectedImageWidth = test[3];
+			expectedImageHeight = test[4];
+			expectedFileSize = test[5];
+			expectedFileType = test[6];
+			pid = viewer.profileStart( msgName, { width: expectedImageWidth, height: expectedImageHeight, filesize: expectedFileSize }, expectedFileType );
+			assert.strictEqual( pid, i, 'nonce-style profile IDs come in order.' );
+
+			expectedMsg = test[2].replace( /\$1/g, i ).replace( /\$2/g, 0 );
+			viewer.profileEnd( pid, false );
+		}
+
+		mw.log = backupLog;
+		mw.eventLog = backupEventLog;
+	} );
+
 }( mediaWiki, jQuery ) );