Add playback ID to media trace events used by media metric

Use the MediaLog ID associated with each WebMediaPlayerImpl object as a
unique identifier, to allow the media metric to handle multiple media
playbacks in a single trace.

Bug: 775264
Change-Id: I412bbf5bf8ccab223c027cb5c936fac3de47251e
Reviewed-on: https://chromium-review.googlesource.com/741143Reviewed-by: Caleb Rouleau <crouleau@chromium.org>
Reviewed-by: Dale Curtis <dalecurtis@chromium.org>
Reviewed-by: Dan Sanders <sandersd@chromium.org>
Commit-Queue: John Chen <johnchen@chromium.org>
Cr-Commit-Position: refs/heads/master@{#513024}

media/base/media_log.h

@@ -102,7 +102,8 @@ class MEDIA_EXPORT MediaLog {
   void SetBooleanProperty(const std::string& key, bool value);
 
   // Getter for |id_|. Used by MojoMediaLogService to construct MediaLogEvents
-  // to log into this MediaLog.
+  // to log into this MediaLog. Also used in trace events to associate each
+  // event with a specific media playback.
   int32_t id() const { return id_; }
 
  private:

media/blink/webmediaplayer_impl.cc

@@ -504,7 +504,7 @@ void WebMediaPlayerImpl::OnDisplayTypeChanged(
 void WebMediaPlayerImpl::DoLoad(LoadType load_type,
                                 const blink::WebURL& url,
                                 CORSMode cors_mode) {
-  TRACE_EVENT0("media", "WebMediaPlayerImpl::DoLoad");
+  TRACE_EVENT1("media", "WebMediaPlayerImpl::DoLoad", "id", media_log_->id());
   DVLOG(1) << __func__;
   DCHECK(main_task_runner_->BelongsToCurrentThread());
 
@@ -647,8 +647,8 @@ void WebMediaPlayerImpl::Seek(double seconds) {
 
 void WebMediaPlayerImpl::DoSeek(base::TimeDelta time, bool time_updated) {
   DCHECK(main_task_runner_->BelongsToCurrentThread());
-  TRACE_EVENT1("media", "WebMediaPlayerImpl::DoSeek", "target",
-               time.InSecondsF());
+  TRACE_EVENT2("media", "WebMediaPlayerImpl::DoSeek", "target",
+               time.InSecondsF(), "id", media_log_->id());
 
 #if defined(OS_ANDROID)  // WMPI_CAST
   if (IsRemote()) {
@@ -1298,8 +1298,8 @@ void WebMediaPlayerImpl::OnCdmAttached(bool success) {
 }
 
 void WebMediaPlayerImpl::OnPipelineSeeked(bool time_updated) {
-  TRACE_EVENT1("media", "WebMediaPlayerImpl::OnPipelineSeeked", "target",
-               seek_time_.InSecondsF());
+  TRACE_EVENT2("media", "WebMediaPlayerImpl::OnPipelineSeeked", "target",
+               seek_time_.InSecondsF(), "id", media_log_->id());
   seeking_ = false;
   seek_time_ = base::TimeDelta();
 
@@ -1442,7 +1442,8 @@ void WebMediaPlayerImpl::OnError(PipelineStatus status) {
 }
 
 void WebMediaPlayerImpl::OnEnded() {
-  TRACE_EVENT1("media", "WebMediaPlayerImpl::OnEnded", "duration", Duration());
+  TRACE_EVENT2("media", "WebMediaPlayerImpl::OnEnded", "duration", Duration(),
+               "id", media_log_->id());
   DVLOG(1) << __func__;
   DCHECK(main_task_runner_->BelongsToCurrentThread());
 
@@ -1588,7 +1589,8 @@ void WebMediaPlayerImpl::OnBufferingStateChange(BufferingState state) {
       "pipeline_buffering_state", state));
 
   if (state == BUFFERING_HAVE_ENOUGH) {
-    TRACE_EVENT0("media", "WebMediaPlayerImpl::BufferingHaveEnough");
+    TRACE_EVENT1("media", "WebMediaPlayerImpl::BufferingHaveEnough", "id",
+                 media_log_->id());
     SetReadyState(CanPlayThrough() ? WebMediaPlayer::kReadyStateHaveEnoughData
                                    : WebMediaPlayer::kReadyStateHaveFutureData);
 

media/renderers/audio_renderer_impl.cc

@@ -879,7 +879,7 @@ int AudioRendererImpl::Render(base::TimeDelta delay,
                               base::TimeTicks delay_timestamp,
                               int prior_frames_skipped,
                               AudioBus* audio_bus) {
-  TRACE_EVENT0("media", "AudioRendererImpl::Render");
+  TRACE_EVENT1("media", "AudioRendererImpl::Render", "id", media_log_->id());
   int frames_requested = audio_bus->frames();
   DVLOG(4) << __func__ << " delay:" << delay
            << " prior_frames_skipped:" << prior_frames_skipped

media/renderers/video_renderer_impl.cc

@@ -282,7 +282,7 @@ scoped_refptr<VideoFrame> VideoRendererImpl::Render(
     base::TimeTicks deadline_min,
     base::TimeTicks deadline_max,
     bool background_rendering) {
-  TRACE_EVENT0("media", "VideoRendererImpl::Render");
+  TRACE_EVENT1("media", "VideoRendererImpl::Render", "id", media_log_->id());
   base::AutoLock auto_lock(lock_);
   DCHECK_EQ(state_, kPlaying);
 
@@ -742,8 +742,9 @@ void VideoRendererImpl::UpdateStats_Locked() {
 
   if (frames_decoded_ || frames_dropped_) {
     if (frames_dropped_)
-      TRACE_EVENT_INSTANT1("media", "VideoFramesDropped",
-                           TRACE_EVENT_SCOPE_THREAD, "count", frames_dropped_);
+      TRACE_EVENT_INSTANT2("media", "VideoFramesDropped",
+                           TRACE_EVENT_SCOPE_THREAD, "count", frames_dropped_,
+                           "id", media_log_->id());
     PipelineStatistics statistics;
     statistics.video_frames_decoded = frames_decoded_;
     statistics.video_frames_dropped = frames_dropped_;