Add periodic logging of video stats.

webrtc/media/engine/webrtcvideoengine2.cc

 /*
  *  Copyright (c) 2014 The WebRTC project authors. All Rights Reserved.
  *
  *  Use of this source code is governed by a BSD-style license
  *  that can be found in the LICENSE file in the root of the source
  *  tree. An additional intellectual property rights grant can be found
  *  in the file PATENTS.  All contributing project authors may
  *  be found in the AUTHORS file in the root of the source tree.
  */
 
@@ skipping 324 matching lines @@
 // duration hasn't been implemented.
 static const int kNackHistoryMs = 1000;
 
 static const int kDefaultQpMax = 56;
 
 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 = 8000;
+
 // 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
 // don't recognize?
 void AddCodecAndMaybeRtxCodec(const VideoCodec& codec,
                               std::vector<VideoCodec>* codecs) {
   codecs->push_back(codec);
   int rtx_payload_type = 0;
   if (CodecNamesEq(codec.name, kVp8CodecName)) {
     rtx_payload_type = kDefaultRtxVp8PlType;
@@ skipping 314 matching lines @@
     const std::vector<VideoCodec>& recv_codecs,
     WebRtcVideoEncoderFactory* external_encoder_factory,
     WebRtcVideoDecoderFactory* external_decoder_factory)
     : VideoMediaChannel(config),
       call_(call),
       unsignalled_ssrc_handler_(&default_unsignalled_ssrc_handler_),
       video_config_(config.video),
       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;
   sending_ = false;
   RTC_DCHECK(ValidateCodecFormats(recv_codecs));
   recv_codecs_ = FilterSupportedCodecs(MapCodecs(recv_codecs));
 }
 
 WebRtcVideoChannel2::~WebRtcVideoChannel2() {
   for (auto& kv : send_streams_)
@@ skipping 648 matching lines @@
     return false;
   }
 
   it->second->SetSink(sink);
   return true;
 }
 
 bool WebRtcVideoChannel2::GetStats(VideoMediaInfo* info) {
   TRACE_EVENT0("webrtc", "WebRtcVideoChannel2::GetStats");
   info->Clear();
   FillSenderStats(info);

[mflodman, 2016/08/04 13:37:09]

We could keep track of time just here and add a "bool log" (or similar) as input
argument to all Fill*Stats(). That would ensure we log all streams at the same
time based on the same timer.

[mflodman, 2016/08/04 13:37:09]

And related, should we just enable this as is or give a heads up to users and
add this as an option for now?

[åsapersson, 2016/08/04 14:54:18]

Done.

   FillReceiverStats(info);
   webrtc::Call::Stats stats = call_->GetStats();
   FillBandwidthEstimationStats(stats, info);
   if (stats.rtt_ms != -1) {
     for (size_t i = 0; i < info->senders.size(); ++i) {
       info->senders[i].rtt_ms = stats.rtt_ms;
     }
   }
+  // Log stats periodically.
+  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(LS_INFO) << stats.ToString(now_ms);
+  }
   return true;
 }
 
 void WebRtcVideoChannel2::FillSenderStats(VideoMediaInfo* video_media_info) {
   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());
   }
@@ skipping 180 matching lines @@
     const rtc::Optional<std::vector<webrtc::RtpExtension>>& rtp_extensions,
     // TODO(deadbeef): Don't duplicate information between send_params,
     // rtp_extensions, options, etc.
     const VideoSendParameters& send_params)
     : worker_thread_(rtc::Thread::Current()),
       ssrcs_(sp.ssrcs),
       ssrc_groups_(sp.ssrc_groups),
       call_(call),
       cpu_restricted_counter_(0),
       number_of_cpu_adapt_changes_(0),
+      last_stats_log_ms_(-1),
       source_(nullptr),
       external_encoder_factory_(external_encoder_factory),
       stream_(nullptr),
       parameters_(config, options, max_bitrate_bps, codec_settings),
       rtp_parameters_(CreateRtpParametersWithOneEncoding()),
       pending_encoder_reconfiguration_(false),
       allocated_encoder_(nullptr, webrtc::kVideoCodecUnknown, false),
       sending_(false),
       last_frame_timestamp_ms_(0) {
   parameters_.config.rtp.max_packet_size = kVideoMtu;
@@ skipping 549 matching lines @@
         info.preferred_bitrate +=
             parameters_.encoder_config.streams[i].target_bitrate_bps;
       }
     }
 
     if (stream_ == NULL)
       return info;
 
     stats = stream_->GetStats();
   }
+
+  // Log stats periodically.
+  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(LS_INFO) << stats.ToString(now_ms);
+  }
+
   info.adapt_changes = number_of_cpu_adapt_changes_;
   info.adapt_reason =
       cpu_restricted_counter_ <= 0 ? ADAPTREASON_NONE : ADAPTREASON_CPU;
 
   // Get bandwidth limitation info from stream_->GetStats().
   // Input resolution (output from video_adapter) can be further scaled down or
   // higher video layer(s) can be dropped due to bitrate constraints.
   // Note, adapt_changes only include changes from the video_adapter.
   if (stats.bw_limited_resolution)
     info.adapt_reason |= ADAPTREASON_BANDWIDTH;
@@ skipping 94 matching lines @@
     bool default_stream,
     const std::vector<VideoCodecSettings>& recv_codecs,
     bool red_disabled_by_remote_side)
     : call_(call),
       stream_params_(sp),
       stream_(NULL),
       default_stream_(default_stream),
       config_(std::move(config)),
       red_disabled_by_remote_side_(red_disabled_by_remote_side),
       external_decoder_factory_(external_decoder_factory),
+      last_stats_log_ms_(-1),
       sink_(NULL),
       last_width_(-1),
       last_height_(-1),
       first_frame_timestamp_(-1),
       estimated_remote_start_ntp_time_ms_(0) {
   config_.renderer = this;
   std::vector<AllocatedDecoder> old_decoders;
   ConfigureCodecs(recv_codecs, &old_decoders);
   RecreateWebRtcStream();
   RTC_DCHECK(old_decoders.empty());
@@ skipping 279 matching lines @@
   info.jitter_buffer_ms = stats.jitter_buffer_ms;
   info.min_playout_delay_ms = stats.min_playout_delay_ms;
   info.render_delay_ms = stats.render_delay_ms;
 
   info.codec_name = GetCodecNameFromPayloadType(stats.current_payload_type);
 
   info.firs_sent = stats.rtcp_packet_type_counts.fir_packets;
   info.plis_sent = stats.rtcp_packet_type_counts.pli_packets;
   info.nacks_sent = stats.rtcp_packet_type_counts.nack_packets;
 
+  // Log stats periodically.
+  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(LS_INFO) << stats.ToString(now_ms);
+  }
+
   return info;
 }
 
 void WebRtcVideoChannel2::WebRtcVideoReceiveStream::SetFecDisabledRemotely(
     bool disable) {
   red_disabled_by_remote_side_ = disable;
   RecreateWebRtcStream();
 }
 
 WebRtcVideoChannel2::VideoCodecSettings::VideoCodecSettings()
@@ skipping 102 matching lines @@
         rtx_mapping[video_codecs[i].codec.id] !=
             fec_settings.red_payload_type) {
       video_codecs[i].rtx_payload_type = rtx_mapping[video_codecs[i].codec.id];
     }
   }
 
   return video_codecs;
 }
 
 }  // namespace cricket