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 25 matching lines @@
   enum libyuv::FourCC encoder_fourcc_;  // Encoder color space format.
   int last_set_bitrate_kbps_;  // Last-requested bitrate in kbps.
   int last_set_fps_;  // Last-requested frame rate.
   int64_t current_timestamp_us_;  // Current frame timestamps in us.
   int frames_received_;  // Number of frames received by encoder.
   int frames_encoded_;  // Number of frames encoded by encoder.
   int frames_dropped_media_encoder_;  // Number of frames dropped by encoder.
   // Number of dropped frames caused by full queue.
   int consecutive_full_queue_frame_drops_;
   int frames_in_queue_;  // Number of frames in encoder queue.
-  int64_t start_time_ms_;  // Start time for statistics.
+  int64_t stat_start_time_ms_;  // Start time for statistics.
   int current_frames_;  // Number of frames in the current statistics interval.
   int current_bytes_;  // Encoded bytes in the current statistics interval.
   int current_acc_qp_; // Accumulated QP in the current statistics interval.
   int current_encoding_time_ms_;  // Overall encoding time in the current second
   int64_t last_input_timestamp_ms_;  // Timestamp of last received yuv frame.
   int64_t last_output_timestamp_ms_;  // Timestamp of last encoded frame.
   std::vector<int32_t> timestamps_;  // Video frames timestamp queue.
   std::vector<int64_t> render_times_ms_;  // Video frames render time queue.
   std::vector<int64_t> frame_rtc_times_ms_;  // Time when video frame is sent to
                                              // encoder input.
@@ skipping 260 matching lines @@
   height_ = height;
   last_set_bitrate_kbps_ = kbps;
   last_set_fps_ = (fps < MAX_VIDEO_FPS) ? fps : MAX_VIDEO_FPS;
   yuv_size_ = width_ * height_ * 3 / 2;
   frames_received_ = 0;
   frames_encoded_ = 0;
   frames_dropped_media_encoder_ = 0;
   consecutive_full_queue_frame_drops_ = 0;
   frames_in_queue_ = 0;
   current_timestamp_us_ = 0;
-  start_time_ms_ = GetCurrentTimeMs();
+  stat_start_time_ms_ = GetCurrentTimeMs();
   current_frames_ = 0;
   current_bytes_ = 0;
   current_acc_qp_ = 0;
   current_encoding_time_ms_ = 0;
   last_input_timestamp_ms_ = -1;
   last_output_timestamp_ms_ = -1;
   output_timestamp_ = 0;
   output_render_time_ms_ = 0;
   timestamps_.clear();
   render_times_ms_.clear();
@@ skipping 67 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 (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;
       }
       frames_received_since_last_key_ = 0;
     }
     last_frame_received_ms_ = now_ms;
   }
 
   frames_received_++;
   if (!DeliverPendingOutputs(jni)) {
     if (!ResetCodecOnCodecThread())
       return WEBRTC_VIDEO_CODEC_ERROR;
   }
   if (frames_encoded_ < kMaxEncodedLogFrames) {
-    ALOGD << "Encoder frame in # " << (frames_received_ - 1) << ". TS: " <<
-        (int)(current_timestamp_us_ / 1000) << ". Q: " << frames_in_queue_ <<
-        ". Fps: " << last_set_fps_ << ". Kbps: " << last_set_bitrate_kbps_;
+    ALOGD << "Encoder frame in # " << (frames_received_ - 1) <<
+        ". TS: " << (int)(current_timestamp_us_ / 1000) <<
+        ". Q: " << frames_in_queue_ <<
+        ". Fps: " << last_set_fps_ <<
+        ". Kbps: " << last_set_bitrate_kbps_;
   }
 
   if (drop_next_input_frame_) {
     ALOGW << "Encoder drop frame - failed callback.";
     drop_next_input_frame_ = false;
     current_timestamp_us_ += rtc::kNumMicrosecsPerSec / last_set_fps_;
     frames_dropped_media_encoder_++;
     OnDroppedFrame();
     return WEBRTC_VIDEO_CODEC_OK;
   }
 
   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 171 matching lines @@
       frames_in_queue_--;
     }
 
     // Extract payload.
     size_t payload_size = jni->GetDirectBufferCapacity(j_output_buffer);
     uint8_t* payload = reinterpret_cast<uint8_t*>(
         jni->GetDirectBufferAddress(j_output_buffer));
     CHECK_EXCEPTION(jni);
 
     if (frames_encoded_ < kMaxEncodedLogFrames) {
-      ALOGD << "Encoder frame out # " << frames_encoded_ << ". Key: " <<
-          key_frame << ". Size: " << payload_size << ". TS: " <<
-          (int)last_output_timestamp_ms_ << ". Latency: " <<
-          (int)(last_input_timestamp_ms_ - last_output_timestamp_ms_) <<
+      int current_latency =
+          (int)(last_input_timestamp_ms_ - last_output_timestamp_ms_);
+      ALOGD << "Encoder frame out # " << frames_encoded_ <<
+          ". Key: " << key_frame <<
+          ". Size: " << payload_size <<
+          ". TS: " << (int)last_output_timestamp_ms_ <<
+          ". Latency: " << current_latency <<
           ". EncTime: " << frame_encoding_time_ms;
     }
 
     // Callback - return encoded frame.
     int32_t callback_status = 0;
     if (callback_) {
       scoped_ptr<webrtc::EncodedImage> image(
           new webrtc::EncodedImage(payload, payload_size, payload_size));
       image->_encodedWidth = width_;
       image->_encodedHeight = height_;
@@ skipping 111 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() - stat_start_time_ms_;
+  if ((statistic_time_ms >= kMediaCodecStatisticsIntervalMs || force_log) &&
+      current_frames_ > 0 && statistic_time_ms > 0) {
+    int current_bitrate = current_bytes_ * 8 / statistic_time_ms;
+    int current_fps =
+        (current_frames_ * 1000 + statistic_time_ms / 2) / statistic_time_ms;
+    ALOGD << "Encoded frames: " << frames_encoded_ <<
+        ". Bitrate: " << current_bitrate <<
+        ", target: " << last_set_bitrate_kbps_ << " kbps" <<
+        ", fps: " << current_fps <<
+        ", encTime: " << (current_encoding_time_ms_ / current_frames_) <<
+        ". QP: " << (current_acc_qp_ / current_frames_) <<
+        " for last " << statistic_time_ms << " ms.";
+    stat_start_time_ms_ = GetCurrentTimeMs();
+    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