[media] Log SbPlayer initialization latencies

Adds a log for the duration between key events as the SbPlayer is
initialized.

Example output (android-arm_devel on Sabrina):

SbPlayer startup latencies
    Event name                                        time since last \
event
    set_drm_system_ready_cb called                    0 us
    SbPlayerCreate() called                           13565 us
    kSbPlayerStateInitialized received                315737 us
    kSbPlayerStatePrerolling received                 606 us
    First media sample(s) written [audio/video]       151/204 us
    kSbPlayerStatePresenting received                 439794 us

b/223811180

Change-Id: Ic6d8ba8fc27aa16a43b560e3f235972542705ee2
(cherry picked from commit 8249fc7adcb032dc38ea57ec345aabd7ad4d8a6f)

cobalt/media/base/sbplayer_pipeline.cc

@@ -200,6 +200,8 @@ class MEDIA_EXPORT SbPlayerPipeline : public Pipeline,
   // playback resume.
   std::string GetTimeInformation() const;
 
+  void RunSetDrmSystemReadyCB();
+
   // An identifier string for the pipeline, used in CVal to identify multiple
   // pipelines.
   const std::string pipeline_identifier_;
@@ -326,6 +328,8 @@ class MEDIA_EXPORT SbPlayerPipeline : public Pipeline,
 
   SbTimeMonotonic last_resume_time_ = -1;
 
+  SbTimeMonotonic set_drm_system_ready_cb_time_ = -1;
+
   DISALLOW_COPY_AND_ASSIGN(SbPlayerPipeline);
 };
 
@@ -515,8 +519,7 @@ void SbPlayerPipeline::Start(const SetDrmSystemReadyCB& set_drm_system_ready_cb,
                  on_encrypted_media_init_data_encountered_cb);
   set_drm_system_ready_cb_ = parameters.set_drm_system_ready_cb;
   DCHECK(!set_drm_system_ready_cb_.is_null());
-  set_drm_system_ready_cb_.Run(
-      base::Bind(&SbPlayerPipeline::SetDrmSystem, this));
+  RunSetDrmSystemReadyCB();
 
   task_runner_->PostTask(
       FROM_HERE, base::Bind(&SbPlayerPipeline::StartTask, this, parameters));
@@ -963,6 +966,7 @@ void SbPlayerPipeline::SetDrmSystem(SbDrmSystem drm_system) {
   }
 
   if (player_->IsValid()) {
+    player_->RecordSetDrmSystemReadyTime(set_drm_system_ready_cb_time_);
     player_->SetDrmSystem(drm_system);
   }
 }
@@ -1032,6 +1036,7 @@ void SbPlayerPipeline::CreatePlayer(SbDrmSystem drm_system) {
   }
 
   if (player_ && player_->IsValid()) {
+    player_->RecordSetDrmSystemReadyTime(set_drm_system_ready_cb_time_);
     base::Closure output_mode_change_cb;
     {
       base::AutoLock auto_lock(lock_);
@@ -1117,8 +1122,7 @@ void SbPlayerPipeline::OnDemuxerInitialized(PipelineStatus status) {
       content_size_change_cb_.Run();
     }
     if (is_encrypted) {
-      set_drm_system_ready_cb_.Run(
-          BindToCurrentLoop(base::Bind(&SbPlayerPipeline::CreatePlayer, this)));
+      RunSetDrmSystemReadyCB();
       return;
     }
   }
@@ -1527,6 +1531,18 @@ std::string SbPlayerPipeline::GetTimeInformation() const {
          ", time since last resume: " + time_since_resume;
 }
 
+void SbPlayerPipeline::RunSetDrmSystemReadyCB() {
+  TRACE_EVENT0("cobalt::media", "SbPlayerPipeline::RunSetDrmSystemReadyCB");
+  set_drm_system_ready_cb_time_ = SbTimeGetMonotonicNow();
+#if SB_HAS(PLAYER_WITH_URL)
+  set_drm_system_ready_cb_.Run(
+      base::Bind(&SbPlayerPipeline::SetDrmSystem, this));
+#else   // SB_HAS(PLAYER_WITH_URL)
+  set_drm_system_ready_cb_.Run(
+      BindToCurrentLoop(base::Bind(&SbPlayerPipeline::CreatePlayer, this)));
+#endif  // SB_HAS(PLAYER_WITH_URL)
+}
+
 }  // namespace
 
 // static

cobalt/media/base/starboard_player.cc

@@ -14,6 +14,8 @@
 
 #include "cobalt/media/base/starboard_player.h"
 
+#include <algorithm>
+#include <iomanip>
 #include <string>
 #include <vector>
 
@@ -25,6 +27,7 @@
 #include "cobalt/media/base/format_support_query_metrics.h"
 #include "cobalt/media/base/starboard_utils.h"
 #include "starboard/common/media.h"
+#include "starboard/common/string.h"
 #include "starboard/configuration.h"
 #include "starboard/memory.h"
 
@@ -524,6 +527,8 @@ void StarboardPlayer::CreateUrlPlayer(const std::string& url) {
     FormatSupportQueryMetrics::PrintAndResetFormatSupportQueryMetrics();
   }
 
+  player_creation_time_ = SbTimeGetMonotonicNow();
+
   player_ =
       SbUrlPlayerCreate(url.c_str(), window_, &StarboardPlayer::PlayerStatusCB,
                         &StarboardPlayer::EncryptedMediaInitDataEncounteredCB,
@@ -566,6 +571,8 @@ void StarboardPlayer::CreatePlayer() {
     FormatSupportQueryMetrics::PrintAndResetFormatSupportQueryMetrics();
   }
 
+  player_creation_time_ = SbTimeGetMonotonicNow();
+
 #if SB_HAS(PLAYER_CREATION_AND_OUTPUT_MODE_QUERY_IMPROVEMENT)
 
   SbPlayerCreationParam creation_param = {};
@@ -663,6 +670,14 @@ void StarboardPlayer::WriteBufferInternal(
   }
 
   auto sample_type = DemuxerStreamTypeToSbMediaType(type);
+
+  if (sample_type == kSbMediaTypeAudio && first_audio_sample_time_ == 0) {
+    first_audio_sample_time_ = SbTimeGetMonotonicNow();
+  } else if (sample_type == kSbMediaTypeVideo &&
+             first_video_sample_time_ == 0) {
+    first_video_sample_time_ = SbTimeGetMonotonicNow();
+  }
+
   SbDrmSampleInfo drm_info;
   SbDrmSubSampleMapping subsample_mapping;
   drm_info.subsample_count = 0;
@@ -817,6 +832,8 @@ void StarboardPlayer::OnDecoderStatus(SbPlayer player, SbMediaType type,
 
 void StarboardPlayer::OnPlayerStatus(SbPlayer player, SbPlayerState state,
                                      int ticket) {
+  TRACE_EVENT1("cobalt::media", "StarboardPlayer::OnPlayerStatus", "state",
+               state);
   DCHECK(task_runner_->BelongsToCurrentThread());
 
   if (player_ != player) {
@@ -833,11 +850,24 @@ void StarboardPlayer::OnPlayerStatus(SbPlayer player, SbPlayerState state,
     if (ticket_ == SB_PLAYER_INITIAL_TICKET) {
       ++ticket_;
     }
+    if (sb_player_state_initialized_time_ == 0) {
+      sb_player_state_initialized_time_ = SbTimeGetMonotonicNow();
+    }
     SbPlayerSeek2(player_, preroll_timestamp_.InMicroseconds(), ticket_);
     SetVolume(volume_);
     SbPlayerSetPlaybackRate(player_, playback_rate_);
     return;
   }
+  if (state == kSbPlayerStatePrerolling &&
+      sb_player_state_prerolling_time_ == 0) {
+    sb_player_state_prerolling_time_ = SbTimeGetMonotonicNow();
+  } else if (state == kSbPlayerStatePresenting &&
+             sb_player_state_presenting_time_ == 0) {
+    sb_player_state_presenting_time_ = SbTimeGetMonotonicNow();
+#if !defined(COBALT_BUILD_TYPE_GOLD)
+    LogStartupLatency();
+#endif  // !defined(COBALT_BUILD_TYPE_GOLD)
+  }
   host_->OnPlayerStatus(state);
 }
 
@@ -994,5 +1024,48 @@ SbPlayerOutputMode StarboardPlayer::ComputeSbPlayerOutputMode(
 #endif  // SB_HAS(PLAYER_CREATION_AND_OUTPUT_MODE_QUERY_IMPROVEMENT)
 }
 
+void StarboardPlayer::LogStartupLatency() const {
+  std::string first_events_str;
+  if (set_drm_system_ready_cb_time_ == -1) {
+    first_events_str =
+        starboard::FormatString("%-50s0 us", "SbPlayerCreate() called");
+
+  } else if (set_drm_system_ready_cb_time_ < player_creation_time_) {
+    first_events_str = starboard::FormatString(
+        "%-50s0 us\n%-50s%" PRId64 " us", "set_drm_system_ready_cb called",
+        "SbPlayerCreate() called",
+        player_creation_time_ - set_drm_system_ready_cb_time_);
+  } else {
+    first_events_str = starboard::FormatString(
+        "%-50s0 us\n%-50s%" PRId64 " us", "SbPlayerCreate() called",
+        "set_drm_system_ready_cb called",
+        set_drm_system_ready_cb_time_ - player_creation_time_);
+  }
+
+  SbTime player_initialization_time_delta =
+      sb_player_state_initialized_time_ -
+      std::max(player_creation_time_, set_drm_system_ready_cb_time_);
+  SbTime player_preroll_time_delta =
+      sb_player_state_prerolling_time_ - sb_player_state_initialized_time_;
+  SbTime first_audio_sample_time_delta = std::max(
+      first_audio_sample_time_ - sb_player_state_prerolling_time_, SbTime(0));
+  SbTime first_video_sample_time_delta = std::max(
+      first_video_sample_time_ - sb_player_state_prerolling_time_, SbTime(0));
+  SbTime player_presenting_time_delta =
+      sb_player_state_presenting_time_ -
+      std::max(first_audio_sample_time_, first_video_sample_time_);
+
+  LOG(INFO) << starboard::FormatString(
+      "SbPlayer startup latencies\n%-50s%s\n%s\n%-50s%" PRId64
+      " us\n%-50s%" PRId64 " us\n%-50s%" PRId64 "/%" PRId64 " us\n%-50s%" PRId64
+      " us",
+      "Event name", "time since last event", first_events_str.c_str(),
+      "kSbPlayerStateInitialized received", player_initialization_time_delta,
+      "kSbPlayerStatePrerolling received", player_preroll_time_delta,
+      "First media sample(s) written [audio/video]",
+      first_audio_sample_time_delta, first_video_sample_time_delta,
+      "kSbPlayerStatePresenting received", player_presenting_time_delta);
+}
+
 }  // namespace media
 }  // namespace cobalt

cobalt/media/base/starboard_player.h

@@ -130,6 +130,10 @@ class StarboardPlayer {
   SbDecodeTarget GetCurrentSbDecodeTarget();
   SbPlayerOutputMode GetSbPlayerOutputMode();
 
+  void RecordSetDrmSystemReadyTime(SbTimeMonotonic timestamp) {
+    set_drm_system_ready_cb_time_ = timestamp;
+  }
+
  private:
   enum State {
     kPlaying,
@@ -216,6 +220,8 @@ class StarboardPlayer {
   SbPlayerOutputMode ComputeSbPlayerOutputMode(
       bool prefer_decode_to_texture) const;
 
+  void LogStartupLatency() const;
+
 // The following variables are initialized in the ctor and never changed.
 #if SB_HAS(PLAYER_WITH_URL)
   std::string url_;
@@ -269,6 +275,15 @@ class StarboardPlayer {
   bool is_creating_player_ = false;
   std::string player_creation_error_message_;
 
+  // Variables related to tracking player startup latencies.
+  SbTimeMonotonic set_drm_system_ready_cb_time_ = -1;
+  SbTimeMonotonic player_creation_time_ = 0;
+  SbTimeMonotonic sb_player_state_initialized_time_ = 0;
+  SbTimeMonotonic sb_player_state_prerolling_time_ = 0;
+  SbTimeMonotonic first_audio_sample_time_ = 0;
+  SbTimeMonotonic first_video_sample_time_ = 0;
+  SbTimeMonotonic sb_player_state_presenting_time_ = 0;
+
 #if SB_HAS(PLAYER_WITH_URL)
   const bool is_url_based_;
 #endif  // SB_HAS(PLAYER_WITH_URL)