diff --git a/rtc_tools/event_log_visualizer/analyzer.cc b/rtc_tools/event_log_visualizer/analyzer.cc index 76ac88a4a0..71707a9d06 100644 --- a/rtc_tools/event_log_visualizer/analyzer.cc +++ b/rtc_tools/event_log_visualizer/analyzer.cc @@ -229,15 +229,14 @@ rtc::Optional NetworkDelayDiff_CaptureTime( // For each element in data_view, use |f()| to extract a y-coordinate and // store the result in a TimeSeries. template -void ProcessPoints(rtc::FunctionView(const DataType&)> f, +void ProcessPoints(rtc::FunctionView fx, + rtc::FunctionView(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(elem.log_time_us() - begin_time) / - kNumMicrosecsPerSec; - rtc::Optional y = f(elem); + float x = fx(elem); + rtc::Optional y = fy(elem); if (y) result->points.emplace_back(x, *y); } @@ -248,55 +247,33 @@ void ProcessPoints(rtc::FunctionView(const DataType&)> f, // will be the time of the second element in the pair. template void ProcessPairs( + rtc::FunctionView fx, rtc::FunctionView(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(data[i].log_time_us() - begin_time) / - kNumMicrosecsPerSec; - rtc::Optional y = f(data[i - 1], data[i]); + float x = fx(data[i]); + rtc::Optional y = fy(data[i - 1], data[i]); if (y) result->points.emplace_back(x, static_cast(*y)); } } -// For each element in data, use |f()| to extract a y-coordinate and -// store the result in a TimeSeries. -template -void AccumulatePoints( - rtc::FunctionView(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(data[i].log_time_us() - begin_time) / - kNumMicrosecsPerSec; - rtc::Optional y = f(data[i]); - if (y) { - sum += *y; - result->points.emplace_back(x, static_cast(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 void AccumulatePairs( + rtc::FunctionView fx, rtc::FunctionView(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(data[i].log_time_us() - begin_time) / - kNumMicrosecsPerSec; - rtc::Optional y = f(data[i - 1], data[i]); + float x = fx(data[i]); + rtc::Optional y = fy(data[i - 1], data[i]); if (y) sum += *y; result->points.emplace_back(x, static_cast(sum)); @@ -309,7 +286,8 @@ void AccumulatePairs( // during the preceeding |window_duration_us| microseconds. template void MovingAverage( - rtc::FunctionView(const DataType&)> f, + rtc::FunctionView fx, + rtc::FunctionView(const DataType&)> fy, const IterableType& data_view, int64_t begin_time, int64_t end_time, @@ -323,7 +301,7 @@ void MovingAverage( 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 value = f(data_view[window_index_end]); + rtc::Optional value = fy(data_view[window_index_end]); if (value) sum_in_window += *value; ++window_index_end; @@ -331,14 +309,14 @@ void MovingAverage( while (window_index_begin < data_view.size() && data_view[window_index_begin].log_time_us() < t - window_duration_us) { - rtc::Optional value = f(data_view[window_index_begin]); + rtc::Optional value = fy(data_view[window_index_begin]); if (value) sum_in_window -= *value; ++window_index_begin; } float window_duration_s = static_cast(window_duration_us) / kNumMicrosecsPerSec; - float x = static_cast(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 @@ std::string GetDirectionAsShortString(PacketDirection direction) { } // 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 @@ class BitrateObserver : public NetworkChangedObserver, bool bitrate_updated_; }; -float EventLogAnalyzer::ToCallTime(int64_t timestamp) const { - return static_cast(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(ToCallTimeUs(timestamp)) / kNumMicrosecsPerSec; } void EventLogAnalyzer::CreatePacketGraph(PacketDirection direction, @@ -549,12 +539,16 @@ void EventLogAnalyzer::CreatePacketGraph(PacketDirection direction, auto GetPacketSize = [](const LoggedRtpPacket& packet) { return rtc::Optional(packet.total_length); }; - ProcessPoints(GetPacketSize, stream.packet_view, - begin_time_, &time_series); + auto ToCallTime = [this](const LoggedRtpPacket& packet) { + return this->ToCallTimeSec(packet.log_time_us()); + }; + ProcessPoints(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 @@ void EventLogAnalyzer::CreateAccumulatedPacketsTimeSeries( 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 @@ void EventLogAnalyzer::CreateAccumulatedPacketsGraph(PacketDirection direction, 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 @@ void EventLogAnalyzer::CreatePlayoutGraph(Plot* plot) { rtc::Optional 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 @@ void EventLogAnalyzer::CreatePlayoutGraph(Plot* plot) { 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 @@ void EventLogAnalyzer::CreateAudioLevelGraph(PacketDirection direction, 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(-packet.header.extension.audioLevel); @@ -643,7 +639,8 @@ void EventLogAnalyzer::CreateAudioLevelGraph(PacketDirection direction, 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 @@ void EventLogAnalyzer::CreateSequenceNumberGraph(Plot* plot) { old_packet.rtp.header.sequenceNumber, 1ul << 16); return diff; }; - ProcessPairs(GetSequenceNumberDiff, - stream.incoming_packets, - begin_time_, &time_series); + auto ToCallTime = [this](const LoggedRtpPacketIncoming& packet) { + return this->ToCallTimeSec(packet.log_time_us()); + }; + ProcessPairs( + 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 @@ void EventLogAnalyzer::CreateIncomingPacketLossGraph(Plot* plot) { 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 @@ void EventLogAnalyzer::CreateIncomingPacketLossGraph(Plot* plot) { 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 @@ void EventLogAnalyzer::CreateIncomingDelayDeltaGraph(Plot* plot) { TimeSeries capture_time_data( GetStreamName(kIncomingPacket, stream.ssrc) + " capture-time", LineStyle::kBar); - ProcessPairs(NetworkDelayDiff_CaptureTime, - stream.packet_view, begin_time_, - &capture_time_data); + auto ToCallTime = [this](const LoggedRtpPacket& packet) { + return this->ToCallTimeSec(packet.log_time_us()); + }; + ProcessPairs( + 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(NetworkDelayDiff_AbsSendTime, - stream.packet_view, begin_time_, - &send_time_data); + ProcessPairs(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 @@ void EventLogAnalyzer::CreateIncomingDelayGraph(Plot* plot) { TimeSeries capture_time_data( GetStreamName(kIncomingPacket, stream.ssrc) + " capture-time", LineStyle::kLine); - AccumulatePairs(NetworkDelayDiff_CaptureTime, - stream.packet_view, begin_time_, - &capture_time_data); + auto ToCallTime = [this](const LoggedRtpPacket& packet) { + return this->ToCallTimeSec(packet.log_time_us()); + }; + AccumulatePairs( + 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(NetworkDelayDiff_AbsSendTime, - stream.packet_view, begin_time_, - &send_time_data); + AccumulatePairs( + 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 @@ void EventLogAnalyzer::CreateFractionLossGraph(Plot* plot) { 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(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 @@ void EventLogAnalyzer::CreateTotalIncomingBitrateGraph(Plot* plot) { } float window_duration_in_seconds = static_cast(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 @@ void EventLogAnalyzer::CreateTotalIncomingBitrateGraph(Plot* plot) { // 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(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 @@ void EventLogAnalyzer::CreateTotalOutgoingBitrateGraph(Plot* plot, } float window_duration_in_seconds = static_cast(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 @@ void EventLogAnalyzer::CreateTotalOutgoingBitrateGraph(Plot* plot, // 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(loss_update.bitrate_bps) / 1000; loss_series.points.emplace_back(x, y); } @@ -926,7 +938,7 @@ void EventLogAnalyzer::CreateTotalOutgoingBitrateGraph(Plot* plot, 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(delay_update.bitrate_bps) / 1000; if (last_detector_state != delay_update.detector_state) { @@ -958,7 +970,7 @@ void EventLogAnalyzer::CreateTotalOutgoingBitrateGraph(Plot* plot, 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(cluster.bitrate_bps) / 1000; created_series.points.emplace_back(x, y); } @@ -967,7 +979,7 @@ void EventLogAnalyzer::CreateTotalOutgoingBitrateGraph(Plot* plot, 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(*result.bitrate_bps) / 1000; result_series.points.emplace_back(x, y); } @@ -977,20 +989,20 @@ void EventLogAnalyzer::CreateTotalOutgoingBitrateGraph(Plot* plot, 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 @@ void EventLogAnalyzer::CreateTotalOutgoingBitrateGraph(Plot* plot, // 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(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 @@ void EventLogAnalyzer::CreateStreamBitrateGraph(PacketDirection direction, auto GetPacketSizeKilobits = [](const LoggedRtpPacket& packet) { return packet.total_length * 8.0 / 1000.0; }; + auto ToCallTime = [this](int64_t time) { + return this->ToCallTimeSec(time); + }; MovingAverage( - 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 @@ void EventLogAnalyzer::CreateSendSideBweSimulationGraph(Plot* plot) { 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 @@ void EventLogAnalyzer::CreateSendSideBweSimulationGraph(Plot* plot) { 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 @@ void EventLogAnalyzer::CreateSendSideBweSimulationGraph(Plot* plot) { 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 @@ void EventLogAnalyzer::CreateReceiveSideBweSimulationGraph(Plot* plot) { rtc::Optional 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 @@ void EventLogAnalyzer::CreateReceiveSideBweSimulationGraph(Plot* plot) { 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 @@ void EventLogAnalyzer::CreateNetworkDelayFeedbackGraph(Plot* plot) { 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 @@ void EventLogAnalyzer::CreateNetworkDelayFeedbackGraph(Plot* plot) { 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 @@ void EventLogAnalyzer::CreatePacerDelayGraph(Plot* plot) { double send_time_ms = static_cast(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 @@ void EventLogAnalyzer::CreateTimestampGraph(PacketDirection direction, 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 @@ void EventLogAnalyzer::CreateTimestampGraph(PacketDirection direction, 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 @@ void EventLogAnalyzer::CreateAudioEncoderTargetBitrateGraph(Plot* plot) { static_cast(*ana_event.config.bitrate_bps)); return rtc::nullopt; }; + auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) { + return this->ToCallTimeSec(packet.log_time_us()); + }; ProcessPoints( - 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 @@ void EventLogAnalyzer::CreateAudioEncoderFrameLengthGraph(Plot* plot) { static_cast(*ana_event.config.frame_length_ms)); return rtc::Optional(); }; + auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) { + return this->ToCallTimeSec(packet.log_time_us()); + }; ProcessPoints( - 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 @@ void EventLogAnalyzer::CreateAudioEncoderPacketLossGraph(Plot* plot) { *ana_event.config.uplink_packet_loss_fraction)); return rtc::Optional(); }; + auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) { + return this->ToCallTimeSec(packet.log_time_us()); + }; ProcessPoints( - 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 @@ void EventLogAnalyzer::CreateAudioEncoderEnableFecGraph(Plot* plot) { static_cast(*ana_event.config.enable_fec)); return rtc::Optional(); }; + auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) { + return this->ToCallTimeSec(packet.log_time_us()); + }; ProcessPoints( - 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 @@ void EventLogAnalyzer::CreateAudioEncoderEnableDtxGraph(Plot* plot) { static_cast(*ana_event.config.enable_dtx)); return rtc::Optional(); }; + auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) { + return this->ToCallTimeSec(packet.log_time_us()); + }; ProcessPoints( - 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 @@ void EventLogAnalyzer::CreateAudioEncoderNumChannelsGraph(Plot* plot) { static_cast(*ana_event.config.num_channels)); return rtc::Optional(); }; + auto ToCallTime = [this](const LoggedAudioNetworkAdaptationEvent& packet) { + return this->ToCallTimeSec(packet.log_time_us()); + }; ProcessPoints( - 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 @@ void EventLogAnalyzer::CreateAudioJitterBufferGraph( 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 @@ void EventLogAnalyzer::CreateNetEqStatsGraph( 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 @@ void EventLogAnalyzer::CreateNetEqStatsGraph( 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 @@ void EventLogAnalyzer::CreateIceCandidatePairConfigGraph(Plot* plot) { 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(config.type); configs_by_cp_id[config.candidate_pair_id].points.emplace_back(x, y); } @@ -1870,7 +1918,8 @@ void EventLogAnalyzer::CreateIceCandidatePairConfigGraph(Plot* plot) { 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 @@ void EventLogAnalyzer::CreateIceConnectivityCheckGraph(Plot* plot) { 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(event.type); checks_by_cp_id[event.candidate_pair_id].points.emplace_back(x, y); } @@ -1916,7 +1965,8 @@ void EventLogAnalyzer::CreateIceConnectivityCheckGraph(Plot* plot) { 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 @@ void EventLogAnalyzer::CreateStreamGapAlerts(PacketDirection direction) { 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 @@ void EventLogAnalyzer::CreateStreamGapAlerts(PacketDirection direction) { 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 @@ void EventLogAnalyzer::CreateTransmissionGapAlerts(PacketDirection direction) { 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 @@ void EventLogAnalyzer::CreateTransmissionGapAlerts(PacketDirection direction) { 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 @@ void EventLogAnalyzer::CreateTransmissionGapAlerts(PacketDirection direction) { 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 51ae015279..d4a7fc3078 100644 --- a/rtc_tools/event_log_visualizer/analyzer.h +++ b/rtc_tools/event_log_visualizer/analyzer.h @@ -31,7 +31,7 @@ class EventLogAnalyzer { // 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 @@ class EventLogAnalyzer { 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 @@ class EventLogAnalyzer { // 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 221b0405c5..802633cad3 100644 --- a/rtc_tools/event_log_visualizer/main.cc +++ b/rtc_tools/event_log_visualizer/main.cc @@ -151,6 +151,10 @@ DEFINE_bool(print_triage_alerts, 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 @@ int main(int argc, char* argv[]) { << std::endl; } - webrtc::EventLogAnalyzer analyzer(parsed_log); + webrtc::EventLogAnalyzer analyzer(parsed_log, FLAG_normalize_time); std::unique_ptr 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 9a21393792..0847cfe390 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 +#include #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 37c4d84b0a..3808e87606 100644 --- a/rtc_tools/event_log_visualizer/plot_python.cc +++ b/rtc_tools/event_log_visualizer/plot_python.cc @@ -38,9 +38,9 @@ void PythonPlot::Draw() { // 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