diff --git a/rtc_tools/BUILD.gn b/rtc_tools/BUILD.gn index b368a0e7d1..ef62b1f276 100644 --- a/rtc_tools/BUILD.gn +++ b/rtc_tools/BUILD.gn @@ -218,6 +218,7 @@ if (!build_with_chromium) { "../modules/audio_coding:ana_debug_dump_proto", "../modules/audio_coding:neteq_tools", "../rtc_base:rtc_base_approved", + "../rtc_base:rtc_numerics", # TODO(kwiberg): Remove this dependency. "../api/audio_codecs:audio_codecs_api", diff --git a/rtc_tools/event_log_visualizer/analyzer.cc b/rtc_tools/event_log_visualizer/analyzer.cc index 7043c68f41..efa9965c30 100644 --- a/rtc_tools/event_log_visualizer/analyzer.cc +++ b/rtc_tools/event_log_visualizer/analyzer.cc @@ -47,6 +47,7 @@ #include "rtc_base/checks.h" #include "rtc_base/format_macros.h" #include "rtc_base/logging.h" +#include "rtc_base/numerics/sequence_number_util.h" #include "rtc_base/ptr_util.h" #include "rtc_base/rate_statistics.h" @@ -596,6 +597,46 @@ std::string EventLogAnalyzer::GetStreamName(StreamId stream_id) const { return name.str(); } +// This is much more reliable for outgoing streams than for incoming streams. +rtc::Optional EventLogAnalyzer::EstimateRtpClockFrequency( + const std::vector& packets) const { + RTC_CHECK(packets.size() >= 2); + uint64_t end_time_us = log_segments_.empty() + ? std::numeric_limits::max() + : log_segments_.front().second; + SeqNumUnwrapper unwrapper; + uint64_t first_rtp_timestamp = unwrapper.Unwrap(packets[0].header.timestamp); + uint64_t first_log_timestamp = packets[0].timestamp; + uint64_t last_rtp_timestamp = first_rtp_timestamp; + uint64_t last_log_timestamp = first_log_timestamp; + for (size_t i = 1; i < packets.size(); i++) { + if (packets[i].timestamp > end_time_us) + break; + last_rtp_timestamp = unwrapper.Unwrap(packets[i].header.timestamp); + last_log_timestamp = packets[i].timestamp; + } + if (last_log_timestamp - first_log_timestamp < 1000000) { + LOG(LS_WARNING) + << "Failed to estimate RTP clock frequency: Stream too short. (" + << packets.size() << " packets, " + << last_log_timestamp - first_log_timestamp << " us)"; + return rtc::Optional(); + } + double duration = + static_cast(last_log_timestamp - first_log_timestamp) / 1000000; + double estimated_frequency = + (last_rtp_timestamp - first_rtp_timestamp) / duration; + for (uint32_t f : {8000, 16000, 32000, 48000, 90000}) { + if (std::fabs(estimated_frequency - f) < 0.05 * f) { + return rtc::Optional(f); + } + } + LOG(LS_WARNING) << "Failed to estimate RTP clock frequency: Estimate " + << estimated_frequency + << "not close to any stardard RTP frequency."; + return rtc::Optional(); +} + void EventLogAnalyzer::CreatePacketGraph(PacketDirection desired_direction, Plot* plot) { for (auto& kv : rtp_packets_) { @@ -1459,6 +1500,55 @@ std::vector> EventLogAnalyzer::GetFrameTimestamps() return timestamps; } +void EventLogAnalyzer::CreatePacerDelayGraph(Plot* plot) { + for (const auto& kv : rtp_packets_) { + const std::vector& packets = kv.second; + StreamId stream_id = kv.first; + + if (packets.size() < 2) { + LOG(LS_WARNING) << "Can't estimate a the RTP clock frequency or the " + "pacer delay with less than 2 packets in the stream"; + continue; + } + rtc::Optional estimated_frequency = + EstimateRtpClockFrequency(packets); + if (!estimated_frequency) + continue; + if (IsVideoSsrc(stream_id) && *estimated_frequency != 90000) { + LOG(LS_WARNING) + << "Video stream should use a 90 kHz clock but appears to use " + << *estimated_frequency / 1000 << ". Discarding."; + continue; + } + + TimeSeries pacer_delay_series( + GetStreamName(stream_id) + "(" + + std::to_string(*estimated_frequency / 1000) + " kHz)", + LINE_DOT_GRAPH); + SeqNumUnwrapper timestamp_unwrapper; + uint64_t first_capture_timestamp = + timestamp_unwrapper.Unwrap(packets.front().header.timestamp); + uint64_t first_send_timestamp = packets.front().timestamp; + for (LoggedRtpPacket packet : packets) { + double capture_time_ms = (static_cast(timestamp_unwrapper.Unwrap( + packet.header.timestamp)) - + first_capture_timestamp) / + *estimated_frequency * 1000; + double send_time_ms = + static_cast(packet.timestamp - first_send_timestamp) / 1000; + float x = static_cast(packet.timestamp - begin_time_) / 1000000; + 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->SetSuggestedYAxis(0, 10, "Pacer delay (ms)", kBottomMargin, kTopMargin); + plot->SetTitle( + "Delay from capture to send time. (First packet normalized to 0.)"); +} + void EventLogAnalyzer::CreateTimestampGraph(Plot* plot) { for (const auto& kv : rtp_packets_) { const std::vector& rtp_packets = kv.second; diff --git a/rtc_tools/event_log_visualizer/analyzer.h b/rtc_tools/event_log_visualizer/analyzer.h index 5504282a51..15f1fa7ea4 100644 --- a/rtc_tools/event_log_visualizer/analyzer.h +++ b/rtc_tools/event_log_visualizer/analyzer.h @@ -94,6 +94,7 @@ class EventLogAnalyzer { void CreateReceiveSideBweSimulationGraph(Plot* plot); void CreateNetworkDelayFeedbackGraph(Plot* plot); + void CreatePacerDelayGraph(Plot* plot); void CreateTimestampGraph(Plot* plot); void CreateAudioEncoderTargetBitrateGraph(Plot* plot); @@ -144,7 +145,10 @@ class EventLogAnalyzer { bool IsAudioSsrc(StreamId stream_id) const; - std::string GetStreamName(StreamId) const; + std::string GetStreamName(StreamId stream_id) const; + + rtc::Optional EstimateRtpClockFrequency( + const std::vector& packets) const; const ParsedRtcEventLog& parsed_log_; diff --git a/rtc_tools/event_log_visualizer/main.cc b/rtc_tools/event_log_visualizer/main.cc index aef040e33d..e028a0f8e1 100644 --- a/rtc_tools/event_log_visualizer/main.cc +++ b/rtc_tools/event_log_visualizer/main.cc @@ -88,6 +88,11 @@ DEFINE_bool(plot_fraction_loss_feedback, true, "Plot packet loss in percent for outgoing packets (as perceived by " "the send-side bandwidth estimator)."); +DEFINE_bool(plot_pacer_delay, + false, + "Plot the time each sent packet has spent in the pacer (based on " + "the difference between the RTP timestamp and the send " + "timestamp)."); DEFINE_bool(plot_timestamps, false, "Plot the rtp timestamps of all rtp and rtcp packets over time."); @@ -265,6 +270,9 @@ int main(int argc, char* argv[]) { if (FLAG_plot_timestamps) { analyzer.CreateTimestampGraph(collection->AppendNewPlot()); } + if (FLAG_plot_pacer_delay) { + analyzer.CreatePacerDelayGraph(collection->AppendNewPlot()); + } if (FLAG_plot_audio_encoder_bitrate_bps) { analyzer.CreateAudioEncoderTargetBitrateGraph(collection->AppendNewPlot()); }