From e15e35c88a215b24bcc4d773aa59b9147cd17352 Mon Sep 17 00:00:00 2001 From: Drew Thomas Date: Thu, 14 Mar 2024 16:11:49 -0700 Subject: [PATCH 1/2] Add telemetry for `SourceBuffer.appendBuffer` (#2586) Modifies the SourceBufferMetrics class to not be completely stubbed out in gold builds, and use it to send UMA histograms for the time spent in `SourceBuffer::PrepareAppend` and `SourceBufferAppendAlgorithm::Process`. Added basic unit tests for the `SourceBufferMetrics` class, to assert that the new code reports telemetry against the correct histograms. b/329439818 Change-Id: I7921434b02c689b645ab2a60464eee166d829135 (cherry picked from commit 0279b59dc75cf252cb1e70a72312fa1139fa38da) --- cobalt/dom/BUILD.gn | 1 + cobalt/dom/source_buffer.cc | 7 +- cobalt/dom/source_buffer_algorithm.cc | 6 +- cobalt/dom/source_buffer_metrics.cc | 73 ++++++++++++++++++- cobalt/dom/source_buffer_metrics.h | 53 +++++++++----- cobalt/dom/source_buffer_metrics_test.cc | 66 +++++++++++++++++ .../histograms/metadata/cobalt/histograms.xml | 34 +++++++++ 7 files changed, 214 insertions(+), 26 deletions(-) create mode 100644 cobalt/dom/source_buffer_metrics_test.cc diff --git a/cobalt/dom/BUILD.gn b/cobalt/dom/BUILD.gn index 17617fa8e355..6cafc64838b4 100644 --- a/cobalt/dom/BUILD.gn +++ b/cobalt/dom/BUILD.gn @@ -408,6 +408,7 @@ target(gtest_target_type, "dom_test") { "rule_matching_test.cc", "screen_test.cc", "serializer_test.cc", + "source_buffer_metrics_test.cc", "storage_area_test.cc", "text_test.cc", "time_ranges_test.cc", diff --git a/cobalt/dom/source_buffer.cc b/cobalt/dom/source_buffer.cc index 1ad5a59630de..087ae14836f4 100644 --- a/cobalt/dom/source_buffer.cc +++ b/cobalt/dom/source_buffer.cc @@ -58,6 +58,7 @@ #include "cobalt/dom/dom_settings.h" #include "cobalt/dom/media_settings.h" #include "cobalt/dom/media_source.h" +#include "cobalt/dom/source_buffer_metrics.h" #include "cobalt/web/context.h" #include "cobalt/web/dom_exception.h" #include "cobalt/web/web_settings.h" @@ -591,7 +592,7 @@ bool SourceBuffer::PrepareAppend(size_t new_data_size, return false; } - metrics_.StartTracking(); + metrics_.StartTracking(SourceBufferMetricsAction::PREPARE_APPEND); media_source_->OpenIfInEndedState(); double current_time = media_source_->GetMediaElement()->current_time(NULL); @@ -600,11 +601,11 @@ bool SourceBuffer::PrepareAppend(size_t new_data_size, new_data_size + evict_extra_in_bytes_)) { web::DOMException::Raise(web::DOMException::kQuotaExceededErr, exception_state); - metrics_.EndTracking(0); + metrics_.EndTracking(SourceBufferMetricsAction::PREPARE_APPEND, 0); return false; } - metrics_.EndTracking(0); + metrics_.EndTracking(SourceBufferMetricsAction::PREPARE_APPEND, 0); return true; } diff --git a/cobalt/dom/source_buffer_algorithm.cc b/cobalt/dom/source_buffer_algorithm.cc index b55e9cd16987..732e463e9a14 100644 --- a/cobalt/dom/source_buffer_algorithm.cc +++ b/cobalt/dom/source_buffer_algorithm.cc @@ -20,6 +20,7 @@ #include "base/logging.h" #include "base/trace_event/trace_event.h" #include "cobalt/dom/media_source.h" +#include "cobalt/dom/source_buffer_metrics.h" namespace cobalt { namespace dom { @@ -67,12 +68,13 @@ void SourceBufferAppendAlgorithm::Process(bool* finished) { TRACE_EVENT1("cobalt::dom", "SourceBufferAppendAlgorithm::Process()", "append_size", append_size); - metrics_->StartTracking(); + metrics_->StartTracking(SourceBufferMetricsAction::APPEND_BUFFER); succeeded_ = chunk_demuxer_->AppendData( id_, buffer_, append_size, append_window_start_, append_window_end_, ×tamp_offset_); update_timestamp_offset_cb_.Run(timestamp_offset_); - metrics_->EndTracking(succeeded_ ? append_size : 0); + metrics_->EndTracking(SourceBufferMetricsAction::APPEND_BUFFER, + succeeded_ ? append_size : 0); if (succeeded_) { buffer_ += append_size; diff --git a/cobalt/dom/source_buffer_metrics.cc b/cobalt/dom/source_buffer_metrics.cc index 82aed8df600e..a1168b27d153 100644 --- a/cobalt/dom/source_buffer_metrics.cc +++ b/cobalt/dom/source_buffer_metrics.cc @@ -17,6 +17,11 @@ #include #include "base/logging.h" +<<<<<<< HEAD +======= +#include "base/metrics/histogram_macros.h" +#include "base/time/time.h" +>>>>>>> 0279b59dc75 (Add telemetry for `SourceBuffer.appendBuffer` (#2586)) #include "cobalt/base/statistics.h" #include "starboard/common/string.h" #include "starboard/once.h" @@ -26,7 +31,6 @@ namespace cobalt { namespace dom { #if !defined(COBALT_BUILD_TYPE_GOLD) - namespace { int GetBandwidth(std::size_t size, SbTimeMonotonic duration) { @@ -59,19 +63,34 @@ double GetWallToThreadTimeRatio(int64_t wall_time, int64_t thread_time) { } // namespace SB_ONCE_INITIALIZE_FUNCTION(StatisticsWrapper, StatisticsWrapper::GetInstance); -void SourceBufferMetrics::StartTracking() { +#endif // !defined(COBALT_BUILD_TYPE_GOLD) + +void SourceBufferMetrics::StartTracking(SourceBufferMetricsAction action) { if (!is_primary_video_) { return; } DCHECK(!is_tracking_); + DCHECK(current_action_ == SourceBufferMetricsAction::NO_ACTION); + DCHECK(action != SourceBufferMetricsAction::NO_ACTION); + is_tracking_ = true; +<<<<<<< HEAD wall_start_time_ = SbTimeGetMonotonicNow(); thread_start_time_ = SbTimeIsTimeThreadNowSupported() ? SbTimeGetMonotonicThreadNow() : -1; +======= + current_action_ = action; + wall_start_time_ = clock_->NowTicks(); + +#if !defined(COBALT_BUILD_TYPE_GOLD) + thread_start_time_ = starboard::CurrentMonotonicThreadTime(); +#endif // !defined(COBALT_BUILD_TYPE_GOLD) +>>>>>>> 0279b59dc75 (Add telemetry for `SourceBuffer.appendBuffer` (#2586)) } -void SourceBufferMetrics::EndTracking(std::size_t size_appended) { +void SourceBufferMetrics::EndTracking(SourceBufferMetricsAction action, + std::size_t size_appended) { if (!is_primary_video_) { return; } @@ -79,29 +98,77 @@ void SourceBufferMetrics::EndTracking(std::size_t size_appended) { DCHECK(is_tracking_); is_tracking_ = false; +<<<<<<< HEAD SbTimeMonotonic wall_duration = SbTimeGetMonotonicNow() - wall_start_time_; SbTimeMonotonic thread_duration = SbTimeIsTimeThreadNowSupported() ? SbTimeGetMonotonicThreadNow() - thread_start_time_ : 0; total_wall_time_ += wall_duration; +======= + DCHECK(action == current_action_); + current_action_ = SourceBufferMetricsAction::NO_ACTION; + + base::TimeDelta wall_duration = clock_->NowTicks() - wall_start_time_; + + RecordTelemetry(action, wall_duration); + +#if !defined(COBALT_BUILD_TYPE_GOLD) + int64_t thread_duration = + starboard::CurrentMonotonicThreadTime() - thread_start_time_; + + total_wall_time_ += wall_duration.InMicroseconds(); +>>>>>>> 0279b59dc75 (Add telemetry for `SourceBuffer.appendBuffer` (#2586)) total_thread_time_ += thread_duration; total_size_ += size_appended; if (size_appended > 0) { +<<<<<<< HEAD int wall_bandwidth = GetBandwidth(size_appended, wall_duration); int thread_bandwidth = SbTimeIsTimeThreadNowSupported() ? GetBandwidth(size_appended, thread_duration) : 0; +======= + int wall_bandwidth = + GetBandwidth(size_appended, wall_duration.InMicroseconds()); + int thread_bandwidth = GetBandwidth(size_appended, thread_duration); +>>>>>>> 0279b59dc75 (Add telemetry for `SourceBuffer.appendBuffer` (#2586)) max_wall_bandwidth_ = std::max(max_wall_bandwidth_, wall_bandwidth); min_wall_bandwidth_ = std::min(min_wall_bandwidth_, wall_bandwidth); max_thread_bandwidth_ = std::max(max_thread_bandwidth_, thread_bandwidth); min_thread_bandwidth_ = std::min(min_thread_bandwidth_, thread_bandwidth); } +#endif // !defined(COBALT_BUILD_TYPE_GOLD) } +void SourceBufferMetrics::RecordTelemetry( + SourceBufferMetricsAction action, const base::TimeDelta& action_duration) { + switch (action) { + case SourceBufferMetricsAction::PREPARE_APPEND: + UMA_HISTOGRAM_CUSTOM_MICROSECONDS_TIMES( + "Cobalt.Media.SourceBuffer.PrepareAppend.Timing", action_duration, + base::TimeDelta::FromMicroseconds(1), + base::TimeDelta::FromMilliseconds(25), 50); + break; + case SourceBufferMetricsAction::APPEND_BUFFER: + UMA_HISTOGRAM_CUSTOM_MICROSECONDS_TIMES( + "Cobalt.Media.SourceBuffer.AppendBuffer.Timing", action_duration, + base::TimeDelta::FromMicroseconds(1), + base::TimeDelta::FromMilliseconds(25), 50); + break; + default: + UMA_HISTOGRAM_CUSTOM_MICROSECONDS_TIMES( + "Cobalt.Media.SourceBuffer.Other.Timing", action_duration, + base::TimeDelta::FromMicroseconds(1), + base::TimeDelta::FromMilliseconds(25), 50); + break; + } +} + +#if !defined(COBALT_BUILD_TYPE_GOLD) + void SourceBufferMetrics::PrintCurrentMetricsAndUpdateAccumulatedMetrics() { if (!is_primary_video_) { return; diff --git a/cobalt/dom/source_buffer_metrics.h b/cobalt/dom/source_buffer_metrics.h index 766ebace20ed..6d5aa6f4ab4b 100644 --- a/cobalt/dom/source_buffer_metrics.h +++ b/cobalt/dom/source_buffer_metrics.h @@ -15,47 +15,65 @@ #ifndef COBALT_DOM_SOURCE_BUFFER_METRICS_H_ #define COBALT_DOM_SOURCE_BUFFER_METRICS_H_ +<<<<<<< HEAD #include "starboard/time.h" +======= +#include "base/time/default_tick_clock.h" +#include "base/time/tick_clock.h" +#include "base/time/time.h" +#include "starboard/types.h" +>>>>>>> 0279b59dc75 (Add telemetry for `SourceBuffer.appendBuffer` (#2586)) namespace cobalt { namespace dom { -#if defined(COBALT_BUILD_TYPE_GOLD) +enum class SourceBufferMetricsAction : uint8_t { + NO_ACTION, + PREPARE_APPEND, + APPEND_BUFFER, +}; class SourceBufferMetrics { public: - explicit SourceBufferMetrics(bool is_primary_video) {} + SourceBufferMetrics( + bool is_primary_video, + const base::TickClock* clock = base::DefaultTickClock::GetInstance()) + : is_primary_video_(is_primary_video), clock_(clock) {} ~SourceBufferMetrics() = default; - void StartTracking() {} - void EndTracking(size_t size_appended) {} + void StartTracking(SourceBufferMetricsAction action); + void EndTracking(SourceBufferMetricsAction action, size_t size_appended); + +#if defined(COBALT_BUILD_TYPE_GOLD) void PrintCurrentMetricsAndUpdateAccumulatedMetrics() {} void PrintAccumulatedMetrics() {} -}; - -#else // defined(COBALT_BUILD_TYPE_GOLD) - -class SourceBufferMetrics { - public: - explicit SourceBufferMetrics(bool is_primary_video) - : is_primary_video_(is_primary_video) {} - ~SourceBufferMetrics() = default; - - void StartTracking(); - void EndTracking(size_t size_appended); +#else // defined(COBALT_BUILD_TYPE_GOLD) void PrintCurrentMetricsAndUpdateAccumulatedMetrics(); void PrintAccumulatedMetrics(); +#endif // defined(COBALT_BUILD_TYPE_GOLD) private: SourceBufferMetrics(const SourceBufferMetrics&) = delete; SourceBufferMetrics& operator=(const SourceBufferMetrics&) = delete; +<<<<<<< HEAD SbTimeMonotonic wall_start_time_ = 0; SbTimeMonotonic thread_start_time_ = 0; +======= + void RecordTelemetry(SourceBufferMetricsAction action, + const base::TimeDelta& action_duration); + + base::TimeTicks wall_start_time_; +>>>>>>> 0279b59dc75 (Add telemetry for `SourceBuffer.appendBuffer` (#2586)) const bool is_primary_video_; bool is_tracking_ = false; + SourceBufferMetricsAction current_action_ = + SourceBufferMetricsAction::NO_ACTION; + const base::TickClock* clock_; +#if !defined(COBALT_BUILD_TYPE_GOLD) + int64_t thread_start_time_ = 0; size_t total_size_ = 0; SbTime total_thread_time_ = 0; SbTime total_wall_time_ = 0; @@ -63,10 +81,9 @@ class SourceBufferMetrics { int min_thread_bandwidth_ = INT_MAX; int max_wall_bandwidth_ = 0; int min_wall_bandwidth_ = INT_MAX; +#endif // !defined(COBALT_BUILD_TYPE_GOLD) }; -#endif // defined(COBALT_BUILD_TYPE_GOLD) - } // namespace dom } // namespace cobalt diff --git a/cobalt/dom/source_buffer_metrics_test.cc b/cobalt/dom/source_buffer_metrics_test.cc new file mode 100644 index 000000000000..3f036e604804 --- /dev/null +++ b/cobalt/dom/source_buffer_metrics_test.cc @@ -0,0 +1,66 @@ +// Copyright 2024 The Cobalt Authors. All Rights Reserved. +// +// 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. + +#include "cobalt/dom/source_buffer_metrics.h" + +#include +#include + +#include "base/test/metrics/histogram_tester.h" +#include "base/test/simple_test_tick_clock.h" +#include "base/time/time.h" +#include "testing/gtest/include/gtest/gtest.h" + +namespace cobalt { +namespace dom { +namespace { +constexpr char kUmaPrefix[] = "Cobalt.Media.SourceBuffer."; + +class SourceBufferMetricsTest : public ::testing::Test { + protected: + SourceBufferMetricsTest() + : metrics_(std::make_unique( + /*is_primary_video=*/true, &clock_)) {} + + void SetUp() override { clock_.SetNowTicks(base::TimeTicks()); } + + base::HistogramTester histogram_tester_; + base::SimpleTestTickClock clock_; + + std::unique_ptr metrics_; +}; + +TEST_F(SourceBufferMetricsTest, RecordsPrepareAppendTelemetry) { + metrics_->StartTracking(SourceBufferMetricsAction::PREPARE_APPEND); + + clock_.Advance(base::TimeDelta::FromMicroseconds(100)); + metrics_->EndTracking(SourceBufferMetricsAction::PREPARE_APPEND, 1234); + + histogram_tester_.ExpectUniqueSample( + std::string(kUmaPrefix) + "PrepareAppend.Timing", 100, 1); +} + +TEST_F(SourceBufferMetricsTest, RecordsAppendBufferTelemetry) { + metrics_->StartTracking(SourceBufferMetricsAction::APPEND_BUFFER); + + clock_.Advance(base::TimeDelta::FromMicroseconds(100)); + metrics_->EndTracking(SourceBufferMetricsAction::APPEND_BUFFER, 1234); + + histogram_tester_.ExpectUniqueSample( + std::string(kUmaPrefix) + "AppendBuffer.Timing", 100, 1); +} + +} // namespace +} // namespace dom +} // namespace cobalt diff --git a/tools/metrics/histograms/metadata/cobalt/histograms.xml b/tools/metrics/histograms/metadata/cobalt/histograms.xml index 7a5547a2c408..d6af96002295 100644 --- a/tools/metrics/histograms/metadata/cobalt/histograms.xml +++ b/tools/metrics/histograms/metadata/cobalt/histograms.xml @@ -151,6 +151,40 @@ Always run the pretty print utility on this file after editing: + + + + async@google.com + cobalt-team@google.com + + Timing data for the main action of the `SourceBuffer.appendBuffer` call. + + + + + + + async@google.com + cobalt-team@google.com + + Timing data for preparation of `SourceBuffer.appendBuffer` calls. + + + + + + + async@google.com + cobalt-team@google.com + + Catch-all for timing data for `SourceBuffer.appendBuffer` calls. This + histogram is not expected to receive data normally. + + + From 0f7c7518c5b22eaaef8b70c320b7e3ac20a8dda2 Mon Sep 17 00:00:00 2001 From: Drew Thomas Date: Tue, 19 Mar 2024 15:37:44 -0700 Subject: [PATCH 2/2] Resolve merge conflicts. Change-Id: I1c45f64787f28899f9a9da575f5b42490fec32e5 --- cobalt/dom/source_buffer_metrics.cc | 36 +++++++---------------------- cobalt/dom/source_buffer_metrics.h | 13 ++--------- 2 files changed, 10 insertions(+), 39 deletions(-) diff --git a/cobalt/dom/source_buffer_metrics.cc b/cobalt/dom/source_buffer_metrics.cc index a1168b27d153..237cedeef955 100644 --- a/cobalt/dom/source_buffer_metrics.cc +++ b/cobalt/dom/source_buffer_metrics.cc @@ -17,11 +17,8 @@ #include #include "base/logging.h" -<<<<<<< HEAD -======= #include "base/metrics/histogram_macros.h" #include "base/time/time.h" ->>>>>>> 0279b59dc75 (Add telemetry for `SourceBuffer.appendBuffer` (#2586)) #include "cobalt/base/statistics.h" #include "starboard/common/string.h" #include "starboard/once.h" @@ -75,18 +72,13 @@ void SourceBufferMetrics::StartTracking(SourceBufferMetricsAction action) { DCHECK(action != SourceBufferMetricsAction::NO_ACTION); is_tracking_ = true; -<<<<<<< HEAD - wall_start_time_ = SbTimeGetMonotonicNow(); - thread_start_time_ = - SbTimeIsTimeThreadNowSupported() ? SbTimeGetMonotonicThreadNow() : -1; -======= current_action_ = action; wall_start_time_ = clock_->NowTicks(); #if !defined(COBALT_BUILD_TYPE_GOLD) - thread_start_time_ = starboard::CurrentMonotonicThreadTime(); + thread_start_time_ = + SbTimeIsTimeThreadNowSupported() ? SbTimeGetMonotonicThreadNow() : -1; #endif // !defined(COBALT_BUILD_TYPE_GOLD) ->>>>>>> 0279b59dc75 (Add telemetry for `SourceBuffer.appendBuffer` (#2586)) } void SourceBufferMetrics::EndTracking(SourceBufferMetricsAction action, @@ -98,14 +90,6 @@ void SourceBufferMetrics::EndTracking(SourceBufferMetricsAction action, DCHECK(is_tracking_); is_tracking_ = false; -<<<<<<< HEAD - SbTimeMonotonic wall_duration = SbTimeGetMonotonicNow() - wall_start_time_; - SbTimeMonotonic thread_duration = - SbTimeIsTimeThreadNowSupported() - ? SbTimeGetMonotonicThreadNow() - thread_start_time_ - : 0; - total_wall_time_ += wall_duration; -======= DCHECK(action == current_action_); current_action_ = SourceBufferMetricsAction::NO_ACTION; @@ -114,26 +98,22 @@ void SourceBufferMetrics::EndTracking(SourceBufferMetricsAction action, RecordTelemetry(action, wall_duration); #if !defined(COBALT_BUILD_TYPE_GOLD) - int64_t thread_duration = - starboard::CurrentMonotonicThreadTime() - thread_start_time_; + SbTimeMonotonic thread_duration = + SbTimeIsTimeThreadNowSupported() + ? SbTimeGetMonotonicThreadNow() - thread_start_time_ + : 0; total_wall_time_ += wall_duration.InMicroseconds(); ->>>>>>> 0279b59dc75 (Add telemetry for `SourceBuffer.appendBuffer` (#2586)) total_thread_time_ += thread_duration; total_size_ += size_appended; if (size_appended > 0) { -<<<<<<< HEAD - int wall_bandwidth = GetBandwidth(size_appended, wall_duration); + int wall_bandwidth = + GetBandwidth(size_appended, wall_duration.InMicroseconds()); int thread_bandwidth = SbTimeIsTimeThreadNowSupported() ? GetBandwidth(size_appended, thread_duration) : 0; -======= - int wall_bandwidth = - GetBandwidth(size_appended, wall_duration.InMicroseconds()); - int thread_bandwidth = GetBandwidth(size_appended, thread_duration); ->>>>>>> 0279b59dc75 (Add telemetry for `SourceBuffer.appendBuffer` (#2586)) max_wall_bandwidth_ = std::max(max_wall_bandwidth_, wall_bandwidth); min_wall_bandwidth_ = std::min(min_wall_bandwidth_, wall_bandwidth); diff --git a/cobalt/dom/source_buffer_metrics.h b/cobalt/dom/source_buffer_metrics.h index 6d5aa6f4ab4b..89e5c103394d 100644 --- a/cobalt/dom/source_buffer_metrics.h +++ b/cobalt/dom/source_buffer_metrics.h @@ -15,14 +15,10 @@ #ifndef COBALT_DOM_SOURCE_BUFFER_METRICS_H_ #define COBALT_DOM_SOURCE_BUFFER_METRICS_H_ -<<<<<<< HEAD -#include "starboard/time.h" -======= #include "base/time/default_tick_clock.h" #include "base/time/tick_clock.h" #include "base/time/time.h" -#include "starboard/types.h" ->>>>>>> 0279b59dc75 (Add telemetry for `SourceBuffer.appendBuffer` (#2586)) +#include "starboard/time.h" namespace cobalt { namespace dom { @@ -56,15 +52,10 @@ class SourceBufferMetrics { SourceBufferMetrics(const SourceBufferMetrics&) = delete; SourceBufferMetrics& operator=(const SourceBufferMetrics&) = delete; -<<<<<<< HEAD - SbTimeMonotonic wall_start_time_ = 0; - SbTimeMonotonic thread_start_time_ = 0; -======= void RecordTelemetry(SourceBufferMetricsAction action, const base::TimeDelta& action_duration); base::TimeTicks wall_start_time_; ->>>>>>> 0279b59dc75 (Add telemetry for `SourceBuffer.appendBuffer` (#2586)) const bool is_primary_video_; bool is_tracking_ = false; @@ -73,7 +64,7 @@ class SourceBufferMetrics { const base::TickClock* clock_; #if !defined(COBALT_BUILD_TYPE_GOLD) - int64_t thread_start_time_ = 0; + SbTimeMonotonic thread_start_time_ = 0; size_t total_size_ = 0; SbTime total_thread_time_ = 0; SbTime total_wall_time_ = 0;