From 4b1a363e4c238f2e1ec2d8a9ce1f819f59d710ce Mon Sep 17 00:00:00 2001 From: Ilya Nikolaevskiy Date: Thu, 19 Oct 2017 11:36:02 +0200 Subject: [PATCH] Add fine grained dropped video frames counters on sending side MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 4 new counters added to SendStatisticsProxy and reported to UMA and logs. Bug: webrtc:8355 Change-Id: Idf9b8dfc295c92821e058a97cb3894dc6a446082 Reviewed-on: https://webrtc-review.googlesource.com/12260 Commit-Queue: Ilya Nikolaevskiy Reviewed-by: Stefan Holmer Reviewed-by: Erik Språng Reviewed-by: Taylor Brandstetter Cr-Commit-Position: refs/heads/master@{#20347} --- api/video_codecs/video_encoder.h | 12 +++++ call/video_send_stream.h | 4 ++ media/base/adaptedvideotracksource.cc | 1 + media/base/videobroadcaster.cc | 6 +++ media/base/videobroadcaster.h | 2 + media/base/videocapturer.cc | 1 + media/base/videosinkinterface.h | 5 ++ modules/video_coding/generic_encoder.cc | 46 ++++++++++++------- modules/video_coding/generic_encoder.h | 12 +++-- .../video_coding/generic_encoder_unittest.cc | 37 ++++++++++++++- .../include/video_coding_defines.h | 2 + modules/video_coding/video_sender.cc | 3 +- video/send_statistics_proxy.cc | 37 +++++++++++++++ video/send_statistics_proxy.h | 6 +++ video/video_stream_encoder.cc | 25 +++++++--- video/video_stream_encoder.h | 3 +- 16 files changed, 174 insertions(+), 28 deletions(-) diff --git a/api/video_codecs/video_encoder.h b/api/video_codecs/video_encoder.h index 505564c130..eb401afded 100644 --- a/api/video_codecs/video_encoder.h +++ b/api/video_codecs/video_encoder.h @@ -56,13 +56,25 @@ class EncodedImageCallback { bool drop_next_frame = false; }; + // Used to signal the encoder about reason a frame is dropped. + // kDroppedByMediaOptimizations - dropped by MediaOptimizations (for rate + // limiting purposes). + // kDroppedByEncoder - dropped by encoder's internal rate limiter. + enum class DropReason : uint8_t { + kDroppedByMediaOptimizations, + kDroppedByEncoder + }; + // Callback function which is called when an image has been encoded. virtual Result OnEncodedImage( const EncodedImage& encoded_image, const CodecSpecificInfo* codec_specific_info, const RTPFragmentationHeader* fragmentation) = 0; + // Deprecated. TODO(ilnik): Remove this in few weeks. virtual void OnDroppedFrame() {} + + virtual void OnDroppedFrame(DropReason reason) {} }; class VideoEncoder { diff --git a/call/video_send_stream.h b/call/video_send_stream.h index 1bc08cb21b..3bdb8ce813 100644 --- a/call/video_send_stream.h +++ b/call/video_send_stream.h @@ -63,6 +63,10 @@ class VideoSendStream { int avg_encode_time_ms = 0; int encode_usage_percent = 0; uint32_t frames_encoded = 0; + uint32_t frames_dropped_by_capturer = 0; + uint32_t frames_dropped_by_encoder_queue = 0; + uint32_t frames_dropped_by_rate_limiter = 0; + uint32_t frames_dropped_by_encoder = 0; rtc::Optional qp_sum; // Bitrate the encoder is currently configured to use due to bandwidth // limitations. diff --git a/media/base/adaptedvideotracksource.cc b/media/base/adaptedvideotracksource.cc index 4b413619a6..16f11b9414 100644 --- a/media/base/adaptedvideotracksource.cc +++ b/media/base/adaptedvideotracksource.cc @@ -105,6 +105,7 @@ bool AdaptedVideoTrackSource::AdaptFrame(int width, if (!video_adapter_.AdaptFrameResolution( width, height, time_us * rtc::kNumNanosecsPerMicrosec, crop_width, crop_height, out_width, out_height)) { + broadcaster_.OnDiscardedFrame(); // VideoAdapter dropped the frame. return false; } diff --git a/media/base/videobroadcaster.cc b/media/base/videobroadcaster.cc index 83ed8444e5..344c3cc263 100644 --- a/media/base/videobroadcaster.cc +++ b/media/base/videobroadcaster.cc @@ -73,6 +73,12 @@ void VideoBroadcaster::OnFrame(const webrtc::VideoFrame& frame) { } } +void VideoBroadcaster::OnDiscardedFrame() { + for (auto& sink_pair : sink_pairs()) { + sink_pair.sink->OnDiscardedFrame(); + } +} + void VideoBroadcaster::UpdateWants() { RTC_DCHECK(thread_checker_.CalledOnValidThread()); diff --git a/media/base/videobroadcaster.h b/media/base/videobroadcaster.h index 4236e96958..a8e21fa5b8 100644 --- a/media/base/videobroadcaster.h +++ b/media/base/videobroadcaster.h @@ -50,6 +50,8 @@ class VideoBroadcaster : public VideoSourceBase, // to the VideoSinkWants. void OnFrame(const webrtc::VideoFrame& frame) override; + void OnDiscardedFrame() override; + protected: void UpdateWants() RTC_EXCLUSIVE_LOCKS_REQUIRED(sinks_and_wants_lock_); const rtc::scoped_refptr& GetBlackFrameBuffer( diff --git a/media/base/videocapturer.cc b/media/base/videocapturer.cc index 592f3e20e3..43f0630edc 100644 --- a/media/base/videocapturer.cc +++ b/media/base/videocapturer.cc @@ -179,6 +179,7 @@ bool VideoCapturer::AdaptFrame(int width, width, height, camera_time_us * rtc::kNumNanosecsPerMicrosec, crop_width, crop_height, out_width, out_height)) { // VideoAdapter dropped the frame. + broadcaster_.OnDiscardedFrame(); return false; } *crop_x = (width - *crop_width) / 2; diff --git a/media/base/videosinkinterface.h b/media/base/videosinkinterface.h index bbcd529cc8..e8e48d884a 100644 --- a/media/base/videosinkinterface.h +++ b/media/base/videosinkinterface.h @@ -11,6 +11,7 @@ #ifndef MEDIA_BASE_VIDEOSINKINTERFACE_H_ #define MEDIA_BASE_VIDEOSINKINTERFACE_H_ +#include // TODO(nisse): Consider moving this interface (and possibly // VideoSourceInterface too) from media/base to common_video, to // reduce dependency cycles. @@ -22,6 +23,10 @@ class VideoSinkInterface { virtual ~VideoSinkInterface() {} virtual void OnFrame(const VideoFrameT& frame) = 0; + + // Should be called by the source when it discards the frame due to rate + // limiting. + virtual void OnDiscardedFrame(){}; }; } // namespace rtc diff --git a/modules/video_coding/generic_encoder.cc b/modules/video_coding/generic_encoder.cc index c4affcf414..5066ba153e 100644 --- a/modules/video_coding/generic_encoder.cc +++ b/modules/video_coding/generic_encoder.cc @@ -216,8 +216,20 @@ void VCMEncodedFrameCallback::OnEncodeStarted(int64_t capture_time_ms, rtc::CritScope crit(&timing_params_lock_); if (timing_frames_info_.size() < simulcast_svc_idx + 1) timing_frames_info_.resize(simulcast_svc_idx + 1); - timing_frames_info_[simulcast_svc_idx].encode_start_time_ms[capture_time_ms] = - rtc::TimeMillis(); + RTC_DCHECK( + timing_frames_info_[simulcast_svc_idx].encode_start_list.empty() || + rtc::TimeDiff(capture_time_ms, timing_frames_info_[simulcast_svc_idx] + .encode_start_list.back() + .capture_time_ms) >= 0); + if (timing_frames_info_[simulcast_svc_idx].encode_start_list.size() == + kMaxEncodeStartTimeListSize) { + LOG(LS_WARNING) << "Too many frames in the encode_start_list." + " Did encoder stall?"; + post_encode_callback_->OnDroppedFrame(DropReason::kDroppedByEncoder); + timing_frames_info_[simulcast_svc_idx].encode_start_list.pop_front(); + } + timing_frames_info_[simulcast_svc_idx].encode_start_list.emplace_back( + capture_time_ms, rtc::TimeMillis()); } EncodedImageCallback::Result VCMEncodedFrameCallback::OnEncodedImage( @@ -249,20 +261,22 @@ EncodedImageCallback::Result VCMEncodedFrameCallback::OnEncodedImage( // OnFrameRateChanged. |timing_frames_info_| may be not filled here. num_simulcast_svc_streams = timing_frames_info_.size(); if (simulcast_svc_idx < num_simulcast_svc_streams) { - auto encode_start_map = - &timing_frames_info_[simulcast_svc_idx].encode_start_time_ms; - auto it = encode_start_map->find(encoded_image.capture_time_ms_); - if (it != encode_start_map->end()) { - encode_start_ms.emplace(it->second); - // Assuming all encoders do not reorder frames within single stream, - // there may be some dropped frames with smaller timestamps. These - // should be purged. - encode_start_map->erase(encode_start_map->begin(), it); - encode_start_map->erase(it); - } else { - // Encoder is with internal source: free our records of any frames just - // in case to free memory. - encode_start_map->clear(); + auto encode_start_list = + &timing_frames_info_[simulcast_svc_idx].encode_start_list; + // Skip frames for which there was OnEncodeStarted but no OnEncodedImage + // call. These are dropped by encoder internally. + while (!encode_start_list->empty() && + encode_start_list->front().capture_time_ms < + encoded_image.capture_time_ms_) { + post_encode_callback_->OnDroppedFrame(DropReason::kDroppedByEncoder); + encode_start_list->pop_front(); + } + if (encode_start_list->size() > 0 && + encode_start_list->front().capture_time_ms == + encoded_image.capture_time_ms_) { + encode_start_ms.emplace( + encode_start_list->front().encode_start_time_ms); + encode_start_list->pop_front(); } size_t target_bitrate = diff --git a/modules/video_coding/generic_encoder.h b/modules/video_coding/generic_encoder.h index 9b003d6dee..2cdf6645a5 100644 --- a/modules/video_coding/generic_encoder.h +++ b/modules/video_coding/generic_encoder.h @@ -12,7 +12,7 @@ #define MODULES_VIDEO_CODING_GENERIC_ENCODER_H_ #include -#include +#include #include #include "modules/video_coding/include/video_codec_interface.h" @@ -71,9 +71,16 @@ class VCMEncodedFrameCallback : public EncodedImageCallback { EncodedImageCallback* const post_encode_callback_; media_optimization::MediaOptimization* const media_opt_; + struct EncodeStartTimeRecord { + EncodeStartTimeRecord(int64_t capture_time, int64_t encode_start_time) + : capture_time_ms(capture_time), + encode_start_time_ms(encode_start_time) {} + int64_t capture_time_ms; + int64_t encode_start_time_ms; + }; struct TimingFramesLayerInfo { size_t target_bitrate_bytes_per_sec = 0; - std::map encode_start_time_ms; + std::list encode_start_list; }; // Separate instance for each simulcast stream or spatial layer. std::vector timing_frames_info_ @@ -111,7 +118,6 @@ class VCMGenericEncoder { int32_t SetPeriodicKeyFrames(bool enable); int32_t RequestFrame(const std::vector& frame_types); bool InternalSource() const; - void OnDroppedFrame(); bool SupportsNativeHandle() const; private: diff --git a/modules/video_coding/generic_encoder_unittest.cc b/modules/video_coding/generic_encoder_unittest.cc index 90d3c05b88..9c879e3add 100644 --- a/modules/video_coding/generic_encoder_unittest.cc +++ b/modules/video_coding/generic_encoder_unittest.cc @@ -27,7 +27,8 @@ inline size_t FrameSize(const size_t& min_frame_size, class FakeEncodedImageCallback : public EncodedImageCallback { public: - FakeEncodedImageCallback() : last_frame_was_timing_(false) {} + FakeEncodedImageCallback() + : last_frame_was_timing_(false), num_frames_dropped_(0) {} Result OnEncodedImage(const EncodedImage& encoded_image, const CodecSpecificInfo* codec_specific_info, const RTPFragmentationHeader* fragmentation) override { @@ -36,10 +37,15 @@ class FakeEncodedImageCallback : public EncodedImageCallback { return Result(Result::OK); }; + void OnDroppedFrame(DropReason reason) override { ++num_frames_dropped_; } + bool WasTimingFrame() { return last_frame_was_timing_; } + size_t GetNumFramesDropped() { return num_frames_dropped_; } + private: bool last_frame_was_timing_; + size_t num_frames_dropped_; }; enum class FrameType { @@ -190,5 +196,34 @@ TEST(TestVCMEncodedFrameCallback, NoTimingFrameIfNoEncodeStartTime) { EXPECT_FALSE(sink.WasTimingFrame()); } +TEST(TestVCMEncodedFrameCallback, NotifiesAboutDroppedFrames) { + EncodedImage image; + CodecSpecificInfo codec_specific; + const int64_t timestamp1 = 100; + const int64_t timestamp2 = 110; + const int64_t timestamp3 = 120; + const int64_t timestamp4 = 130; + codec_specific.codecType = kVideoCodecGeneric; + codec_specific.codecSpecific.generic.simulcast_idx = 0; + FakeEncodedImageCallback sink; + VCMEncodedFrameCallback callback(&sink, nullptr); + callback.OnEncodeStarted(timestamp1, 0); + EXPECT_EQ(0u, sink.GetNumFramesDropped()); + image.capture_time_ms_ = timestamp1; + callback.OnEncodedImage(image, &codec_specific, nullptr); + callback.OnEncodeStarted(timestamp2, 0); + // No OnEncodedImageCall for timestamp2. Yet, at this moment it's not known + // that frame with timestamp2 was dropped. + EXPECT_EQ(0u, sink.GetNumFramesDropped()); + callback.OnEncodeStarted(timestamp3, 0); + image.capture_time_ms_ = timestamp3; + callback.OnEncodedImage(image, &codec_specific, nullptr); + EXPECT_EQ(1u, sink.GetNumFramesDropped()); + callback.OnEncodeStarted(timestamp4, 0); + image.capture_time_ms_ = timestamp4; + callback.OnEncodedImage(image, &codec_specific, nullptr); + EXPECT_EQ(1u, sink.GetNumFramesDropped()); +} + } // namespace test } // namespace webrtc diff --git a/modules/video_coding/include/video_coding_defines.h b/modules/video_coding/include/video_coding_defines.h index 7209792e91..5bf019df1d 100644 --- a/modules/video_coding/include/video_coding_defines.h +++ b/modules/video_coding/include/video_coding_defines.h @@ -45,6 +45,8 @@ enum { // |kDefaultOutliserFrameSizePercent| in size of average frame. kDefaultTimingFramesDelayMs = 200, kDefaultOutlierFrameSizePercent = 250, + // Maximum number of frames for what we store encode start timing information. + kMaxEncodeStartTimeListSize = 50, }; enum VCMVideoProtection { diff --git a/modules/video_coding/video_sender.cc b/modules/video_coding/video_sender.cc index fd35245e74..5b7bcdafe9 100644 --- a/modules/video_coding/video_sender.cc +++ b/modules/video_coding/video_sender.cc @@ -324,7 +324,8 @@ int32_t VideoSender::AddVideoFrame(const VideoFrame& videoFrame, << " loss rate " << encoder_params.loss_rate << " rtt " << encoder_params.rtt << " input frame rate " << encoder_params.input_frame_rate; - post_encode_callback_->OnDroppedFrame(); + post_encode_callback_->OnDroppedFrame( + EncodedImageCallback::DropReason::kDroppedByMediaOptimizations); return VCM_OK; } // TODO(pbos): Make sure setting send codec is synchronized with video diff --git a/video/send_statistics_proxy.cc b/video/send_statistics_proxy.cc index d72b741b81..04f907e3c3 100644 --- a/video/send_statistics_proxy.cc +++ b/video/send_statistics_proxy.cc @@ -560,6 +560,23 @@ void SendStatisticsProxy::UmaSamplesContainer::UpdateHistograms( << fec_bytes_per_sec.ToStringWithMultiplier(8); } } + LOG(LS_INFO) << "Frames encoded " << current_stats.frames_encoded; + LOG(LS_INFO) << uma_prefix_ << "DroppedFrames.Capturer " + << current_stats.frames_dropped_by_capturer; + RTC_HISTOGRAMS_COUNTS_1000(kIndex, uma_prefix_ + "DroppedFrames.Capturer", + current_stats.frames_dropped_by_capturer); + LOG(LS_INFO) << uma_prefix_ << "DroppedFrames.EncoderQueue " + << current_stats.frames_dropped_by_encoder_queue; + RTC_HISTOGRAMS_COUNTS_1000(kIndex, uma_prefix_ + "DroppedFrames.EncoderQueue", + current_stats.frames_dropped_by_encoder_queue); + LOG(LS_INFO) << uma_prefix_ << "DroppedFrames.Encoder " + << current_stats.frames_dropped_by_encoder; + RTC_HISTOGRAMS_COUNTS_1000(kIndex, uma_prefix_ + "DroppedFrames.Encoder", + current_stats.frames_dropped_by_encoder); + LOG(LS_INFO) << uma_prefix_ << "DroppedFrames.Ratelimiter " + << current_stats.frames_dropped_by_rate_limiter; + RTC_HISTOGRAMS_COUNTS_1000(kIndex, uma_prefix_ + "DroppedFrames.Ratelimiter", + current_stats.frames_dropped_by_rate_limiter); } void SendStatisticsProxy::OnEncoderReconfigured( @@ -860,6 +877,26 @@ void SendStatisticsProxy::OnIncomingFrame(int width, int height) { } } +void SendStatisticsProxy::OnFrameDroppedBySource() { + rtc::CritScope lock(&crit_); + ++stats_.frames_dropped_by_capturer; +} + +void SendStatisticsProxy::OnFrameDroppedInEncoderQueue() { + rtc::CritScope lock(&crit_); + ++stats_.frames_dropped_by_encoder_queue; +} + +void SendStatisticsProxy::OnFrameDroppedByEncoder() { + rtc::CritScope lock(&crit_); + ++stats_.frames_dropped_by_encoder; +} + +void SendStatisticsProxy::OnFrameDroppedByMediaOptimizations() { + rtc::CritScope lock(&crit_); + ++stats_.frames_dropped_by_rate_limiter; +} + void SendStatisticsProxy::SetAdaptationStats( const VideoStreamEncoder::AdaptCounts& cpu_counts, const VideoStreamEncoder::AdaptCounts& quality_counts) { diff --git a/video/send_statistics_proxy.h b/video/send_statistics_proxy.h index fb133de932..19c8ca7d62 100644 --- a/video/send_statistics_proxy.h +++ b/video/send_statistics_proxy.h @@ -57,6 +57,12 @@ class SendStatisticsProxy : public CpuOveruseMetricsObserver, // Used to update incoming frame rate. void OnIncomingFrame(int width, int height); + // Dropped frame stats. + void OnFrameDroppedBySource(); + void OnFrameDroppedInEncoderQueue(); + void OnFrameDroppedByEncoder(); + void OnFrameDroppedByMediaOptimizations(); + // Adaptation stats. void SetAdaptationStats( const VideoStreamEncoder::AdaptCounts& cpu_counts, diff --git a/video/video_stream_encoder.cc b/video/video_stream_encoder.cc index f8396654ec..3793737225 100644 --- a/video/video_stream_encoder.cc +++ b/video/video_stream_encoder.cc @@ -149,6 +149,7 @@ class VideoStreamEncoder::EncodeTask : public rtc::QueuedTask { LOG(LS_VERBOSE) << "Incoming frame dropped due to that the encoder is blocked."; ++video_stream_encoder_->dropped_frame_count_; + video_stream_encoder_->stats_proxy_->OnFrameDroppedInEncoderQueue(); } if (log_stats_) { LOG(LS_INFO) << "Number of frames: captured " @@ -723,6 +724,10 @@ void VideoStreamEncoder::OnFrame(const VideoFrame& video_frame) { incoming_frame, this, rtc::TimeMicros(), log_stats))); } +void VideoStreamEncoder::OnDiscardedFrame() { + stats_proxy_->OnFrameDroppedBySource(); +} + bool VideoStreamEncoder::EncoderPaused() const { RTC_DCHECK_RUN_ON(&encoder_queue_); // Pause video if paused by caller or as long as the network is down or the @@ -861,12 +866,20 @@ EncodedImageCallback::Result VideoStreamEncoder::OnEncodedImage( return result; } -void VideoStreamEncoder::OnDroppedFrame() { - encoder_queue_.PostTask([this] { - RTC_DCHECK_RUN_ON(&encoder_queue_); - if (quality_scaler_) - quality_scaler_->ReportDroppedFrame(); - }); +void VideoStreamEncoder::OnDroppedFrame(DropReason reason) { + switch (reason) { + case DropReason::kDroppedByMediaOptimizations: + stats_proxy_->OnFrameDroppedByMediaOptimizations(); + encoder_queue_.PostTask([this] { + RTC_DCHECK_RUN_ON(&encoder_queue_); + if (quality_scaler_) + quality_scaler_->ReportDroppedFrame(); + }); + break; + case DropReason::kDroppedByEncoder: + stats_proxy_->OnFrameDroppedByEncoder(); + break; + } } void VideoStreamEncoder::OnReceivedIntraFrameRequest(size_t stream_index) { diff --git a/video/video_stream_encoder.h b/video/video_stream_encoder.h index 1e00397d93..7c6ac6c50c 100644 --- a/video/video_stream_encoder.h +++ b/video/video_stream_encoder.h @@ -159,6 +159,7 @@ class VideoStreamEncoder : public rtc::VideoSinkInterface, // Implements VideoSinkInterface. void OnFrame(const VideoFrame& video_frame) override; + void OnDiscardedFrame() override; void EncodeVideoFrame(const VideoFrame& frame, int64_t time_when_posted_in_ms); @@ -169,7 +170,7 @@ class VideoStreamEncoder : public rtc::VideoSinkInterface, const CodecSpecificInfo* codec_specific_info, const RTPFragmentationHeader* fragmentation) override; - void OnDroppedFrame() override; + void OnDroppedFrame(EncodedImageCallback::DropReason reason) override; bool EncoderPaused() const; void TraceFrameDropStart();