From 2e5cfcd6c27861fb1839f12bb2268d01d6f5a85e Mon Sep 17 00:00:00 2001 From: asapersson Date: Thu, 11 Aug 2016 08:41:18 -0700 Subject: [PATCH] Add periodic logging of video stats. Add ToString method to: Call::Stats, VideoSendStream::Stats, VideoReceiveStream::Stats and log stats periodically (every 10 seconds). BUG= Review-Url: https://codereview.webrtc.org/2133073002 Cr-Commit-Position: refs/heads/master@{#13727} --- webrtc/call.h | 2 + webrtc/call/call.cc | 12 +++++ webrtc/media/engine/webrtcvideoengine2.cc | 50 +++++++++++++++---- webrtc/media/engine/webrtcvideoengine2.h | 9 ++-- webrtc/video/receive_statistics_proxy.cc | 2 + webrtc/video/send_statistics_proxy.cc | 18 ++++--- .../video/send_statistics_proxy_unittest.cc | 5 ++ webrtc/video/video_receive_stream.cc | 28 +++++++++++ webrtc/video/video_send_stream.cc | 40 +++++++++++++++ webrtc/video_receive_stream.h | 5 ++ webrtc/video_send_stream.h | 4 ++ 11 files changed, 155 insertions(+), 20 deletions(-) diff --git a/webrtc/call.h b/webrtc/call.h index 779ffe9d0d..ec43b18ad4 100644 --- a/webrtc/call.h +++ b/webrtc/call.h @@ -92,6 +92,8 @@ class Call { }; struct Stats { + std::string ToString(int64_t time_ms) const; + int send_bandwidth_bps = 0; // Estimated available send bandwidth. int max_padding_bitrate_bps = 0; // Cumulative configured max padding. int recv_bandwidth_bps = 0; // Estimated available receive bandwidth. diff --git a/webrtc/call/call.cc b/webrtc/call/call.cc index f50a8d69a5..f6354ade28 100644 --- a/webrtc/call/call.cc +++ b/webrtc/call/call.cc @@ -203,6 +203,18 @@ class Call : public webrtc::Call, }; } // namespace internal +std::string Call::Stats::ToString(int64_t time_ms) const { + std::stringstream ss; + ss << "Call stats: " << time_ms << ", {"; + ss << "send_bw_bps: " << send_bandwidth_bps << ", "; + ss << "recv_bw_bps: " << recv_bandwidth_bps << ", "; + ss << "max_pad_bps: " << max_padding_bitrate_bps << ", "; + ss << "pacer_delay_ms: " << pacer_delay_ms << ", "; + ss << "rtt_ms: " << rtt_ms; + ss << '}'; + return ss.str(); +} + Call* Call::Create(const Call::Config& config) { return new internal::Call(config); } diff --git a/webrtc/media/engine/webrtcvideoengine2.cc b/webrtc/media/engine/webrtcvideoengine2.cc index dc9cdf0422..4a72ef6139 100644 --- a/webrtc/media/engine/webrtcvideoengine2.cc +++ b/webrtc/media/engine/webrtcvideoengine2.cc @@ -342,6 +342,9 @@ static const int kDefaultRtcpReceiverReportSsrc = 1; // Down grade resolution at most 2 times for CPU reasons. static const int kMaxCpuDowngrades = 2; +// Minimum time interval for logging stats. +static const int64_t kStatsLogIntervalMs = 10000; + // Adds |codec| to |list|, and also adds an RTX codec if |codec|'s name is // recognized. // TODO(deadbeef): Should we add RTX codecs for external codecs whose names we @@ -676,7 +679,8 @@ WebRtcVideoChannel2::WebRtcVideoChannel2( external_encoder_factory_(external_encoder_factory), external_decoder_factory_(external_decoder_factory), default_send_options_(options), - red_disabled_by_remote_side_(false) { + red_disabled_by_remote_side_(false), + last_stats_log_ms_(-1) { RTC_DCHECK(thread_checker_.CalledOnValidThread()); rtcp_receiver_report_ssrc_ = kDefaultRtcpReceiverReportSsrc; @@ -1344,9 +1348,19 @@ bool WebRtcVideoChannel2::SetSink(uint32_t ssrc, bool WebRtcVideoChannel2::GetStats(VideoMediaInfo* info) { TRACE_EVENT0("webrtc", "WebRtcVideoChannel2::GetStats"); + + // Log stats periodically. + bool log_stats = false; + int64_t now_ms = rtc::TimeMillis(); + if (last_stats_log_ms_ == -1 || + now_ms - last_stats_log_ms_ > kStatsLogIntervalMs) { + last_stats_log_ms_ = now_ms; + log_stats = true; + } + info->Clear(); - FillSenderStats(info); - FillReceiverStats(info); + FillSenderStats(info, log_stats); + FillReceiverStats(info, log_stats); webrtc::Call::Stats stats = call_->GetStats(); FillBandwidthEstimationStats(stats, info); if (stats.rtt_ms != -1) { @@ -1354,24 +1368,32 @@ bool WebRtcVideoChannel2::GetStats(VideoMediaInfo* info) { info->senders[i].rtt_ms = stats.rtt_ms; } } + + if (log_stats) + LOG(LS_INFO) << stats.ToString(now_ms); + return true; } -void WebRtcVideoChannel2::FillSenderStats(VideoMediaInfo* video_media_info) { +void WebRtcVideoChannel2::FillSenderStats(VideoMediaInfo* video_media_info, + bool log_stats) { rtc::CritScope stream_lock(&stream_crit_); for (std::map::iterator it = send_streams_.begin(); it != send_streams_.end(); ++it) { - video_media_info->senders.push_back(it->second->GetVideoSenderInfo()); + video_media_info->senders.push_back( + it->second->GetVideoSenderInfo(log_stats)); } } -void WebRtcVideoChannel2::FillReceiverStats(VideoMediaInfo* video_media_info) { +void WebRtcVideoChannel2::FillReceiverStats(VideoMediaInfo* video_media_info, + bool log_stats) { rtc::CritScope stream_lock(&stream_crit_); for (std::map::iterator it = receive_streams_.begin(); it != receive_streams_.end(); ++it) { - video_media_info->receivers.push_back(it->second->GetVideoReceiverInfo()); + video_media_info->receivers.push_back( + it->second->GetVideoReceiverInfo(log_stats)); } } @@ -2096,8 +2118,8 @@ void WebRtcVideoChannel2::WebRtcVideoSendStream::OnLoadUpdate(Load load) { source_->AddOrUpdateSink(this, sink_wants_); } -VideoSenderInfo -WebRtcVideoChannel2::WebRtcVideoSendStream::GetVideoSenderInfo() { +VideoSenderInfo WebRtcVideoChannel2::WebRtcVideoSendStream::GetVideoSenderInfo( + bool log_stats) { VideoSenderInfo info; webrtc::VideoSendStream::Stats stats; RTC_DCHECK(thread_checker_.CalledOnValidThread()); @@ -2123,6 +2145,10 @@ WebRtcVideoChannel2::WebRtcVideoSendStream::GetVideoSenderInfo() { stats = stream_->GetStats(); } + + if (log_stats) + LOG(LS_INFO) << stats.ToString(rtc::TimeMillis()); + info.adapt_changes = number_of_cpu_adapt_changes_; info.adapt_reason = cpu_restricted_counter_ <= 0 ? ADAPTREASON_NONE : ADAPTREASON_CPU; @@ -2512,7 +2538,8 @@ WebRtcVideoChannel2::WebRtcVideoReceiveStream::GetCodecNameFromPayloadType( } VideoReceiverInfo -WebRtcVideoChannel2::WebRtcVideoReceiveStream::GetVideoReceiverInfo() { +WebRtcVideoChannel2::WebRtcVideoReceiveStream::GetVideoReceiverInfo( + bool log_stats) { VideoReceiverInfo info; info.ssrc_groups = stream_params_.ssrc_groups; info.add_ssrc(config_.rtp.remote_ssrc); @@ -2551,6 +2578,9 @@ WebRtcVideoChannel2::WebRtcVideoReceiveStream::GetVideoReceiverInfo() { info.plis_sent = stats.rtcp_packet_type_counts.pli_packets; info.nacks_sent = stats.rtcp_packet_type_counts.nack_packets; + if (log_stats) + LOG(LS_INFO) << stats.ToString(rtc::TimeMillis()); + return info; } diff --git a/webrtc/media/engine/webrtcvideoengine2.h b/webrtc/media/engine/webrtcvideoengine2.h index 14f271f1df..9413047cb3 100644 --- a/webrtc/media/engine/webrtcvideoengine2.h +++ b/webrtc/media/engine/webrtcvideoengine2.h @@ -274,7 +274,7 @@ class WebRtcVideoChannel2 : public VideoMediaChannel, public webrtc::Transport { void OnLoadUpdate(Load load) override; const std::vector& GetSsrcs() const; - VideoSenderInfo GetVideoSenderInfo(); + VideoSenderInfo GetVideoSenderInfo(bool log_stats); void FillBandwidthEstimationInfo(BandwidthEstimationInfo* bwe_info); private: @@ -442,7 +442,7 @@ class WebRtcVideoChannel2 : public VideoMediaChannel, public webrtc::Transport { void SetSink(rtc::VideoSinkInterface* sink); - VideoReceiverInfo GetVideoReceiverInfo(); + VideoReceiverInfo GetVideoReceiverInfo(bool log_stats); // Used to disable RED/FEC when the remote description doesn't contain those // codecs. This is needed to be able to work around an RTX bug which is only @@ -514,8 +514,8 @@ class WebRtcVideoChannel2 : public VideoMediaChannel, public webrtc::Transport { static bool ReceiveCodecsHaveChanged(std::vector before, std::vector after); - void FillSenderStats(VideoMediaInfo* info); - void FillReceiverStats(VideoMediaInfo* info); + void FillSenderStats(VideoMediaInfo* info, bool log_stats); + void FillReceiverStats(VideoMediaInfo* info, bool log_stats); void FillBandwidthEstimationStats(const webrtc::Call::Stats& stats, VideoMediaInfo* info); @@ -553,6 +553,7 @@ class WebRtcVideoChannel2 : public VideoMediaChannel, public webrtc::Transport { VideoOptions default_send_options_; VideoRecvParameters recv_params_; bool red_disabled_by_remote_side_; + int64_t last_stats_log_ms_; }; } // namespace cricket diff --git a/webrtc/video/receive_statistics_proxy.cc b/webrtc/video/receive_statistics_proxy.cc index 90575436a2..9e6c380ce8 100644 --- a/webrtc/video/receive_statistics_proxy.cc +++ b/webrtc/video/receive_statistics_proxy.cc @@ -263,6 +263,8 @@ void ReceiveStatisticsProxy::OnRenderedFrame(int width, int height) { rtc::CritScope lock(&crit_); renders_fps_estimator_.Update(1, now); stats_.render_frame_rate = renders_fps_estimator_.Rate(now).value_or(0); + stats_.width = width; + stats_.height = height; render_width_counter_.Add(width); render_height_counter_.Add(height); render_fps_tracker_.AddSamples(1); diff --git a/webrtc/video/send_statistics_proxy.cc b/webrtc/video/send_statistics_proxy.cc index dfa7185f36..9325b2f7dd 100644 --- a/webrtc/video/send_statistics_proxy.cc +++ b/webrtc/video/send_statistics_proxy.cc @@ -402,15 +402,21 @@ VideoSendStream::StreamStats* SendStatisticsProxy::GetStatsEntry( if (it != stats_.substreams.end()) return &it->second; + bool is_rtx = false; if (std::find(config_.rtp.ssrcs.begin(), config_.rtp.ssrcs.end(), ssrc) == - config_.rtp.ssrcs.end() && - std::find(config_.rtp.rtx.ssrcs.begin(), - config_.rtp.rtx.ssrcs.end(), - ssrc) == config_.rtp.rtx.ssrcs.end()) { - return nullptr; + config_.rtp.ssrcs.end()) { + if (std::find(config_.rtp.rtx.ssrcs.begin(), config_.rtp.rtx.ssrcs.end(), + ssrc) == config_.rtp.rtx.ssrcs.end()) { + return nullptr; + } + is_rtx = true; } - return &stats_.substreams[ssrc]; // Insert new entry and return ptr. + // Insert new entry and return ptr. + VideoSendStream::StreamStats* entry = &stats_.substreams[ssrc]; + entry->is_rtx = is_rtx; + + return entry; } void SendStatisticsProxy::OnInactiveSsrc(uint32_t ssrc) { diff --git a/webrtc/video/send_statistics_proxy_unittest.cc b/webrtc/video/send_statistics_proxy_unittest.cc index b1bf161d80..1e9287749e 100644 --- a/webrtc/video/send_statistics_proxy_unittest.cc +++ b/webrtc/video/send_statistics_proxy_unittest.cc @@ -45,6 +45,10 @@ class SendStatisticsProxyTest : public ::testing::Test { &fake_clock_, GetTestConfig(), VideoEncoderConfig::ContentType::kRealtimeVideo)); expected_ = VideoSendStream::Stats(); + for (const auto& ssrc : config_.rtp.ssrcs) + expected_.substreams[ssrc].is_rtx = false; + for (const auto& ssrc : config_.rtp.rtx.ssrcs) + expected_.substreams[ssrc].is_rtx = true; } VideoSendStream::Config GetTestConfig() { @@ -73,6 +77,7 @@ class SendStatisticsProxyTest : public ::testing::Test { const VideoSendStream::StreamStats& a = it->second; const VideoSendStream::StreamStats& b = corresponding_it->second; + EXPECT_EQ(a.is_rtx, b.is_rtx); EXPECT_EQ(a.frame_counts.key_frames, b.frame_counts.key_frames); EXPECT_EQ(a.frame_counts.delta_frames, b.frame_counts.delta_frames); EXPECT_EQ(a.total_bitrate_bps, b.total_bitrate_bps); diff --git a/webrtc/video/video_receive_stream.cc b/webrtc/video/video_receive_stream.cc index 4b5dd754c5..86bb76f4bb 100644 --- a/webrtc/video/video_receive_stream.cc +++ b/webrtc/video/video_receive_stream.cc @@ -116,6 +116,34 @@ std::string VideoReceiveStream::Config::Rtp::ToString() const { return ss.str(); } +std::string VideoReceiveStream::Stats::ToString(int64_t time_ms) const { + std::stringstream ss; + ss << "VideoReceiveStream stats: " << time_ms << ", {ssrc: " << ssrc << ", "; + ss << "total_bps: " << total_bitrate_bps << ", "; + ss << "width: " << width << ", "; + ss << "height: " << height << ", "; + ss << "key: " << frame_counts.key_frames << ", "; + ss << "delta: " << frame_counts.delta_frames << ", "; + ss << "network_fps: " << network_frame_rate << ", "; + ss << "decode_fps: " << decode_frame_rate << ", "; + ss << "render_fps: " << render_frame_rate << ", "; + ss << "decode_ms: " << decode_ms << ", "; + ss << "max_decode_ms: " << max_decode_ms << ", "; + ss << "cur_delay_ms: " << current_delay_ms << ", "; + ss << "targ_delay_ms: " << target_delay_ms << ", "; + ss << "jb_delay_ms: " << jitter_buffer_ms << ", "; + ss << "min_playout_delay_ms: " << min_playout_delay_ms << ", "; + ss << "discarded: " << discarded_packets << ", "; + ss << "sync_offset_ms: " << sync_offset_ms << ", "; + ss << "cum_loss: " << rtcp_stats.cumulative_lost << ", "; + ss << "max_ext_seq: " << rtcp_stats.extended_max_sequence_number << ", "; + ss << "nack: " << rtcp_packet_type_counts.nack_packets << ", "; + ss << "fir: " << rtcp_packet_type_counts.fir_packets << ", "; + ss << "pli: " << rtcp_packet_type_counts.pli_packets; + ss << '}'; + return ss.str(); +} + namespace { VideoCodec CreateDecoderVideoCodec(const VideoReceiveStream::Decoder& decoder) { VideoCodec codec; diff --git a/webrtc/video/video_send_stream.cc b/webrtc/video/video_send_stream.cc index cb9ff4100d..a46bc859e7 100644 --- a/webrtc/video/video_send_stream.cc +++ b/webrtc/video/video_send_stream.cc @@ -162,6 +162,46 @@ std::string VideoSendStream::Config::ToString() const { return ss.str(); } +std::string VideoSendStream::Stats::ToString(int64_t time_ms) const { + std::stringstream ss; + ss << "VideoSendStream stats: " << time_ms << ", {"; + ss << "input_fps: " << input_frame_rate << ", "; + ss << "encode_fps: " << encode_frame_rate << ", "; + ss << "encode_ms: " << avg_encode_time_ms << ", "; + ss << "encode_usage_perc: " << encode_usage_percent << ", "; + ss << "target_bps: " << target_media_bitrate_bps << ", "; + ss << "media_bps: " << media_bitrate_bps << ", "; + ss << "suspended: " << (suspended ? "true" : "false") << ", "; + ss << "bw_adapted: " << (bw_limited_resolution ? "true" : "false"); + ss << '}'; + for (const auto& substream : substreams) { + if (!substream.second.is_rtx) { + ss << " {ssrc: " << substream.first << ", "; + ss << substream.second.ToString(); + ss << '}'; + } + } + return ss.str(); +} + +std::string VideoSendStream::StreamStats::ToString() const { + std::stringstream ss; + ss << "width: " << width << ", "; + ss << "height: " << height << ", "; + ss << "key: " << frame_counts.key_frames << ", "; + ss << "delta: " << frame_counts.delta_frames << ", "; + ss << "total_bps: " << total_bitrate_bps << ", "; + ss << "retransmit_bps: " << retransmit_bitrate_bps << ", "; + ss << "avg_delay_ms: " << avg_delay_ms << ", "; + ss << "max_delay_ms: " << max_delay_ms << ", "; + ss << "cum_loss: " << rtcp_stats.cumulative_lost << ", "; + ss << "max_ext_seq: " << rtcp_stats.extended_max_sequence_number << ", "; + ss << "nack: " << rtcp_packet_type_counts.nack_packets << ", "; + ss << "fir: " << rtcp_packet_type_counts.fir_packets << ", "; + ss << "pli: " << rtcp_packet_type_counts.pli_packets; + return ss.str(); +} + namespace { VideoCodecType PayloadNameToCodecType(const std::string& payload_name) { diff --git a/webrtc/video_receive_stream.h b/webrtc/video_receive_stream.h index 49466ffcbd..0adcf3fc0d 100644 --- a/webrtc/video_receive_stream.h +++ b/webrtc/video_receive_stream.h @@ -48,6 +48,8 @@ class VideoReceiveStream { }; struct Stats { + std::string ToString(int64_t time_ms) const; + int network_frame_rate = 0; int decode_frame_rate = 0; int render_frame_rate = 0; @@ -68,6 +70,9 @@ class VideoReceiveStream { int total_bitrate_bps = 0; int discarded_packets = 0; + int width = 0; + int height = 0; + int sync_offset_ms = std::numeric_limits::max(); uint32_t ssrc = 0; diff --git a/webrtc/video_send_stream.h b/webrtc/video_send_stream.h index 886367f0a5..b79f6dd30e 100644 --- a/webrtc/video_send_stream.h +++ b/webrtc/video_send_stream.h @@ -41,7 +41,10 @@ class VideoCaptureInput { class VideoSendStream { public: struct StreamStats { + std::string ToString() const; + FrameCounts frame_counts; + bool is_rtx = false; int width = 0; int height = 0; // TODO(holmer): Move bitrate_bps out to the webrtc::Call layer. @@ -55,6 +58,7 @@ class VideoSendStream { }; struct Stats { + std::string ToString(int64_t time_ms) const; std::string encoder_implementation_name = "unknown"; int input_frame_rate = 0; int encode_frame_rate = 0;