Add periodic logging of sync delays.

Bug: none
Change-Id: Ib2371651c7a912231c93742410a8aa1b01cc9896
Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/168344
Reviewed-by: Sam Zackrisson <saza@webrtc.org>
Reviewed-by: Niels Moller <nisse@webrtc.org>
Commit-Queue: Åsa Persson <asapersson@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#30495}

audio/audio_receive_stream.cc

@@ -295,7 +295,7 @@ int AudioReceiveStream::PreferredSampleRate() const {
   return channel_receive_->PreferredSampleRate();
 }
 
-int AudioReceiveStream::id() const {
+uint32_t AudioReceiveStream::id() const {
   RTC_DCHECK_RUN_ON(&worker_thread_checker_);
   return config_.rtp.remote_ssrc;
 }

audio/audio_receive_stream.h

@@ -87,7 +87,7 @@ class AudioReceiveStream final : public webrtc::AudioReceiveStream,
   int PreferredSampleRate() const override;
 
   // Syncable
-  int id() const override;
+  uint32_t id() const override;
   absl::optional<Syncable::Info> GetInfo() const override;
   bool GetPlayoutRtpTimestamp(uint32_t* rtp_timestamp,
                               int64_t* time_ms) const override;

call/syncable.h

@@ -33,7 +33,7 @@ class Syncable {
 
   virtual ~Syncable();
 
-  virtual int id() const = 0;
+  virtual uint32_t id() const = 0;
   virtual absl::optional<Info> GetInfo() const = 0;
   virtual bool GetPlayoutRtpTimestamp(uint32_t* rtp_timestamp,
                                       int64_t* time_ms) const = 0;

video/rtp_streams_synchronizer.cc

@@ -13,12 +13,16 @@
 #include "absl/types/optional.h"
 #include "call/syncable.h"
 #include "rtc_base/checks.h"
+#include "rtc_base/logging.h"
 #include "rtc_base/time_utils.h"
 #include "rtc_base/trace_event.h"
 #include "system_wrappers/include/rtp_to_ntp_estimator.h"
 
 namespace webrtc {
 namespace {
+// Time interval for logging stats.
+constexpr int64_t kStatsLogIntervalMs = 10000;
+
 bool UpdateMeasurements(StreamSynchronization::Measurements* stream,
                         const Syncable::Info& info) {
   RTC_DCHECK(stream);
@@ -38,7 +42,8 @@ RtpStreamsSynchronizer::RtpStreamsSynchronizer(Syncable* syncable_video)
     : syncable_video_(syncable_video),
       syncable_audio_(nullptr),
       sync_(),
-      last_sync_time_(rtc::TimeNanos()) {
+      last_sync_time_(rtc::TimeNanos()),
+      last_stats_log_ms_(rtc::TimeMillis()) {
   RTC_DCHECK(syncable_video);
   process_thread_checker_.Detach();
 }
@@ -77,6 +82,13 @@ void RtpStreamsSynchronizer::Process() {
   }
   RTC_DCHECK(sync_.get());
 
+  bool log_stats = false;
+  const int64_t now_ms = rtc::TimeMillis();
+  if (now_ms - last_stats_log_ms_ > kStatsLogIntervalMs) {
+    last_stats_log_ms_ = now_ms;
+    log_stats = true;
+  }
+
   absl::optional<Syncable::Info> audio_info = syncable_audio_->GetInfo();
   if (!audio_info || !UpdateMeasurements(&audio_measurement_, *audio_info)) {
     return;
@@ -100,11 +112,21 @@ void RtpStreamsSynchronizer::Process() {
     return;
   }
 
+  if (log_stats) {
+    RTC_LOG(LS_INFO) << "Sync info stats: " << now_ms
+                     << ", {ssrc: " << sync_->audio_stream_id() << ", "
+                     << "cur_delay_ms: " << audio_info->current_delay_ms
+                     << "} {ssrc: " << sync_->video_stream_id() << ", "
+                     << "cur_delay_ms: " << video_info->current_delay_ms
+                     << "} {relative_delay_ms: " << relative_delay_ms << "} ";
+  }
+
   TRACE_COUNTER1("webrtc", "SyncCurrentVideoDelay",
                  video_info->current_delay_ms);
   TRACE_COUNTER1("webrtc", "SyncCurrentAudioDelay",
                  audio_info->current_delay_ms);
   TRACE_COUNTER1("webrtc", "SyncRelativeDelay", relative_delay_ms);
+
   int target_audio_delay_ms = 0;
   int target_video_delay_ms = video_info->current_delay_ms;
   // Calculate the necessary extra audio delay and desired total video
@@ -114,6 +136,14 @@ void RtpStreamsSynchronizer::Process() {
     return;
   }
 
+  if (log_stats) {
+    RTC_LOG(LS_INFO) << "Sync delay stats: " << now_ms
+                     << ", {ssrc: " << sync_->audio_stream_id() << ", "
+                     << "target_delay_ms: " << target_audio_delay_ms
+                     << "} {ssrc: " << sync_->video_stream_id() << ", "
+                     << "target_delay_ms: " << target_video_delay_ms << "} ";
+  }
+
   syncable_audio_->SetMinimumPlayoutDelay(target_audio_delay_ms);
   syncable_video_->SetMinimumPlayoutDelay(target_video_delay_ms);
 }

video/rtp_streams_synchronizer.h

@@ -8,8 +8,8 @@
  *  be found in the AUTHORS file in the root of the source tree.
  */
 
-// RtpStreamsSynchronizer is responsible for synchronization audio and video for
+// RtpStreamsSynchronizer is responsible for synchronizing audio and video for
-// a given voice engine channel and video receive stream.
+// a given audio receive stream and video receive stream.
 
 #ifndef VIDEO_RTP_STREAMS_SYNCHRONIZER_H_
 #define VIDEO_RTP_STREAMS_SYNCHRONIZER_H_
@@ -58,6 +58,7 @@ class RtpStreamsSynchronizer : public Module {
 
   rtc::ThreadChecker process_thread_checker_;
   int64_t last_sync_time_ RTC_GUARDED_BY(&process_thread_checker_);
+  int64_t last_stats_log_ms_ RTC_GUARDED_BY(&process_thread_checker_);
 };
 
 }  // namespace webrtc

video/stream_synchronization.cc

@@ -24,8 +24,8 @@ static const int kFilterLength = 4;
 // Minimum difference between audio and video to warrant a change.
 static const int kMinDeltaMs = 30;
 
-StreamSynchronization::StreamSynchronization(int video_stream_id,
+StreamSynchronization::StreamSynchronization(uint32_t video_stream_id,
-                                             int audio_stream_id)
+                                             uint32_t audio_stream_id)
     : video_stream_id_(video_stream_id),
       audio_stream_id_(audio_stream_id),
       base_target_delay_ms_(0),
@@ -53,6 +53,7 @@ bool StreamSynchronization::ComputeRelativeDelay(
       video_measurement.latest_receive_time_ms -
       audio_measurement.latest_receive_time_ms -
       (video_last_capture_time_ms - audio_last_capture_time_ms);
+
   if (*relative_delay_ms > kMaxDeltaDelayMs ||
       *relative_delay_ms < -kMaxDeltaDelayMs) {
     return false;
@@ -177,7 +178,6 @@ void StreamSynchronization::SetTargetBufferingDelay(int target_delay_ms) {
   // The video delay is compared to the last value (and how much we can update
   // is limited by that as well).
   video_delay_.last_ms += target_delay_ms - base_target_delay_ms_;
-
   video_delay_.extra_ms += target_delay_ms - base_target_delay_ms_;
 
   // Video is already delayed by the desired amount.

video/stream_synchronization.h

@@ -26,7 +26,7 @@ class StreamSynchronization {
     uint32_t latest_timestamp;
   };
 
-  StreamSynchronization(int video_stream_id, int audio_stream_id);
+  StreamSynchronization(uint32_t video_stream_id, uint32_t audio_stream_id);
 
   bool ComputeDelays(int relative_delay_ms,
                      int current_audio_delay_ms,
@@ -44,16 +44,19 @@ class StreamSynchronization {
   // |target_delay_ms|.
   void SetTargetBufferingDelay(int target_delay_ms);
 
+  uint32_t audio_stream_id() const { return audio_stream_id_; }
+  uint32_t video_stream_id() const { return video_stream_id_; }
+
  private:
   struct SynchronizationDelays {
     int extra_ms = 0;
     int last_ms = 0;
   };
 
+  const uint32_t video_stream_id_;
+  const uint32_t audio_stream_id_;
   SynchronizationDelays audio_delay_;
   SynchronizationDelays video_delay_;
-  const int video_stream_id_;
-  const int audio_stream_id_;
   int base_target_delay_ms_;
   int avg_diff_ms_;
 };

video/video_receive_stream.cc

@@ -580,7 +580,7 @@ void VideoReceiveStream::OnRttUpdate(int64_t avg_rtt_ms, int64_t max_rtt_ms) {
   rtp_video_stream_receiver_.UpdateRtt(max_rtt_ms);
 }
 
-int VideoReceiveStream::id() const {
+uint32_t VideoReceiveStream::id() const {
   RTC_DCHECK_RUN_ON(&worker_sequence_checker_);
   return config_.rtp.remote_ssrc;
 }

video/video_receive_stream.h

@@ -117,7 +117,7 @@ class VideoReceiveStream : public webrtc::VideoReceiveStream,
   void OnRttUpdate(int64_t avg_rtt_ms, int64_t max_rtt_ms) override;
 
   // Implements Syncable.
-  int id() const override;
+  uint32_t id() const override;
   absl::optional<Syncable::Info> GetInfo() const override;
   bool GetPlayoutRtpTimestamp(uint32_t* rtp_timestamp,
                               int64_t* time_ms) const override;