[Adaptation] Add more ResourceAdaptationProcessor logging.

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 <hbos@webrtc.org>
Reviewed-by: Evan Shrubsole <eshr@google.com>
Reviewed-by: Harald Alvestrand <hta@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#31378}

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;

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 {

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") {

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

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 <string>
+
 #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;
 };

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()

call/adaptation/resource.h

@@ -32,6 +32,8 @@ enum class ResourceUsageState {
   kUnderuse,
 };
 
+const char* ResourceUsageStateToString(ResourceUsageState usage_state);
+
 class ResourceListener {
  public:
   virtual ~ResourceListener();

call/adaptation/resource_adaptation_processor.cc

@@ -11,12 +11,23 @@
 #include "call/adaptation/resource_adaptation_processor.h"
 
 #include <algorithm>
+#include <string>
 #include <utility>
 
 #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<VideoStreamAdapter>()),
       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> 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<Resource> 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> 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<Resource> 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<Resource> reason_resource) {
   RTC_DCHECK_RUN_ON(&sequence_checker_);
+  RTC_LOG(INFO) << "TriggerAdaptationDueToFrameDroppedDueToSize called";
   VideoAdaptationCounters counters_before =
       stream_adapter_->adaptation_counters();
   OnResourceOveruse(reason_resource);

call/adaptation/resource_adaptation_processor.h

@@ -13,6 +13,7 @@
 
 #include <map>
 #include <memory>
+#include <string>
 #include <vector>
 
 #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<Resource> reason_resource);
-  void OnResourceOveruse(rtc::scoped_refptr<Resource> reason_resource);
+  MitigationResultAndLogMessage OnResourceUnderuse(
+      rtc::scoped_refptr<Resource> reason_resource);
+  MitigationResultAndLogMessage OnResourceOveruse(
+      rtc::scoped_refptr<Resource> 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<Resource*, MitigationResult> previous_mitigation_results_
+      RTC_GUARDED_BY(sequence_checker_);
   // Prevents recursion.
   //
   // This is used to prevent triggering resource adaptation in the process of

call/adaptation/video_stream_adapter.cc

@@ -111,6 +111,18 @@ int GetHigherResolutionThan(int pixel_count) {
              : std::numeric_limits<int>::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

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;