blob: 0b11d30142b7d90a1df8f87a71ac34a5f5bff54e [file] [log] [blame]
<!DOCTYPE html>
<!--
Copyright 2017 The Chromium Authors. All rights reserved.
Use of this source code is governed by a BSD-style license that can be
found in the LICENSE file.
-->
<!--
media_metric uses Chrome trace events to calculate metrics about video
and audio playback. It is meant to be used for pages with <video> and/or
<audio> elements. It is used by videostack-eng@google.com team for
regression testing.
See class PerPlaybackData for details on each of the values that are measured.
This metric supports media playbacks happening simultaneously over multiple
pages, supports multiple media elements on a page, and supports multiple
playbacks with each element. It does not support media playback using
flash or any other technology not provided by Chrome videostack team.
Please inform johnchen@chromium.org about
changes to this file.
-->
<link rel="import" href="/tracing/metrics/metric_registry.html">
<link rel="import" href="/tracing/model/helpers/chrome_model_helper.html">
<link rel="import" href="/tracing/value/histogram.html">
<script>
'use strict';
tr.exportTo('tr.metrics', function() {
function mediaMetric(histograms, model) {
const chromeHelper = model.getOrCreateHelper(
tr.model.helpers.ChromeModelHelper);
if (chromeHelper === undefined) return;
for (const rendererHelper of Object.values(chromeHelper.rendererHelpers)) {
// Find the threads we're interested in, and if a needed thread
// is missing, no need to look further in this process.
const mainThread = rendererHelper.mainThread;
if (mainThread === undefined) continue;
const videoThreads = rendererHelper.process.findAllThreadsMatching(
thread => (thread.name ? thread.name.startsWith(
'ThreadPoolSingleThreadSharedForegroundBlocking') : false));
const compositorThread = rendererHelper.compositorThread;
if (compositorThread !== undefined) {
videoThreads.push(compositorThread);
}
const audioThreads =
rendererHelper.process.findAllThreadsNamed('AudioOutputDevice');
if (audioThreads.length === 0 && videoThreads.length === 0) continue;
const processData = new PerProcessData();
processData.recordPlayStarts(mainThread);
if (!processData.hasPlaybacks) continue;
if (videoThreads.length !== 0) {
processData.calculateTimeToVideoPlays(videoThreads);
processData.calculateDroppedFrameCounts(videoThreads);
}
if (audioThreads.length !== 0) {
processData.calculateTimeToAudioPlays(audioThreads);
}
processData.calculateSeekTimes(mainThread);
processData.calculateBufferingTimes(mainThread);
// Roughness metrics are output from a thread pool worker, so we don't
// have a convenient name for the thread. Check all threads.
const allThreads =
rendererHelper.process.findAllThreadsMatching(function() {
return true;
});
processData.calculateVideoPlaybackQuality(allThreads);
processData.addMetricToHistograms(histograms);
}
}
// PerProcessData manages all metric values associated with a renderer
// process. The process can have multiple media playbacks.
class PerProcessData {
constructor() {
// All the perf data we collect for a process are stored in a Map.
// Each key of the map is an ID of a media playback, and the value
// associated with each key is a PerPlaybackData object containing
// all the perf data for that playback.
this.playbackIdToDataMap_ = new Map();
}
recordPlayStarts(mainThread) {
for (const event of mainThread.sliceGroup.getDescendantEvents()) {
if (event.title === 'WebMediaPlayerImpl::DoLoad') {
const id = event.args.id;
if (this.playbackIdToDataMap_.has(id)) {
throw new Error(
'Unexpected multiple initialization of a media playback');
}
this.playbackIdToDataMap_.set(id, new PerPlaybackData(event.start));
}
}
}
get hasPlaybacks() {
return this.playbackIdToDataMap_.size > 0;
}
calculateTimeToVideoPlays(videoThreads) {
for (const thread of videoThreads) {
for (const event of thread.sliceGroup.getDescendantEvents()) {
if (event.title === 'VideoRendererImpl::Render') {
this.getPerPlaybackObject_(event.args.id)
.processVideoRenderTime(event.start);
}
}
}
}
calculateTimeToAudioPlays(audioThreads) {
for (const audioThread of audioThreads) {
for (const event of audioThread.sliceGroup.getDescendantEvents()) {
if (event.title === 'AudioRendererImpl::Render') {
this.getPerPlaybackObject_(event.args.id)
.processAudioRenderTime(event.start);
}
}
}
}
calculateSeekTimes(mainThread) {
for (const event of mainThread.sliceGroup.getDescendantEvents()) {
if (event.title === 'WebMediaPlayerImpl::DoSeek') {
this.getPerPlaybackObject_(event.args.id)
.processDoSeek(event.args.target, event.start);
} else if (event.title === 'WebMediaPlayerImpl::OnPipelineSeeked') {
this.getPerPlaybackObject_(event.args.id)
.processOnPipelineSeeked(event.args.target, event.start);
} else if (event.title === 'WebMediaPlayerImpl::BufferingHaveEnough') {
this.getPerPlaybackObject_(event.args.id)
.processBufferingHaveEnough(event.start);
}
}
}
calculateBufferingTimes(mainThread) {
for (const event of mainThread.sliceGroup.getDescendantEvents()) {
if (event.title === 'WebMediaPlayerImpl::OnEnded') {
this.getPerPlaybackObject_(event.args.id)
.processOnEnded(event.start, event.args.duration);
}
}
}
calculateDroppedFrameCounts(videoThreads) {
for (const thread of videoThreads) {
for (const event of thread.sliceGroup.getDescendantEvents()) {
if (event.title === 'VideoFramesDropped') {
this.getPerPlaybackObject_(event.args.id)
.processVideoFramesDropped(event.args.count);
}
}
}
}
calculateVideoPlaybackQuality(threads) {
for (const thread of threads) {
for (const event of thread.sliceGroup.getDescendantEvents()) {
if (event.title === 'VideoPlaybackRoughness') {
this.getPerPlaybackObject_(event.args.id)
.processVideoRoughness(event.args.roughness);
} else if (event.title === 'VideoPlaybackFreezing') {
this.getPerPlaybackObject_(event.args.id)
.processVideoFreezing(event.args.freezing);
}
}
}
}
addMetricToHistograms(histograms) {
for (const [id, playbackData] of this.playbackIdToDataMap_) {
playbackData.addMetricToHistograms(histograms);
}
}
// @private
getPerPlaybackObject_(playbackId) {
let perPlaybackObject = this.playbackIdToDataMap_.get(playbackId);
if (perPlaybackObject === undefined) {
// The trace isn't complete, and didn't contain the DoLoad event for
// this playback. Create a new PerPlaybackData object for this playback.
perPlaybackObject = new PerPlaybackData(undefined);
this.playbackIdToDataMap_.set(playbackId, perPlaybackObject);
}
return perPlaybackObject;
}
}
// PerPlaybackData contains all metric values associated with a single
// media playback.
class PerPlaybackData {
constructor(playStartTime) {
this.playStart_ = playStartTime;
this.timeToVideoPlay_ = undefined;
this.timeToAudioPlay_ = undefined;
this.bufferingTime_ = undefined;
this.droppedFrameCount_ = 0;
this.seekError_ = false;
this.seekTimes_ = new Map();
this.currentSeek_ = undefined;
this.roughness_ = undefined;
this.freezing_ = undefined;
}
// API methods for retrieving metric values. Each method returns undefined
// if no value is available (e.g., timeToVideoPlay() returns undefined for
// an audio-only playback).
// Returns how long after a video is requested to start playing before
// the video actually starts. If time_to_video_play regresses, then users
// will click to play videos and then have to wait longer before the videos
// start actually playing.
get timeToVideoPlay() {
return this.timeToVideoPlay_;
}
// Similar to timeToVideoPlay, but measures the time delay before audio
// starts playing.
get timeToAudioPlay() {
return this.timeToAudioPlay_;
}
// Returns the difference between the actual play time of media vs its
// expected play time. Ideally the two should be the same. If actual play
// time is significantly longer than expected play time, it indicates that
// there were stalls during the play for buffering or some other reasons.
// Current limitation: Buffering time isn't calculated if seek occurred
// during playback, and it gives incorrect value if the playback isn't
// from beginning to end without pauses.
get bufferingTime() {
return this.bufferingTime_;
}
// Reports the number of video frames that were dropped. Ideally this
// should be 0. If a large number of frames are dropped, the video playback
// will not be smooth.
get droppedFrameCount() {
// We should report dropped frame count as long as video was played.
return (this.timeToVideoPlay_ !== undefined) ?
this.droppedFrameCount_ : undefined;
}
// Returns a Map containing seek times. The keys of the map are numerical
// values indicating the target location of the seek, in unit of seconds.
// The values of the map are objects with the following public properties:
// * pipelineSeekTime: amount of time taken by media pipeline to process
// this seek operation, from when the seek request is received, to when
// the pipeline starts processing at the new location, in milliseconds.
// * seekTime: how long after a user requests a seek operation before the
// seek completes and the media starts playing at the new location, as
// perceived by the user, in milliseconds.
get seekTimes() {
if (this.seekError_ || this.currentSeek_ !== undefined) return new Map();
return this.seekTimes_;
}
// Reports aggregate roughness.
get roughness() {
return this.roughness_;
}
// Reports aggregate freezing.
get freezing() {
return this.freezing_;
}
// API methods for processing data from trace events.
processVideoRenderTime(videoRenderTime) {
// Each video playback can generate multiple Render events, one for
// each frame. For calculating time to video play, we only use the
// first Render event.
if (this.playStart_ !== undefined &&
this.timeToVideoPlay_ === undefined) {
this.timeToVideoPlay_ = videoRenderTime - this.playStart_;
}
}
processAudioRenderTime(audioRenderTime) {
if (this.playStart_ !== undefined &&
this.timeToAudioPlay_ === undefined) {
this.timeToAudioPlay_ = audioRenderTime - this.playStart_;
}
}
processVideoFramesDropped(count) {
this.droppedFrameCount_ += count;
}
// We support multiple seeks per element, as long as they seek to different
// target time. Thus the seek times are stored in a Map instead of a scalar
// property. The key of the map is event.args.target, which is a numerical
// value indicating the target location of the seek, in unit of seconds.
// For example, with a seek to 5 seconds mark, event.args.target === 5.
// The value of the map is an object with 4 properties (the first two are
// added during object creation, the latter two are added as the data
// become available):
// * target: seek target time (same as the map key)
// * startTime: timestamp of the event marking start of seek
// * pipelineSeekTime: amount of time taken by media pipeline to process
// this seek (milliseconds)
// * seekTime: amount of seek time perceived by the user (milliseconds)
// If any unexpected conditions occur, we stop processing and set an error
// flag this.seekError_.
// TODO(https://github.com/catapult-project/catapult/issues/3976):
// Emit detailed warnings.
processDoSeek(target, startTime) {
// currentSeek_ refers to the object associated with the
// seek that is currently being processed for this media element.
// It is used to match seek end events against seek start events.
if (this.currentSeek_ !== undefined) {
// TODO(https://github.com/catapult-project/catapult/issues/3976):
// Warning 'Overlapping seek not supported'.
this.seekError_ = true;
return;
}
this.currentSeek_ = { target, startTime };
this.seekTimes_.set(target, this.currentSeek_);
}
processOnPipelineSeeked(target, time) {
if (this.seekError_) return;
const currentSeek = this.currentSeek_;
if (currentSeek === undefined) {
// OK to have this event when there is no active seek, as this event
// can be generated for other reasons, e.g., initial loading of media
// generates this event with target of 0 seconds.
return;
}
if (currentSeek.target !== target) {
// TODO(https://github.com/catapult-project/catapult/issues/3976):
// Warning 'WebMediaPlayerImpl::OnPipelineSeeked to unexpected target'.
this.seekError_ = true;
return;
}
if (currentSeek.pipelineSeekTime !== undefined) {
// TODO(https://github.com/catapult-project/catapult/issues/3976):
// Warning 'Multiple WebMediaPlayerImpl::OnPipelineSeeked events'.
this.seekError_ = true;
return;
}
currentSeek.pipelineSeekTime = time - currentSeek.startTime;
}
processBufferingHaveEnough(time) {
if (this.seekError_) return;
const currentSeek = this.currentSeek_;
if (currentSeek === undefined) {
// No current seek means this event is generated by non-seek related
// events, e.g., initial loading of media.
return;
}
if (currentSeek.pipelineSeekTime === undefined) {
// Since we haven't seen WebMediaPlayerImpl::OnPipelineSeeked event
// event yet, this event is triggered by something else, e.g., a
// have_nothing->have_enough cycle due to underflow from decoders.
return;
}
currentSeek.seekTime = time - currentSeek.startTime;
// Finished processing current seek.
this.currentSeek_ = undefined;
}
processOnEnded(playEndTime, duration) {
if (this.playStart_ === undefined) return;
// Can't calculate buffering time if there were any seeks.
if (this.seekTimes_.size !== 0 || this.seekError_) return;
// Play was resumed after it ended previously.
if (this.bufferingTime_ !== undefined) return;
// Convert duration from seconds to milliseconds.
duration = tr.b.convertUnit(duration, tr.b.UnitPrefixScale.METRIC.NONE,
tr.b.UnitPrefixScale.METRIC.MILLI);
const playTime = playEndTime - this.playStart_;
if (this.timeToVideoPlay_ !== undefined) {
this.bufferingTime_ = playTime - duration - this.timeToVideoPlay_;
} else if (this.timeToAudioPlay !== undefined) {
this.bufferingTime_ = playTime - duration - this.timeToAudioPlay_;
}
}
processVideoRoughness(roughness) {
// Record the worst roughness.
if (this.roughness_ === undefined || this.roughness_ > roughness) {
this.roughness_ = roughness;
}
}
processVideoFreezing(freezing) {
// Record the worst freezing.
if (this.freezing_ === undefined || this.freezing_ > freezing) {
this.freezing_ = freezing;
}
}
addMetricToHistograms(histograms) {
this.addSample_(histograms, 'time_to_video_play',
tr.b.Unit.byName.timeDurationInMs_smallerIsBetter,
this.timeToVideoPlay);
this.addSample_(histograms, 'time_to_audio_play',
tr.b.Unit.byName.timeDurationInMs_smallerIsBetter,
this.timeToAudioPlay);
this.addSample_(histograms, 'dropped_frame_count',
tr.b.Unit.byName.count_smallerIsBetter,
this.droppedFrameCount);
for (const [key, value] of this.seekTimes.entries()) {
// key is a numerical value that can have '.' when converted to
// string. However, '.' causes problems in histogram names, so
// replace with '_'.
const keyString = key.toString().replace('.', '_');
this.addSample_(histograms, 'pipeline_seek_time_' + keyString,
tr.b.Unit.byName.timeDurationInMs_smallerIsBetter,
value.pipelineSeekTime);
this.addSample_(histograms, 'seek_time_' + keyString,
tr.b.Unit.byName.timeDurationInMs_smallerIsBetter,
value.seekTime);
}
this.addSample_(histograms, 'buffering_time',
tr.b.Unit.byName.timeDurationInMs_smallerIsBetter,
this.bufferingTime);
this.addSample_(histograms, 'roughness',
tr.b.Unit.byName.count_smallerIsBetter,
this.roughness);
this.addSample_(histograms, 'freezing',
tr.b.Unit.byName.timeDurationInMs_smallerIsBetter,
this.freezing);
}
// @private
addSample_(histograms, name, unit, sample) {
if (sample === undefined) return;
const histogram = histograms.getHistogramNamed(name);
if (histogram === undefined) {
histograms.createHistogram(name, unit, sample);
} else {
histogram.addSample(sample);
}
}
}
tr.metrics.MetricRegistry.register(mediaMetric);
return {
mediaMetric,
};
});
</script>