From d34a7ab50d4d9891b2773cf78d88d7e8c4b58fbe Mon Sep 17 00:00:00 2001 From: Artem Titov Date: Sun, 6 Nov 2022 17:57:44 +0100 Subject: [PATCH] [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 Reviewed-by: Mirko Bonadei Cr-Commit-Position: refs/heads/main@{#38559} --- test/pc/e2e/BUILD.gn | 10 -- .../video/default_video_quality_analyzer.cc | 102 ++++++++++++++++-- .../video/default_video_quality_analyzer.h | 4 - ...lt_video_quality_analyzer_shared_objects.h | 14 +++ .../default_video_quality_analyzer_test.cc | 64 +++++++++++ 5 files changed, 174 insertions(+), 20 deletions(-) diff --git a/test/pc/e2e/BUILD.gn b/test/pc/e2e/BUILD.gn index 5e3ac05b50..8bad901980 100644 --- a/test/pc/e2e/BUILD.gn +++ b/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" ] diff --git a/test/pc/e2e/analyzer/video/default_video_quality_analyzer.cc b/test/pc/e2e/analyzer/video/default_video_quality_analyzer.cc index 67376ccf9a..54f1ac75b2 100644 --- a/test/pc/e2e/analyzer/video/default_video_quality_analyzer.cc +++ b/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()); + } } 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()); + } } 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()); + } } 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()); + } } 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()); + } } 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()); + } } 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()); + } } 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( diff --git a/test/pc/e2e/analyzer/video/default_video_quality_analyzer.h b/test/pc/e2e/analyzer/video/default_video_quality_analyzer.h index bc3edf7dd2..b67e5a0147 100644 --- a/test/pc/e2e/analyzer/video/default_video_quality_analyzer.h +++ b/test/pc/e2e/analyzer/video/default_video_quality_analyzer.h @@ -21,16 +21,12 @@ #include #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" diff --git a/test/pc/e2e/analyzer/video/default_video_quality_analyzer_shared_objects.h b/test/pc/e2e/analyzer/video/default_video_quality_analyzer_shared_objects.h index a647290e63..f419089a01 100644 --- a/test/pc/e2e/analyzer/video/default_video_quality_analyzer_shared_objects.h +++ b/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 #include #include #include @@ -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 diff --git a/test/pc/e2e/analyzer/video/default_video_quality_analyzer_test.cc b/test/pc/e2e/analyzer/video/default_video_quality_analyzer_test.cc index bc1e3999a1..7d39238f8a 100644 --- a/test/pc/e2e/analyzer/video/default_video_quality_analyzer_test.cc +++ b/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 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{"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 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{"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 {};