From 3791274c7fb901cbbc669a4486fa50cbcb598dc6 Mon Sep 17 00:00:00 2001 From: Cobalt Team Date: Tue, 22 Mar 2022 15:24:44 -0700 Subject: [PATCH] [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 | 24 +++++++-- cobalt/media/base/starboard_player.cc | 73 ++++++++++++++++++++++++++ cobalt/media/base/starboard_player.h | 15 ++++++ 3 files changed, 108 insertions(+), 4 deletions(-) diff --git a/cobalt/media/base/sbplayer_pipeline.cc b/cobalt/media/base/sbplayer_pipeline.cc index f7fbbd4ad965..9530bfd56f0c 100644 --- a/cobalt/media/base/sbplayer_pipeline.cc +++ b/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 diff --git a/cobalt/media/base/starboard_player.cc b/cobalt/media/base/starboard_player.cc index 1c476a663afd..30f3a4cbe0ef 100644 --- a/cobalt/media/base/starboard_player.cc +++ b/cobalt/media/base/starboard_player.cc @@ -14,6 +14,8 @@ #include "cobalt/media/base/starboard_player.h" +#include +#include #include #include @@ -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 diff --git a/cobalt/media/base/starboard_player.h b/cobalt/media/base/starboard_player.h index 6e40ac4cc1d9..7e3ffd846bb8 100644 --- a/cobalt/media/base/starboard_player.h +++ b/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)