Enable BWE logging to command line when rtc_enable_bwe_test_logging is set to true

This patch enables bwe related variable logging to the command line.
This is useful to test congestion control algorithm over real networks.

NOTRY=true

Review-Url: https://codereview.webrtc.org/2296253002
Cr-Commit-Position: refs/heads/master@{#14209}
This commit is contained in:
gaetano.carlucci 2016-09-14 05:04:36 -07:00 committed by Commit bot
parent b471d1cffb
commit 52a5703721
19 changed files with 148 additions and 33 deletions

View File

@ -45,6 +45,9 @@ declare_args() {
# should be generated.
apm_debug_dump = false
# Set this to true to enable BWE test logging.
rtc_enable_bwe_test_logging = false
# Disable these to not build components which can be externally provided.
rtc_build_expat = true
rtc_build_json = true

View File

@ -18,6 +18,12 @@ rtc_source_set("bitrate_controller") {
"send_side_bandwidth_estimation.h",
]
if (rtc_enable_bwe_test_logging) {
defines = [ "BWE_TEST_LOGGING_COMPILE_TIME_ENABLE=1" ]
} else {
defines = [ "BWE_TEST_LOGGING_COMPILE_TIME_ENABLE=0" ]
}
# TODO(jschuh): Bug 1348: fix this warning.
configs += [ "//build/config/compiler:no_size_t_to_int_warning" ]

View File

@ -21,6 +21,13 @@
'send_side_bandwidth_estimation.cc',
'send_side_bandwidth_estimation.h',
],
'conditions': [
['enable_bwe_test_logging==1', {
'defines': [ 'BWE_TEST_LOGGING_COMPILE_TIME_ENABLE=1' ],
}, {
'defines': [ 'BWE_TEST_LOGGING_COMPILE_TIME_ENABLE=0' ],
}],
],
# TODO(jschuh): Bug 1348: fix size_t to int truncations.
'msvs_disabled_warnings': [ 4267, ],
},

View File

@ -17,6 +17,7 @@
#include "webrtc/base/checks.h"
#include "webrtc/base/logging.h"
#include "webrtc/modules/remote_bitrate_estimator/test/bwe_test_logging.h"
#include "webrtc/modules/rtp_rtcp/include/rtp_rtcp_defines.h"
namespace webrtc {
@ -179,6 +180,8 @@ void BitrateControllerImpl::OnReceiverEstimatedBitrate(uint32_t bitrate) {
rtc::CritScope cs(&critsect_);
bandwidth_estimation_.UpdateReceiverEstimate(clock_->TimeInMilliseconds(),
bitrate);
BWE_TEST_LOGGING_PLOT(1, "REMB[kbps]", clock_->TimeInMilliseconds(),
bitrate / 1000);
}
MaybeTriggerOnNetworkChanged();
}
@ -269,6 +272,14 @@ bool BitrateControllerImpl::GetNetworkParameters(uint32_t* bitrate,
last_reserved_bitrate_bps_ = reserved_bitrate_bps_;
new_bitrate = true;
}
BWE_TEST_LOGGING_PLOT(1, "fraction_loss_[%%]", clock_->TimeInMilliseconds(),
(last_fraction_loss_ * 100) / 256);
BWE_TEST_LOGGING_PLOT(1, "rtt[ms]", clock_->TimeInMilliseconds(),
last_rtt_ms_);
BWE_TEST_LOGGING_PLOT(1, "Target_bitrate[kbps]", clock_->TimeInMilliseconds(),
last_bitrate_bps_ / 1000);
return new_bitrate;
}

View File

@ -104,7 +104,8 @@ void DelayBasedBwe::IncomingPacketInfo(const PacketInfo& info) {
info.payload_size, &ts_delta, &t_delta,
&size_delta)) {
double ts_delta_ms = (1000.0 * ts_delta) / (1 << kInterArrivalShift);
estimator_->Update(t_delta, ts_delta_ms, size_delta, detector_.State());
estimator_->Update(t_delta, ts_delta_ms, size_delta, detector_.State(),
info.arrival_time_ms);
detector_.Detect(estimator_->offset(), ts_delta_ms,
estimator_->num_of_deltas(), info.arrival_time_ms);
}

View File

@ -8,11 +8,6 @@
import("../../build/webrtc.gni")
declare_args() {
# Set this to true to enable BWE test logging.
rtc_enable_bwe_test_logging = false
}
rtc_source_set("remote_bitrate_estimator") {
sources = [
"aimd_rate_control.cc",
@ -39,11 +34,13 @@ rtc_source_set("remote_bitrate_estimator") {
"transport_feedback_adapter.h",
]
if (rtc_enable_bwe_test_logging) {
defines = [ "BWE_TEST_LOGGING_COMPILE_TIME_ENABLE=1" ]
sources += [ "test/bwe_test_logging.cc" ]
} else {
defines = [ "BWE_TEST_LOGGING_COMPILE_TIME_ENABLE=0" ]
if (!rtc_include_tests) {
if (rtc_enable_bwe_test_logging) {
defines = [ "BWE_TEST_LOGGING_COMPILE_TIME_ENABLE=1" ]
sources += [ "test/bwe_test_logging.cc" ]
} else {
defines = [ "BWE_TEST_LOGGING_COMPILE_TIME_ENABLE=0" ]
}
}
if (is_clang) {
@ -62,6 +59,7 @@ if (rtc_include_tests) {
rtc_source_set("bwe_simulator") {
testonly = true
sources = [
"bwe_simulations.cc",
"test/bwe.cc",
"test/bwe.h",
"test/bwe_test.cc",

View File

@ -36,6 +36,7 @@ const size_t kDisabledPrefixLength = sizeof(kDisabledPrefix) - 1;
const double kMaxAdaptOffsetMs = 15.0;
const double kOverUsingTimeThreshold = 10;
const int kMinNumDeltas = 60;
bool AdaptiveThresholdExperimentIsDisabled() {
std::string experiment_string =
@ -92,9 +93,9 @@ BandwidthUsage OveruseDetector::Detect(double offset,
}
const double prev_offset = prev_offset_;
prev_offset_ = offset;
const double T = std::min(num_of_deltas, 60) * offset;
BWE_TEST_LOGGING_PLOT(1, "offset", now_ms, T);
BWE_TEST_LOGGING_PLOT(1, "threshold", now_ms, threshold_);
const double T = std::min(num_of_deltas, kMinNumDeltas) * offset;
BWE_TEST_LOGGING_PLOT(1, "offset[ms]", now_ms, offset);
BWE_TEST_LOGGING_PLOT(1, "gamma[ms]", now_ms, threshold_ / kMinNumDeltas);
if (T > threshold_) {
if (time_over_using_ == -1) {
// Initialize the timer. Assume that we've been

View File

@ -100,7 +100,7 @@ class OveruseDetectorTest : public ::testing::Test {
&timestamp_delta, &time_delta, &size_delta)) {
double timestamp_delta_ms = timestamp_delta / 90.0;
overuse_estimator_->Update(time_delta, timestamp_delta_ms, size_delta,
overuse_detector_->State());
overuse_detector_->State(), receive_time_ms);
overuse_detector_->Detect(
overuse_estimator_->offset(), timestamp_delta_ms,
overuse_estimator_->num_of_deltas(), receive_time_ms);

View File

@ -19,6 +19,7 @@
#include "webrtc/base/logging.h"
#include "webrtc/modules/remote_bitrate_estimator/include/bwe_defines.h"
#include "webrtc/modules/remote_bitrate_estimator/test/bwe_test_logging.h"
namespace webrtc {
@ -48,9 +49,11 @@ OveruseEstimator::~OveruseEstimator() {
void OveruseEstimator::Update(int64_t t_delta,
double ts_delta,
int size_delta,
BandwidthUsage current_hypothesis) {
BandwidthUsage current_hypothesis,
int64_t now_ms) {
const double min_frame_period = UpdateMinFramePeriod(ts_delta);
const double t_ts_delta = t_delta - ts_delta;
BWE_TEST_LOGGING_PLOT(1, "dm[ms]", now_ms, t_ts_delta);
double fs_delta = size_delta;
++num_of_deltas_;
@ -71,6 +74,8 @@ void OveruseEstimator::Update(int64_t t_delta,
const double Eh[2] = {E_[0][0]*h[0] + E_[0][1]*h[1],
E_[1][0]*h[0] + E_[1][1]*h[1]};
BWE_TEST_LOGGING_PLOT(1, "d[ms]", now_ms, slope_ * h[0] - offset_);
const double residual = t_ts_delta - slope_*h[0] - offset_;
const bool in_stable_state = (current_hypothesis == kBwNormal);
@ -112,6 +117,11 @@ void OveruseEstimator::Update(int64_t t_delta,
slope_ = slope_ + K[0] * residual;
prev_offset_ = offset_;
offset_ = offset_ + K[1] * residual;
BWE_TEST_LOGGING_PLOT(1, "kc", now_ms, K[0]);
BWE_TEST_LOGGING_PLOT(1, "km", now_ms, K[1]);
BWE_TEST_LOGGING_PLOT(1, "slope[1/bps]", now_ms, slope_);
BWE_TEST_LOGGING_PLOT(1, "var_noise", now_ms, var_noise_);
}
double OveruseEstimator::UpdateMinFramePeriod(double ts_delta) {

View File

@ -27,8 +27,11 @@ class OveruseEstimator {
// between timestamp groups as defined by the InterArrival class.
// |current_hypothesis| should be the hypothesis of the over-use detector at
// this time.
void Update(int64_t t_delta, double ts_delta, int size_delta,
BandwidthUsage current_hypothesis);
void Update(int64_t t_delta,
double ts_delta,
int size_delta,
BandwidthUsage current_hypothesis,
int64_t now_ms);
// Returns the estimated noise/jitter variance in ms^2.
double var_noise() const {

View File

@ -10,10 +10,6 @@
'includes': [
'../../build/common.gypi',
],
'variables': {
# Set this to true to enable BWE test logging.
'enable_bwe_test_logging%': 0,
},
'targets': [
{
'target_name': 'remote_bitrate_estimator',
@ -47,13 +43,17 @@
'test/bwe_test_logging.h',
], # source
'conditions': [
['enable_bwe_test_logging==1', {
'defines': [ 'BWE_TEST_LOGGING_COMPILE_TIME_ENABLE=1' ],
'sources': [
'test/bwe_test_logging.cc'
['include_tests==0', {
'conditions': [
['enable_bwe_test_logging==1', {
'defines': [ 'BWE_TEST_LOGGING_COMPILE_TIME_ENABLE=1' ],
'sources': [
'test/bwe_test_logging.cc'
],
}, {
'defines': [ 'BWE_TEST_LOGGING_COMPILE_TIME_ENABLE=0' ],
}],
],
}, {
'defines': [ 'BWE_TEST_LOGGING_COMPILE_TIME_ENABLE=0' ],
}],
],
},
@ -71,6 +71,7 @@
'<(DEPTH)/testing/gmock.gyp:gmock',
],
'sources': [
'bwe_simulations.cc',
'test/bwe.cc',
'test/bwe.h',
'test/bwe_test.cc',

View File

@ -313,7 +313,8 @@ void RemoteBitrateEstimatorAbsSendTime::IncomingPacketInfo(
payload_size, &ts_delta, &t_delta,
&size_delta)) {
double ts_delta_ms = (1000.0 * ts_delta) / (1 << kInterArrivalShift);
estimator_->Update(t_delta, ts_delta_ms, size_delta, detector_.State());
estimator_->Update(t_delta, ts_delta_ms, size_delta, detector_.State(),
arrival_time_ms);
detector_.Detect(estimator_->offset(), ts_delta_ms,
estimator_->num_of_deltas(), arrival_time_ms);
}

View File

@ -123,7 +123,7 @@ void RemoteBitrateEstimatorSingleStream::IncomingPacket(
&timestamp_delta, &time_delta, &size_delta)) {
double timestamp_delta_ms = timestamp_delta * kTimestampToMs;
estimator->estimator.Update(time_delta, timestamp_delta_ms, size_delta,
estimator->detector.State());
estimator->detector.State(), now_ms);
estimator->detector.Detect(estimator->estimator.offset(),
timestamp_delta_ms,
estimator->estimator.num_of_deltas(), now_ms);

View File

@ -91,15 +91,28 @@ void Logging::Log(const char format[], ...) {
}
void Logging::Plot(int figure, double value) {
Plot(figure, value, "-");
Plot(figure, value, 0, "-");
}
void Logging::Plot(int figure, double value, uint32_t ssrc) {
Plot(figure, value, ssrc, "-");
}
void Logging::Plot(int figure, double value, const std::string& alg_name) {
Plot(figure, value, 0, alg_name);
}
void Logging::Plot(int figure,
double value,
uint32_t ssrc,
const std::string& alg_name) {
CriticalSectionScoped cs(crit_sect_.get());
ThreadMap::iterator it = thread_map_.find(rtc::CurrentThreadId());
assert(it != thread_map_.end());
const State& state = it->second.stack.top();
std::string label = state.tag + '@' + alg_name;
std::stringstream ss;
ss << ssrc;
std::string label = state.tag + ':' + ss.str() + '@' + alg_name;
std::string prefix("Available");
if (alg_name.compare(0, prefix.length(), prefix) == 0) {
std::string receiver("Receiver");

View File

@ -91,9 +91,13 @@
// |name| is a char*, std::string or uint32_t to name the plotted value.
// |time| is an int64_t time in ms, or -1 to inherit time from previous context.
// |value| is a double precision float to be plotted.
// |ssrc| identifies the source of a stream
// |alg_name| is an optional argument, a string
#define BWE_TEST_LOGGING_PLOT(figure, name, time, value)
#define BWE_TEST_LOGGING_PLOT_WITH_NAME(figure, name, time, value, alg_name)
#define BWE_TEST_LOGGING_PLOT_WITH_SSRC(figure, name, time, value, ssrc)
#define BWE_TEST_LOGGING_PLOT_WITH_NAME_AND_SSRC(figure, name, time, value, \
ssrc, alg_name)
// Print to stdout in tab-separated format suitable for plotting, e.g.:
// BAR figure Context1_Context2_Name x_left width value
@ -194,6 +198,22 @@
alg_name); \
} while (0)
#define BWE_TEST_LOGGING_PLOT_WITH_SSRC(figure, name, time, value, ssrc) \
do { \
__BWE_TEST_LOGGING_CONTEXT_DECLARE(__bwe_log_, __PLOT__, name, \
static_cast<int64_t>(time), true); \
webrtc::testing::bwe::Logging::GetInstance()->Plot(figure, value, ssrc); \
} while (0)
#define BWE_TEST_LOGGING_PLOT_WITH_NAME_AND_SSRC(figure, name, time, value, \
ssrc, alg_name) \
do { \
__BWE_TEST_LOGGING_CONTEXT_DECLARE(__bwe_log_, __PLOT__, name, \
static_cast<int64_t>(time), true); \
webrtc::testing::bwe::Logging::GetInstance()->Plot(figure, value, ssrc, \
alg_name); \
} while (0)
#define BWE_TEST_LOGGING_BAR(figure, name, value, flow_id) \
do { \
BWE_TEST_LOGGING_CONTEXT(name); \
@ -261,6 +281,11 @@ class Logging {
void Log(const char format[], ...);
void Plot(int figure, double value);
void Plot(int figure, double value, const std::string& alg_name);
void Plot(int figure, double value, uint32_t ssrc);
void Plot(int figure,
double value,
uint32_t ssrc,
const std::string& alg_name);
void PlotBar(int figure, const std::string& name, double value, int flow_id);
void PlotBaselineBar(int figure,
const std::string& name,

View File

@ -154,6 +154,12 @@ rtc_source_set("rtp_rtcp") {
"source/vp8_partition_aggregator.h",
]
if (rtc_enable_bwe_test_logging) {
defines = [ "BWE_TEST_LOGGING_COMPILE_TIME_ENABLE=1" ]
} else {
defines = [ "BWE_TEST_LOGGING_COMPILE_TIME_ENABLE=0" ]
}
if (is_clang) {
# Suppress warnings from Chrome's Clang plugins.
# See http://code.google.com/p/webrtc/issues/detail?id=163 for details.

View File

@ -163,7 +163,14 @@
# Mocks
'mocks/mock_rtp_rtcp.h',
'source/mock/mock_rtp_payload_strategy.h',
], # source
], # source
'conditions': [
['enable_bwe_test_logging==1', {
'defines': [ 'BWE_TEST_LOGGING_COMPILE_TIME_ENABLE=1' ],
}, {
'defines': [ 'BWE_TEST_LOGGING_COMPILE_TIME_ENABLE=0' ],
}],
],
# TODO(jschuh): Bug 1348: fix size_t to int truncations.
'msvs_disabled_warnings': [ 4267, ],
},

View File

@ -14,6 +14,7 @@
#include <cstdlib>
#include "webrtc/modules/remote_bitrate_estimator/test/bwe_test_logging.h"
#include "webrtc/modules/rtp_rtcp/source/rtp_rtcp_config.h"
#include "webrtc/modules/rtp_rtcp/source/time_util.h"
@ -276,6 +277,12 @@ RtcpStatistics StreamStatisticianImpl::CalculateRtcpStatistics() {
receive_counters_.retransmitted.packets;
last_report_old_packets_ = receive_counters_.retransmitted.packets;
last_report_seq_max_ = received_seq_max_;
BWE_TEST_LOGGING_PLOT_WITH_SSRC(1, "cumulative_loss[pkts]",
clock_->TimeInMilliseconds(),
cumulative_loss_, ssrc_);
BWE_TEST_LOGGING_PLOT_WITH_SSRC(
1, "received_seq_max[pkts]", clock_->TimeInMilliseconds(),
(received_seq_max_ - received_seq_first_), ssrc_);
return stats;
}

View File

@ -20,6 +20,7 @@
#include "webrtc/base/timeutils.h"
#include "webrtc/call.h"
#include "webrtc/call/rtc_event_log.h"
#include "webrtc/modules/remote_bitrate_estimator/test/bwe_test_logging.h"
#include "webrtc/modules/rtp_rtcp/include/rtp_cvo.h"
#include "webrtc/modules/rtp_rtcp/source/byte_io.h"
#include "webrtc/modules/rtp_rtcp/source/playout_delay_oracle.h"
@ -905,6 +906,20 @@ bool RTPSender::SendToNetwork(std::unique_ptr<RtpPacketToSend> packet,
}
packet->SetExtension<AbsoluteSendTime>(now_ms);
if (video_) {
BWE_TEST_LOGGING_PLOT_WITH_SSRC(1, "VideoTotBitrate[kbps]", now_ms,
ActualSendBitrateKbit(), packet->Ssrc());
BWE_TEST_LOGGING_PLOT_WITH_SSRC(1, "VideoFecBitrate[Kbps]", now_ms,
FecOverheadRate() / 1000, packet->Ssrc());
BWE_TEST_LOGGING_PLOT_WITH_SSRC(1, "VideoNackBitrate[Kbps]", now_ms,
NackOverheadRate() / 1000, packet->Ssrc());
} else {
BWE_TEST_LOGGING_PLOT_WITH_SSRC(1, "AudioTotBitrate[kbps]", now_ms,
ActualSendBitrateKbit(), packet->Ssrc());
BWE_TEST_LOGGING_PLOT_WITH_SSRC(1, "AudioNackBitrate[Kbps]", now_ms,
NackOverheadRate() / 1000, packet->Ssrc());
}
if (paced_sender_) {
uint16_t seq_no = packet->SequenceNumber();
uint32_t ssrc = packet->Ssrc();