Estimate RTP clock frequency and plot capture-send delay.

Bug: webrtc:8450
Change-Id: Idea093854a644f3018a565168425583dc4783ce9
Reviewed-on: https://webrtc-review.googlesource.com/15480
Reviewed-by: Patrik Höglund <phoglund@webrtc.org>
Reviewed-by: Philip Eliasson <philipel@webrtc.org>
Commit-Queue: Björn Terelius <terelius@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#20442}

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<uint32_t> EventLogAnalyzer::EstimateRtpClockFrequency(
+    const std::vector<LoggedRtpPacket>& packets) const {
+  RTC_CHECK(packets.size() >= 2);
+  uint64_t end_time_us = log_segments_.empty()
+                             ? std::numeric_limits<uint64_t>::max()
+                             : log_segments_.front().second;
+  SeqNumUnwrapper<uint32_t> 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<uint32_t>();
+  }
+  double duration =
+      static_cast<double>(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<uint32_t>(f);
+    }
+  }
+  LOG(LS_WARNING) << "Failed to estimate RTP clock frequency: Estimate "
+                  << estimated_frequency
+                  << "not close to any stardard RTP frequency.";
+  return rtc::Optional<uint32_t>();
+}
+
 void EventLogAnalyzer::CreatePacketGraph(PacketDirection desired_direction,
                                          Plot* plot) {
   for (auto& kv : rtp_packets_) {
@@ -1459,6 +1500,55 @@ std::vector<std::pair<int64_t, int64_t>> EventLogAnalyzer::GetFrameTimestamps()
   return timestamps;
 }
 
+void EventLogAnalyzer::CreatePacerDelayGraph(Plot* plot) {
+  for (const auto& kv : rtp_packets_) {
+    const std::vector<LoggedRtpPacket>& 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<uint32_t> 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<uint32_t> 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<double>(timestamp_unwrapper.Unwrap(
+                                    packet.header.timestamp)) -
+                                first_capture_timestamp) /
+                               *estimated_frequency * 1000;
+      double send_time_ms =
+          static_cast<double>(packet.timestamp - first_send_timestamp) / 1000;
+      float x = static_cast<float>(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<LoggedRtpPacket>& rtp_packets = kv.second;

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<uint32_t> EstimateRtpClockFrequency(
+      const std::vector<LoggedRtpPacket>& packets) const;
 
   const ParsedRtcEventLog& parsed_log_;
 

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