Add QP statistics logging to Android HW encoder.

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 53 matching lines @@
 
 // H.264 start code length.
 #define H264_SC_LENGTH 4
 // Maximum allowed NALUs in one output frame.
 #define MAX_NALUS_PERFRAME 32
 // Maximum supported HW video encoder resolution.
 #define MAX_VIDEO_WIDTH 1280
 #define MAX_VIDEO_HEIGHT 1280
 // Maximum supported HW video encoder fps.
 #define MAX_VIDEO_FPS 30
+// Maximum allowed fps value in SetRates() call.
+#define MAX_ALLOWED_VIDEO_FPS 60
+// Maximum allowed frames in encoder input queue.
+#define MAX_ENCODER_Q_SIZE 2
+// Maximum allowed latency in ms.
+#define MAX_LATENCY_MS 70
+
+
+// Logging macros.
+#define TAG_ENCODER "MediaCodecVideoEncoder"
+#ifdef TRACK_BUFFER_TIMING
+#define ALOGV(...)
+  __android_log_print(ANDROID_LOG_VERBOSE, TAG_ENCODER, __VA_ARGS__)
+#else
+#define ALOGV(...)
+#endif
+#define ALOGD LOG_TAG(rtc::LS_INFO, TAG_ENCODER)
+#define ALOGW LOG_TAG(rtc::LS_WARNING, TAG_ENCODER)
+#define ALOGE LOG_TAG(rtc::LS_ERROR, TAG_ENCODER)
 
 // MediaCodecVideoEncoder is a webrtc::VideoEncoder implementation that uses
 // Android's MediaCodec SDK API behind the scenes to implement (hopefully)
 // HW-backed video encode.  This C++ class is implemented as a very thin shim,
 // delegating all of the interesting work to org.webrtc.MediaCodecVideoEncoder.
 // MediaCodecVideoEncoder is created, operated, and destroyed on a single
 // thread, currently the libjingle Worker thread.
 class MediaCodecVideoEncoder : public webrtc::VideoEncoder,
                                public rtc::MessageHandler {
  public:
@@ skipping 115 matching lines @@
   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_;  // Number of frames dropped by encoder.
   int frames_in_queue_;  // Number of frames in encoder queue.
   int64_t 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.
   int32_t output_timestamp_;  // Last output frame timestamp from timestamps_ Q.
   int64_t output_render_time_ms_; // Last output frame render time from
                                   // render_times_ms_ queue.
@@ skipping 241 matching lines @@
   JNIEnv* jni = AttachCurrentThreadIfNeeded();
   ScopedLocalRefFrame local_ref_frame(jni);
 
   ALOGD << "InitEncodeOnCodecThread Type: " <<  (int)codecType_ << ", " <<
       width << " x " << height << ". Bitrate: " << kbps <<
       " kbps. Fps: " << fps;
   if (kbps == 0) {
     kbps = last_set_bitrate_kbps_;
   }
   if (fps == 0) {
-    fps = last_set_fps_;
+    fps = MAX_VIDEO_FPS;
   }
 
   width_ = width;
   height_ = height;
   last_set_bitrate_kbps_ = kbps;
-  last_set_fps_ = fps;
+  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_ = 0;
   frames_in_queue_ = 0;
   current_timestamp_us_ = 0;
   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();
   frame_rtc_times_ms_.clear();
   drop_next_input_frame_ = false;
   use_surface_ = use_surface;
@@ skipping 66 matching lines @@
 
   if (!inited_) {
     return WEBRTC_VIDEO_CODEC_UNINITIALIZED;
   }
 
   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_;
+  }
 
   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_++;
+    // Report dropped frame to quality_scaler_.
+    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_LATENCY_MS) {
+      ALOGD << "Drop frame - encoder is behind by " << encoder_latency_ms <<
+          " ms. Q size: " << frames_in_queue_;
+      current_timestamp_us_ += rtc::kNumMicrosecsPerSec / last_set_fps_;
+      frames_dropped_++;

[pbos-webrtc, 2016/01/15 10:54:04]

Can we move frames_dropped_++ into OnDroppedFrame(), and move the comment about
reporting it to quality scaler in there?

[AlexG, 2016/01/15 20:48:11]

Done.

+      // Report dropped frame to quality_scaler_.
+      OnDroppedFrame();

[perkj_webrtc, 2016/01/15 07:33:08]

OnDropped frame now happens before quality_scaler_.OnEncodeFrame and thus, if
the frame is dropped quality_scaler_.OnEncodeFrame is not called. Is the scaler
logic ok with this ? Was it wrong before?

[pbos-webrtc, 2016/01/15 10:54:04]

I think this is fine from glancing at it. OnEncodeFrame computes which
resolution should be used for the frame, so it doesn't matter if it's not called
for a frame that's dropped. Maybe this should be named better.

[AlexG, 2016/01/15 20:48:10]

Acknowledged.

+      return WEBRTC_VIDEO_CODEC_OK;
+    }
+  }
+
   VideoFrame input_frame = frame;
   if (scale_) {
     // Check framerate before spatial resolution change.
     quality_scaler_.OnEncodeFrame(frame);
     const webrtc::QualityScaler::Resolution scaled_resolution =
         quality_scaler_.GetScaledResolution();
     if (scaled_resolution.width != frame.width() ||
         scaled_resolution.height != frame.height()) {
       if (frame.native_handle() != nullptr) {
         rtc::scoped_refptr<webrtc::VideoFrameBuffer> scaled_buffer(
             static_cast<AndroidTextureBuffer*>(
                 frame.video_frame_buffer().get())->ScaleAndRotate(
                     scaled_resolution.width,
                     scaled_resolution.height,
                     webrtc::kVideoRotation_0));
         input_frame.set_video_frame_buffer(scaled_buffer);
       } else {
         input_frame = quality_scaler_.GetScaledFrame(frame);
       }
     }
   }
 
   if (!MaybeReconfigureEncoderOnCodecThread(input_frame)) {
     ALOGE << "Failed to reconfigure encoder.";
     return WEBRTC_VIDEO_CODEC_ERROR;
   }
 
-  // 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_ > 2 || encoder_latency_ms > 70) {
-      ALOGD << "Drop frame - encoder is behind by " << encoder_latency_ms <<
-          " ms. Q size: " << frames_in_queue_;
-      frames_dropped_++;
-      // Report dropped frame to quality_scaler_.
-      OnDroppedFrame();
-      return WEBRTC_VIDEO_CODEC_OK;
-    }
-  }
+  // Save time when input frame is sent to the encoder input.
+  frame_rtc_times_ms_.push_back(GetCurrentTimeMs());
 
   const bool key_frame = frame_types->front() != webrtc::kVideoFrameDelta;
   bool encode_status = true;
   if (!input_frame.native_handle()) {
     int j_input_buffer_index = jni->CallIntMethod(*j_media_codec_video_encoder_,
         j_dequeue_input_buffer_method_);
     CHECK_EXCEPTION(jni);
     if (j_input_buffer_index == -1) {
       // Video codec falls behind - no input buffer available.
       ALOGW << "Encoder drop frame - no input buffers available";
+      current_timestamp_us_ += rtc::kNumMicrosecsPerSec / last_set_fps_;
       frames_dropped_++;
+      frame_rtc_times_ms_.erase(frame_rtc_times_ms_.begin());
       // Report dropped frame to quality_scaler_.
       OnDroppedFrame();
       return WEBRTC_VIDEO_CODEC_OK;  // TODO(fischman): see webrtc bug 2887.
     }
     if (j_input_buffer_index == -2) {
       ResetCodecOnCodecThread();
       return WEBRTC_VIDEO_CODEC_ERROR;
     }
     encode_status = EncodeByteBufferOnCodecThread(jni, key_frame, input_frame,
         j_input_buffer_index);
   } else {
     encode_status = EncodeTextureOnCodecThread(jni, key_frame, input_frame);
   }
 
   if (!encode_status) {
     ALOGE << "Failed encode frame with timestamp: " << input_frame.timestamp();
     ResetCodecOnCodecThread();
     return WEBRTC_VIDEO_CODEC_ERROR;
   }
 
   last_input_timestamp_ms_ =
       current_timestamp_us_ / rtc::kNumMicrosecsPerMillisec;
   frames_in_queue_++;
 
   // Save input image timestamps for later output
   timestamps_.push_back(input_frame.timestamp());
   render_times_ms_.push_back(input_frame.render_time_ms());
-  frame_rtc_times_ms_.push_back(GetCurrentTimeMs());
   current_timestamp_us_ += rtc::kNumMicrosecsPerSec / last_set_fps_;
 
   if (!DeliverPendingOutputs(jni)) {
     ALOGE << "Failed deliver pending outputs.";
     ResetCodecOnCodecThread();
     return WEBRTC_VIDEO_CODEC_ERROR;
   }
   return WEBRTC_VIDEO_CODEC_OK;
 }
 
@@ skipping 27 matching lines @@
 
   return InitEncodeOnCodecThread(width_, height_, 0, 0 , is_texture_frame) ==
       WEBRTC_VIDEO_CODEC_OK;
 }
 
 bool MediaCodecVideoEncoder::EncodeByteBufferOnCodecThread(JNIEnv* jni,
     bool key_frame, const webrtc::VideoFrame& frame, int input_buffer_index) {
   RTC_DCHECK(codec_thread_checker_.CalledOnValidThread());
   RTC_CHECK(!use_surface_);
 
-  ALOGV("Encoder frame in # %d. TS: %lld. Q: %d",
-      frames_received_ - 1, current_timestamp_us_ / 1000, frames_in_queue_);
-
   jobject j_input_buffer = input_buffers_[input_buffer_index];
   uint8_t* yuv_buffer =
       reinterpret_cast<uint8_t*>(jni->GetDirectBufferAddress(j_input_buffer));
   CHECK_EXCEPTION(jni);
   RTC_CHECK(yuv_buffer) << "Indirect buffer??";
   RTC_CHECK(!libyuv::ConvertFromI420(
       frame.buffer(webrtc::kYPlane), frame.stride(webrtc::kYPlane),
       frame.buffer(webrtc::kUPlane), frame.stride(webrtc::kUPlane),
       frame.buffer(webrtc::kVPlane), frame.stride(webrtc::kVPlane),
       yuv_buffer, width_, width_, height_, encoder_fourcc_))
@@ skipping 55 matching lines @@
   rtc::MessageQueueManager::Clear(this);
   inited_ = false;
   use_surface_ = false;
   ALOGD << "EncoderReleaseOnCodecThread done.";
   return WEBRTC_VIDEO_CODEC_OK;
 }
 
 int32_t MediaCodecVideoEncoder::SetRatesOnCodecThread(uint32_t new_bit_rate,
                                                       uint32_t frame_rate) {
   RTC_DCHECK(codec_thread_checker_.CalledOnValidThread());
+  frame_rate = (frame_rate < MAX_ALLOWED_VIDEO_FPS) ?
+      frame_rate : MAX_ALLOWED_VIDEO_FPS;
   if (last_set_bitrate_kbps_ == new_bit_rate &&
       last_set_fps_ == frame_rate) {
     return WEBRTC_VIDEO_CODEC_OK;
   }
   JNIEnv* jni = AttachCurrentThreadIfNeeded();
   ScopedLocalRefFrame local_ref_frame(jni);
   if (new_bit_rate > 0) {
     last_set_bitrate_kbps_ = new_bit_rate;
   }
   if (frame_rate > 0) {
@@ skipping 72 matching lines @@
       frame_rtc_times_ms_.erase(frame_rtc_times_ms_.begin());
       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);
 
-    ALOGV("Encoder frame out # %d. Key: %d. Size: %d. TS: %lld."
-        " Latency: %lld. EncTime: %lld",
-        frames_encoded_, key_frame, payload_size,
-        last_output_timestamp_ms_,
-        last_input_timestamp_ms_ - last_output_timestamp_ms_,
-        frame_encoding_time_ms);
-
-    // 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_) << " for last " <<
-          statistic_time_ms << " ms.";
-      start_time_ms_ = GetCurrentTimeMs();
-      current_frames_ = 0;
-      current_bytes_ = 0;
-      current_encoding_time_ms_ = 0;
+    if (frames_encoded_ < kMaxEncodedLogFrames) {
+      ALOGD << "Encoder frame out # " << frames_encoded_ << ". Key: " <<
+          key_frame << ". Size: " << payload_size << ". TS: " <<

[perkj_webrtc, 2016/01/15 07:33:08]

Do you want to change key_frame ? "true": "false" ;

[AlexG, 2016/01/15 20:48:11]

I think it will be a bit longer in the log : "false" instead of "0". This log
message is already too long.

+          (int)last_output_timestamp_ms_ << ". Latency: " <<
+          (int)(last_input_timestamp_ms_ - last_output_timestamp_ms_) <<
+          ". 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_;
       image->_timeStamp = output_timestamp_;
@@ skipping 45 matching lines @@
       webrtc::RTPFragmentationHeader header;
       memset(&header, 0, sizeof(header));
       if (codecType_ == kVideoCodecVP8 || codecType_ == kVideoCodecVP9) {
         header.VerifyAndAllocateFragmentationHeader(1);
         header.fragmentationOffset[0] = 0;
         header.fragmentationLength[0] = image->_length;
         header.fragmentationPlType[0] = 0;
         header.fragmentationTimeDiff[0] = 0;
         if (codecType_ == kVideoCodecVP8 && scale_) {
           int qp;
-          if (webrtc::vp8::GetQp(payload, payload_size, &qp))
+          if (webrtc::vp8::GetQp(payload, payload_size, &qp)) {
+            current_acc_qp_ += qp;
             quality_scaler_.ReportQP(qp);
+          }
         }
       } else if (codecType_ == kVideoCodecH264) {
         if (scale_) {
           h264_bitstream_parser_.ParseBitstream(payload, payload_size);
           int qp;
-          if (h264_bitstream_parser_.GetLastSliceQp(&qp))
+          if (h264_bitstream_parser_.GetLastSliceQp(&qp)) {
+            current_acc_qp_ += qp;
             quality_scaler_.ReportQP(qp);
+          }
         }
         // For H.264 search for start codes.
         int32_t scPositions[MAX_NALUS_PERFRAME + 1] = {};
         int32_t scPositionsLength = 0;
         int32_t scPosition = 0;
         while (scPositionsLength < MAX_NALUS_PERFRAME) {
           int32_t naluPosition = NextNaluPosition(
               payload + scPosition, payload_size - scPosition);
           if (naluPosition < 0) {
             break;
@@ skipping 27 matching lines @@
     // Return output buffer back to the encoder.
     bool success = jni->CallBooleanMethod(*j_media_codec_video_encoder_,
                                           j_release_output_buffer_method_,
                                           output_buffer_index);
     CHECK_EXCEPTION(jni);
     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;
+    }
+
     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;
 }
 
@@ skipping 134 matching lines @@
 }
 
 void MediaCodecVideoEncoderFactory::DestroyVideoEncoder(
     webrtc::VideoEncoder* encoder) {
   ALOGD << "Destroy video encoder.";
   delete encoder;
 }
 
 }  // namespace webrtc_jni