Add more logging and fix PTS overflow for HW decoder.

talk/app/webrtc/java/jni/androidmediadecoder_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 61 matching lines @@
 #ifdef TRACK_BUFFER_TIMING
 #define ALOGV(...)
   __android_log_print(ANDROID_LOG_VERBOSE, TAG_DECODER, __VA_ARGS__)
 #else
 #define ALOGV(...)
 #endif
 #define ALOGD LOG_TAG(rtc::LS_INFO, TAG_DECODER)
 #define ALOGW LOG_TAG(rtc::LS_WARNING, TAG_DECODER)
 #define ALOGE LOG_TAG(rtc::LS_ERROR, TAG_DECODER)
 
+enum { kMaxWarningLogFrames = 2 };
+
 class MediaCodecVideoDecoder : public webrtc::VideoDecoder,
                                public rtc::MessageHandler {
  public:
   explicit MediaCodecVideoDecoder(
       JNIEnv* jni, VideoCodecType codecType, jobject render_egl_context);
   virtual ~MediaCodecVideoDecoder();
 
   int32_t InitDecode(const VideoCodec* codecSettings, int32_t numberOfCores)
       override;
 
@@ skipping 19 matching lines @@
   // CHECK-fail if not running on |codec_thread_|.
   void CheckOnCodecThread();
 
   int32_t InitDecodeOnCodecThread();
   int32_t ReleaseOnCodecThread();
   int32_t DecodeOnCodecThread(const EncodedImage& inputImage);
   // Deliver any outputs pending in the MediaCodec to our |callback_| and return
   // true on success.
   bool DeliverPendingOutputs(JNIEnv* jni, int dequeue_timeout_us);
   int32_t ProcessHWErrorOnCodecThread();
+  void EnableFrameLogOnWarning();
 
   // Type of video codec.
   VideoCodecType codecType_;
 
   // Render EGL context - owned by factory, should not be allocated/destroyed
   // by VideoDecoder.
   jobject render_egl_context_;
 
   bool key_frame_required_;
   bool inited_;
   bool sw_fallback_required_;
   bool use_surface_;
   VideoCodec codec_;
   webrtc::I420BufferPool decoded_frame_pool_;
   rtc::scoped_refptr<SurfaceTextureHelper> surface_texture_helper_;
   DecodedImageCallback* callback_;
   int frames_received_;  // Number of frames received by decoder.
   int frames_decoded_;  // Number of frames decoded by decoder.
+  // Number of decoded frames for which log information is displayed.
+  int frames_decoded_logged_;
   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_decoding_time_ms_;  // Overall decoding time in the current second
   uint32_t max_pending_frames_;  // Maximum number of pending input frames
 
   // 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.
   ScopedGlobalRef<jclass> j_media_codec_video_decoder_class_;
@@ skipping 179 matching lines @@
   if (ret_val < 0) {
     ALOGE << "Release failure: " << ret_val << " - fallback to SW codec";
     sw_fallback_required_ = true;
     return WEBRTC_VIDEO_CODEC_ERROR;
   }
 
   // Always start with a complete key frame.
   key_frame_required_ = true;
   frames_received_ = 0;
   frames_decoded_ = 0;
+  frames_decoded_logged_ = kMaxDecodedLogFrames;
 
   jobject java_surface_texture_helper_ = nullptr;
   if (use_surface_) {
     java_surface_texture_helper_ = jni->CallStaticObjectMethod(
         FindClass(jni, "org/webrtc/SurfaceTextureHelper"),
         GetStaticMethodID(jni,
                           FindClass(jni, "org/webrtc/SurfaceTextureHelper"),
                           "create",
                           "(Lorg/webrtc/EglBase$Context;)"
                           "Lorg/webrtc/SurfaceTextureHelper;"),
@@ skipping 86 matching lines @@
   }
   ALOGD << "DecoderReleaseOnCodecThread done";
   return WEBRTC_VIDEO_CODEC_OK;
 }
 
 void MediaCodecVideoDecoder::CheckOnCodecThread() {
   RTC_CHECK(codec_thread_ == ThreadManager::Instance()->CurrentThread())
       << "Running on wrong thread!";
 }
 
+void MediaCodecVideoDecoder::EnableFrameLogOnWarning() {
+  // Log next 2 output frames.
+  frames_decoded_logged_ = std::max(
+      frames_decoded_logged_, frames_decoded_ + kMaxWarningLogFrames);
+}
+
 int32_t MediaCodecVideoDecoder::ProcessHWErrorOnCodecThread() {
   CheckOnCodecThread();
   int ret_val = ReleaseOnCodecThread();
   if (ret_val < 0) {
     ALOGE << "ProcessHWError: Release failure";
   }
   if (codecType_ == kVideoCodecH264) {
     // For now there is no SW H.264 which can be used as fallback codec.
     // So try to restart hw codec for now.
     ret_val = InitDecodeOnCodecThread();
@@ skipping 71 matching lines @@
 }
 
 int32_t MediaCodecVideoDecoder::DecodeOnCodecThread(
     const EncodedImage& inputImage) {
   CheckOnCodecThread();
   JNIEnv* jni = AttachCurrentThreadIfNeeded();
   ScopedLocalRefFrame local_ref_frame(jni);
 
   // Try to drain the decoder and wait until output is not too
   // much behind the input.
+  if (frames_received_ > frames_decoded_ + max_pending_frames_) {
+    ALOGW << "Decoder is too far behind. Try to drain. Received: " <<
+        frames_received_ << ". Decoded: " << frames_decoded_;
+    EnableFrameLogOnWarning();
+  }
   const int64 drain_start = GetCurrentTimeMs();
   while ((frames_received_ > frames_decoded_ + max_pending_frames_) &&
          (GetCurrentTimeMs() - drain_start) < kMediaCodecTimeoutMs) {
-    ALOGV("Received: %d. Decoded: %d. Wait for output...",
-        frames_received_, frames_decoded_);
     if (!DeliverPendingOutputs(jni, kMediaCodecPollMs)) {
       ALOGE << "DeliverPendingOutputs error. Frames received: " <<
           frames_received_ << ". Frames decoded: " << frames_decoded_;
       return ProcessHWErrorOnCodecThread();
     }
   }
   if (frames_received_ > frames_decoded_ + max_pending_frames_) {
     ALOGE << "Output buffer dequeue timeout. Frames received: " <<
         frames_received_ << ". Frames decoded: " << frames_decoded_;
     return ProcessHWErrorOnCodecThread();
   }
 
   // Get input buffer.
-  int j_input_buffer_index = jni->CallIntMethod(*j_media_codec_video_decoder_,
-                                                j_dequeue_input_buffer_method_);
+  int j_input_buffer_index = jni->CallIntMethod(
+      *j_media_codec_video_decoder_, j_dequeue_input_buffer_method_);
   if (CheckException(jni) || j_input_buffer_index < 0) {
-    ALOGE << "dequeueInputBuffer error";
-    return ProcessHWErrorOnCodecThread();
+    ALOGE << "dequeueInputBuffer error: " << j_input_buffer_index <<
+        ". Retry DeliverPendingOutputs.";
+    EnableFrameLogOnWarning();
+    // Try to drain the decoder.
+    if (!DeliverPendingOutputs(jni, kMediaCodecPollMs)) {
+      ALOGE << "DeliverPendingOutputs error. Frames received: " <<
+          frames_received_ << ". Frames decoded: " << frames_decoded_;
+      return ProcessHWErrorOnCodecThread();
+    }
+    // Try dequeue input buffer one last time.
+    j_input_buffer_index = jni->CallIntMethod(
+        *j_media_codec_video_decoder_, j_dequeue_input_buffer_method_);
+    if (CheckException(jni) || j_input_buffer_index < 0) {
+      ALOGE << "dequeueInputBuffer critical error: " << j_input_buffer_index;
+      return ProcessHWErrorOnCodecThread();
+    }
   }
 
   // Copy encoded data to Java ByteBuffer.
   jobject j_input_buffer = input_buffers_[j_input_buffer_index];
   uint8_t* buffer =
       reinterpret_cast<uint8_t*>(jni->GetDirectBufferAddress(j_input_buffer));
   RTC_CHECK(buffer) << "Indirect buffer??";
   int64_t buffer_capacity = jni->GetDirectBufferCapacity(j_input_buffer);
   if (CheckException(jni) || buffer_capacity < inputImage._length) {
     ALOGE << "Input frame size "<<  inputImage._length <<
         " is bigger than buffer size " << buffer_capacity;
     return ProcessHWErrorOnCodecThread();
   }
-  jlong presentation_timestamp_us =
-      (frames_received_ * 1000000) / codec_.maxFramerate;
+  jlong presentation_timestamp_us = static_cast<jlong>(
+      static_cast<int64_t>(frames_received_) * 1000000 / codec_.maxFramerate);
   memcpy(buffer, inputImage._buffer, inputImage._length);
 
-  if (frames_decoded_ < kMaxDecodedLogFrames) {
+  if (frames_decoded_ < frames_decoded_logged_) {
     ALOGD << "Decoder frame in # " << frames_received_ <<
         ". Type: " << inputImage._frameType <<
         ". Buffer # " << j_input_buffer_index <<
-        ". TS: " << (int)(presentation_timestamp_us / 1000) <<
+        ". TS: " << presentation_timestamp_us / 1000 <<
         ". Size: " << inputImage._length;
   }
 
   // Save input image timestamps for later output.
   frames_received_++;
   current_bytes_ += inputImage._length;
 
   // Feed input to decoder.
   bool success = jni->CallBooleanMethod(
       *j_media_codec_video_decoder_,
@@ skipping 49 matching lines @@
       j_slice_height_field_);
 
   rtc::scoped_refptr<webrtc::VideoFrameBuffer> frame_buffer;
   int64_t presentation_timestamps_ms = 0;
   int64_t output_timestamps_ms = 0;
   int64_t output_ntp_timestamps_ms = 0;
   int decode_time_ms = 0;
   int64_t frame_delayed_ms = 0;
   if (use_surface_) {
     // Extract data from Java DecodedTextureBuffer.
+    presentation_timestamps_ms = GetLongField(
+        jni, j_decoder_output_buffer,
+        j_texture_presentation_timestamp_ms_field_);
+    output_timestamps_ms = GetLongField(
+        jni, j_decoder_output_buffer, j_texture_timestamp_ms_field_);
+    output_ntp_timestamps_ms = GetLongField(
+        jni, j_decoder_output_buffer, j_texture_ntp_timestamp_ms_field_);
+    decode_time_ms = GetLongField(
+        jni, j_decoder_output_buffer, j_texture_decode_time_ms_field_);
+
     const int texture_id =
         GetIntField(jni, j_decoder_output_buffer, j_texture_id_field_);
     if (texture_id != 0) {  // |texture_id| == 0 represents a dropped frame.
       const jfloatArray j_transform_matrix =
           reinterpret_cast<jfloatArray>(GetObjectField(
               jni, j_decoder_output_buffer, j_transform_matrix_field_));
-      const int64_t timestamp_us = GetLongField(
-          jni, j_decoder_output_buffer, j_texture_timestamp_ms_field_);
-      presentation_timestamps_ms = GetLongField(
-          jni, j_decoder_output_buffer,
-          j_texture_presentation_timestamp_ms_field_);
-      output_timestamps_ms = GetLongField(
-          jni, j_decoder_output_buffer, j_texture_timestamp_ms_field_);
-      output_ntp_timestamps_ms = GetLongField(
-          jni, j_decoder_output_buffer, j_texture_ntp_timestamp_ms_field_);
-      decode_time_ms = GetLongField(
-          jni, j_decoder_output_buffer, j_texture_decode_time_ms_field_);
       frame_delayed_ms = GetLongField(
           jni, j_decoder_output_buffer, j_texture_frame_delay_ms_field_);
 
       // Create webrtc::VideoFrameBuffer with native texture handle.
       frame_buffer = surface_texture_helper_->CreateTextureFrame(
           width, height, NativeHandleImpl(jni, texture_id, j_transform_matrix));
+    } else {
+      EnableFrameLogOnWarning();
     }
   } else {
     // Extract data from Java ByteBuffer and create output yuv420 frame -
     // for non surface decoding only.
     const int output_buffer_index = GetIntField(
         jni, j_decoder_output_buffer, j_info_index_field_);
     const int output_buffer_offset = GetIntField(
         jni, j_decoder_output_buffer, j_info_offset_field_);
     const int output_buffer_size = GetIntField(
         jni, j_decoder_output_buffer, j_info_size_field_);
@@ skipping 64 matching lines @@
         output_buffer_index);
     if (CheckException(jni)) {
       ALOGE << "returnDecodedOutputBuffer error";
       return false;
     }
   }
   VideoFrame decoded_frame(frame_buffer, 0, 0, webrtc::kVideoRotation_0);
   decoded_frame.set_timestamp(output_timestamps_ms);
   decoded_frame.set_ntp_time_ms(output_ntp_timestamps_ms);
 
-  if (frames_decoded_ < kMaxDecodedLogFrames) {
+  if (frames_decoded_ < frames_decoded_logged_) {
     ALOGD << "Decoder frame out # " << frames_decoded_ <<
         ". " << width << " x " << height <<
         ". " << stride << " x " <<  slice_height <<
         ". Color: " << color_format <<
         ". TS: " << presentation_timestamps_ms <<
         ". DecTime: " << (int)decode_time_ms <<
         ". DelayTime: " << (int)frame_delayed_ms;
   }
 
   // Calculate and print decoding statistics - every 3 seconds.
@@ skipping 131 matching lines @@
   ALOGD << "Destroy video decoder.";
   delete decoder;
 }
 
 const char* MediaCodecVideoDecoder::ImplementationName() const {
   return "MediaCodec";
 }
 
 }  // namespace webrtc_jni