From f0eef12e68b2373768632a34d7a6f2e009223532 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Henrik=20Bostr=C3=B6m?= Date: Thu, 28 May 2020 16:22:42 +0200 Subject: [PATCH] [Adaptation] Add more ResourceAdaptationProcessor logging. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This should help debugging when adaptation is or is not happening unexpectedly. Log spam is prevented by not logging if the same result happened to the same resource already and we haven't adapted since then. Bug: webrtc:11616 Change-Id: Ia6c5cc35061d252f1c66f2f2bf3b94d2485498d6 Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/176221 Commit-Queue: Henrik Boström Reviewed-by: Evan Shrubsole Reviewed-by: Harald Alvestrand Cr-Commit-Position: refs/heads/master@{#31378} --- api/rtp_parameters.cc | 14 ++ api/rtp_parameters.h | 3 + api/video/BUILD.gn | 5 +- api/video/video_adaptation_counters.cc | 9 ++ api/video/video_adaptation_counters.h | 4 + call/adaptation/resource.cc | 9 ++ call/adaptation/resource.h | 2 + .../resource_adaptation_processor.cc | 125 ++++++++++++++---- .../resource_adaptation_processor.h | 27 +++- call/adaptation/video_stream_adapter.cc | 14 ++ call/adaptation/video_stream_adapter.h | 2 + 11 files changed, 184 insertions(+), 30 deletions(-) diff --git a/api/rtp_parameters.cc b/api/rtp_parameters.cc index a05b2bfa7b..c44e4c4b4a 100644 --- a/api/rtp_parameters.cc +++ b/api/rtp_parameters.cc @@ -18,6 +18,20 @@ namespace webrtc { +const char* DegradationPreferenceToString( + DegradationPreference degradation_preference) { + switch (degradation_preference) { + case DegradationPreference::DISABLED: + return "disabled"; + case DegradationPreference::MAINTAIN_FRAMERATE: + return "maintain-framerate"; + case DegradationPreference::MAINTAIN_RESOLUTION: + return "maintain-resolution"; + case DegradationPreference::BALANCED: + return "balanced"; + } +} + const double kDefaultBitratePriority = 1.0; RtcpFeedback::RtcpFeedback() = default; diff --git a/api/rtp_parameters.h b/api/rtp_parameters.h index d7156db05b..f831e51f68 100644 --- a/api/rtp_parameters.h +++ b/api/rtp_parameters.h @@ -92,6 +92,9 @@ enum class DegradationPreference { BALANCED, }; +RTC_EXPORT const char* DegradationPreferenceToString( + DegradationPreference degradation_preference); + RTC_EXPORT extern const double kDefaultBitratePriority; struct RTC_EXPORT RtcpFeedback { diff --git a/api/video/BUILD.gn b/api/video/BUILD.gn index 7f9b034192..3bce91e26d 100644 --- a/api/video/BUILD.gn +++ b/api/video/BUILD.gn @@ -237,7 +237,10 @@ rtc_library("video_adaptation") { "video_adaptation_reason.h", ] - deps = [ "../../rtc_base:checks" ] + deps = [ + "../../rtc_base:checks", + "../../rtc_base:stringutils", + ] } rtc_source_set("video_stream_encoder") { diff --git a/api/video/video_adaptation_counters.cc b/api/video/video_adaptation_counters.cc index 25e0bee1ff..df1769d5d4 100644 --- a/api/video/video_adaptation_counters.cc +++ b/api/video/video_adaptation_counters.cc @@ -10,6 +10,8 @@ #include "api/video/video_adaptation_counters.h" +#include "rtc_base/strings/string_builder.h" + namespace webrtc { bool VideoAdaptationCounters::operator==( @@ -30,4 +32,11 @@ VideoAdaptationCounters VideoAdaptationCounters::operator+( fps_adaptations + other.fps_adaptations); } +std::string VideoAdaptationCounters::ToString() const { + rtc::StringBuilder ss; + ss << "{ res=" << resolution_adaptations << " fps=" << fps_adaptations + << " }"; + return ss.Release(); +} + } // namespace webrtc diff --git a/api/video/video_adaptation_counters.h b/api/video/video_adaptation_counters.h index eff0baaa21..2dea902f2f 100644 --- a/api/video/video_adaptation_counters.h +++ b/api/video/video_adaptation_counters.h @@ -11,6 +11,8 @@ #ifndef API_VIDEO_VIDEO_ADAPTATION_COUNTERS_H_ #define API_VIDEO_VIDEO_ADAPTATION_COUNTERS_H_ +#include + #include "rtc_base/checks.h" namespace webrtc { @@ -33,6 +35,8 @@ struct VideoAdaptationCounters { VideoAdaptationCounters operator+(const VideoAdaptationCounters& other) const; + std::string ToString() const; + int resolution_adaptations; int fps_adaptations; }; diff --git a/call/adaptation/resource.cc b/call/adaptation/resource.cc index a546450bc6..7d83c4db75 100644 --- a/call/adaptation/resource.cc +++ b/call/adaptation/resource.cc @@ -15,6 +15,15 @@ namespace webrtc { +const char* ResourceUsageStateToString(ResourceUsageState usage_state) { + switch (usage_state) { + case ResourceUsageState::kOveruse: + return "kOveruse"; + case ResourceUsageState::kUnderuse: + return "kUnderuse"; + } +} + ResourceListener::~ResourceListener() {} Resource::Resource() diff --git a/call/adaptation/resource.h b/call/adaptation/resource.h index 2ee0c720d2..d7ecf9482f 100644 --- a/call/adaptation/resource.h +++ b/call/adaptation/resource.h @@ -32,6 +32,8 @@ enum class ResourceUsageState { kUnderuse, }; +const char* ResourceUsageStateToString(ResourceUsageState usage_state); + class ResourceListener { public: virtual ~ResourceListener(); diff --git a/call/adaptation/resource_adaptation_processor.cc b/call/adaptation/resource_adaptation_processor.cc index 0224ac3bb2..57ace71a3f 100644 --- a/call/adaptation/resource_adaptation_processor.cc +++ b/call/adaptation/resource_adaptation_processor.cc @@ -11,12 +11,23 @@ #include "call/adaptation/resource_adaptation_processor.h" #include +#include #include #include "absl/algorithm/container.h" +#include "rtc_base/logging.h" +#include "rtc_base/strings/string_builder.h" namespace webrtc { +ResourceAdaptationProcessor::MitigationResultAndLogMessage:: + MitigationResultAndLogMessage() + : result(MitigationResult::kAdaptationApplied), message() {} + +ResourceAdaptationProcessor::MitigationResultAndLogMessage:: + MitigationResultAndLogMessage(MitigationResult result, std::string message) + : result(result), message(std::move(message)) {} + ResourceAdaptationProcessor::ResourceAdaptationProcessor( VideoStreamInputStateProvider* input_state_provider, VideoStreamEncoderObserver* encoder_stats_observer) @@ -30,6 +41,7 @@ ResourceAdaptationProcessor::ResourceAdaptationProcessor( is_screenshare_(false), stream_adapter_(std::make_unique()), last_reported_source_restrictions_(), + previous_mitigation_results_(), processing_in_progress_(false) { sequence_checker_.Detach(); } @@ -150,6 +162,7 @@ void ResourceAdaptationProcessor::MaybeUpdateEffectiveDegradationPreference() { void ResourceAdaptationProcessor::ResetVideoSourceRestrictions() { RTC_DCHECK_RUN_ON(&sequence_checker_); + RTC_LOG(INFO) << "Resetting restrictions"; stream_adapter_->ClearRestrictions(); adaptations_counts_by_resource_.clear(); MaybeUpdateVideoSourceRestrictions(nullptr); @@ -163,6 +176,10 @@ void ResourceAdaptationProcessor::MaybeUpdateVideoSourceRestrictions( stream_adapter_->source_restrictions(), effective_degradation_preference_); if (last_reported_source_restrictions_ != new_source_restrictions) { + RTC_LOG(INFO) << "Reporting new restrictions (in " + << DegradationPreferenceToString( + effective_degradation_preference_) + << "): " << new_source_restrictions.ToString(); last_reported_source_restrictions_ = std::move(new_source_restrictions); for (auto* adaptation_listener : adaptation_listeners_) { adaptation_listener->OnVideoSourceRestrictionsUpdated( @@ -179,14 +196,33 @@ void ResourceAdaptationProcessor::OnResourceUsageStateMeasured( rtc::scoped_refptr resource) { RTC_DCHECK_RUN_ON(&sequence_checker_); RTC_DCHECK(resource->usage_state().has_value()); - switch (resource->usage_state().value()) { + ResourceUsageState usage_state = resource->usage_state().value(); + MitigationResultAndLogMessage result_and_message; + switch (usage_state) { case ResourceUsageState::kOveruse: - OnResourceOveruse(resource); + result_and_message = OnResourceOveruse(resource); break; case ResourceUsageState::kUnderuse: - OnResourceUnderuse(resource); + result_and_message = OnResourceUnderuse(resource); break; } + // Maybe log the result of the operation. + auto it = previous_mitigation_results_.find(resource.get()); + if (it != previous_mitigation_results_.end() && + it->second == result_and_message.result) { + // This resource has previously reported the same result and we haven't + // successfully adapted since - don't log to avoid spam. + return; + } + RTC_LOG(INFO) << "Resource \"" << resource->name() << "\" signalled " + << ResourceUsageStateToString(usage_state) << ". " + << result_and_message.message; + if (result_and_message.result == MitigationResult::kAdaptationApplied) { + previous_mitigation_results_.clear(); + } else { + previous_mitigation_results_.insert( + std::make_pair(resource.get(), result_and_message.result)); + } } bool ResourceAdaptationProcessor::HasSufficientInputForAdaptation( @@ -198,7 +234,8 @@ bool ResourceAdaptationProcessor::HasSufficientInputForAdaptation( input_state.frames_per_second() >= kMinFrameRateFps); } -void ResourceAdaptationProcessor::OnResourceUnderuse( +ResourceAdaptationProcessor::MitigationResultAndLogMessage +ResourceAdaptationProcessor::OnResourceUnderuse( rtc::scoped_refptr reason_resource) { RTC_DCHECK_RUN_ON(&sequence_checker_); RTC_DCHECK(!processing_in_progress_); @@ -210,15 +247,25 @@ void ResourceAdaptationProcessor::OnResourceUnderuse( for (const auto& resource : resources_) { resource->ClearUsageState(); } - VideoStreamInputState input_state = input_state_provider_->InputState(); - if (effective_degradation_preference_ == DegradationPreference::DISABLED || - !HasSufficientInputForAdaptation(input_state)) { + if (effective_degradation_preference_ == DegradationPreference::DISABLED) { processing_in_progress_ = false; - return; + return MitigationResultAndLogMessage( + MitigationResult::kDisabled, + "Not adapting up because DegradationPreference is disabled"); + } + VideoStreamInputState input_state = input_state_provider_->InputState(); + if (!HasSufficientInputForAdaptation(input_state)) { + processing_in_progress_ = false; + return MitigationResultAndLogMessage( + MitigationResult::kInsufficientInput, + "Not adapting up because input is insufficient"); } if (!IsResourceAllowedToAdaptUp(reason_resource)) { processing_in_progress_ = false; - return; + return MitigationResultAndLogMessage( + MitigationResult::kRejectedByAdaptationCounts, + "Not adapting up because this resource has not previously adapted down " + "(according to adaptation counters)"); } // Update video input states and encoder settings for accurate adaptation. stream_adapter_->SetInput(input_state); @@ -226,22 +273,27 @@ void ResourceAdaptationProcessor::OnResourceUnderuse( Adaptation adaptation = stream_adapter_->GetAdaptationUp(); if (adaptation.status() != Adaptation::Status::kValid) { processing_in_progress_ = false; - return; + rtc::StringBuilder message; + message << "Not adapting up because VideoStreamAdapter returned " + << Adaptation::StatusToString(adaptation.status()); + return MitigationResultAndLogMessage(MitigationResult::kRejectedByAdapter, + message.Release()); } // Are all resources OK with this adaptation being applied? VideoSourceRestrictions restrictions_before = stream_adapter_->source_restrictions(); VideoSourceRestrictions restrictions_after = stream_adapter_->PeekNextRestrictions(adaptation); - if (!absl::c_all_of(resources_, [&input_state, &restrictions_before, - &restrictions_after, &reason_resource]( - rtc::scoped_refptr resource) { - return resource->IsAdaptationUpAllowed(input_state, restrictions_before, - restrictions_after, - reason_resource); - })) { - processing_in_progress_ = false; - return; + for (const auto& resource : resources_) { + if (!resource->IsAdaptationUpAllowed(input_state, restrictions_before, + restrictions_after, reason_resource)) { + processing_in_progress_ = false; + rtc::StringBuilder message; + message << "Not adapting up because resource \"" << resource->name() + << "\" disallowed it"; + return MitigationResultAndLogMessage( + MitigationResult::kRejectedByResource, message.Release()); + } } // Apply adaptation. stream_adapter_->ApplyAdaptation(adaptation); @@ -253,9 +305,15 @@ void ResourceAdaptationProcessor::OnResourceUnderuse( // |adaptation_listeners_|. MaybeUpdateVideoSourceRestrictions(reason_resource); processing_in_progress_ = false; + rtc::StringBuilder message; + message << "Adapted up successfully. Unfiltered adaptations: " + << stream_adapter_->adaptation_counters().ToString(); + return MitigationResultAndLogMessage(MitigationResult::kAdaptationApplied, + message.Release()); } -void ResourceAdaptationProcessor::OnResourceOveruse( +ResourceAdaptationProcessor::MitigationResultAndLogMessage +ResourceAdaptationProcessor::OnResourceOveruse( rtc::scoped_refptr reason_resource) { RTC_DCHECK_RUN_ON(&sequence_checker_); RTC_DCHECK(!processing_in_progress_); @@ -267,15 +325,18 @@ void ResourceAdaptationProcessor::OnResourceOveruse( for (const auto& resource : resources_) { resource->ClearUsageState(); } - VideoStreamInputState input_state = input_state_provider_->InputState(); - if (!input_state.has_input()) { + if (effective_degradation_preference_ == DegradationPreference::DISABLED) { processing_in_progress_ = false; - return; + return MitigationResultAndLogMessage( + MitigationResult::kDisabled, + "Not adapting down because DegradationPreference is disabled"); } - if (effective_degradation_preference_ == DegradationPreference::DISABLED || - !HasSufficientInputForAdaptation(input_state)) { + VideoStreamInputState input_state = input_state_provider_->InputState(); + if (!HasSufficientInputForAdaptation(input_state)) { processing_in_progress_ = false; - return; + return MitigationResultAndLogMessage( + MitigationResult::kInsufficientInput, + "Not adapting down because input is insufficient"); } // Update video input states and encoder settings for accurate adaptation. stream_adapter_->SetInput(input_state); @@ -286,7 +347,11 @@ void ResourceAdaptationProcessor::OnResourceOveruse( } if (adaptation.status() != Adaptation::Status::kValid) { processing_in_progress_ = false; - return; + rtc::StringBuilder message; + message << "Not adapting down because VideoStreamAdapter returned " + << Adaptation::StatusToString(adaptation.status()); + return MitigationResultAndLogMessage(MitigationResult::kRejectedByAdapter, + message.Release()); } // Apply adaptation. VideoSourceRestrictions restrictions_before = @@ -302,11 +367,17 @@ void ResourceAdaptationProcessor::OnResourceOveruse( // |adaptation_listeners_|. MaybeUpdateVideoSourceRestrictions(reason_resource); processing_in_progress_ = false; + rtc::StringBuilder message; + message << "Adapted down successfully. Unfiltered adaptations: " + << stream_adapter_->adaptation_counters().ToString(); + return MitigationResultAndLogMessage(MitigationResult::kAdaptationApplied, + message.Release()); } void ResourceAdaptationProcessor::TriggerAdaptationDueToFrameDroppedDueToSize( rtc::scoped_refptr reason_resource) { RTC_DCHECK_RUN_ON(&sequence_checker_); + RTC_LOG(INFO) << "TriggerAdaptationDueToFrameDroppedDueToSize called"; VideoAdaptationCounters counters_before = stream_adapter_->adaptation_counters(); OnResourceOveruse(reason_resource); diff --git a/call/adaptation/resource_adaptation_processor.h b/call/adaptation/resource_adaptation_processor.h index cf1e187026..06b9a4c1cd 100644 --- a/call/adaptation/resource_adaptation_processor.h +++ b/call/adaptation/resource_adaptation_processor.h @@ -13,6 +13,7 @@ #include #include +#include #include #include "absl/types/optional.h" @@ -89,11 +90,29 @@ class ResourceAdaptationProcessor : public ResourceAdaptationProcessorInterface, bool HasSufficientInputForAdaptation( const VideoStreamInputState& input_state) const; + enum class MitigationResult { + kDisabled, + kInsufficientInput, + kRejectedByAdaptationCounts, + kRejectedByAdapter, + kRejectedByResource, + kAdaptationApplied, + }; + + struct MitigationResultAndLogMessage { + MitigationResultAndLogMessage(); + MitigationResultAndLogMessage(MitigationResult result, std::string message); + MitigationResult result; + std::string message; + }; + // Performs the adaptation by getting the next target, applying it and // informing listeners of the new VideoSourceRestriction and adaptation // counters. - void OnResourceUnderuse(rtc::scoped_refptr reason_resource); - void OnResourceOveruse(rtc::scoped_refptr reason_resource); + MitigationResultAndLogMessage OnResourceUnderuse( + rtc::scoped_refptr reason_resource); + MitigationResultAndLogMessage OnResourceOveruse( + rtc::scoped_refptr reason_resource); // Needs to be invoked any time |degradation_preference_| or |is_screenshare_| // changes to ensure |effective_degradation_preference_| is up-to-date. @@ -138,6 +157,10 @@ class ResourceAdaptationProcessor : public ResourceAdaptationProcessorInterface, RTC_GUARDED_BY(sequence_checker_); VideoSourceRestrictions last_reported_source_restrictions_ RTC_GUARDED_BY(sequence_checker_); + // Keeps track of previous mitigation results per resource since the last + // successful adaptation. Used to avoid RTC_LOG spam. + std::map previous_mitigation_results_ + RTC_GUARDED_BY(sequence_checker_); // Prevents recursion. // // This is used to prevent triggering resource adaptation in the process of diff --git a/call/adaptation/video_stream_adapter.cc b/call/adaptation/video_stream_adapter.cc index 4ebe00fb0c..ebca989f42 100644 --- a/call/adaptation/video_stream_adapter.cc +++ b/call/adaptation/video_stream_adapter.cc @@ -111,6 +111,18 @@ int GetHigherResolutionThan(int pixel_count) { : std::numeric_limits::max(); } +// static +const char* Adaptation::StatusToString(Adaptation::Status status) { + switch (status) { + case Adaptation::Status::kValid: + return "kValid"; + case Adaptation::Status::kLimitReached: + return "kLimitReached"; + case Adaptation::Status::kAwaitingPreviousAdaptation: + return "kAwaitingPreviousAdaptation"; + } +} + Adaptation::Step::Step(StepType type, int target) : type(type), target(target) {} @@ -504,6 +516,7 @@ Adaptation VideoStreamAdapter::GetAdaptationDown() const { VideoSourceRestrictions VideoStreamAdapter::PeekNextRestrictions( const Adaptation& adaptation) const { RTC_DCHECK_EQ(adaptation.validation_id_, adaptation_validation_id_); + RTC_LOG(LS_INFO) << "PeekNextRestrictions called"; if (adaptation.status() != Adaptation::Status::kValid) return source_restrictor_->source_restrictions(); VideoSourceRestrictor restrictor_copy = *source_restrictor_; @@ -514,6 +527,7 @@ VideoSourceRestrictions VideoStreamAdapter::PeekNextRestrictions( void VideoStreamAdapter::ApplyAdaptation(const Adaptation& adaptation) { RTC_DCHECK_EQ(adaptation.validation_id_, adaptation_validation_id_); + RTC_LOG(LS_INFO) << "ApplyAdaptation called"; if (adaptation.status() != Adaptation::Status::kValid) return; // Remember the input pixels and fps of this adaptation. Used to avoid diff --git a/call/adaptation/video_stream_adapter.h b/call/adaptation/video_stream_adapter.h index f313e6bed6..179412fbcc 100644 --- a/call/adaptation/video_stream_adapter.h +++ b/call/adaptation/video_stream_adapter.h @@ -56,6 +56,8 @@ class Adaptation final { kAwaitingPreviousAdaptation, }; + static const char* StatusToString(Status status); + // The status of this Adaptation. To find out how this Adaptation affects // VideoSourceRestrictions, see VideoStreamAdapter::PeekNextRestrictions(). Status status() const;