From 4d5e668583aedad41327957ca2779fd2fc7eb653 Mon Sep 17 00:00:00 2001 From: Joey Parrish Date: Tue, 17 Jan 2017 12:57:42 -0800 Subject: [PATCH] Expand player stats and track metadata Visible changes: - Add loadLatency stat - Add mimeType to tracks - Track state changes (buffering, playing, paused, ended) Internal changes: - Track switchHistory, playTime, bufferingTime in private Stats struct - Remove dead timer code Change-Id: I4566373251b9876b0d4f762a9d77aa50aea8ed00 --- build/types/core | 1 - externs/shaka/player.js | 37 ++++++++- lib/debug/timer.js | 119 ---------------------------- lib/player.js | 148 +++++++++++++++++++++++++++++------ lib/util/stream_utils.js | 5 ++ test/offline/storage_unit.js | 3 + test/player_integration.js | 8 ++ test/player_unit.js | 128 ++++++++++++++++++++++++++++++ 8 files changed, 302 insertions(+), 147 deletions(-) delete mode 100644 lib/debug/timer.js diff --git a/build/types/core b/build/types/core index b520c82e7..2820b29e3 100644 --- a/build/types/core +++ b/build/types/core @@ -7,7 +7,6 @@ +../../lib/debug/asserts.js +../../lib/debug/log.js -+../../lib/debug/timer.js +../../lib/media/drm_engine.js +../../lib/media/manifest_parser.js diff --git a/externs/shaka/player.js b/externs/shaka/player.js index 04c865c81..e542ec48e 100644 --- a/externs/shaka/player.js +++ b/externs/shaka/player.js @@ -42,6 +42,28 @@ shakaExtern.StreamChoice; +/** + * @typedef {{ + * timestamp: number, + * state: string, + * duration: number + * }} + * + * @property {number} timestamp + * The timestamp the state was entered, in seconds since 1970 + * (i.e. Date.now() / 1000). + * @property {string} state + * The state the player entered. This could be 'buffering', 'playing', + * 'paused', or 'ended'. + * @property {number} duration + * The number of seconds the player was in this state. If this is the last + * entry in the list, the player is still in this state, so the duration will + * continue to increase. + * @exportDoc + */ +shakaExtern.StateChange; + + /** * @typedef {{ * width: number, @@ -51,10 +73,13 @@ shakaExtern.StreamChoice; * decodedFrames: number, * droppedFrames: number, * estimatedBandwidth: number, + * + * loadLatency: number, * playTime: number, * bufferingTime: number, * - * switchHistory: !Array. + * switchHistory: !Array., + * stateHistory: !Array. * }} * * @description @@ -77,6 +102,11 @@ shakaExtern.StreamChoice; * is not supported by the browser. * @property {number} estimatedBandwidth * The current estimated network bandwidth (in bit/sec). + * + * @property {number} loadLatency + * This is the number of seconds it took for the video element to have enough + * data to begin playback. This is measured from the time load() is called to + * the time the 'loadeddata' event is fired by the media element. * @property {number} playTime * The total time spent in a playing state in seconds. * @property {number} bufferingTime @@ -84,6 +114,8 @@ shakaExtern.StreamChoice; * * @property {!Array.} switchHistory * A history of the stream changes. + * @property {!Array.} stateHistory + * A history of the state changes. * @exportDoc */ shakaExtern.Stats; @@ -102,6 +134,7 @@ shakaExtern.Stats; * width: ?number, * height: ?number, * frameRate: ?number, + * mimeType: ?string, * codecs: ?string * }} * @@ -133,6 +166,8 @@ shakaExtern.Stats; * (only for video tracks) The height of the track in pixels. * @property {?number} frameRate * The video framerate provided in the manifest, if present. + * @property {?string} mimeType + * The MIME type of the content provided in the manifest. * @property {?string} codecs * The audio/video codecs string provided in the manifest, if present. * @exportDoc diff --git a/lib/debug/timer.js b/lib/debug/timer.js deleted file mode 100644 index 660a1eeba..000000000 --- a/lib/debug/timer.js +++ /dev/null @@ -1,119 +0,0 @@ -/** - * @license - * Copyright 2016 Google Inc. - * - * Licensed under the Apache License, Version 2.0 (the "License"); - * you may not use this file except in compliance with the License. - * You may obtain a copy of the License at - * - * http://www.apache.org/licenses/LICENSE-2.0 - * - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an "AS IS" BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. - * See the License for the specific language governing permissions and - * limitations under the License. - */ - -goog.provide('shaka.timer'); - -goog.require('shaka.log'); - - -/** - * @namespace shaka.timer - * @summary A performance timing framework. - * Used in both debugging and production builds. - */ - - -/** - * Begins a timer. - * - * @param {string} name - */ -shaka.timer.begin = function(name) { - shaka.timer.timers_[name] = { - begin: shaka.timer.now_(), - end: NaN - }; -}; - - -/** - * End a timer and log (debug) the elapsed time. - * Does nothing if the timer has not begun. - * - * @param {string} name - */ -shaka.timer.end = function(name) { - var record = shaka.timer.timers_[name]; - if (!record) { - return; - } - - record.end = shaka.timer.now_(); - var diff = record.end - record.begin; - shaka.log.debug(name + ': ' + diff.toFixed(3) + 'ms'); -}; - - -/** - * Log (debug) the diff between two or more completed timers and return it. - * Does nothing if not all of the timers have begun. - * - * @param {string} name1 - * @param {string} name2 - * @param {...string} var_args - * @return {number} The diff between the timers, or NaN if they have not all - * completed. - */ -shaka.timer.diff = function(name1, name2, var_args) { - var t1 = shaka.timer.get(name1); - var t2 = shaka.timer.get(name2); - if (!t1 || !t2) { - return NaN; - } - var diff = t1 - t2; - var name = name1 + ' - ' + name2; - - for (var i = 2; i < arguments.length; ++i) { - var name3 = arguments[i]; - var t3 = shaka.timer.get(name3); - if (!t3) { - return NaN; - } - diff -= t3; - name += ' - ' + name3; - } - - shaka.log.debug(name + ': ' + diff.toFixed(3) + 'ms'); - return diff; -}; - - -/** - * Query a timer. - * - * @param {string} name - * @return {number} The elapsed time in milliseconds, if the timer is complete. - * Returns NaN if the timer doesn't exist or hasn't ended yet. - */ -shaka.timer.get = function(name) { - var record = shaka.timer.timers_[name]; - if (!record || !record.end) { - return NaN; - } - - return record.end - record.begin; -}; - - -/** @private {function():number} */ -shaka.timer.now_ = window.performance && window.performance.now ? - window.performance.now.bind(window.performance) : - Date.now; - - -/** @private {!Object.} */ -shaka.timer.timers_ = {}; diff --git a/lib/player.js b/lib/player.js index d4e90280c..8c3559568 100644 --- a/lib/player.js +++ b/lib/player.js @@ -141,17 +141,11 @@ shaka.Player = function(video, opt_dependencyInjector) { /** @private {{width: number, height: number}} */ this.maxHwRes_ = { width: Infinity, height: Infinity }; - /** @private {!Array.} */ - this.switchHistory_ = []; + /** @private {shakaExtern.Stats} */ + this.stats_ = this.getCleanStats_(); /** @private {number} */ - this.playTime_ = 0; - - /** @private {number} */ - this.bufferingTime_ = 0; - - /** @private {number} */ - this.lastStatUpdateTimestamp_ = 0; + this.lastTimeStatsUpdateTimestamp_ = 0; /** @private {string} */ this.currentAudioLanguage_ = this.config_.preferredAudioLanguage; @@ -432,9 +426,23 @@ shaka.Player.prototype.load = function(manifestUri, opt_startTime, this.loadChain_ = loadChain; this.dispatchEvent(new shaka.util.FakeEvent('loading')); + var startTime = Date.now(); + return loadChain.then(function() { return unloadPromise; }).then(function() { + // Not tracked in stats because it should be insignificant. + // Logged in case it is not. + shaka.log.debug('Unload latency:', (Date.now() - startTime) / 1000); + + this.stats_ = this.getCleanStats_(); + + this.eventManager_.listen(this.video_, 'playing', + this.updateState_.bind(this)); + this.eventManager_.listen(this.video_, 'pause', + this.updateState_.bind(this)); + this.eventManager_.listen(this.video_, 'ended', + this.updateState_.bind(this)); goog.asserts.assert(this.networkingEngine_, 'Must not be destroyed'); return shaka.media.ManifestParser.getFactory( @@ -486,7 +494,7 @@ shaka.Player.prototype.load = function(manifestUri, opt_startTime, // Re-filter the manifest after DRM has been initialized. this.manifest_.periods.forEach(this.filterPeriod_.bind(this)); - this.lastStatUpdateTimestamp_ = Date.now() / 1000; + this.lastTimeStatsUpdateTimestamp_ = Date.now() / 1000; // Wait for MediaSource to open before continuing. return Promise.all([ @@ -524,6 +532,14 @@ shaka.Player.prototype.load = function(manifestUri, opt_startTime, this.manifest_.periods[0], this.currentAudioLanguage_); this.config_.abr.manager.setVariants(variants); + // Wait for the 'loadeddata' event to measure load() latency. + this.eventManager_.listenOnce(this.video_, 'loadeddata', function() { + // Compute latency in seconds (Date.now() gives ms): + var latency = (Date.now() - startTime) / 1000; + this.stats_.loadLatency = latency; + shaka.log.debug('Load latency:', latency); + }.bind(this)); + this.loadChain_ = null; }.bind(this)).finalize().catch(function(error) { goog.asserts.assert(error instanceof shaka.util.Error, @@ -1189,13 +1205,14 @@ shaka.Player.prototype.getPlayheadTimeAsDate = function() { * @export */ shaka.Player.prototype.getStats = function() { - this.updateStats_(); + this.updateTimeStats_(); + this.updateState_(); var video = null; var audio = null; var videoInfo = this.video_ && this.video_.getVideoPlaybackQuality ? - this.video_.getVideoPlaybackQuality() : - {}; + this.video_.getVideoPlaybackQuality() : {}; + if (this.streamingEngine_) { var activeStreams = this.streamingEngine_.getActiveStreams(); video = activeStreams['video'] || {}; @@ -1208,18 +1225,25 @@ shaka.Player.prototype.getStats = function() { period.variants); if (!video) video = {}; if (!audio) audio = {}; + + // Clone the internal object so our state cannot be tampered with. return { + // Not tracked in this.stats_: width: video.width || 0, height: video.height || 0, streamBandwidth: variant ? variant.bandwidth : 0, - decodedFrames: Number(videoInfo.totalVideoFrames), droppedFrames: Number(videoInfo.droppedVideoFrames), estimatedBandwidth: this.config_.abr.manager.getBandwidthEstimate(), - playTime: this.playTime_, - bufferingTime: this.bufferingTime_, - switchHistory: this.switchHistory_.slice(0) + loadLatency: this.stats_.loadLatency, + playTime: this.stats_.playTime, + bufferingTime: this.stats_.bufferingTime, + // Deep-clone the objects as well as the arrays that contain them: + switchHistory: /** @type {!Array.} */( + JSON.parse(JSON.stringify(this.stats_.switchHistory))), + stateHistory: /** @type {!Array.} */( + JSON.parse(JSON.stringify(this.stats_.stateHistory))) }; }; @@ -1382,7 +1406,7 @@ shaka.Player.prototype.initialize_ = function() { * @private */ shaka.Player.prototype.addToSwitchHistory_ = function(stream, fromAdaptation) { - this.switchHistory_.push({ + this.stats_.switchHistory.push({ timestamp: Date.now() / 1000, id: stream.id, type: stream.type, @@ -1400,6 +1424,10 @@ shaka.Player.prototype.addToSwitchHistory_ = function(stream, fromAdaptation) { shaka.Player.prototype.destroyStreaming_ = function() { if (this.eventManager_) { this.eventManager_.unlisten(this.mediaSource_, 'sourceopen'); + this.eventManager_.unlisten(this.video_, 'loadeddata'); + this.eventManager_.unlisten(this.video_, 'playing'); + this.eventManager_.unlisten(this.video_, 'pause'); + this.eventManager_.unlisten(this.video_, 'ended'); } if (this.video_) { @@ -1426,9 +1454,7 @@ shaka.Player.prototype.destroyStreaming_ = function() { this.mediaSourceOpen_ = null; this.mediaSource_ = null; this.deferredSwitches_ = {}; - this.switchHistory_ = []; - this.playTime_ = 0; - this.bufferingTime_ = 0; + this.stats_ = this.getCleanStats_(); return p; }; @@ -1554,6 +1580,32 @@ shaka.Player.prototype.defaultConfig_ = function() { }; +/** + * @return {shakaExtern.Stats} + * @private + */ +shaka.Player.prototype.getCleanStats_ = function() { + return { + // These are not tracked in the private stats structure and are only here to + // satisfy the compiler. + width: NaN, + height: NaN, + streamBandwidth: NaN, + decodedFrames: NaN, + droppedFrames: NaN, + estimatedBandwidth: NaN, + + // These are tracked in the private stats structure to avoid the need for + // many private member variables. + loadLatency: NaN, + playTime: 0, + bufferingTime: 0, + switchHistory: [], + stateHistory: [] + }; +}; + + /** * @param {shakaExtern.Period} period * @private @@ -1617,18 +1669,18 @@ shaka.Player.prototype.deferredSwitch_ = function( /** @private */ -shaka.Player.prototype.updateStats_ = function() { +shaka.Player.prototype.updateTimeStats_ = function() { // Only count while we're loaded. if (!this.manifest_) return; var now = Date.now() / 1000; if (this.buffering_) - this.bufferingTime_ += (now - this.lastStatUpdateTimestamp_); + this.stats_.bufferingTime += (now - this.lastTimeStatsUpdateTimestamp_); else - this.playTime_ += (now - this.lastStatUpdateTimestamp_); + this.stats_.playTime += (now - this.lastTimeStatsUpdateTimestamp_); - this.lastStatUpdateTimestamp_ = now; + this.lastTimeStatsUpdateTimestamp_ = now; }; @@ -1652,14 +1704,58 @@ shaka.Player.prototype.onSegmentDownloaded_ = function(deltaTimeMs, numBytes) { */ shaka.Player.prototype.onBuffering_ = function(buffering) { // Before setting |buffering_|, update the time spent in the previous state. - this.updateStats_(); + this.updateTimeStats_(); this.buffering_ = buffering; + this.updateState_(); var event = new shaka.util.FakeEvent('buffering', { 'buffering': buffering }); this.dispatchEvent(event); }; +/** + * Called from potential initiators of state change, or before returning stats + * to the user. + * + * This method decides if state has actually changed, updates the last entry, + * and adds a new one if needed. + * + * @private + */ +shaka.Player.prototype.updateState_ = function() { + if (this.destroyed_) return; + + var newState; + if (this.buffering_) { + newState = 'buffering'; + } else if (this.video_.ended) { + newState = 'ended'; + } else if (this.video_.paused) { + newState = 'paused'; + } else { + newState = 'playing'; + } + + var now = Date.now() / 1000; + if (this.stats_.stateHistory.length) { + var lastIndex = this.stats_.stateHistory.length - 1; + var lastEntry = this.stats_.stateHistory[lastIndex]; + lastEntry.duration = now - lastEntry.timestamp; + + if (newState == lastEntry.state) { + // The state has not changed, so do not add anything to the history. + return; + } + } + + this.stats_.stateHistory.push({ + timestamp: now, + state: newState, + duration: 0 + }); +}; + + /** * Callback from Playhead. * diff --git a/lib/util/stream_utils.js b/lib/util/stream_utils.js index a7d58e542..db5fda1ef 100644 --- a/lib/util/stream_utils.js +++ b/lib/util/stream_utils.js @@ -231,6 +231,9 @@ shaka.util.StreamUtils.getVariantTracks = if (codecs != '') codecs += ', '; codecs += variant.audio.codecs; } + var mimeType = null; + if (variant.video) mimeType = variant.video.mimeType; + else if (variant.audio) mimeType = variant.audio.mimeType; return { id: variant.id, @@ -242,6 +245,7 @@ shaka.util.StreamUtils.getVariantTracks = width: variant.video ? variant.video.width : null, height: variant.video ? variant.video.height : null, frameRate: variant.video ? variant.video.frameRate : undefined, + mimeType: mimeType, codecs: codecs }; }); @@ -265,6 +269,7 @@ shaka.util.StreamUtils.getTextTracks = function(period, activeStream) { type: 'text', language: stream.language, kind: stream.kind, + mimeType: stream.mimeType, codecs: stream.codecs || null }; }); diff --git a/test/offline/storage_unit.js b/test/offline/storage_unit.js index 03f0053d2..165d0d501 100644 --- a/test/offline/storage_unit.js +++ b/test/offline/storage_unit.js @@ -64,6 +64,7 @@ describe('Storage', function() { width: 1920, height: 1080, frameRate: 24, + mimeType: 'video/mp4', codecs: 'avc1.4d401f', segments: [] }, @@ -75,6 +76,7 @@ describe('Storage', function() { width: null, height: null, frameRate: undefined, + mimeType: 'audio/mp4', codecs: 'vorbis', segments: [] } @@ -108,6 +110,7 @@ describe('Storage', function() { width: 1920, height: 1080, frameRate: 24, + mimeType: 'video/mp4', codecs: 'avc1.4d401f, vorbis' } ]; diff --git a/test/player_integration.js b/test/player_integration.js index a143607e6..d5b8feab4 100644 --- a/test/player_integration.js +++ b/test/player_integration.js @@ -112,6 +112,8 @@ describe('Player', function() { decodedFrames: jasmine.any(Number), droppedFrames: jasmine.any(Number), estimatedBandwidth: jasmine.any(Number), + + loadLatency: jasmine.any(Number), playTime: jasmine.any(Number), bufferingTime: jasmine.any(Number), @@ -122,6 +124,12 @@ describe('Player', function() { id: jasmine.any(Number), type: 'video', fromAdaptation: true + }]), + + stateHistory: jasmine.arrayContaining([{ + state: 'playing', + timestamp: jasmine.any(Number), + duration: jasmine.any(Number) }]) }; expect(stats).toEqual(expected); diff --git a/test/player_unit.js b/test/player_unit.js index 2064d4f51..ab60f52c4 100644 --- a/test/player_unit.js +++ b/test/player_unit.js @@ -732,6 +732,7 @@ describe('Player', function() { width: 100, height: 200, frameRate: 1000000 / 42000, + mimeType: 'video/mp4', codecs: 'avc1.4d401f, mp4a.40.2' }, { @@ -744,6 +745,7 @@ describe('Player', function() { width: 200, height: 400, frameRate: 24, + mimeType: 'video/mp4', codecs: 'avc1.4d401f, mp4a.40.2' }, { @@ -756,6 +758,7 @@ describe('Player', function() { width: 100, height: 200, frameRate: 1000000 / 42000, + mimeType: 'video/mp4', codecs: 'avc1.4d401f, mp4a.40.2' }, { @@ -768,6 +771,7 @@ describe('Player', function() { width: 200, height: 400, frameRate: 24, + mimeType: 'video/mp4', codecs: 'avc1.4d401f, mp4a.40.2' }, { @@ -780,6 +784,7 @@ describe('Player', function() { width: 200, height: 400, frameRate: 24, + mimeType: 'video/mp4', codecs: 'avc1.4d401f, mp4a.40.2' } ]; @@ -791,6 +796,7 @@ describe('Player', function() { type: 'text', language: 'es', kind: 'caption', + mimeType: 'text/vtt', codecs: null }, { @@ -799,6 +805,7 @@ describe('Player', function() { type: 'text', language: 'en', kind: 'caption', + mimeType: 'application/ttml+xml', codecs: null } ]; @@ -1193,6 +1200,7 @@ describe('Player', function() { describe('.switchHistory', function() { it('includes original choices', function() { + // checkHistory prepends the initial stream selections. checkHistory([]); }); @@ -1292,6 +1300,126 @@ describe('Player', function() { player.switch_(streamsByType); } }); + + describe('.stateHistory', function() { + it('begins with buffering state', function() { + setBuffering(true); + expect(player.getStats().stateHistory).toEqual([ + { + // We are using a mock date, so this is not a race. + timestamp: Date.now() / 1000, + duration: 0, + state: 'buffering' + } + ]); + }); + + it('transitions to paused if the video is paused', function() { + setBuffering(true); + video.paused = true; + setBuffering(false); + expect(player.getStats().stateHistory).toEqual([ + { + timestamp: jasmine.any(Number), + duration: jasmine.any(Number), + state: 'buffering' + }, + { + timestamp: jasmine.any(Number), + duration: jasmine.any(Number), + state: 'paused' + } + ]); + }); + + it('transitions to playing if the video is playing', function() { + setBuffering(true); + video.paused = false; + setBuffering(false); + expect(player.getStats().stateHistory).toEqual([ + { + timestamp: jasmine.any(Number), + duration: jasmine.any(Number), + state: 'buffering' + }, + { + timestamp: jasmine.any(Number), + duration: jasmine.any(Number), + state: 'playing' + } + ]); + }); + + it('transitions to ended when the video ends', function() { + setBuffering(false); + + video.ended = true; + // Fire an 'ended' event on the mock video. + // Using quotes to access 'on' to avoid casting to our mock video type. + video['on']['ended'](); + + expect(player.getStats().stateHistory).toEqual([ + { + timestamp: jasmine.any(Number), + duration: jasmine.any(Number), + state: 'playing' + }, + { + timestamp: jasmine.any(Number), + duration: jasmine.any(Number), + state: 'ended' + } + ]); + }); + + it('accumulates duration as time passes', function() { + // We are using a mock date, so this is not a race. + var bufferingStarts = Date.now() / 1000; + setBuffering(true); + + expect(player.getStats().stateHistory).toEqual([ + { + timestamp: bufferingStarts, + duration: 0, + state: 'buffering' + } + ]); + + jasmine.clock().tick(1500); + expect(player.getStats().stateHistory).toEqual([ + { + timestamp: bufferingStarts, + duration: 1.5, + state: 'buffering' + } + ]); + + var playbackStarts = Date.now() / 1000; + setBuffering(false); + jasmine.clock().tick(9000); + expect(player.getStats().stateHistory).toEqual([ + { + timestamp: bufferingStarts, + duration: 1.5, + state: 'buffering' + }, + { + timestamp: playbackStarts, + duration: 9, + state: 'playing' + } + ]); + + }); + + /** + * @param {boolean} buffering + * @suppress {accessControls} + */ + function setBuffering(buffering) { + player.onBuffering_(buffering); + } + }); }); describe('restrictions', function() {