Add event log visualization of rtp timestamps over time.

webrtc/tools/event_log_visualizer/analyzer.cc

 /*
  *  Copyright (c) 2016 The WebRTC project authors. All Rights Reserved.
  *
  *  Use of this source code is governed by a BSD-style license
  *  that can be found in the LICENSE file in the root of the source
  *  tree. An additional intellectual property rights grant can be found
  *  in the file PATENTS.  All contributing project authors may
  *  be found in the AUTHORS file in the root of the source tree.
  */
 
@@ skipping 11 matching lines @@
 #include "webrtc/base/rate_statistics.h"
 #include "webrtc/call/audio_receive_stream.h"
 #include "webrtc/call/audio_send_stream.h"
 #include "webrtc/call/call.h"
 #include "webrtc/common_types.h"
 #include "webrtc/modules/bitrate_controller/include/bitrate_controller.h"
 #include "webrtc/modules/congestion_controller/include/congestion_controller.h"
 #include "webrtc/modules/rtp_rtcp/include/rtp_rtcp.h"
 #include "webrtc/modules/rtp_rtcp/include/rtp_rtcp_defines.h"
 #include "webrtc/modules/rtp_rtcp/source/rtcp_packet/common_header.h"
+#include "webrtc/modules/rtp_rtcp/source/rtcp_packet/receiver_report.h"
+#include "webrtc/modules/rtp_rtcp/source/rtcp_packet/sender_report.h"
 #include "webrtc/modules/rtp_rtcp/source/rtcp_packet/transport_feedback.h"
 #include "webrtc/modules/rtp_rtcp/source/rtp_header_extensions.h"
 #include "webrtc/modules/rtp_rtcp/source/rtp_utility.h"
 #include "webrtc/video_receive_stream.h"
 #include "webrtc/video_send_stream.h"
 
 namespace webrtc {
 namespace plotting {
 
 namespace {
@@ skipping 337 matching lines @@
         break;
       }
       case ParsedRtcEventLog::RTCP_EVENT: {
         uint8_t packet[IP_PACKET_SIZE];
         MediaType media_type;
         parsed_log_.GetRtcpPacket(i, &direction, &media_type, packet,
                                   &total_length);
 
         // Currently feedback is logged twice, both for audio and video.
         // Only act on one of them.
-        if (media_type == MediaType::VIDEO) {
+        if (media_type == MediaType::AUDIO || media_type == MediaType::ANY) {

[terelius, 2017/02/01 13:29:31]

Won't this mean that we do act on the same RTCP report twice?

[stefan-webrtc, 2017/02/02 13:19:17]

No. ANY basically means that the packet is logged on the send-side, while AUDIO
and VIDEO is used on the receive-side. Received RTCP packets are logged both on
VIDEO and AUDIO but not on ANY, while sent RTCP are only logged once and as ANY.

[terelius, 2017/02/02 13:45:56]

Acknowledged.

           rtcp::CommonHeader header;
           const uint8_t* packet_end = packet + total_length;
           for (const uint8_t* block = packet; block < packet_end;
                block = header.NextPacket()) {
             RTC_CHECK(header.Parse(block, packet_end - block));
             if (header.type() == rtcp::TransportFeedback::kPacketType &&
                 header.fmt() == rtcp::TransportFeedback::kFeedbackMessageType) {
               std::unique_ptr<rtcp::TransportFeedback> rtcp_packet(
                   new rtcp::TransportFeedback());
               if (rtcp_packet->Parse(header)) {
                 uint32_t ssrc = rtcp_packet->sender_ssrc();
                 StreamId stream(ssrc, direction);
                 uint64_t timestamp = parsed_log_.GetTimestamp(i);
                 rtcp_packets_[stream].push_back(LoggedRtcpPacket(
                     timestamp, kRtcpTransportFeedback, std::move(rtcp_packet)));
               }
+            } else if (header.type() == rtcp::SenderReport::kPacketType) {
+              std::unique_ptr<rtcp::SenderReport> rtcp_packet(
+                  new rtcp::SenderReport());
+              if (rtcp_packet->Parse(header)) {
+                uint32_t ssrc = rtcp_packet->sender_ssrc();
+                StreamId stream(ssrc, direction);
+                uint64_t timestamp = parsed_log_.GetTimestamp(i);
+                rtcp_packets_[stream].push_back(LoggedRtcpPacket(
+                    timestamp, kRtcpSr, std::move(rtcp_packet)));
+              }
+            } else if (header.type() == rtcp::ReceiverReport::kPacketType) {
+              std::unique_ptr<rtcp::ReceiverReport> rtcp_packet(
+                  new rtcp::ReceiverReport());
+              if (rtcp_packet->Parse(header)) {
+                uint32_t ssrc = rtcp_packet->sender_ssrc();
+                StreamId stream(ssrc, direction);
+                uint64_t timestamp = parsed_log_.GetTimestamp(i);
+                rtcp_packets_[stream].push_back(LoggedRtcpPacket(
+                    timestamp, kRtcpRr, std::move(rtcp_packet)));
+              }
             }
           }
         }
         break;
       }
       case ParsedRtcEventLog::LOG_START: {
         break;
       }
       case ParsedRtcEventLog::LOG_END: {
         break;
@@ skipping 775 matching lines @@
     for (auto& packet : *largest_video_stream) {
       if (packet.header.markerBit) {
         int64_t capture_ms = packet.header.timestamp / 90.0;
         int64_t arrival_ms = packet.timestamp / 1000.0;
         timestamps.push_back(std::make_pair(capture_ms, arrival_ms));
       }
     }
   }
   return timestamps;
 }
+
+void EventLogAnalyzer::CreateTimestampGraph(Plot* plot) {
+  for (const auto& kv : rtp_packets_) {
+    const std::vector<LoggedRtpPacket>& rtp_packets = kv.second;
+    StreamId stream_id = kv.first;
+
+    {
+      TimeSeries timestamp_data;
+      timestamp_data.label = GetStreamName(stream_id) + " capture-time";
+      timestamp_data.style = LINE_DOT_GRAPH;
+      rtc::Optional<uint32_t> first_timestamp;
+      for (LoggedRtpPacket packet : rtp_packets) {
+        float x = static_cast<float>(packet.timestamp - begin_time_) / 1000000;
+        if (!first_timestamp)
+          first_timestamp = rtc::Optional<uint32_t>(packet.header.timestamp);

[terelius, 2017/02/02 13:45:56]

Are we using first_timestamp anywhere?

[stefan-webrtc, 2017/02/02 15:00:37]

Done.

+        float y = packet.header.timestamp;
+        timestamp_data.points.emplace_back(x, y);
+      }
+      plot->series_list_.push_back(std::move(timestamp_data));
+    }
+
+    {
+      auto kv = rtcp_packets_.find(stream_id);
+      if (kv != rtcp_packets_.end()) {
+        const auto& packets = kv->second;
+        TimeSeries timestamp_data;
+        timestamp_data.label = GetStreamName(stream_id) + " rtcp capture-time";
+        timestamp_data.style = LINE_DOT_GRAPH;
+        rtc::Optional<uint32_t> first_timestamp;
+        for (const LoggedRtcpPacket& rtcp : packets) {
+          if (rtcp.type != kRtcpSr)
+            continue;
+          rtcp::SenderReport* sr;
+          sr = static_cast<rtcp::SenderReport*>(rtcp.packet.get());
+          float x = static_cast<float>(rtcp.timestamp - begin_time_) / 1000000;
+          if (!first_timestamp)
+            first_timestamp = rtc::Optional<uint32_t>(sr->rtp_timestamp());

[terelius, 2017/02/02 13:45:56]

Are we using first_timestamp anywhere?

[stefan-webrtc, 2017/02/02 15:00:37]

Good point, no!

+          float y = sr->rtp_timestamp();
+          timestamp_data.points.emplace_back(x, y);
+        }
+        plot->series_list_.push_back(std::move(timestamp_data));
+      }
+    }
+  }
+
+  plot->SetXAxis(0, call_duration_s_, "Time (s)", kLeftMargin, kRightMargin);
+  plot->SetSuggestedYAxis(0, 1, "Timestamp (90khz)", kBottomMargin, kTopMargin);
+  plot->SetTitle("Timestamps");
+}
 }  // namespace plotting
 }  // namespace webrtc