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}
diff --git a/audio/audio_receive_stream.cc b/audio/audio_receive_stream.cc
index 2e02388..7c6adcd 100644
--- a/audio/audio_receive_stream.cc
+++ b/audio/audio_receive_stream.cc
@@ -295,7 +295,7 @@
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;
}
diff --git a/audio/audio_receive_stream.h b/audio/audio_receive_stream.h
index 24dcbf2..c197aa8 100644
--- a/audio/audio_receive_stream.h
+++ b/audio/audio_receive_stream.h
@@ -87,7 +87,7 @@
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;
diff --git a/call/syncable.h b/call/syncable.h
index 067e01c..3bbe50c 100644
--- a/call/syncable.h
+++ b/call/syncable.h
@@ -33,7 +33,7 @@
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;
diff --git a/video/rtp_streams_synchronizer.cc b/video/rtp_streams_synchronizer.cc
index 156ebbb..3dedc43 100644
--- a/video/rtp_streams_synchronizer.cc
+++ b/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 @@
: 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 @@
}
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 @@
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 @@
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);
}
diff --git a/video/rtp_streams_synchronizer.h b/video/rtp_streams_synchronizer.h
index b6e5e61..60e2c8e 100644
--- a/video/rtp_streams_synchronizer.h
+++ b/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
-// a given voice engine channel and video receive stream.
+// RtpStreamsSynchronizer is responsible for synchronizing audio and video for
+// 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 @@
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
diff --git a/video/stream_synchronization.cc b/video/stream_synchronization.cc
index 159eb7a..8c808f1 100644
--- a/video/stream_synchronization.cc
+++ b/video/stream_synchronization.cc
@@ -24,8 +24,8 @@
// Minimum difference between audio and video to warrant a change.
static const int kMinDeltaMs = 30;
-StreamSynchronization::StreamSynchronization(int video_stream_id,
- int audio_stream_id)
+StreamSynchronization::StreamSynchronization(uint32_t video_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 @@
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 @@
// 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.
diff --git a/video/stream_synchronization.h b/video/stream_synchronization.h
index 5f7ca6a..1aba62d 100644
--- a/video/stream_synchronization.h
+++ b/video/stream_synchronization.h
@@ -26,7 +26,7 @@
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 @@
// |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_;
};
diff --git a/video/video_receive_stream.cc b/video/video_receive_stream.cc
index 4f0dfaf..0a2d819 100644
--- a/video/video_receive_stream.cc
+++ b/video/video_receive_stream.cc
@@ -580,7 +580,7 @@
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;
}
diff --git a/video/video_receive_stream.h b/video/video_receive_stream.h
index f097710..a93a45a 100644
--- a/video/video_receive_stream.h
+++ b/video/video_receive_stream.h
@@ -117,7 +117,7 @@
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;
