From f144a0a403fdf379c99fc097e16c43fd08944fb0 Mon Sep 17 00:00:00 2001 From: Mark Holmquist Date: Fri, 6 Dec 2013 09:10:39 -0800 Subject: [PATCH] Add performance logging Change-Id: If6e3aec4b2547fa9768eaaf5387729ed2b427ab1 --- MultimediaViewer.php | 8 +- .../ext.multimediaViewer.js | 129 ++++++++++++++++-- tests/qunit/ext.multimediaViewer.test.js | 96 +++++++++++++ 3 files changed, 222 insertions(+), 11 deletions(-) diff --git a/MultimediaViewer.php b/MultimediaViewer.php index 2933653e0..b5d4fe050 100644 --- a/MultimediaViewer.php +++ b/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'; diff --git a/resources/ext.multimediaViewer/ext.multimediaViewer.js b/resources/ext.multimediaViewer/ext.multimediaViewer.js index f58c1b4e2..6f3d15999 100755 --- a/resources/ext.multimediaViewer/ext.multimediaViewer.js +++ b/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,10 +273,12 @@ * @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, - image = new Image(); + viewer = this; + image = new Image(); $.each( data.query.pages, function ( i, page ) { imageInfo = 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', - action: action, - userId: mw.user.getId(), - editCount: mw.config.get( 'wgUserEditCount', 0 ) + version: '1.1', + action: action } ); } }; + ( 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. diff --git a/tests/qunit/ext.multimediaViewer.test.js b/tests/qunit/ext.multimediaViewer.test.js index 2bd6789d5..bb91f5833 100644 --- a/tests/qunit/ext.multimediaViewer.test.js +++ b/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 ) );