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

@@ -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.

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);
 }

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);
+  FillSenderStats(info, log_stats);
-  FillReceiverStats(info);
+  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<uint32_t, WebRtcVideoSendStream*>::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<uint32_t, WebRtcVideoReceiveStream*>::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
+VideoSenderInfo WebRtcVideoChannel2::WebRtcVideoSendStream::GetVideoSenderInfo(
-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;
 }
 

webrtc/media/engine/webrtcvideoengine2.h

@@ -274,7 +274,7 @@ class WebRtcVideoChannel2 : public VideoMediaChannel, public webrtc::Transport {
     void OnLoadUpdate(Load load) override;
 
     const std::vector<uint32_t>& 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<cricket::VideoFrame>* 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<VideoCodecSettings> before,
                                        std::vector<VideoCodecSettings> after);
 
-  void FillSenderStats(VideoMediaInfo* info);
+  void FillSenderStats(VideoMediaInfo* info, bool log_stats);
-  void FillReceiverStats(VideoMediaInfo* info);
+  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

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);

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() &&
+      config_.rtp.ssrcs.end()) {
-      std::find(config_.rtp.rtx.ssrcs.begin(),
+    if (std::find(config_.rtp.rtx.ssrcs.begin(), config_.rtp.rtx.ssrcs.end(),
-                config_.rtp.rtx.ssrcs.end(),
+                  ssrc) == config_.rtp.rtx.ssrcs.end()) {
-                ssrc) == config_.rtp.rtx.ssrcs.end()) {
+      return nullptr;
-    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) {

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);

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;

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) {

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<int>::max();
 
     uint32_t ssrc = 0;

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;