Extra logging for HW codec.

talk/app/webrtc/java/jni/androidmediaencoder_jni.cc

 /*
  * libjingle
  * Copyright 2015 Google Inc.
  *
  * Redistribution and use in source and binary forms, with or without
  * modification, are permitted provided that the following conditions are met:
  *
  *  1. Redistributions of source code must retain the above copyright notice,
  *     this list of conditions and the following disclaimer.
  *  2. Redistributions in binary form must reproduce the above copyright notice,
@@ skipping 170 matching lines @@
   jlong GetOutputBufferInfoPresentationTimestampUs(
       JNIEnv* jni, jobject j_output_buffer_info);
 
   // Deliver any outputs pending in the MediaCodec to our |callback_| and return
   // true on success.
   bool DeliverPendingOutputs(JNIEnv* jni);
 
   // Search for H.264 start codes.
   int32_t NextNaluPosition(uint8_t *buffer, size_t buffer_size);
 
+  // Displays encoder statistics.
+  void LogStatistics(bool force_log);
+
   // Type of video codec.
   VideoCodecType codecType_;
 
   // Valid all the time since RegisterEncodeCompleteCallback() Invoke()s to
   // |codec_thread_| synchronously.
   webrtc::EncodedImageCallback* callback_;
 
   // State that is constant for the lifetime of this object once the ctor
   // returns.
   scoped_ptr<Thread> codec_thread_;  // Thread on which to operate MediaCodec.
@@ skipping 394 matching lines @@
     const std::vector<webrtc::FrameType>* frame_types) {
   RTC_DCHECK(codec_thread_checker_.CalledOnValidThread());
   JNIEnv* jni = AttachCurrentThreadIfNeeded();
   ScopedLocalRefFrame local_ref_frame(jni);
 
   if (!inited_) {
     return WEBRTC_VIDEO_CODEC_UNINITIALIZED;
   }
 
   bool send_key_frame = false;
-  if (codecType_ == kVideoCodecVP8 && codec_mode_ == webrtc::kRealtimeVideo) {
+  if ((codecType_ == kVideoCodecVP8 || codecType_ == kVideoCodecH264)

[perkj_webrtc, 2016/02/01 09:20:53]

remove check for codectType_ ? Always do this regardless of codec type.
Does this make the quality better for bad network conditions with H264? I
assigned a bug regarding that to pbos.

[AlexG, 2016/02/01 20:13:35]

Done.

+      && codec_mode_ == webrtc::kRealtimeVideo) {
     ++frames_received_since_last_key_;
     int64_t now_ms = GetCurrentTimeMs();
     if (last_frame_received_ms_ != -1 &&
         (now_ms - last_frame_received_ms_) > kFrameDiffThresholdMs) {
       // Add limit to prevent triggering a key for every frame for very low
       // framerates (e.g. if frame diff > kFrameDiffThresholdMs).
       if (frames_received_since_last_key_ > kMinKeyFrameInterval) {
         ALOGD << "Send key, frame diff: " << (now_ms - last_frame_received_ms_);
         send_key_frame = true;
       }
@@ skipping 25 matching lines @@
   RTC_CHECK(frame_types->size() == 1) << "Unexpected stream count";
 
   // Check if we accumulated too many frames in encoder input buffers
   // or the encoder latency exceeds 70 ms and drop frame if so.
   if (frames_in_queue_ > 0 && last_input_timestamp_ms_ >= 0) {
     int encoder_latency_ms = last_input_timestamp_ms_ -
         last_output_timestamp_ms_;
     if (frames_in_queue_ > MAX_ENCODER_Q_SIZE ||
         encoder_latency_ms > MAX_ENCODER_LATENCY_MS) {
       ALOGD << "Drop frame - encoder is behind by " << encoder_latency_ms <<
-          " ms. Q size: " << frames_in_queue_ << ". Consecutive drops: " <<
-          consecutive_full_queue_frame_drops_;
+          " ms. Q size: " << frames_in_queue_ << ". TS: " <<
+          (int)(current_timestamp_us_ / 1000) <<  ". Fps: " << last_set_fps_ <<
+          ". Consecutive drops: " << consecutive_full_queue_frame_drops_ ;
       current_timestamp_us_ += rtc::kNumMicrosecsPerSec / last_set_fps_;
       consecutive_full_queue_frame_drops_++;
       if (consecutive_full_queue_frame_drops_ >=
           ENCODER_STALL_FRAMEDROP_THRESHOLD) {
         ALOGE << "Encoder got stuck. Reset.";
         ResetCodecOnCodecThread();
         return WEBRTC_VIDEO_CODEC_ERROR;
       }
       frames_dropped_media_encoder_++;
       OnDroppedFrame();
@@ skipping 88 matching lines @@
   const bool is_texture_frame = frame.native_handle() != nullptr;
   const bool reconfigure_due_to_format = is_texture_frame != use_surface_;
   const bool reconfigure_due_to_size =
       frame.width() != width_ || frame.height() != height_;
 
   if (reconfigure_due_to_format) {
       ALOGD << "Reconfigure encoder due to format change. "
             << (use_surface_ ?
                 "Reconfiguring to encode from byte buffer." :
                 "Reconfiguring to encode from texture.");
+      LogStatistics(true);
   }
   if (reconfigure_due_to_size) {
-    ALOGD << "Reconfigure encoder due to frame resolution change from "
+    ALOGW << "Reconfigure encoder due to frame resolution change from "
         << width_ << " x " << height_ << " to " << frame.width() << " x "
         << frame.height();
+    LogStatistics(true);
     width_ = frame.width();
     height_ = frame.height();
   }
 
   if (!reconfigure_due_to_format && !reconfigure_due_to_size)
     return true;
 
   ReleaseOnCodecThread();
 
   return InitEncodeOnCodecThread(width_, height_, 0, 0 , is_texture_frame) ==
@@ skipping 306 matching lines @@
     if (!success) {
       ResetCodecOnCodecThread();
       return false;
     }
 
     // Calculate and print encoding statistics - every 3 seconds.
     frames_encoded_++;
     current_frames_++;
     current_bytes_ += payload_size;
     current_encoding_time_ms_ += frame_encoding_time_ms;
-    int statistic_time_ms = GetCurrentTimeMs() - start_time_ms_;
-    if (statistic_time_ms >= kMediaCodecStatisticsIntervalMs &&
-        current_frames_ > 0) {
-      ALOGD << "Encoded frames: " << frames_encoded_ << ". Bitrate: " <<
-          (current_bytes_ * 8 / statistic_time_ms) <<
-          ", target: " << last_set_bitrate_kbps_ << " kbps, fps: " <<
-          ((current_frames_ * 1000 + statistic_time_ms / 2) / statistic_time_ms)
-          << ", encTime: " <<
-          (current_encoding_time_ms_ / current_frames_) << ". QP: " <<
-          (current_acc_qp_ / current_frames_) <<  " for last " <<
-          statistic_time_ms << " ms.";
-      start_time_ms_ = GetCurrentTimeMs();
-      current_frames_ = 0;
-      current_bytes_ = 0;
-      current_acc_qp_ = 0;
-      current_encoding_time_ms_ = 0;
-    }
+    LogStatistics(false);
 
     if (callback_status > 0) {
       drop_next_input_frame_ = true;
       // Theoretically could handle callback_status<0 here, but unclear what
       // that would mean for us.
     }
   }
+  return true;
+}
 
-  return true;
+void MediaCodecVideoEncoder::LogStatistics(bool force_log) {
+  int statistic_time_ms = GetCurrentTimeMs() - start_time_ms_;
+  if ((statistic_time_ms >= kMediaCodecStatisticsIntervalMs || force_log) &&
+      current_frames_ > 0 && statistic_time_ms > 0) {
+    ALOGD << "Encoded frames: " << frames_encoded_ << ". Bitrate: " <<
+        (current_bytes_ * 8 / statistic_time_ms) <<
+        ", target: " << last_set_bitrate_kbps_ << " kbps, fps: " <<
+        ((current_frames_ * 1000 + statistic_time_ms / 2) / statistic_time_ms)
+        << ", encTime: " <<

[perkj_webrtc, 2016/02/01 09:20:53]

Can this be aligned in a more readable way.

[AlexG, 2016/02/01 20:13:35]

Done. And for other similar logs in encoder and decoder code.

+        (current_encoding_time_ms_ / current_frames_) << ". QP: " <<
+        (current_acc_qp_ / current_frames_) <<  " for last " <<
+        statistic_time_ms << " ms.";
+    start_time_ms_ = GetCurrentTimeMs();

[perkj_webrtc, 2016/02/01 09:20:53]

change name of start_time_ms_  to something more descriptive. How about
log_statistics_time_ ? 

[AlexG, 2016/02/01 20:13:35]

Done.

+    current_frames_ = 0;
+    current_bytes_ = 0;
+    current_acc_qp_ = 0;
+    current_encoding_time_ms_ = 0;
+  }
 }
 
 int32_t MediaCodecVideoEncoder::NextNaluPosition(
     uint8_t *buffer, size_t buffer_size) {
   if (buffer_size < H264_SC_LENGTH) {
     return -1;
   }
   uint8_t *head = buffer;
   // Set end buffer pointer to 4 bytes before actual buffer end so we can
   // access head[1], head[2] and head[3] in a loop without buffer overrun.
@@ skipping 109 matching lines @@
 }
 
 void MediaCodecVideoEncoderFactory::DestroyVideoEncoder(
     webrtc::VideoEncoder* encoder) {
   ALOGD << "Destroy video encoder.";
   delete encoder;
 }
 
 }  // namespace webrtc_jni