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