[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}

6 files changed, 149 insertions, 28 deletions

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 <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();
   }
+  if (effective_degradation_preference_ == DegradationPreference::DISABLED) {
+    processing_in_progress_ = false;
+    return MitigationResultAndLogMessage(
+        MitigationResult::kDisabled,
+        "Not adapting up because DegradationPreference is disabled");
+  }
   VideoStreamInputState input_state = input_state_provider_->InputState();
-  if (effective_degradation_preference_ == DegradationPreference::DISABLED ||
-      !HasSufficientInputForAdaptation(input_state)) {
+  if (!HasSufficientInputForAdaptation(input_state)) {
     processing_in_progress_ = false;
-    return;
+    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);
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 <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
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<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
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;