Video/Screenshare loopback tool.

webrtc/modules/congestion_controller/probe_bitrate_estimator.cc

Index: webrtc/modules/congestion_controller/probe_bitrate_estimator.cc
diff --git a/webrtc/modules/congestion_controller/probe_bitrate_estimator.cc b/webrtc/modules/congestion_controller/probe_bitrate_estimator.cc
index 8fa22e7dcd6edfc9f379d5df0c0c225537eac1b5..7babf80de2b4db61a6f569d2fe2875ecdc785e06 100644
--- a/webrtc/modules/congestion_controller/probe_bitrate_estimator.cc
+++ b/webrtc/modules/congestion_controller/probe_bitrate_estimator.cc
@@ -11,10 +11,12 @@
 #include "webrtc/modules/congestion_controller/probe_bitrate_estimator.h"
 
 #include <algorithm>
+#include <sstream>
 
 #include "webrtc/logging/rtc_event_log/rtc_event_log.h"
 #include "webrtc/rtc_base/checks.h"
 #include "webrtc/rtc_base/logging.h"
+#include "webrtc/rtc_base/timeutils.h"
 
 namespace {
 // The minumum number of probes we need to receive feedback about in percent
@@ -61,6 +63,14 @@ int ProbeBitrateEstimator::HandleProbeAndEstimateBitrate(
   RTC_DCHECK_NE(cluster_id, PacedPacketInfo::kNotAProbe);
 
   EraseOldClusters(packet_feedback.arrival_time_ms - kMaxClusterHistoryMs);
+  if (start_ == 0)
+    start_ = packet_feedback.send_time_ms;
+
+  Print("Feedback:%5u id:%3d send:%8ld receive:%8ld size:%4lu",
+        packet_feedback.sequence_number,
+        packet_feedback.pacing_info.probe_cluster_id,
+        packet_feedback.send_time_ms - start_,
+        packet_feedback.arrival_time_ms - start_, packet_feedback.payload_size);
 
   int payload_size_bits = packet_feedback.payload_size * 8;
   AggregatedCluster* cluster = &clusters_[cluster_id];
@@ -98,10 +108,16 @@ int ProbeBitrateEstimator::HandleProbeAndEstimateBitrate(
 
   if (send_interval_ms <= 0 || send_interval_ms > kMaxProbeIntervalMs ||
       receive_interval_ms <= 0 || receive_interval_ms > kMaxProbeIntervalMs) {
+    std::stringstream ss1;
+    ss1 << "Probing unsuccessful, invalid send/receive interval"
+        << " [cluster id: " << cluster_id
+        << "] [send interval: " << send_interval_ms << " ms]"
+        << " [receive interval: " << receive_interval_ms << " ms]";
     LOG(LS_INFO) << "Probing unsuccessful, invalid send/receive interval"
                  << " [cluster id: " << cluster_id
                  << "] [send interval: " << send_interval_ms << " ms]"
                  << " [receive interval: " << receive_interval_ms << " ms]";
+    Print("%s", ss1.str().c_str());
     if (event_log_) {
       event_log_->LogProbeResultFailure(cluster_id,
                                         kInvalidSendReceiveInterval);
@@ -112,23 +128,33 @@ int ProbeBitrateEstimator::HandleProbeAndEstimateBitrate(
   // send the last packet the size of the last sent packet should not be
   // included when calculating the send bitrate.
   RTC_DCHECK_GT(cluster->size_total, cluster->size_last_send);
-  float send_size = cluster->size_total - cluster->size_last_send;
-  float send_bps = send_size / send_interval_ms * 1000;
+  float send_size_bits = cluster->size_total - cluster->size_last_send;
+  float send_bps = send_size_bits / send_interval_ms * 1000;
 
   // Since the |receive_interval_ms| does not include the time it takes to
   // actually receive the first packet the size of the first received packet
   // should not be included when calculating the receive bitrate.
   RTC_DCHECK_GT(cluster->size_total, cluster->size_first_receive);
-  float receive_size = cluster->size_total - cluster->size_first_receive;
-  float receive_bps = receive_size / receive_interval_ms * 1000;
+  float receive_size_bits = cluster->size_total - cluster->size_first_receive;
+  float receive_bps = receive_size_bits / receive_interval_ms * 1000;
 
   float ratio = receive_bps / send_bps;
   if (ratio > kMaxValidRatio) {
+    std::stringstream ss2;
+    ss2 << "Probing unsuccessful, receive/send ratio too high"
+        << " [cluster id: " << cluster_id << "] [send: " << send_size_bits / 8
+        << " bytes / " << send_interval_ms << " ms = " << send_bps / 1000
+        << " kb/s]"
+        << " [receive: " << receive_size_bits / 8 << " bytes / "
+        << receive_interval_ms << " ms = " << receive_bps / 1000 << " kb/s]"
+        << " [ratio: " << receive_bps / 1000 << " / " << send_bps / 1000
+        << " = " << ratio << " > kMaxValidRatio (" << kMaxValidRatio << ")]";
+    Print("%s", ss2.str().c_str());
     LOG(LS_INFO) << "Probing unsuccessful, receive/send ratio too high"
-                 << " [cluster id: " << cluster_id << "] [send: " << send_size
-                 << " bytes / " << send_interval_ms
-                 << " ms = " << send_bps / 1000 << " kb/s]"
-                 << " [receive: " << receive_size << " bytes / "
+                 << " [cluster id: " << cluster_id
+                 << "] [send: " << send_size_bits / 8 << " bytes / "
+                 << send_interval_ms << " ms = " << send_bps / 1000 << " kb/s]"
+                 << " [receive: " << receive_size_bits / 8 << " bytes / "
                  << receive_interval_ms << " ms = " << receive_bps / 1000
                  << " kb/s]"
                  << " [ratio: " << receive_bps / 1000 << " / "
@@ -138,11 +164,18 @@ int ProbeBitrateEstimator::HandleProbeAndEstimateBitrate(
       event_log_->LogProbeResultFailure(cluster_id, kInvalidSendReceiveRatio);
     return -1;
   }
+  std::stringstream ss3;
+  ss3 << "Probing successful"
+      << " [cluster id: " << cluster_id << "] [send: " << send_size_bits / 8
+      << " bytes / " << send_interval_ms << " ms = " << send_bps / 1000
+      << " kb/s]"
+      << " [receive: " << receive_size_bits / 8 << " bytes / "
+      << receive_interval_ms << " ms = " << receive_bps / 1000 << " kb/s]";
   LOG(LS_INFO) << "Probing successful"
-               << " [cluster id: " << cluster_id << "] [send: " << send_size
-               << " bytes / " << send_interval_ms << " ms = " << send_bps / 1000
-               << " kb/s]"
-               << " [receive: " << receive_size << " bytes / "
+               << " [cluster id: " << cluster_id
+               << "] [send: " << send_size_bits / 8 << " bytes / "
+               << send_interval_ms << " ms = " << send_bps / 1000 << " kb/s]"
+               << " [receive: " << receive_size_bits / 8 << " bytes / "
                << receive_interval_ms << " ms = " << receive_bps / 1000
                << " kb/s]";
 
@@ -154,15 +187,27 @@ int ProbeBitrateEstimator::HandleProbeAndEstimateBitrate(
     RTC_DCHECK_GT(send_bps, receive_bps);
     res = kTargetUtilizationFraction * receive_bps;
   }
-  if (event_log_)
-    event_log_->LogProbeResultSuccess(cluster_id, res);
   estimated_bitrate_bps_ = rtc::Optional<int>(res);
+  last_estimate_update_ms_ = rtc::TimeMillis();
+  cluster_id_ = cluster_id;
+  Print("%s, estimated kbps: %d", ss3.str().c_str(),
+        *estimated_bitrate_bps_ / 1000);
   return *estimated_bitrate_bps_;
 }
 
-rtc::Optional<int>
-ProbeBitrateEstimator::FetchAndResetLastEstimatedBitrateBps() {
+rtc::Optional<int> ProbeBitrateEstimator::FetchAndResetLastEstimatedBitrateBps(
+    int64_t timeout) {
+  int64_t now_ms = rtc::TimeMillis();
   rtc::Optional<int> estimated_bitrate_bps = estimated_bitrate_bps_;
+
+  if (!estimated_bitrate_bps || now_ms < last_estimate_update_ms_ + timeout)
+    return rtc::Optional<int>();
+
+  Print("Probe result %d kbps", *estimated_bitrate_bps / 1000);
+
+  if (event_log_)
+    event_log_->LogProbeResultSuccess(cluster_id_, *estimated_bitrate_bps);
+
   estimated_bitrate_bps_.reset();
   return estimated_bitrate_bps;
 }