Add support for visualizing event logs without normalizing time.
Bug: webrtc:9299
Change-Id: Icdc4cba14f143cedb7c35347dd9711ab13f975d8
Reviewed-on: https://webrtc-review.googlesource.com/77820
Commit-Queue: Stefan Holmer <stefan@webrtc.org>
Reviewed-by: Björn Terelius <terelius@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#23392}diff --git a/rtc_tools/event_log_visualizer/analyzer.cc b/rtc_tools/event_log_visualizer/analyzer.cc
index 76ac88a..71707a9 100644
--- a/rtc_tools/event_log_visualizer/analyzer.cc
+++ b/rtc_tools/event_log_visualizer/analyzer.cc
@@ -229,15 +229,14 @@
// For each element in data_view, use |f()| to extract a y-coordinate and
// store the result in a TimeSeries.
template <typename DataType, typename IterableType>
-void ProcessPoints(rtc::FunctionView<rtc::Optional<float>(const DataType&)> f,
+void ProcessPoints(rtc::FunctionView<float(const DataType&)> fx,
+ rtc::FunctionView<rtc::Optional<float>(const DataType&)> fy,
const IterableType& data_view,
- int64_t begin_time,
TimeSeries* result) {
for (size_t i = 0; i < data_view.size(); i++) {
const DataType& elem = data_view[i];
- float x = static_cast<float>(elem.log_time_us() - begin_time) /
- kNumMicrosecsPerSec;
- rtc::Optional<float> y = f(elem);
+ float x = fx(elem);
+ rtc::Optional<float> y = fy(elem);
if (y)
result->points.emplace_back(x, *y);
}
@@ -248,55 +247,33 @@
// will be the time of the second element in the pair.
template <typename DataType, typename ResultType, typename IterableType>
void ProcessPairs(
+ rtc::FunctionView<float(const DataType&)> fx,
rtc::FunctionView<rtc::Optional<ResultType>(const DataType&,
- const DataType&)> f,
+ const DataType&)> fy,
const IterableType& data,
- int64_t begin_time,
TimeSeries* result) {
for (size_t i = 1; i < data.size(); i++) {
- float x = static_cast<float>(data[i].log_time_us() - begin_time) /
- kNumMicrosecsPerSec;
- rtc::Optional<ResultType> y = f(data[i - 1], data[i]);
+ float x = fx(data[i]);
+ rtc::Optional<ResultType> y = fy(data[i - 1], data[i]);
if (y)
result->points.emplace_back(x, static_cast<float>(*y));
}
}
-// For each element in data, use |f()| to extract a y-coordinate and
-// store the result in a TimeSeries.
-template <typename DataType, typename ResultType, typename IterableType>
-void AccumulatePoints(
- rtc::FunctionView<rtc::Optional<ResultType>(const DataType&)> f,
- const IterableType& data,
- int64_t begin_time,
- TimeSeries* result) {
- ResultType sum = 0;
- for (size_t i = 0; i < data.size(); i++) {
- float x = static_cast<float>(data[i].log_time_us() - begin_time) /
- kNumMicrosecsPerSec;
- rtc::Optional<ResultType> y = f(data[i]);
- if (y) {
- sum += *y;
- result->points.emplace_back(x, static_cast<float>(sum));
- }
- }
-}
-
// For each pair of adjacent elements in |data|, use |f()| to extract a
// y-coordinate and store the result in a TimeSeries. Note that the x-coordinate
// will be the time of the second element in the pair.
template <typename DataType, typename ResultType, typename IterableType>
void AccumulatePairs(
+ rtc::FunctionView<float(const DataType&)> fx,
rtc::FunctionView<rtc::Optional<ResultType>(const DataType&,
- const DataType&)> f,
+ const DataType&)> fy,
const IterableType& data,
- int64_t begin_time,
TimeSeries* result) {
ResultType sum = 0;
for (size_t i = 1; i < data.size(); i++) {
- float x = static_cast<float>(data[i].log_time_us() - begin_time) /
- kNumMicrosecsPerSec;
- rtc::Optional<ResultType> y = f(data[i - 1], data[i]);
+ float x = fx(data[i]);
+ rtc::Optional<ResultType> y = fy(data[i - 1], data[i]);
if (y)
sum += *y;
result->points.emplace_back(x, static_cast<float>(sum));
@@ -309,7 +286,8 @@
// during the preceeding |window_duration_us| microseconds.
template <typename DataType, typename ResultType, typename IterableType>
void MovingAverage(
- rtc::FunctionView<rtc::Optional<ResultType>(const DataType&)> f,
+ rtc::FunctionView<float(int64_t)> fx,
+ rtc::FunctionView<rtc::Optional<ResultType>(const DataType&)> fy,
const IterableType& data_view,
int64_t begin_time,
int64_t end_time,
@@ -323,7 +301,7 @@
for (int64_t t = begin_time; t < end_time + step; t += step) {
while (window_index_end < data_view.size() &&
data_view[window_index_end].log_time_us() < t) {
- rtc::Optional<ResultType> value = f(data_view[window_index_end]);
+ rtc::Optional<ResultType> value = fy(data_view[window_index_end]);
if (value)
sum_in_window += *value;
++window_index_end;
@@ -331,14 +309,14 @@
while (window_index_begin < data_view.size() &&
data_view[window_index_begin].log_time_us() <
t - window_duration_us) {
- rtc::Optional<ResultType> value = f(data_view[window_index_begin]);
+ rtc::Optional<ResultType> value = fy(data_view[window_index_begin]);
if (value)
sum_in_window -= *value;
++window_index_begin;
}
float window_duration_s =
static_cast<float>(window_duration_us) / kNumMicrosecsPerSec;
- float x = static_cast<float>(t - begin_time) / kNumMicrosecsPerSec;
+ float x = fx(t);
float y = sum_in_window / window_duration_s;
result->points.emplace_back(x, y);
}
@@ -466,15 +444,19 @@
} // namespace
-EventLogAnalyzer::EventLogAnalyzer(const ParsedRtcEventLogNew& log)
- : parsed_log_(log), window_duration_(250000), step_(10000) {
+EventLogAnalyzer::EventLogAnalyzer(const ParsedRtcEventLogNew& log,
+ bool normalize_time)
+ : parsed_log_(log),
+ window_duration_(250000),
+ step_(10000),
+ normalize_time_(normalize_time) {
begin_time_ = parsed_log_.first_timestamp();
end_time_ = parsed_log_.last_timestamp();
if (end_time_ < begin_time_) {
RTC_LOG(LS_WARNING) << "No useful events in the log.";
begin_time_ = end_time_ = 0;
}
- call_duration_s_ = ToCallTime(end_time_);
+ call_duration_s_ = ToCallTimeSec(end_time_);
const auto& log_start_events = parsed_log_.start_log_events();
const auto& log_end_events = parsed_log_.stop_log_events();
@@ -532,8 +514,16 @@
bool bitrate_updated_;
};
-float EventLogAnalyzer::ToCallTime(int64_t timestamp) const {
- return static_cast<float>(timestamp - begin_time_) / kNumMicrosecsPerSec;
+int64_t EventLogAnalyzer::ToCallTimeUs(int64_t timestamp) const {
+ int64_t begin_time = 0;
+ if (normalize_time_) {
+ begin_time = begin_time_;
+ }
+ return timestamp - begin_time;
+}
+
+float EventLogAnalyzer::ToCallTimeSec(int64_t timestamp) const {
+ return static_cast<float>(ToCallTimeUs(timestamp)) / kNumMicrosecsPerSec;
}
void EventLogAnalyzer::CreatePacketGraph(PacketDirection direction,
@@ -549,12 +539,16 @@
auto GetPacketSize = [](const LoggedRtpPacket& packet) {
return rtc::Optional<float>(packet.total_length);
};
- ProcessPoints<LoggedRtpPacket>(GetPacketSize, stream.packet_view,
- begin_time_, &time_series);
+ auto ToCallTime = [this](const LoggedRtpPacket& packet) {
+ return this->ToCallTimeSec(packet.log_time_us());
+ };
+ ProcessPoints<LoggedRtpPacket>(ToCallTime, GetPacketSize,
+ stream.packet_view, &time_series);
plot->AppendTimeSeries(std::move(time_series));
}
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 1, "Packet size (bytes)", kBottomMargin,
kTopMargin);
plot->SetTitle(GetDirectionAsString(direction) + " RTP packets");
@@ -567,7 +561,7 @@
const std::string& label) {
TimeSeries time_series(label, LineStyle::kStep);
for (size_t i = 0; i < packets.size(); i++) {
- float x = ToCallTime(packets[i].log_time_us());
+ float x = ToCallTimeSec(packets[i].log_time_us());
time_series.points.emplace_back(x, i + 1);
}
plot->AppendTimeSeries(std::move(time_series));
@@ -592,7 +586,8 @@
plot, parsed_log_.outgoing_rtcp_packets(), label);
}
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 1, "Received Packets", kBottomMargin, kTopMargin);
plot->SetTitle(std::string("Accumulated ") + GetDirectionAsString(direction) +
" RTP/RTCP packets");
@@ -607,7 +602,7 @@
rtc::Optional<int64_t> last_playout_ms;
TimeSeries time_series(SsrcToString(ssrc), LineStyle::kBar);
for (const auto& playout_event : playout_stream.second) {
- float x = ToCallTime(playout_event.log_time_us());
+ float x = ToCallTimeSec(playout_event.log_time_us());
int64_t playout_time_ms = playout_event.log_time_ms();
// If there were no previous playouts, place the point on the x-axis.
float y = playout_time_ms - last_playout_ms.value_or(playout_time_ms);
@@ -617,7 +612,8 @@
plot->AppendTimeSeries(std::move(time_series));
}
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 1, "Time since last playout (ms)", kBottomMargin,
kTopMargin);
plot->SetTitle("Audio playout");
@@ -633,7 +629,7 @@
LineStyle::kLine);
for (auto& packet : stream.packet_view) {
if (packet.header.extension.hasAudioLevel) {
- float x = ToCallTime(packet.log_time_us());
+ float x = ToCallTimeSec(packet.log_time_us());
// The audio level is stored in -dBov (so e.g. -10 dBov is stored as 10)
// Here we convert it to dBov.
float y = static_cast<float>(-packet.header.extension.audioLevel);
@@ -643,7 +639,8 @@
plot->AppendTimeSeries(std::move(time_series));
}
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetYAxis(-127, 0, "Audio level (dBov)", kBottomMargin,
kTopMargin);
plot->SetTitle(GetDirectionAsString(direction) + " audio level");
@@ -666,13 +663,17 @@
old_packet.rtp.header.sequenceNumber, 1ul << 16);
return diff;
};
- ProcessPairs<LoggedRtpPacketIncoming, float>(GetSequenceNumberDiff,
- stream.incoming_packets,
- begin_time_, &time_series);
+ auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) {
+ return this->ToCallTimeSec(packet.log_time_us());
+ };
+ ProcessPairs<LoggedRtpPacketIncoming, float>(
+ ToCallTime, GetSequenceNumberDiff, stream.incoming_packets,
+ &time_series);
plot->AppendTimeSeries(std::move(time_series));
}
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 1, "Difference since last packet", kBottomMargin,
kTopMargin);
plot->SetTitle("Sequence number");
@@ -718,7 +719,7 @@
std::max(highest_prior_seq_number, sequence_number);
++window_index_begin;
}
- float x = ToCallTime(t);
+ float x = ToCallTimeSec(t);
uint64_t expected_packets = highest_seq_number - highest_prior_seq_number;
if (expected_packets > 0) {
int64_t received_packets = window_index_end - window_index_begin;
@@ -730,7 +731,8 @@
plot->AppendTimeSeries(std::move(time_series));
}
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 1, "Estimated loss rate (%)", kBottomMargin,
kTopMargin);
plot->SetTitle("Estimated incoming loss rate");
@@ -749,21 +751,25 @@
TimeSeries capture_time_data(
GetStreamName(kIncomingPacket, stream.ssrc) + " capture-time",
LineStyle::kBar);
- ProcessPairs<LoggedRtpPacket, double>(NetworkDelayDiff_CaptureTime,
- stream.packet_view, begin_time_,
- &capture_time_data);
+ auto ToCallTime = [this](const LoggedRtpPacket& packet) {
+ return this->ToCallTimeSec(packet.log_time_us());
+ };
+ ProcessPairs<LoggedRtpPacket, double>(
+ ToCallTime, NetworkDelayDiff_CaptureTime, stream.packet_view,
+ &capture_time_data);
plot->AppendTimeSeries(std::move(capture_time_data));
TimeSeries send_time_data(
GetStreamName(kIncomingPacket, stream.ssrc) + " abs-send-time",
LineStyle::kBar);
- ProcessPairs<LoggedRtpPacket, double>(NetworkDelayDiff_AbsSendTime,
- stream.packet_view, begin_time_,
- &send_time_data);
+ ProcessPairs<LoggedRtpPacket, double>(ToCallTime,
+ NetworkDelayDiff_AbsSendTime,
+ stream.packet_view, &send_time_data);
plot->AppendTimeSeries(std::move(send_time_data));
}
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 1, "Latency change (ms)", kBottomMargin,
kTopMargin);
plot->SetTitle("Network latency difference between consecutive packets");
@@ -782,21 +788,25 @@
TimeSeries capture_time_data(
GetStreamName(kIncomingPacket, stream.ssrc) + " capture-time",
LineStyle::kLine);
- AccumulatePairs<LoggedRtpPacket, double>(NetworkDelayDiff_CaptureTime,
- stream.packet_view, begin_time_,
- &capture_time_data);
+ auto ToCallTime = [this](const LoggedRtpPacket& packet) {
+ return this->ToCallTimeSec(packet.log_time_us());
+ };
+ AccumulatePairs<LoggedRtpPacket, double>(
+ ToCallTime, NetworkDelayDiff_CaptureTime, stream.packet_view,
+ &capture_time_data);
plot->AppendTimeSeries(std::move(capture_time_data));
TimeSeries send_time_data(
GetStreamName(kIncomingPacket, stream.ssrc) + " abs-send-time",
LineStyle::kLine);
- AccumulatePairs<LoggedRtpPacket, double>(NetworkDelayDiff_AbsSendTime,
- stream.packet_view, begin_time_,
- &send_time_data);
+ AccumulatePairs<LoggedRtpPacket, double>(
+ ToCallTime, NetworkDelayDiff_AbsSendTime, stream.packet_view,
+ &send_time_data);
plot->AppendTimeSeries(std::move(send_time_data));
}
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 1, "Latency change (ms)", kBottomMargin,
kTopMargin);
plot->SetTitle("Network latency (relative to first packet)");
@@ -807,13 +817,14 @@
TimeSeries time_series("Fraction lost", LineStyle::kLine,
PointStyle::kHighlight);
for (auto& bwe_update : parsed_log_.bwe_loss_updates()) {
- float x = ToCallTime(bwe_update.log_time_us());
+ float x = ToCallTimeSec(bwe_update.log_time_us());
float y = static_cast<float>(bwe_update.fraction_lost) / 255 * 100;
time_series.points.emplace_back(x, y);
}
plot->AppendTimeSeries(std::move(time_series));
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 10, "Percent lost packets", kBottomMargin,
kTopMargin);
plot->SetTitle("Reported packet loss");
@@ -848,7 +859,7 @@
}
float window_duration_in_seconds =
static_cast<float>(window_duration_) / kNumMicrosecsPerSec;
- float x = ToCallTime(time);
+ float x = ToCallTimeSec(time);
float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
bitrate_series.points.emplace_back(x, y);
}
@@ -857,13 +868,14 @@
// Overlay the outgoing REMB over incoming bitrate.
TimeSeries remb_series("Remb", LineStyle::kStep);
for (const auto& rtcp : parsed_log_.rembs(kOutgoingPacket)) {
- float x = ToCallTime(rtcp.log_time_us());
+ float x = ToCallTimeSec(rtcp.log_time_us());
float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
remb_series.points.emplace_back(x, y);
}
plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
plot->SetTitle("Incoming RTP bitrate");
}
@@ -899,7 +911,7 @@
}
float window_duration_in_seconds =
static_cast<float>(window_duration_) / kNumMicrosecsPerSec;
- float x = ToCallTime(time);
+ float x = ToCallTimeSec(time);
float y = bytes_in_window * 8 / window_duration_in_seconds / 1000;
bitrate_series.points.emplace_back(x, y);
}
@@ -908,7 +920,7 @@
// Overlay the send-side bandwidth estimate over the outgoing bitrate.
TimeSeries loss_series("Loss-based estimate", LineStyle::kStep);
for (auto& loss_update : parsed_log_.bwe_loss_updates()) {
- float x = ToCallTime(loss_update.log_time_us());
+ float x = ToCallTimeSec(loss_update.log_time_us());
float y = static_cast<float>(loss_update.bitrate_bps) / 1000;
loss_series.points.emplace_back(x, y);
}
@@ -926,7 +938,7 @@
BandwidthUsage last_detector_state = BandwidthUsage::kBwNormal;
for (auto& delay_update : parsed_log_.bwe_delay_updates()) {
- float x = ToCallTime(delay_update.log_time_us());
+ float x = ToCallTimeSec(delay_update.log_time_us());
float y = static_cast<float>(delay_update.bitrate_bps) / 1000;
if (last_detector_state != delay_update.detector_state) {
@@ -958,7 +970,7 @@
TimeSeries created_series("Probe cluster created.", LineStyle::kNone,
PointStyle::kHighlight);
for (auto& cluster : parsed_log_.bwe_probe_cluster_created_events()) {
- float x = ToCallTime(cluster.log_time_us());
+ float x = ToCallTimeSec(cluster.log_time_us());
float y = static_cast<float>(cluster.bitrate_bps) / 1000;
created_series.points.emplace_back(x, y);
}
@@ -967,7 +979,7 @@
PointStyle::kHighlight);
for (auto& result : parsed_log_.bwe_probe_result_events()) {
if (result.bitrate_bps) {
- float x = ToCallTime(result.log_time_us());
+ float x = ToCallTimeSec(result.log_time_us());
float y = static_cast<float>(*result.bitrate_bps) / 1000;
result_series.points.emplace_back(x, y);
}
@@ -977,20 +989,20 @@
bool previously_in_alr = false;
int64_t alr_start = 0;
for (auto& alr : parsed_log_.alr_state_events()) {
- float y = ToCallTime(alr.log_time_us());
+ float y = ToCallTimeSec(alr.log_time_us());
if (!previously_in_alr && alr.in_alr) {
alr_start = alr.log_time_us();
previously_in_alr = true;
} else if (previously_in_alr && !alr.in_alr) {
- float x = ToCallTime(alr_start);
+ float x = ToCallTimeSec(alr_start);
alr_state.intervals.emplace_back(x, y);
previously_in_alr = false;
}
}
if (previously_in_alr) {
- float x = ToCallTime(alr_start);
- float y = ToCallTime(end_time_);
+ float x = ToCallTimeSec(alr_start);
+ float y = ToCallTimeSec(end_time_);
alr_state.intervals.emplace_back(x, y);
}
@@ -1011,13 +1023,14 @@
// Overlay the incoming REMB over the outgoing bitrate.
TimeSeries remb_series("Remb", LineStyle::kStep);
for (const auto& rtcp : parsed_log_.rembs(kIncomingPacket)) {
- float x = ToCallTime(rtcp.log_time_us());
+ float x = ToCallTimeSec(rtcp.log_time_us());
float y = static_cast<float>(rtcp.remb.bitrate_bps()) / 1000;
remb_series.points.emplace_back(x, y);
}
plot->AppendTimeSeriesIfNotEmpty(std::move(remb_series));
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
plot->SetTitle("Outgoing RTP bitrate");
}
@@ -1036,13 +1049,17 @@
auto GetPacketSizeKilobits = [](const LoggedRtpPacket& packet) {
return packet.total_length * 8.0 / 1000.0;
};
+ auto ToCallTime = [this](int64_t time) {
+ return this->ToCallTimeSec(time);
+ };
MovingAverage<LoggedRtpPacket, double>(
- GetPacketSizeKilobits, stream.packet_view, begin_time_, end_time_,
- window_duration_, step_, &time_series);
+ ToCallTime, GetPacketSizeKilobits, stream.packet_view, begin_time_,
+ end_time_, window_duration_, step_, &time_series);
plot->AppendTimeSeries(std::move(time_series));
}
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 1, "Bitrate (kbps)", kBottomMargin, kTopMargin);
plot->SetTitle(GetDirectionAsString(direction) + " bitrate per stream");
}
@@ -1133,7 +1150,7 @@
acked_bitrate.Update(packet.payload_size, packet.arrival_time_ms);
bitrate_bps = acked_bitrate.Rate(feedback.back().arrival_time_ms);
}
- float x = ToCallTime(clock.TimeInMicroseconds());
+ float x = ToCallTimeSec(clock.TimeInMicroseconds());
float y = bitrate_bps.value_or(0) / 1000;
acked_time_series.points.emplace_back(x, y);
#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
@@ -1164,7 +1181,7 @@
if (observer.GetAndResetBitrateUpdated() ||
time_us - last_update_us >= 1e6) {
uint32_t y = observer.last_bitrate_bps() / 1000;
- float x = ToCallTime(clock.TimeInMicroseconds());
+ float x = ToCallTimeSec(clock.TimeInMicroseconds());
time_series.points.emplace_back(x, y);
last_update_us = time_us;
}
@@ -1175,7 +1192,8 @@
plot->AppendTimeSeries(std::move(acked_time_series));
plot->AppendTimeSeriesIfNotEmpty(std::move(acked_estimate_time_series));
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
plot->SetTitle("Simulated send-side BWE behavior");
}
@@ -1238,13 +1256,13 @@
rtc::Optional<uint32_t> bitrate_bps = acked_bitrate.Rate(arrival_time_ms);
if (bitrate_bps) {
uint32_t y = *bitrate_bps / 1000;
- float x = ToCallTime(clock.TimeInMicroseconds());
+ float x = ToCallTimeSec(clock.TimeInMicroseconds());
acked_time_series.points.emplace_back(x, y);
}
if (packet_router.GetAndResetBitrateUpdated() ||
clock.TimeInMicroseconds() - last_update_us >= 1e6) {
uint32_t y = packet_router.last_bitrate_bps() / 1000;
- float x = ToCallTime(clock.TimeInMicroseconds());
+ float x = ToCallTimeSec(clock.TimeInMicroseconds());
time_series.points.emplace_back(x, y);
last_update_us = clock.TimeInMicroseconds();
}
@@ -1253,7 +1271,8 @@
plot->AppendTimeSeries(std::move(time_series));
plot->AppendTimeSeries(std::move(acked_time_series));
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 10, "Bitrate (kbps)", kBottomMargin, kTopMargin);
plot->SetTitle("Simulated receive-side BWE behavior");
}
@@ -1308,7 +1327,7 @@
feedback_adapter.GetTransportFeedbackVector();
SortPacketFeedbackVector(&feedback);
for (const PacketFeedback& packet : feedback) {
- float x = ToCallTime(clock.TimeInMicroseconds());
+ float x = ToCallTimeSec(clock.TimeInMicroseconds());
if (packet.send_time_ms == PacketFeedback::kNoSendTime) {
late_feedback_series.points.emplace_back(x, prev_y);
continue;
@@ -1346,7 +1365,8 @@
plot->AppendTimeSeriesIfNotEmpty(std::move(time_series));
plot->AppendTimeSeriesIfNotEmpty(std::move(late_feedback_series));
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 10, "Delay (ms)", kBottomMargin, kTopMargin);
plot->SetTitle("Network Delay Change.");
}
@@ -1393,14 +1413,15 @@
double send_time_ms =
static_cast<double>(packet.rtp.log_time_us() - first_send_timestamp) /
1000;
- float x = ToCallTime(packet.rtp.log_time_us());
+ float x = ToCallTimeSec(packet.rtp.log_time_us());
float y = send_time_ms - capture_time_ms;
pacer_delay_series.points.emplace_back(x, y);
}
plot->AppendTimeSeries(std::move(pacer_delay_series));
}
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 10, "Pacer delay (ms)", kBottomMargin, kTopMargin);
plot->SetTitle(
"Delay from capture to send time. (First packet normalized to 0.)");
@@ -1413,7 +1434,7 @@
GetStreamName(direction, stream.ssrc) + " capture-time",
LineStyle::kLine, PointStyle::kHighlight);
for (const auto& packet : stream.packet_view) {
- float x = ToCallTime(packet.log_time_us());
+ float x = ToCallTimeSec(packet.log_time_us());
float y = packet.header.timestamp;
rtp_timestamps.points.emplace_back(x, y);
}
@@ -1427,14 +1448,15 @@
for (const auto& rtcp : sender_reports) {
if (rtcp.sr.sender_ssrc() != stream.ssrc)
continue;
- float x = ToCallTime(rtcp.log_time_us());
+ float x = ToCallTimeSec(rtcp.log_time_us());
float y = rtcp.sr.rtp_timestamp();
rtcp_timestamps.points.emplace_back(x, y);
}
plot->AppendTimeSeriesIfNotEmpty(std::move(rtcp_timestamps));
}
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 1, "RTP timestamp", kBottomMargin, kTopMargin);
plot->SetTitle(GetDirectionAsString(direction) + " timestamps");
}
@@ -1449,11 +1471,15 @@
static_cast<float>(*ana_event.config.bitrate_bps));
return rtc::nullopt;
};
+ auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
+ return this->ToCallTimeSec(packet.log_time_us());
+ };
ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
- GetAnaBitrateBps, parsed_log_.audio_network_adaptation_events(),
- begin_time_, &time_series);
+ ToCallTime, GetAnaBitrateBps,
+ parsed_log_.audio_network_adaptation_events(), &time_series);
plot->AppendTimeSeries(std::move(time_series));
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 1, "Bitrate (bps)", kBottomMargin, kTopMargin);
plot->SetTitle("Reported audio encoder target bitrate");
}
@@ -1468,11 +1494,15 @@
static_cast<float>(*ana_event.config.frame_length_ms));
return rtc::Optional<float>();
};
+ auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
+ return this->ToCallTimeSec(packet.log_time_us());
+ };
ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
- GetAnaFrameLengthMs, parsed_log_.audio_network_adaptation_events(),
- begin_time_, &time_series);
+ ToCallTime, GetAnaFrameLengthMs,
+ parsed_log_.audio_network_adaptation_events(), &time_series);
plot->AppendTimeSeries(std::move(time_series));
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 1, "Frame length (ms)", kBottomMargin, kTopMargin);
plot->SetTitle("Reported audio encoder frame length");
}
@@ -1487,11 +1517,15 @@
*ana_event.config.uplink_packet_loss_fraction));
return rtc::Optional<float>();
};
+ auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
+ return this->ToCallTimeSec(packet.log_time_us());
+ };
ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
- GetAnaPacketLoss, parsed_log_.audio_network_adaptation_events(),
- begin_time_, &time_series);
+ ToCallTime, GetAnaPacketLoss,
+ parsed_log_.audio_network_adaptation_events(), &time_series);
plot->AppendTimeSeries(std::move(time_series));
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 10, "Percent lost packets", kBottomMargin,
kTopMargin);
plot->SetTitle("Reported audio encoder lost packets");
@@ -1507,11 +1541,15 @@
static_cast<float>(*ana_event.config.enable_fec));
return rtc::Optional<float>();
};
+ auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
+ return this->ToCallTimeSec(packet.log_time_us());
+ };
ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
- GetAnaFecEnabled, parsed_log_.audio_network_adaptation_events(),
- begin_time_, &time_series);
+ ToCallTime, GetAnaFecEnabled,
+ parsed_log_.audio_network_adaptation_events(), &time_series);
plot->AppendTimeSeries(std::move(time_series));
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 1, "FEC (false/true)", kBottomMargin, kTopMargin);
plot->SetTitle("Reported audio encoder FEC");
}
@@ -1526,11 +1564,15 @@
static_cast<float>(*ana_event.config.enable_dtx));
return rtc::Optional<float>();
};
+ auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
+ return this->ToCallTimeSec(packet.log_time_us());
+ };
ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
- GetAnaDtxEnabled, parsed_log_.audio_network_adaptation_events(),
- begin_time_, &time_series);
+ ToCallTime, GetAnaDtxEnabled,
+ parsed_log_.audio_network_adaptation_events(), &time_series);
plot->AppendTimeSeries(std::move(time_series));
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 1, "DTX (false/true)", kBottomMargin, kTopMargin);
plot->SetTitle("Reported audio encoder DTX");
}
@@ -1545,11 +1587,15 @@
static_cast<float>(*ana_event.config.num_channels));
return rtc::Optional<float>();
};
+ auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) {
+ return this->ToCallTimeSec(packet.log_time_us());
+ };
ProcessPoints<LoggedAudioNetworkAdaptationEvent>(
- GetAnaNumChannels, parsed_log_.audio_network_adaptation_events(),
- begin_time_, &time_series);
+ ToCallTime, GetAnaNumChannels,
+ parsed_log_.audio_network_adaptation_events(), &time_series);
plot->AppendTimeSeries(std::move(time_series));
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 1, "Number of channels (1 (mono)/2 (stereo))",
kBottomMargin, kTopMargin);
plot->SetTitle("Reported audio encoder number of channels");
@@ -1802,7 +1848,8 @@
plot->AppendTimeSeries(std::move(series.second));
}
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetYAxis(min_y_axis, max_y_axis, "Relative delay (ms)", kBottomMargin,
kTopMargin);
plot->SetTitle("NetEq timing for " + GetStreamName(kIncomingPacket, ssrc));
@@ -1825,7 +1872,7 @@
const auto& stats = st.second->stats();
for (size_t i = 0; i < stats.size(); ++i) {
- const float time = ToCallTime(stats[i].first * 1000); // ms to us.
+ const float time = ToCallTimeSec(stats[i].first * 1000); // ms to us.
const float value = stats_extractor(stats[i].second);
time_series[ssrc].points.emplace_back(TimeSeriesPoint(time, value));
min_y_axis = std::min(min_y_axis, value);
@@ -1839,7 +1886,8 @@
plot->AppendTimeSeries(std::move(series.second));
}
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetYAxis(min_y_axis, max_y_axis, plot_name, kBottomMargin, kTopMargin);
plot->SetTitle(plot_name);
}
@@ -1858,7 +1906,7 @@
candidate_pair_desc_by_id_[config.candidate_pair_id] =
candidate_pair_desc;
}
- float x = ToCallTime(config.log_time_us());
+ float x = ToCallTimeSec(config.log_time_us());
float y = static_cast<float>(config.type);
configs_by_cp_id[config.candidate_pair_id].points.emplace_back(x, y);
}
@@ -1870,7 +1918,8 @@
plot->AppendTimeSeries(std::move(kv.second));
}
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 3, "Numeric Config Type", kBottomMargin,
kTopMargin);
plot->SetTitle("[IceEventLog] ICE candidate pair configs");
@@ -1906,7 +1955,7 @@
GetCandidatePairLogDescriptionFromId(event.candidate_pair_id),
LineStyle::kNone, PointStyle::kHighlight);
}
- float x = ToCallTime(event.log_time_us());
+ float x = ToCallTimeSec(event.log_time_us());
float y = static_cast<float>(event.type);
checks_by_cp_id[event.candidate_pair_id].points.emplace_back(x, y);
}
@@ -1916,7 +1965,8 @@
plot->AppendTimeSeries(std::move(kv.second));
}
- plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+ plot->SetXAxis(ToCallTimeSec(begin_time_), call_duration_s_, "Time (s)",
+ kLeftMargin, kRightMargin);
plot->SetSuggestedYAxis(0, 4, "Numeric Connectivity State", kBottomMargin,
kTopMargin);
plot->SetTitle("[IceEventLog] ICE connectivity checks");
@@ -1980,7 +2030,7 @@
int64_t seq_num = seq_num_unwrapper.Unwrap(packet.header.sequenceNumber);
if (last_seq_num.has_value() &&
std::abs(seq_num - last_seq_num.value()) > kMaxSeqNumJump) {
- Alert_SeqNumJump(direction, ToCallTime(packet.log_time_us()),
+ Alert_SeqNumJump(direction, ToCallTimeSec(packet.log_time_us()),
packet.header.ssrc);
}
last_seq_num.emplace(seq_num);
@@ -1990,7 +2040,7 @@
if (last_capture_time.has_value() &&
std::abs(capture_time - last_capture_time.value()) >
kMaxCaptureTimeJump) {
- Alert_CaptureTimeJump(direction, ToCallTime(packet.log_time_us()),
+ Alert_CaptureTimeJump(direction, ToCallTimeSec(packet.log_time_us()),
packet.header.ssrc);
}
last_capture_time.emplace(capture_time);
@@ -2022,7 +2072,7 @@
int64_t duration = timestamp - last_rtp_time.value_or(0);
if (last_rtp_time.has_value() && duration > kMaxRtpTransmissionGap) {
// No packet sent/received for more than 500 ms.
- Alert_RtpLogTimeGap(direction, ToCallTime(timestamp), duration / 1000);
+ Alert_RtpLogTimeGap(direction, ToCallTimeSec(timestamp), duration / 1000);
}
last_rtp_time.emplace(timestamp);
}
@@ -2037,7 +2087,7 @@
int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
// No feedback sent/received for more than 2000 ms.
- Alert_RtcpLogTimeGap(direction, ToCallTime(rtcp.log_time_us()),
+ Alert_RtcpLogTimeGap(direction, ToCallTimeSec(rtcp.log_time_us()),
duration / 1000);
}
last_rtcp_time.emplace(rtcp.log_time_us());
@@ -2051,7 +2101,7 @@
int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
// No feedback sent/received for more than 2000 ms.
- Alert_RtcpLogTimeGap(direction, ToCallTime(rtcp.log_time_us()),
+ Alert_RtcpLogTimeGap(direction, ToCallTimeSec(rtcp.log_time_us()),
duration / 1000);
}
last_rtcp_time.emplace(rtcp.log_time_us());
diff --git a/rtc_tools/event_log_visualizer/analyzer.h b/rtc_tools/event_log_visualizer/analyzer.h
index 51ae015..d4a7fc3 100644
--- a/rtc_tools/event_log_visualizer/analyzer.h
+++ b/rtc_tools/event_log_visualizer/analyzer.h
@@ -31,7 +31,7 @@
// The EventLogAnalyzer keeps a reference to the ParsedRtcEventLogNew for the
// duration of its lifetime. The ParsedRtcEventLogNew must not be destroyed or
// modified while the EventLogAnalyzer is being used.
- explicit EventLogAnalyzer(const ParsedRtcEventLogNew& log);
+ EventLogAnalyzer(const ParsedRtcEventLogNew& log, bool normalize_time);
void CreatePacketGraph(PacketDirection direction, Plot* plot);
@@ -151,7 +151,8 @@
return name.str();
}
- float ToCallTime(int64_t timestamp) const;
+ int64_t ToCallTimeUs(int64_t timestamp) const;
+ float ToCallTimeSec(int64_t timestamp) const;
void Alert_RtpLogTimeGap(PacketDirection direction,
float time_seconds,
@@ -231,6 +232,7 @@
// First and last events of the log.
int64_t begin_time_;
int64_t end_time_;
+ const bool normalize_time_;
// Duration (in seconds) of log file.
float call_duration_s_;
diff --git a/rtc_tools/event_log_visualizer/main.cc b/rtc_tools/event_log_visualizer/main.cc
index 221b040..802633c 100644
--- a/rtc_tools/event_log_visualizer/main.cc
+++ b/rtc_tools/event_log_visualizer/main.cc
@@ -151,6 +151,10 @@
false,
"Print triage alerts, i.e. a list of potential problems.");
+DEFINE_bool(normalize_time,
+ true,
+ "Normalize the log timestamps so that the call starts at time 0.");
+
void SetAllPlotFlags(bool setting);
@@ -227,7 +231,7 @@
<< std::endl;
}
- webrtc::EventLogAnalyzer analyzer(parsed_log);
+ webrtc::EventLogAnalyzer analyzer(parsed_log, FLAG_normalize_time);
std::unique_ptr<webrtc::PlotCollection> collection(
new webrtc::PythonPlotCollection());
diff --git a/rtc_tools/event_log_visualizer/plot_base.cc b/rtc_tools/event_log_visualizer/plot_base.cc
index 9a21393..0847cfe 100644
--- a/rtc_tools/event_log_visualizer/plot_base.cc
+++ b/rtc_tools/event_log_visualizer/plot_base.cc
@@ -11,6 +11,7 @@
#include "rtc_tools/event_log_visualizer/plot_base.h"
#include <algorithm>
+#include <limits>
#include "rtc_base/checks.h"
diff --git a/rtc_tools/event_log_visualizer/plot_python.cc b/rtc_tools/event_log_visualizer/plot_python.cc
index 37c4d84..3808e87 100644
--- a/rtc_tools/event_log_visualizer/plot_python.cc
+++ b/rtc_tools/event_log_visualizer/plot_python.cc
@@ -38,9 +38,9 @@
// List x coordinates
printf("x%zu = [", i);
if (series_list_[i].points.size() > 0)
- printf("%G", series_list_[i].points[0].x);
+ printf("%.3f", series_list_[i].points[0].x);
for (size_t j = 1; j < series_list_[i].points.size(); j++)
- printf(", %G", series_list_[i].points[j].x);
+ printf(", %.3f", series_list_[i].points[j].x);
printf("]\n");
// List y coordinates