Extra logging for HW codec.

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

Index: talk/app/webrtc/java/jni/androidmediaencoder_jni.cc
diff --git a/talk/app/webrtc/java/jni/androidmediaencoder_jni.cc b/talk/app/webrtc/java/jni/androidmediaencoder_jni.cc
index 05e81458a5a4cdd83dd534497f1d53c3ce7bcea2..551083174ede18dc646ed7708454d4ed3d54a3b9 100644
--- a/talk/app/webrtc/java/jni/androidmediaencoder_jni.cc
+++ b/talk/app/webrtc/java/jni/androidmediaencoder_jni.cc
@@ -188,6 +188,9 @@ class MediaCodecVideoEncoder : public webrtc::VideoEncoder,
   // 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_;
 
@@ -602,7 +605,8 @@ int32_t MediaCodecVideoEncoder::EncodeOnCodecThread(
   }
 
   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 &&
@@ -648,8 +652,9 @@ int32_t MediaCodecVideoEncoder::EncodeOnCodecThread(
     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_ >=
@@ -758,11 +763,13 @@ bool MediaCodecVideoEncoder::MaybeReconfigureEncoderOnCodecThread(
             << (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();
   }
@@ -1089,23 +1096,7 @@ bool MediaCodecVideoEncoder::DeliverPendingOutputs(JNIEnv* jni) {
     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;
@@ -1113,10 +1104,29 @@ bool MediaCodecVideoEncoder::DeliverPendingOutputs(JNIEnv* jni) {
       // that would mean for us.
     }
   }
-
   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) {