[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}
diff --git a/api/rtp_parameters.cc b/api/rtp_parameters.cc
index a05b2bf..c44e4c4 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 d7156db..f831e51 100644
--- a/api/rtp_parameters.h
+++ b/api/rtp_parameters.h
@@ -92,6 +92,9 @@
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 7f9b034..3bce91e 100644
--- a/api/video/BUILD.gn
+++ b/api/video/BUILD.gn
@@ -237,7 +237,10 @@
"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 25e0bee..df1769d 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 @@
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 eff0baa..2dea902 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 <string>
+
#include "rtc_base/checks.h"
namespace webrtc {
@@ -33,6 +35,8 @@
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 a546450..7d83c4d 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 2ee0c72..d7ecf94 100644
--- a/call/adaptation/resource.h
+++ b/call/adaptation/resource.h
@@ -32,6 +32,8 @@
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 0224ac3..57ace71 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 @@
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::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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
// |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 @@
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 @@
}
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 @@
// |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 cf1e187..06b9a4c 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 @@
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 @@
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 4ebe00f..ebca989 100644
--- a/call/adaptation/video_stream_adapter.cc
+++ b/call/adaptation/video_stream_adapter.cc
@@ -111,6 +111,18 @@
: 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 @@
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 @@
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 f313e6b..179412f 100644
--- a/call/adaptation/video_stream_adapter.h
+++ b/call/adaptation/video_stream_adapter.h
@@ -56,6 +56,8 @@
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;
