Add periodic logging of received RTP headers and estimated clock offsets for e2e delay.

R=mflodman@webrtc.org

Review URL: https://webrtc-codereview.appspot.com/25789004

git-svn-id: http://webrtc.googlecode.com/svn/trunk/webrtc@7444 4adac7df-926f-26a2-2b94-8c16560cd09d

4 files changed, 53 insertions, 13 deletions

diff --git a/modules/rtp_rtcp/interface/remote_ntp_time_estimator.h b/modules/rtp_rtcp/interface/remote_ntp_time_estimator.h
index 08fc605a..c237986a 100644
--- a/modules/rtp_rtcp/interface/remote_ntp_time_estimator.h
+++ b/modules/rtp_rtcp/interface/remote_ntp_time_estimator.h
@@ -42,6 +42,7 @@ class RemoteNtpTimeEstimator {
   Clock* clock_;
   scoped_ptr<TimestampExtrapolator> ts_extrapolator_;
   RtcpList rtcp_list_;
+  int64_t last_timing_log_ms_;
   DISALLOW_COPY_AND_ASSIGN(RemoteNtpTimeEstimator);
 };
 
diff --git a/modules/rtp_rtcp/source/remote_ntp_time_estimator.cc b/modules/rtp_rtcp/source/remote_ntp_time_estimator.cc
index ed356b4c..8e2651c6 100644
--- a/modules/rtp_rtcp/source/remote_ntp_time_estimator.cc
+++ b/modules/rtp_rtcp/source/remote_ntp_time_estimator.cc
@@ -11,16 +11,19 @@
 #include "webrtc/modules/rtp_rtcp/interface/remote_ntp_time_estimator.h"
 
 #include "webrtc/system_wrappers/interface/clock.h"
+#include "webrtc/system_wrappers/interface/logging.h"
 #include "webrtc/system_wrappers/interface/timestamp_extrapolator.h"
 
 namespace webrtc {
 
+static const int kTimingLogIntervalMs = 10000;
+
 // TODO(wu): Refactor this class so that it can be shared with
 // vie_sync_module.cc.
 RemoteNtpTimeEstimator::RemoteNtpTimeEstimator(Clock* clock)
     : clock_(clock),
-      ts_extrapolator_(
-          new TimestampExtrapolator(clock_->TimeInMilliseconds())) {
+      ts_extrapolator_(new TimestampExtrapolator(clock_->TimeInMilliseconds())),
+      last_timing_log_ms_(-1) {
 }
 
 RemoteNtpTimeEstimator::~RemoteNtpTimeEstimator() {}
@@ -61,7 +64,16 @@ int64_t RemoteNtpTimeEstimator::Estimate(uint32_t rtp_timestamp) {
       ts_extrapolator_->ExtrapolateLocalTime(timestamp);
   int64_t ntp_offset =
       clock_->CurrentNtpInMilliseconds() - clock_->TimeInMilliseconds();
-  return receiver_capture_ms + ntp_offset;
+  int64_t receiver_capture_ntp_ms = receiver_capture_ms + ntp_offset;
+  int64_t now_ms = clock_->TimeInMilliseconds();
+  if (now_ms - last_timing_log_ms_ > kTimingLogIntervalMs) {
+    LOG(LS_INFO) << "RTP timestamp: " << rtp_timestamp
+                 << " in NTP clock: " << sender_capture_ntp_ms
+                 << " estimated time in receiver clock: " << receiver_capture_ms
+                 << " converted to NTP clock: " << receiver_capture_ntp_ms;
+    last_timing_log_ms_ = now_ms;
+  }
+  return receiver_capture_ntp_ms;
 }
 
 }  // namespace webrtc
diff --git a/video_engine/vie_receiver.cc b/video_engine/vie_receiver.cc
index cb574665..0501ec31 100644
--- a/video_engine/vie_receiver.cc
+++ b/video_engine/vie_receiver.cc
@@ -30,28 +30,34 @@
 
 namespace webrtc {
 
+static const int kPacketLogIntervalMs = 10000;
+
 ViEReceiver::ViEReceiver(const int32_t channel_id,
                          VideoCodingModule* module_vcm,
                          RemoteBitrateEstimator* remote_bitrate_estimator,
                          RtpFeedback* rtp_feedback)
     : receive_cs_(CriticalSectionWrapper::CreateCriticalSection()),
+      clock_(Clock::GetRealTimeClock()),
       rtp_header_parser_(RtpHeaderParser::Create()),
-      rtp_payload_registry_(new RTPPayloadRegistry(
-          RTPPayloadStrategy::CreateStrategy(false))),
-      rtp_receiver_(RtpReceiver::CreateVideoReceiver(
-          channel_id, Clock::GetRealTimeClock(), this, rtp_feedback,
-          rtp_payload_registry_.get())),
-      rtp_receive_statistics_(ReceiveStatistics::Create(
-          Clock::GetRealTimeClock())),
+      rtp_payload_registry_(
+          new RTPPayloadRegistry(RTPPayloadStrategy::CreateStrategy(false))),
+      rtp_receiver_(
+          RtpReceiver::CreateVideoReceiver(channel_id,
+                                           clock_,
+                                           this,
+                                           rtp_feedback,
+                                           rtp_payload_registry_.get())),
+      rtp_receive_statistics_(ReceiveStatistics::Create(clock_)),
       fec_receiver_(FecReceiver::Create(this)),
       rtp_rtcp_(NULL),
       vcm_(module_vcm),
       remote_bitrate_estimator_(remote_bitrate_estimator),
-      ntp_estimator_(new RemoteNtpTimeEstimator(Clock::GetRealTimeClock())),
+      ntp_estimator_(new RemoteNtpTimeEstimator(clock_)),
       rtp_dump_(NULL),
       receiving_(false),
       restored_packet_in_use_(false),
-      receiving_ast_enabled_(false) {
+      receiving_ast_enabled_(false),
+      last_packet_log_ms_(-1) {
   assert(remote_bitrate_estimator);
 }
 
@@ -229,10 +235,29 @@ int ViEReceiver::InsertRTPPacket(const uint8_t* rtp_packet,
   }
   int payload_length = rtp_packet_length - header.headerLength;
   int64_t arrival_time_ms;
+  int64_t now_ms = clock_->TimeInMilliseconds();
   if (packet_time.timestamp != -1)
     arrival_time_ms = (packet_time.timestamp + 500) / 1000;
   else
-    arrival_time_ms = TickTime::MillisecondTimestamp();
+    arrival_time_ms = now_ms;
+
+  {
+    // Periodically log the RTP header of incoming packets.
+    CriticalSectionScoped cs(receive_cs_.get());
+    if (now_ms - last_packet_log_ms_ > kPacketLogIntervalMs) {
+      std::stringstream ss;
+      ss << "Packet received on SSRC: " << header.ssrc << " with payload type: "
+         << static_cast<int>(header.payloadType) << ", timestamp: "
+         << header.timestamp << ", sequence number: " << header.sequenceNumber
+         << ", arrival time: " << arrival_time_ms;
+      if (header.extension.hasTransmissionTimeOffset)
+        ss << ", toffset: " << header.extension.transmissionTimeOffset;
+      if (header.extension.hasAbsoluteSendTime)
+        ss << ", abs send time: " << header.extension.absoluteSendTime;
+      LOG(LS_INFO) << ss.str();
+      last_packet_log_ms_ = now_ms;
+    }
+  }
 
   remote_bitrate_estimator_->IncomingPacket(arrival_time_ms,
                                             payload_length, header);
diff --git a/video_engine/vie_receiver.h b/video_engine/vie_receiver.h
index 3451d524..e9d28f33 100644
--- a/video_engine/vie_receiver.h
+++ b/video_engine/vie_receiver.h
@@ -105,6 +105,7 @@ class ViEReceiver : public RtpData {
   bool IsPacketRetransmitted(const RTPHeader& header, bool in_order) const;
 
   scoped_ptr<CriticalSectionWrapper> receive_cs_;
+  Clock* clock_;
   scoped_ptr<RtpHeaderParser> rtp_header_parser_;
   scoped_ptr<RTPPayloadRegistry> rtp_payload_registry_;
   scoped_ptr<RtpReceiver> rtp_receiver_;
@@ -122,6 +123,7 @@ class ViEReceiver : public RtpData {
   uint8_t restored_packet_[kViEMaxMtu];
   bool restored_packet_in_use_;
   bool receiving_ast_enabled_;
+  int64_t last_packet_log_ms_;
 };
 
 }  // namespace webrt