jenkins-bot has submitted this change and it was merged. Change subject: Track the most recent upload time for duration events ......................................................................
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 --- M MultimediaViewer.php M resources/mmv/logging/mmv.logging.DurationLogger.js M resources/mmv/mmv.head.js M resources/mmv/mmv.js M tests/qunit/mmv/logging/mmv.logging.DurationLogger.test.js 5 files changed, 138 insertions(+), 34 deletions(-) Approvals: Gergő Tisza: Looks good to me, approved jenkins-bot: Verified diff --git a/MultimediaViewer.php b/MultimediaViewer.php index 5822e44..5e3434c 100644 --- a/MultimediaViewer.php +++ b/MultimediaViewer.php @@ -1015,7 +1015,7 @@ $schemas += array( 'MediaViewer' => 10308479, 'MultimediaViewerNetworkPerformance' => 7917896, - 'MultimediaViewerDuration' => 8572641, + 'MultimediaViewerDuration' => 10427980, 'MultimediaViewerAttribution' => 9758179, 'MultimediaViewerDimensions' => 10014238, ); diff --git a/resources/mmv/logging/mmv.logging.DurationLogger.js b/resources/mmv/logging/mmv.logging.DurationLogger.js index 1a769d7..d7320e5 100644 --- a/resources/mmv/logging/mmv.logging.DurationLogger.js +++ b/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(); diff --git a/resources/mmv/mmv.head.js b/resources/mmv/mmv.head.js index 43a8b63..0310c51 100644 --- a/resources/mmv/mmv.head.js +++ b/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 } ); diff --git a/resources/mmv/mmv.js b/resources/mmv/mmv.js index 46d440c..0b1f8b4 100644 --- a/resources/mmv/mmv.js +++ b/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 diff --git a/tests/qunit/mmv/logging/mmv.logging.DurationLogger.test.js b/tests/qunit/mmv/logging/mmv.logging.DurationLogger.test.js index 9cd849c..e555e74 100644 --- a/tests/qunit/mmv/logging/mmv.logging.DurationLogger.test.js +++ b/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 ) { -- To view, visit https://gerrit.wikimedia.org/r/171228 To unsubscribe, visit https://gerrit.wikimedia.org/r/settings Gerrit-MessageType: merged Gerrit-Change-Id: I4ce358ff54e4ca4e290349aa3ff4810ad4714d24 Gerrit-PatchSet: 6 Gerrit-Project: mediawiki/extensions/MultimediaViewer Gerrit-Branch: master Gerrit-Owner: Gilles <[email protected]> Gerrit-Reviewer: Gergő Tisza <[email protected]> Gerrit-Reviewer: Gilles <[email protected]> Gerrit-Reviewer: jenkins-bot <> _______________________________________________ MediaWiki-commits mailing list [email protected] https://lists.wikimedia.org/mailman/listinfo/mediawiki-commits
