[DVQA] Add infra metrics to measure time of each frame's processing step

Bug: b/240540204
Change-Id: Ib3395d2d8d61b3cfef60d0463d7b53f96a9f8c83
Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/282000
Commit-Queue: Artem Titov <titovartem@webrtc.org>
Reviewed-by: Mirko Bonadei <mbonadei@webrtc.org>
Cr-Commit-Position: refs/heads/main@{#38559}

test/pc/e2e/BUILD.gn

@@ -889,7 +889,6 @@ if (!build_with_chromium) {
       ":default_video_quality_analyzer_internal",
       ":default_video_quality_analyzer_shared",
       ":metric_metadata_keys",
-      "../..:perf_test",
       "../../../api:array_view",
       "../../../api:video_quality_analyzer_api",
       "../../../api/numerics",
@@ -900,20 +899,11 @@ if (!build_with_chromium) {
       "../../../api/units:timestamp",
       "../../../api/video:encoded_image",
       "../../../api/video:video_frame",
-      "../../../api/video:video_frame_type",
-      "../../../api/video:video_rtp_headers",
-      "../../../common_video",
       "../../../rtc_base:checks",
-      "../../../rtc_base:criticalsection",
       "../../../rtc_base:logging",
       "../../../rtc_base:macromagic",
-      "../../../rtc_base:platform_thread",
-      "../../../rtc_base:rtc_event",
-      "../../../rtc_base:rtc_numerics",
       "../../../rtc_base:stringutils",
-      "../../../rtc_base:timeutils",
       "../../../rtc_base/synchronization:mutex",
-      "../../../rtc_tools:video_quality_analysis",
       "../../../system_wrappers",
     ]
     absl_deps = [ "//third_party/abseil-cpp/absl/types:optional" ]

test/pc/e2e/analyzer/video/default_video_quality_analyzer.cc

@@ -22,15 +22,11 @@
 #include "api/numerics/samples_stats_counter.h"
 #include "api/test/metrics/metric.h"
 #include "api/units/time_delta.h"
-#include "api/video/i420_buffer.h"
+#include "api/units/timestamp.h"
 #include "api/video/video_frame.h"
-#include "common_video/libyuv/include/webrtc_libyuv.h"
 #include "rtc_base/checks.h"
 #include "rtc_base/logging.h"
-#include "rtc_base/platform_thread.h"
 #include "rtc_base/strings/string_builder.h"
-#include "rtc_base/time_utils.h"
-#include "rtc_tools/frame_analyzer/video_geometry_aligner.h"
 #include "test/pc/e2e/analyzer/video/default_video_quality_analyzer_frame_in_flight.h"
 #include "test/pc/e2e/analyzer/video/default_video_quality_analyzer_frames_comparator.h"
 #include "test/pc/e2e/analyzer/video/default_video_quality_analyzer_internal_shared_objects.h"
@@ -269,6 +265,10 @@ uint16_t DefaultVideoQualityAnalyzer::OnFrameCaptured(
       RTC_DCHECK(is_removed)
           << "Invalid stream state: alive frame is removed already";
     }
+    if (options_.report_infra_metrics) {
+      analyzer_stats_.on_frame_captured_processing_time_ms.AddSample(
+          (Now() - captured_time).ms<double>());
+    }
   }
   return frame_id;
 }
@@ -276,6 +276,7 @@ uint16_t DefaultVideoQualityAnalyzer::OnFrameCaptured(
 void DefaultVideoQualityAnalyzer::OnFramePreEncode(
     absl::string_view peer_name,
     const webrtc::VideoFrame& frame) {
+  Timestamp processing_started = Now();
   MutexLock lock(&mutex_);
   RTC_CHECK_EQ(state_, State::kActive)
       << "DefaultVideoQualityAnalyzer has to be started before use";
@@ -293,6 +294,11 @@ void DefaultVideoQualityAnalyzer::OnFramePreEncode(
     }
   }
   frame_in_flight.SetPreEncodeTime(Now());
+
+  if (options_.report_infra_metrics) {
+    analyzer_stats_.on_frame_pre_encode_processing_time_ms.AddSample(
+        (Now() - processing_started).ms<double>());
+  }
 }
 
 void DefaultVideoQualityAnalyzer::OnFrameEncoded(
@@ -303,6 +309,8 @@ void DefaultVideoQualityAnalyzer::OnFrameEncoded(
     bool discarded) {
   if (discarded)
     return;
+
+  Timestamp processing_started = Now();
   MutexLock lock(&mutex_);
   RTC_CHECK_EQ(state_, State::kActive)
       << "DefaultVideoQualityAnalyzer has to be started before use";
@@ -342,6 +350,11 @@ void DefaultVideoQualityAnalyzer::OnFrameEncoded(
   frame_in_flight.OnFrameEncoded(now, encoded_image._frameType,
                                  DataSize::Bytes(encoded_image.size()),
                                  stats.target_encode_bitrate, used_encoder);
+
+  if (options_.report_infra_metrics) {
+    analyzer_stats_.on_frame_encoded_processing_time_ms.AddSample(
+        (Now() - processing_started).ms<double>());
+  }
 }
 
 void DefaultVideoQualityAnalyzer::OnFrameDropped(
@@ -354,6 +367,7 @@ void DefaultVideoQualityAnalyzer::OnFramePreDecode(
     absl::string_view peer_name,
     uint16_t frame_id,
     const webrtc::EncodedImage& input_image) {
+  Timestamp processing_started = Now();
   MutexLock lock(&mutex_);
   RTC_CHECK_EQ(state_, State::kActive)
       << "DefaultVideoQualityAnalyzer has to be started before use";
@@ -395,12 +409,18 @@ void DefaultVideoQualityAnalyzer::OnFramePreDecode(
                               /*decode_start_time=*/Now(),
                               input_image._frameType,
                               DataSize::Bytes(input_image.size()));
+
+  if (options_.report_infra_metrics) {
+    analyzer_stats_.on_frame_pre_decode_processing_time_ms.AddSample(
+        (Now() - processing_started).ms<double>());
+  }
 }
 
 void DefaultVideoQualityAnalyzer::OnFrameDecoded(
     absl::string_view peer_name,
     const webrtc::VideoFrame& frame,
     const DecoderStats& stats) {
+  Timestamp processing_started = Now();
   MutexLock lock(&mutex_);
   RTC_CHECK_EQ(state_, State::kActive)
       << "DefaultVideoQualityAnalyzer has to be started before use";
@@ -436,11 +456,17 @@ void DefaultVideoQualityAnalyzer::OnFrameDecoded(
   used_decoder.switched_from_at = now;
   it->second.OnFrameDecoded(peer_index, now, frame.width(), frame.height(),
                             used_decoder);
+
+  if (options_.report_infra_metrics) {
+    analyzer_stats_.on_frame_decoded_processing_time_ms.AddSample(
+        (Now() - processing_started).ms<double>());
+  }
 }
 
 void DefaultVideoQualityAnalyzer::OnFrameRendered(
     absl::string_view peer_name,
     const webrtc::VideoFrame& frame) {
+  Timestamp processing_started = Now();
   MutexLock lock(&mutex_);
   RTC_CHECK_EQ(state_, State::kActive)
       << "DefaultVideoQualityAnalyzer has to be started before use";
@@ -543,6 +569,11 @@ void DefaultVideoQualityAnalyzer::OnFrameRendered(
   if (frame_it->second.HaveAllPeersReceived()) {
     captured_frames_in_flight_.erase(frame_it);
   }
+
+  if (options_.report_infra_metrics) {
+    analyzer_stats_.on_frame_rendered_processing_time_ms.AddSample(
+        (Now() - processing_started).ms<double>());
+  }
 }
 
 void DefaultVideoQualityAnalyzer::OnEncoderError(
@@ -560,6 +591,7 @@ void DefaultVideoQualityAnalyzer::OnDecoderError(absl::string_view peer_name,
   RTC_LOG(LS_ERROR) << "Decoder error for frame_id=" << frame_id
                     << ", code=" << error_code;
 
+  Timestamp processing_started = Now();
   MutexLock lock(&mutex_);
   RTC_CHECK_EQ(state_, State::kActive)
       << "DefaultVideoQualityAnalyzer has to be started before use";
@@ -594,6 +626,11 @@ void DefaultVideoQualityAnalyzer::OnDecoderError(absl::string_view peer_name,
   used_decoder.switched_on_at = now;
   used_decoder.switched_from_at = now;
   it->second.OnDecoderError(peer_index, used_decoder);
+
+  if (options_.report_infra_metrics) {
+    analyzer_stats_.on_decoder_error_processing_time_ms.AddSample(
+        (Now() - processing_started).ms<double>());
+  }
 }
 
 void DefaultVideoQualityAnalyzer::RegisterParticipantInCall(
@@ -757,7 +794,7 @@ void DefaultVideoQualityAnalyzer::Stop() {
     FramesComparatorStats frames_comparator_stats =
         frames_comparator_.frames_comparator_stats();
     analyzer_stats_.comparisons_queue_size =
-        frames_comparator_stats.comparisons_queue_size;
+        std::move(frames_comparator_stats.comparisons_queue_size);
     analyzer_stats_.comparisons_done = frames_comparator_stats.comparisons_done;
     analyzer_stats_.cpu_overloaded_comparisons_done =
         frames_comparator_stats.cpu_overloaded_comparisons_done;
@@ -932,6 +969,59 @@ void DefaultVideoQualityAnalyzer::ReportResults() {
                    << analyzer_stats_.cpu_overloaded_comparisons_done;
   RTC_LOG(LS_INFO) << "memory_overloaded_comparisons_done="
                    << analyzer_stats_.memory_overloaded_comparisons_done;
+  if (options_.report_infra_metrics) {
+    metrics_logger_->LogMetric("comparisons_queue_size", test_label_,
+                               analyzer_stats_.comparisons_queue_size,
+                               Unit::kCount,
+                               ImprovementDirection::kSmallerIsBetter);
+    metrics_logger_->LogMetric("frames_in_flight_left_count", test_label_,
+                               analyzer_stats_.frames_in_flight_left_count,
+                               Unit::kCount,
+                               ImprovementDirection::kSmallerIsBetter);
+    metrics_logger_->LogSingleValueMetric(
+        "comparisons_done", test_label_, analyzer_stats_.comparisons_done,
+        Unit::kCount, ImprovementDirection::kNeitherIsBetter);
+    metrics_logger_->LogSingleValueMetric(
+        "cpu_overloaded_comparisons_done", test_label_,
+        analyzer_stats_.cpu_overloaded_comparisons_done, Unit::kCount,
+        ImprovementDirection::kNeitherIsBetter);
+    metrics_logger_->LogSingleValueMetric(
+        "memory_overloaded_comparisons_done", test_label_,
+        analyzer_stats_.memory_overloaded_comparisons_done, Unit::kCount,
+        ImprovementDirection::kNeitherIsBetter);
+    metrics_logger_->LogSingleValueMetric(
+        "test_duration", test_label_, (Now() - start_time_).ms(),
+        Unit::kMilliseconds, ImprovementDirection::kNeitherIsBetter);
+
+    metrics_logger_->LogMetric(
+        "on_frame_captured_processing_time_ms", test_label_,
+        analyzer_stats_.on_frame_captured_processing_time_ms,
+        Unit::kMilliseconds, ImprovementDirection::kSmallerIsBetter);
+    metrics_logger_->LogMetric(
+        "on_frame_pre_encode_processing_time_ms", test_label_,
+        analyzer_stats_.on_frame_pre_encode_processing_time_ms,
+        Unit::kMilliseconds, ImprovementDirection::kSmallerIsBetter);
+    metrics_logger_->LogMetric(
+        "on_frame_encoded_processing_time_ms", test_label_,
+        analyzer_stats_.on_frame_encoded_processing_time_ms,
+        Unit::kMilliseconds, ImprovementDirection::kSmallerIsBetter);
+    metrics_logger_->LogMetric(
+        "on_frame_pre_decode_processing_time_ms", test_label_,
+        analyzer_stats_.on_frame_pre_decode_processing_time_ms,
+        Unit::kMilliseconds, ImprovementDirection::kSmallerIsBetter);
+    metrics_logger_->LogMetric(
+        "on_frame_decoded_processing_time_ms", test_label_,
+        analyzer_stats_.on_frame_decoded_processing_time_ms,
+        Unit::kMilliseconds, ImprovementDirection::kSmallerIsBetter);
+    metrics_logger_->LogMetric(
+        "on_frame_rendered_processing_time_ms", test_label_,
+        analyzer_stats_.on_frame_rendered_processing_time_ms,
+        Unit::kMilliseconds, ImprovementDirection::kSmallerIsBetter);
+    metrics_logger_->LogMetric(
+        "on_decoder_error_processing_time_ms", test_label_,
+        analyzer_stats_.on_decoder_error_processing_time_ms,
+        Unit::kMilliseconds, ImprovementDirection::kSmallerIsBetter);
+  }
 }
 
 void DefaultVideoQualityAnalyzer::ReportResults(

test/pc/e2e/analyzer/video/default_video_quality_analyzer.h

@@ -21,16 +21,12 @@
 #include <vector>
 
 #include "api/array_view.h"
-#include "api/numerics/samples_stats_counter.h"
 #include "api/test/metrics/metrics_logger.h"
 #include "api/test/video_quality_analyzer_interface.h"
 #include "api/units/data_size.h"
 #include "api/units/timestamp.h"
 #include "api/video/encoded_image.h"
 #include "api/video/video_frame.h"
-#include "api/video/video_frame_type.h"
-#include "rtc_base/event.h"
-#include "rtc_base/platform_thread.h"
 #include "rtc_base/synchronization/mutex.h"
 #include "rtc_base/thread_annotations.h"
 #include "system_wrappers/include/clock.h"

test/pc/e2e/analyzer/video/default_video_quality_analyzer_shared_objects.h

@@ -11,6 +11,7 @@
 #ifndef TEST_PC_E2E_ANALYZER_VIDEO_DEFAULT_VIDEO_QUALITY_ANALYZER_SHARED_OBJECTS_H_
 #define TEST_PC_E2E_ANALYZER_VIDEO_DEFAULT_VIDEO_QUALITY_ANALYZER_SHARED_OBJECTS_H_
 
+#include <cstdint>
 #include <map>
 #include <memory>
 #include <ostream>
@@ -182,6 +183,16 @@ struct AnalyzerStats {
   // Count of frames in flight in analyzer measured when new comparison is added
   // and after analyzer was stopped.
   SamplesStatsCounter frames_in_flight_left_count;
+
+  // Next metrics are collected and reported iff
+  // `DefaultVideoQualityAnalyzerOptions::report_infra_metrics` is true.
+  SamplesStatsCounter on_frame_captured_processing_time_ms;
+  SamplesStatsCounter on_frame_pre_encode_processing_time_ms;
+  SamplesStatsCounter on_frame_encoded_processing_time_ms;
+  SamplesStatsCounter on_frame_pre_decode_processing_time_ms;
+  SamplesStatsCounter on_frame_decoded_processing_time_ms;
+  SamplesStatsCounter on_frame_rendered_processing_time_ms;
+  SamplesStatsCounter on_decoder_error_processing_time_ms;
 };
 
 struct StatsKey {
@@ -245,6 +256,9 @@ struct DefaultVideoQualityAnalyzerOptions {
   // Tells DefaultVideoQualityAnalyzer if detailed frame stats should be
   // reported.
   bool report_detailed_frame_stats = false;
+  // Tells DefaultVideoQualityAnalyzer if infra metrics related to the
+  // performance and stability of the analyzer itself should be reported.
+  bool report_infra_metrics = false;
   // If true DefaultVideoQualityAnalyzer will try to adjust frames before
   // computing PSNR and SSIM for them. In some cases picture may be shifted by
   // a few pixels after the encode/decode step. Those difference is invisible

test/pc/e2e/analyzer/video/default_video_quality_analyzer_test.cc

@@ -2059,6 +2059,70 @@ TEST(DefaultVideoQualityAnalyzerTest,
   EXPECT_GE(stats.encode_time_ms.GetAverage(), 10);
 }
 
+TEST(DefaultVideoQualityAnalyzerTest, InfraMetricsAreReportedWhenRequested) {
+  std::unique_ptr<test::FrameGeneratorInterface> frame_generator =
+      test::CreateSquareFrameGenerator(kFrameWidth, kFrameHeight,
+                                       /*type=*/absl::nullopt,
+                                       /*num_squares=*/absl::nullopt);
+
+  DefaultVideoQualityAnalyzerOptions options = AnalyzerOptionsForTest();
+  options.report_infra_metrics = true;
+  DefaultVideoQualityAnalyzer analyzer(Clock::GetRealTimeClock(),
+                                       test::GetGlobalMetricsLogger(), options);
+  analyzer.Start("test_case", std::vector<std::string>{"alice", "bob"},
+                 kAnalyzerMaxThreadsCount);
+
+  PassFramesThroughAnalyzer(analyzer, "alice", "alice_video", {"bob"},
+                            /*frames_count=*/1, *frame_generator);
+
+  // Give analyzer some time to process frames on async thread. The computations
+  // have to be fast (heavy metrics are disabled!), so if doesn't fit 100ms it
+  // means we have an issue!
+  SleepMs(100);
+  analyzer.Stop();
+
+  AnalyzerStats stats = analyzer.GetAnalyzerStats();
+  EXPECT_EQ(stats.on_frame_captured_processing_time_ms.NumSamples(), 1);
+  EXPECT_EQ(stats.on_frame_pre_encode_processing_time_ms.NumSamples(), 1);
+  EXPECT_EQ(stats.on_frame_encoded_processing_time_ms.NumSamples(), 1);
+  EXPECT_EQ(stats.on_frame_pre_decode_processing_time_ms.NumSamples(), 1);
+  EXPECT_EQ(stats.on_frame_decoded_processing_time_ms.NumSamples(), 1);
+  EXPECT_EQ(stats.on_frame_rendered_processing_time_ms.NumSamples(), 1);
+  EXPECT_EQ(stats.on_decoder_error_processing_time_ms.NumSamples(), 0);
+}
+
+TEST(DefaultVideoQualityAnalyzerTest, InfraMetricsNotCollectedByDefault) {
+  std::unique_ptr<test::FrameGeneratorInterface> frame_generator =
+      test::CreateSquareFrameGenerator(kFrameWidth, kFrameHeight,
+                                       /*type=*/absl::nullopt,
+                                       /*num_squares=*/absl::nullopt);
+
+  DefaultVideoQualityAnalyzerOptions options = AnalyzerOptionsForTest();
+  options.report_infra_metrics = false;
+  DefaultVideoQualityAnalyzer analyzer(Clock::GetRealTimeClock(),
+                                       test::GetGlobalMetricsLogger(), options);
+  analyzer.Start("test_case", std::vector<std::string>{"alice", "bob"},
+                 kAnalyzerMaxThreadsCount);
+
+  PassFramesThroughAnalyzer(analyzer, "alice", "alice_video", {"bob"},
+                            /*frames_count=*/1, *frame_generator);
+
+  // Give analyzer some time to process frames on async thread. The computations
+  // have to be fast (heavy metrics are disabled!), so if doesn't fit 100ms it
+  // means we have an issue!
+  SleepMs(100);
+  analyzer.Stop();
+
+  AnalyzerStats stats = analyzer.GetAnalyzerStats();
+  EXPECT_EQ(stats.on_frame_captured_processing_time_ms.NumSamples(), 0);
+  EXPECT_EQ(stats.on_frame_pre_encode_processing_time_ms.NumSamples(), 0);
+  EXPECT_EQ(stats.on_frame_encoded_processing_time_ms.NumSamples(), 0);
+  EXPECT_EQ(stats.on_frame_pre_decode_processing_time_ms.NumSamples(), 0);
+  EXPECT_EQ(stats.on_frame_decoded_processing_time_ms.NumSamples(), 0);
+  EXPECT_EQ(stats.on_frame_rendered_processing_time_ms.NumSamples(), 0);
+  EXPECT_EQ(stats.on_decoder_error_processing_time_ms.NumSamples(), 0);
+}
+
 class DefaultVideoQualityAnalyzerTimeBetweenFreezesTest
     : public TestWithParam<bool> {};