Always on statistics for AndroidMediaEncoder.

webrtc/api/java/jni/androidmediaencoder_jni.cc

 /*
  *  Copyright 2015 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 208 matching lines @@
   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_;
   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.
-  bool output_delivery_loop_running_; // Is the onMessage loop running
+  // Is the onMessage loop running at regular polling rate. If false, it is
+  // running at lower poll rate of kMediaCodecStatisticsIntervalMs.
+  bool output_delivery_loop_running_;
 
   struct InputFrameInfo {
     InputFrameInfo(int64_t encode_start_time,
                    int32_t frame_timestamp,
                    int64_t frame_render_time_ms,
                    webrtc::VideoRotation rotation)
         : encode_start_time(encode_start_time),
           frame_timestamp(frame_timestamp),
           frame_render_time_ms(frame_render_time_ms),
           rotation(rotation) {}
@@ skipping 60 matching lines @@
     j_media_codec_video_encoder_(
         jni,
         jni->NewObject(*j_media_codec_video_encoder_class_,
                        GetMethodID(jni,
                                    *j_media_codec_video_encoder_class_,
                                    "<init>",
                                    "()V"))),
     inited_(false),
     use_surface_(false),
     picture_id_(0),
-    output_delivery_loop_running_(false),
     egl_context_(egl_context) {
   ScopedLocalRefFrame local_ref_frame(jni);
   // It would be nice to avoid spinning up a new thread per MediaCodec, and
   // instead re-use e.g. the PeerConnectionFactory's |worker_thread_|, but bug
   // 2732 means that deadlocks abound.  This class synchronously trampolines
   // to |codec_thread_|, so if anything else can be coming to _us_ from
   // |codec_thread_|, or from any thread holding the |_sendCritSect| described
   // in the bug, we have a problem.  For now work around that with a dedicated
   // thread.
   codec_thread_->SetName("MediaCodecVideoEncoder", NULL);
@@ skipping 151 matching lines @@
   }
 
   // It would be nice to recover from a failure here if one happened, but it's
   // unclear how to signal such a failure to the app, so instead we stay silent
   // about it and let the next app-called API method reveal the borkedness.
   DeliverPendingOutputs(jni);
 
   // If there aren't more frames to deliver, we can stop the loop
   if (!input_frame_infos_.empty()) {
     codec_thread_->PostDelayed(kMediaCodecPollMs, this);
+    output_delivery_loop_running_ = true;
   } else {
+    codec_thread_->PostDelayed(kMediaCodecStatisticsIntervalMs, this);

[AlexG, 2016/06/10 20:16:25]

I think this stopping or increasing polling interval may be dangerous for the
case when encoder generates 2 frames for a single output - suppose for H.264
encoder it generates first frame with SPS and PPS NAL and then actual encoded
frame. Or something happens in HW that it by error generates 2 outputs. I
suggest instead of complete polling stop or increasing polling interval to 3
second increase it to 50 or 100 ms - it should not affect the performance, but
will make code more robust against encoder mis behaviour.

[sakal, 2016/06/13 07:13:21]

Done.

     output_delivery_loop_running_ = false;
   }
+
+  // Call log statistics here so it's called even if no frames are being
+  // delivered.
+  LogStatistics(false);
 }
 
 bool MediaCodecVideoEncoder::ResetCodecOnCodecThread() {
   RTC_DCHECK(codec_thread_checker_.CalledOnValidThread());
   ALOGE << "ResetOnCodecThread";
   if (ReleaseOnCodecThread() != WEBRTC_VIDEO_CODEC_OK ||
       InitEncodeOnCodecThread(width_, height_, 0, 0, false) !=
           WEBRTC_VIDEO_CODEC_OK) {
     // TODO(fischman): wouldn't it be nice if there was a way to gracefully
     // degrade to a SW encoder at this point?  There isn't one AFAICT :(
@@ skipping 30 matching lines @@
   frames_dropped_media_encoder_ = 0;
   consecutive_full_queue_frame_drops_ = 0;
   current_timestamp_us_ = 0;
   stat_start_time_ms_ = rtc::TimeMillis();
   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_delivery_loop_running_ = false;
   output_timestamp_ = 0;
   output_render_time_ms_ = 0;
   input_frame_infos_.clear();
   drop_next_input_frame_ = false;
   use_surface_ = use_surface;
   picture_id_ = static_cast<uint16_t>(rand()) & 0x7FFF;
   gof_.SetGofInfoVP9(webrtc::TemporalStructureMode::kTemporalStructureMode1);
   tl0_pic_idx_ = static_cast<uint8_t>(rand());
   gof_idx_ = 0;
   last_frame_received_ms_ = -1;
@@ skipping 43 matching lines @@
       input_buffers_[i] =
           jni->NewGlobalRef(jni->GetObjectArrayElement(input_buffers, i));
       int64_t yuv_buffer_capacity =
           jni->GetDirectBufferCapacity(input_buffers_[i]);
       CHECK_EXCEPTION(jni);
       RTC_CHECK(yuv_buffer_capacity >= yuv_size_) << "Insufficient capacity";
     }
   }
 
   inited_ = true;
+  codec_thread_->PostDelayed(kMediaCodecStatisticsIntervalMs, this);

[AlexG, 2016/06/10 20:16:25]

This is not needed - first 10 frames are logged, so we can detect jam for them.

[sakal, 2016/06/13 07:13:21]

Done.

   return WEBRTC_VIDEO_CODEC_OK;
 }
 
 int32_t MediaCodecVideoEncoder::EncodeOnCodecThread(
     const webrtc::VideoFrame& frame,
     const std::vector<webrtc::FrameType>* frame_types) {
   RTC_DCHECK(codec_thread_checker_.CalledOnValidThread());
   JNIEnv* jni = AttachCurrentThreadIfNeeded();
   ScopedLocalRefFrame local_ref_frame(jni);
 
@@ skipping 125 matching lines @@
   // Save input image timestamps for later output.
   input_frame_infos_.emplace_back(
       time_before_calling_encode, input_frame.timestamp(),
       input_frame.render_time_ms(), input_frame.rotation());
 
   last_input_timestamp_ms_ =
       current_timestamp_us_ / rtc::kNumMicrosecsPerMillisec;
 
   current_timestamp_us_ += rtc::kNumMicrosecsPerSec / last_set_fps_;
 
   if (!output_delivery_loop_running_) {

[AlexG, 2016/06/10 20:16:25]

It is safer and less code to just remove this if condition - always schedule
DeliverPendingOutptu when input frame arrives

[sakal, 2016/06/13 07:13:21]

Done.

+    codec_thread_->Clear(this);
+    codec_thread_->PostDelayed(kMediaCodecPollMs, this);
     output_delivery_loop_running_ = true;
-    codec_thread_->PostDelayed(kMediaCodecPollMs, this);
   }
 
   if (!DeliverPendingOutputs(jni)) {
     ALOGE << "Failed deliver pending outputs.";
     ResetCodecOnCodecThread();
     return WEBRTC_VIDEO_CODEC_ERROR;
   }
   return WEBRTC_VIDEO_CODEC_OK;
 }
 
@@ skipping 163 matching lines @@
 
 jlong MediaCodecVideoEncoder::GetOutputBufferInfoPresentationTimestampUs(
     JNIEnv* jni,
     jobject j_output_buffer_info) {
   return GetLongField(
       jni, j_output_buffer_info, j_info_presentation_timestamp_us_field_);
 }
 
 bool MediaCodecVideoEncoder::DeliverPendingOutputs(JNIEnv* jni) {
   RTC_DCHECK(codec_thread_checker_.CalledOnValidThread());
+
   while (true) {
     jobject j_output_buffer_info = jni->CallObjectMethod(
         *j_media_codec_video_encoder_, j_dequeue_output_buffer_method_);
     CHECK_EXCEPTION(jni);
     if (IsNull(jni, j_output_buffer_info)) {
       break;
     }
 
     int output_buffer_index =
         GetOutputBufferInfoIndex(jni, j_output_buffer_info);
@@ skipping 175 matching lines @@
       drop_next_input_frame_ = true;
       // Theoretically could handle callback_status<0 here, but unclear what
       // that would mean for us.
     }
   }
   return true;
 }
 
 void MediaCodecVideoEncoder::LogStatistics(bool force_log) {
   int statistic_time_ms = rtc::TimeMillis() - stat_start_time_ms_;
-  if ((statistic_time_ms >= kMediaCodecStatisticsIntervalMs || force_log) &&
-      current_frames_ > 0 && statistic_time_ms > 0) {
+  if ((statistic_time_ms >= kMediaCodecStatisticsIntervalMs || force_log)
+      && statistic_time_ms > 0) {
+    // Prevent division by zero
+    int current_frames_divider = current_frames_ != 0 ? current_frames_ : 1;
+
     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_) <<
+        ", encTime: " << (current_encoding_time_ms_ / current_frames_divider) <<
+        ". QP: " << (current_acc_qp_ / current_frames_divider) <<
         " for last " << statistic_time_ms << " ms.";
     stat_start_time_ms_ = rtc::TimeMillis();
     current_frames_ = 0;
     current_bytes_ = 0;
     current_acc_qp_ = 0;
     current_encoding_time_ms_ = 0;
   }
 }
 
 int32_t MediaCodecVideoEncoder::NextNaluPosition(
@@ skipping 130 matching lines @@
   return supported_codecs_;
 }
 
 void MediaCodecVideoEncoderFactory::DestroyVideoEncoder(
     webrtc::VideoEncoder* encoder) {
   ALOGD << "Destroy video encoder.";
   delete encoder;
 }
 
 }  // namespace webrtc_jni