Video/Screenshare loopback tool.

webrtc/modules/congestion_controller/probe_bitrate_estimator.cc

 /*
  *  Copyright (c) 2016 The WebRTC project authors. All Rights Reserved.
  *
  *  Use of this source code is governed by a BSD-style license
  *  that can be found in the LICENSE file in the root of the source
  *  tree. An additional intellectual property rights grant can be found
  *  in the file PATENTS.  All contributing project authors may
  *  be found in the AUTHORS file in the root of the source tree.
  */
 
 #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
 // in order to have a valid estimate.
 constexpr int kMinReceivedProbesPercent = 80;
 
 // The minumum number of bytes we need to receive feedback about in percent
 // in order to have a valid estimate.
 constexpr int kMinReceivedBytesPercent = 80;
 
@@ skipping 26 matching lines @@
     : event_log_(event_log) {}
 
 ProbeBitrateEstimator::~ProbeBitrateEstimator() = default;
 
 int ProbeBitrateEstimator::HandleProbeAndEstimateBitrate(
     const PacketFeedback& packet_feedback) {
   int cluster_id = packet_feedback.pacing_info.probe_cluster_id;
   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];
 
   if (packet_feedback.send_time_ms < cluster->first_send_ms) {
     cluster->first_send_ms = packet_feedback.send_time_ms;
   }
   if (packet_feedback.send_time_ms > cluster->last_send_ms) {
     cluster->last_send_ms = packet_feedback.send_time_ms;
     cluster->size_last_send = payload_size_bits;
@@ skipping 17 matching lines @@
                   kMinReceivedBytesPercent / 100;
   if (cluster->num_probes < min_probes || cluster->size_total < min_bytes * 8)
     return -1;
 
   float send_interval_ms = cluster->last_send_ms - cluster->first_send_ms;
   float receive_interval_ms =
       cluster->last_receive_ms - cluster->first_receive_ms;
 
   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);
     }
     return -1;
   }
   // Since the |send_interval_ms| does not include the time it takes to actually
   // 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 << " / "
                  << send_bps / 1000 << " = " << ratio << " > kMaxValidRatio ("
                  << kMaxValidRatio << ")]";
     if (event_log_)
       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]";
 
   float res = std::min(send_bps, receive_bps);
   // If we're receiving at significantly lower bitrate than we were sending at,
   // it suggests that we've found the true capacity of the link. In this case,
   // set the target bitrate slightly lower to not immediately overuse.
   if (receive_bps < kMinRatioForUnsaturatedLink * send_bps) {
     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;
 }
 
 void ProbeBitrateEstimator::EraseOldClusters(int64_t timestamp_ms) {
   for (auto it = clusters_.begin(); it != clusters_.end();) {
     if (it->second.last_receive_ms < timestamp_ms) {
       it = clusters_.erase(it);
     } else {
       ++it;
     }
   }
 }
 }  // namespace webrtc