v4l2_vda: Adjust the DVLOG levels.

media/gpu/v4l2_video_decode_accelerator.cc

 // Copyright 2014 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "media/gpu/v4l2_video_decode_accelerator.h"
 
 #include <dlfcn.h>
 #include <errno.h>
 #include <fcntl.h>
 #include <linux/videodev2.h>
@@ skipping 182 matching lines @@
   DCHECK(!device_poll_thread_.IsRunning());
 
   // These maps have members that should be manually destroyed, e.g. file
   // descriptors, mmap() segments, etc.
   DCHECK(input_buffer_map_.empty());
   DCHECK(output_buffer_map_.empty());
 }
 
 bool V4L2VideoDecodeAccelerator::Initialize(const Config& config,
                                             Client* client) {
-  DVLOGF(3) << "profile: " << config.profile
+  DVLOGF(2) << "profile: " << config.profile
             << ", output_mode=" << static_cast<int>(config.output_mode);
   DCHECK(child_task_runner_->BelongsToCurrentThread());
   DCHECK_EQ(decoder_state_, kUninitialized);
 
   if (config.is_encrypted()) {
     NOTREACHED() << "Encrypted streams are not supported for this VDA";
     return false;
   }
 
   if (config.output_mode != Config::OutputMode::ALLOCATE &&
@@ skipping 74 matching lines @@
 
   // InitializeTask will NOTIFY_ERROR on failure.
   decoder_thread_.task_runner()->PostTask(
       FROM_HERE, base::Bind(&V4L2VideoDecodeAccelerator::InitializeTask,
                             base::Unretained(this)));
 
   return true;
 }
 
 void V4L2VideoDecodeAccelerator::InitializeTask() {
-  DVLOGF(3);
+  DVLOGF(2);
   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
   DCHECK_EQ(decoder_state_, kInitialized);
 
   // Subscribe to the resolution change event.
   struct v4l2_event_subscription sub;
   memset(&sub, 0, sizeof(sub));
   sub.type = V4L2_EVENT_SOURCE_CHANGE;
   IOCTL_OR_ERROR_RETURN(VIDIOC_SUBSCRIBE_EVENT, &sub);
 
   if (!CreateInputBuffers()) {
     NOTIFY_ERROR(PLATFORM_FAILURE);
     return;
   }
 
   decoder_cmd_supported_ = IsDecoderCmdSupported();
 
   if (!StartDevicePoll())
     return;
 }
 
 void V4L2VideoDecodeAccelerator::Decode(
     const BitstreamBuffer& bitstream_buffer) {
-  DVLOGF(1) << "input_id=" << bitstream_buffer.id()
+  DVLOGF(4) << "input_id=" << bitstream_buffer.id()
             << ", size=" << bitstream_buffer.size();
   DCHECK(decode_task_runner_->BelongsToCurrentThread());
 
   if (bitstream_buffer.id() < 0) {
     LOGF(ERROR) << "Invalid bitstream_buffer, id: " << bitstream_buffer.id();
     if (base::SharedMemory::IsHandleValid(bitstream_buffer.handle()))
       base::SharedMemory::CloseHandle(bitstream_buffer.handle());
     NOTIFY_ERROR(INVALID_ARGUMENT);
     return;
   }
 
   // DecodeTask() will take care of running a DecodeBufferTask().
   decoder_thread_.task_runner()->PostTask(
       FROM_HERE, base::Bind(&V4L2VideoDecodeAccelerator::DecodeTask,
                             base::Unretained(this), bitstream_buffer));
 }
 
 void V4L2VideoDecodeAccelerator::AssignPictureBuffers(
     const std::vector<PictureBuffer>& buffers) {
-  DVLOGF(3) << "buffer_count=" << buffers.size();
+  DVLOGF(2) << "buffer_count=" << buffers.size();
   DCHECK(child_task_runner_->BelongsToCurrentThread());
 
   decoder_thread_.task_runner()->PostTask(
       FROM_HERE,
       base::Bind(&V4L2VideoDecodeAccelerator::AssignPictureBuffersTask,
                  base::Unretained(this), buffers));
 }
 
 void V4L2VideoDecodeAccelerator::AssignPictureBuffersTask(
     const std::vector<PictureBuffer>& buffers) {
-  DVLOGF(3);
+  DVLOGF(2);
   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
   DCHECK_EQ(decoder_state_, kAwaitingPictureBuffers);
 
   uint32_t req_buffer_count = output_dpb_size_ + kDpbOutputBufferExtraCount;
   if (image_processor_device_)
     req_buffer_count += kDpbOutputBufferExtraCountForImageProcessor;
 
   if (buffers.size() < req_buffer_count) {
     LOGF(ERROR) << "Failed to provide requested picture buffers. (Got "
                 << buffers.size() << ", requested " << req_buffer_count << ")";
@@ skipping 69 matching lines @@
       ImportBufferForPictureTask(
           output_record.picture_id, std::move(dmabuf_fds),
           egl_image_size_.width() * plane_horiz_bits_per_pixel / 8);
     }  // else we'll get triggered via ImportBufferForPicture() from client.
 
     DVLOGF(3) << "buffer[" << i << "]: picture_id=" << output_record.picture_id;
   }
 
   if (output_mode_ == Config::OutputMode::ALLOCATE) {
     DCHECK_EQ(kAwaitingPictureBuffers, decoder_state_);
     DVLOGF(1) << "Change state to kDecoding";

[Pawel Osciak, 2017/05/23 09:49:21]

2 or 3?

[Owen Lin, 2017/06/02 08:51:44]

Done.

     decoder_state_ = kDecoding;
     if (reset_pending_) {
       FinishReset();
       return;
     }
     ScheduleDecodeBufferTaskIfNeeded();
   }
 }
 
 void V4L2VideoDecodeAccelerator::CreateEGLImageFor(
@@ skipping 150 matching lines @@
     NOTIFY_ERROR(INVALID_ARGUMENT);
     return;
   }
   int adjusted_coded_width = stride * 8 / plane_horiz_bits_per_pixel;
 
   if (image_processor_device_ && !image_processor_) {
     // This is the first buffer import. Create the image processor and change
     // the decoder state. The client may adjust the coded width. We don't have
     // the final coded size in AssignPictureBuffers yet. Use the adjusted coded
     // width to create the image processor.
     DVLOGF(3) << "Original egl_image_size=" << egl_image_size_.ToString()

[Pawel Osciak, 2017/05/23 09:49:21]

2?

[Owen Lin, 2017/06/02 08:51:43]

Done.

               << ", adjusted coded width=" << adjusted_coded_width;
     DCHECK_GE(adjusted_coded_width, egl_image_size_.width());
     egl_image_size_.set_width(adjusted_coded_width);
     if (!CreateImageProcessor())
       return;
     DCHECK_EQ(kAwaitingPictureBuffers, decoder_state_);
-    DVLOGF(1) << "Change state to kDecoding";
+    DVLOGF(2) << "Change state to kDecoding";
     decoder_state_ = kDecoding;
     if (reset_pending_) {
       FinishReset();
     }
   } else {
     DCHECK_EQ(egl_image_size_.width(), adjusted_coded_width);
   }
 
   size_t index = iter - output_buffer_map_.begin();
   DCHECK_EQ(std::count(free_output_buffers_.begin(), free_output_buffers_.end(),
@@ skipping 20 matching lines @@
     iter->processor_output_fds.swap(dmabuf_fds);
     free_output_buffers_.push_back(index);
     if (decoder_state_ != kChangingResolution) {
       Enqueue();
       ScheduleDecodeBufferTaskIfNeeded();
     }
   }
 }
 
 void V4L2VideoDecodeAccelerator::ReusePictureBuffer(int32_t picture_buffer_id) {
-  DVLOGF(3) << "picture_buffer_id=" << picture_buffer_id;
+  DVLOGF(4) << "picture_buffer_id=" << picture_buffer_id;
   // Must be run on child thread, as we'll insert a sync in the EGL context.
   DCHECK(child_task_runner_->BelongsToCurrentThread());
 
   std::unique_ptr<EGLSyncKHRRef> egl_sync_ref;
 
   if (!make_context_current_cb_.is_null()) {
     if (!make_context_current_cb_.Run()) {
       LOGF(ERROR) << "could not make context current";
       NOTIFY_ERROR(PLATFORM_FAILURE);
       return;
@@ skipping 13 matching lines @@
     egl_sync_ref.reset(new EGLSyncKHRRef(egl_display_, egl_sync));
   }
 
   decoder_thread_.task_runner()->PostTask(
       FROM_HERE, base::Bind(&V4L2VideoDecodeAccelerator::ReusePictureBufferTask,
                             base::Unretained(this), picture_buffer_id,
                             base::Passed(&egl_sync_ref)));
 }
 
 void V4L2VideoDecodeAccelerator::Flush() {
-  DVLOGF(3);
+  DVLOGF(2);
   DCHECK(child_task_runner_->BelongsToCurrentThread());
   decoder_thread_.task_runner()->PostTask(
       FROM_HERE, base::Bind(&V4L2VideoDecodeAccelerator::FlushTask,
                             base::Unretained(this)));
 }
 
 void V4L2VideoDecodeAccelerator::Reset() {
-  DVLOGF(3);
+  DVLOGF(2);
   DCHECK(child_task_runner_->BelongsToCurrentThread());
   decoder_thread_.task_runner()->PostTask(
       FROM_HERE, base::Bind(&V4L2VideoDecodeAccelerator::ResetTask,
                             base::Unretained(this)));
 }
 
 void V4L2VideoDecodeAccelerator::Destroy() {
-  DVLOGF(3);
+  DVLOGF(2);
   DCHECK(child_task_runner_->BelongsToCurrentThread());
 
   // We're destroying; cancel all callbacks.
   client_ptr_factory_.reset();
   weak_this_factory_.InvalidateWeakPtrs();
 
   // If the decoder thread is running, destroy using posted task.
   if (decoder_thread_.IsRunning()) {
     decoder_thread_.task_runner()->PostTask(
         FROM_HERE, base::Bind(&V4L2VideoDecodeAccelerator::DestroyTask,
@@ skipping 23 matching lines @@
   scoped_refptr<V4L2Device> device = V4L2Device::Create();
   if (!device)
     return SupportedProfiles();
 
   return device->GetSupportedDecodeProfiles(arraysize(supported_input_fourccs_),
                                             supported_input_fourccs_);
 }
 
 void V4L2VideoDecodeAccelerator::DecodeTask(
     const BitstreamBuffer& bitstream_buffer) {
-  DVLOGF(3) << "input_id=" << bitstream_buffer.id();
+  DVLOGF(4) << "input_id=" << bitstream_buffer.id();
   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
   DCHECK_NE(decoder_state_, kUninitialized);
   TRACE_EVENT1("Video Decoder", "V4L2VDA::DecodeTask", "input_id",
                bitstream_buffer.id());
 
   std::unique_ptr<BitstreamBufferRef> bitstream_record(new BitstreamBufferRef(
       decode_client_, decode_task_runner_,
       std::unique_ptr<SharedMemoryRegion>(
           new SharedMemoryRegion(bitstream_buffer, true)),
       bitstream_buffer.id()));
 
   // Skip empty buffer.
   if (bitstream_buffer.size() == 0)
     return;
 
   if (!bitstream_record->shm->Map()) {
     LOGF(ERROR) << "could not map bitstream_buffer";
     NOTIFY_ERROR(UNREADABLE_INPUT);
     return;
   }
-  DVLOGF(3) << "mapped at=" << bitstream_record->shm->memory();
+  DVLOGF(4) << "mapped at=" << bitstream_record->shm->memory();
 
   if (decoder_state_ == kResetting || decoder_flushing_) {
     // In the case that we're resetting or flushing, we need to delay decoding
     // the BitstreamBuffers that come after the Reset() or Flush() call.  When
     // we're here, we know that this DecodeTask() was scheduled by a Decode()
     // call that came after (in the client thread) the Reset() or Flush() call;
     // thus set up the delay if necessary.
     if (decoder_delay_bitstream_buffer_id_ == -1)
       decoder_delay_bitstream_buffer_id_ = bitstream_record->input_id;
   } else if (decoder_state_ == kError) {
     DVLOGF(2) << "early out: kError state";
     return;
   }
 
   decoder_input_queue_.push(
       linked_ptr<BitstreamBufferRef>(bitstream_record.release()));
   decoder_decode_buffer_tasks_scheduled_++;
   DecodeBufferTask();
 }
 
 void V4L2VideoDecodeAccelerator::DecodeBufferTask() {
-  DVLOGF(3);
+  DVLOGF(4);
   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
   DCHECK_NE(decoder_state_, kUninitialized);
   TRACE_EVENT0("Video Decoder", "V4L2VDA::DecodeBufferTask");
 
   decoder_decode_buffer_tasks_scheduled_--;
 
   if (decoder_state_ != kInitialized && decoder_state_ != kDecoding) {
     DVLOGF(2) << "early out: state=" << decoder_state_;
     return;
   }
 
   if (decoder_current_bitstream_buffer_ == NULL) {
     if (decoder_input_queue_.empty()) {
       // We're waiting for a new buffer -- exit without scheduling a new task.
       return;
     }
     linked_ptr<BitstreamBufferRef>& buffer_ref = decoder_input_queue_.front();
     if (decoder_delay_bitstream_buffer_id_ == buffer_ref->input_id) {
       // We're asked to delay decoding on this and subsequent buffers.
       return;
     }
 
     // Setup to use the next buffer.
     decoder_current_bitstream_buffer_.reset(buffer_ref.release());
     decoder_input_queue_.pop();
     const auto& shm = decoder_current_bitstream_buffer_->shm;
     if (shm) {
-      DVLOGF(3) << "reading input_id="
+      DVLOGF(4) << "reading input_id="
                 << decoder_current_bitstream_buffer_->input_id
                 << ", addr=" << shm->memory() << ", size=" << shm->size();
     } else {
       DCHECK_EQ(decoder_current_bitstream_buffer_->input_id, kFlushBufferId);
-      DVLOGF(3) << "reading input_id=kFlushBufferId";
+      DVLOGF(4) << "reading input_id=kFlushBufferId";
     }
   }
   bool schedule_task = false;
   size_t decoded_size = 0;
   const auto& shm = decoder_current_bitstream_buffer_->shm;
   if (!shm) {
     // This is a dummy buffer, queued to flush the pipe.  Flush.
     DCHECK_EQ(decoder_current_bitstream_buffer_->input_id, kFlushBufferId);
     // Enqueue a buffer guaranteed to be empty.  To do that, we flush the
     // current input, enqueue no data to the next frame, then flush that down.
@@ skipping 48 matching lines @@
     // Failed during decode.
     return;
   }
 
   if (schedule_task) {
     decoder_current_bitstream_buffer_->bytes_used += decoded_size;
     if ((shm ? shm->size() : 0) ==
         decoder_current_bitstream_buffer_->bytes_used) {
       // Our current bitstream buffer is done; return it.
       int32_t input_id = decoder_current_bitstream_buffer_->input_id;
-      DVLOGF(3) << "finished input_id=" << input_id;
+      DVLOGF(4) << "finished input_id=" << input_id;
       // BitstreamBufferRef destructor calls NotifyEndOfBitstreamBuffer().
       decoder_current_bitstream_buffer_.reset();
     }
     ScheduleDecodeBufferTaskIfNeeded();
   }
 }
 
 bool V4L2VideoDecodeAccelerator::AdvanceFrameFragment(const uint8_t* data,
                                                       size_t size,
                                                       size_t* endpos) {
@@ skipping 91 matching lines @@
     decoder_decode_buffer_tasks_scheduled_++;
     decoder_thread_.task_runner()->PostTask(
         FROM_HERE, base::Bind(&V4L2VideoDecodeAccelerator::DecodeBufferTask,
                               base::Unretained(this)));
   }
 }
 
 bool V4L2VideoDecodeAccelerator::DecodeBufferInitial(const void* data,
                                                      size_t size,
                                                      size_t* endpos) {
-  DVLOGF(3) << "data=" << data << ", size=" << size;
+  DVLOGF(4) << "data=" << data << ", size=" << size;
   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
   DCHECK_EQ(decoder_state_, kInitialized);
   // Initial decode.  We haven't been able to get output stream format info yet.
   // Get it, and start decoding.
 
   // Copy in and send to HW.
   if (!AppendToInputFrame(data, size))
     return false;
 
   // If we only have a partial frame, don't flush and process yet.
@@ skipping 15 matching lines @@
 
   *endpos = size;
 
   if (again) {
     // Need more stream to decode format, return true and schedule next buffer.
     return true;
   }
 
   // Run this initialization only on first startup.
   if (output_buffer_map_.empty()) {
-    DVLOGF(3) << "running initialization";
+    DVLOGF(4) << "running initialization";
     // Success! Setup our parameters.
     if (!CreateBuffersForFormat(format, visible_size))
       return false;
     // We are waiting for AssignPictureBuffers. Do not set the state to
     // kDecoding.
   } else {
     decoder_state_ = kDecoding;
     ScheduleDecodeBufferTaskIfNeeded();
   }
   return true;
 }
 
 bool V4L2VideoDecodeAccelerator::DecodeBufferContinue(const void* data,
                                                       size_t size) {
-  DVLOGF(3) << "data=" << data << ", size=" << size;
+  DVLOGF(4) << "data=" << data << ", size=" << size;
   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
   DCHECK_EQ(decoder_state_, kDecoding);
 
   // Both of these calls will set kError state if they fail.
   // Only flush the frame if it's complete.
   return (AppendToInputFrame(data, size) &&
           (decoder_partial_frame_pending_ || FlushInputFrame()));
 }
 
 bool V4L2VideoDecodeAccelerator::AppendToInputFrame(const void* data,
                                                     size_t size) {
   DVLOGF(3);

[Pawel Osciak, 2017/05/23 09:49:22]

4?

[Owen Lin, 2017/06/02 08:51:43]

Done.

   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
   DCHECK_NE(decoder_state_, kUninitialized);
   DCHECK_NE(decoder_state_, kResetting);
   DCHECK_NE(decoder_state_, kError);
   // This routine can handle data == NULL and size == 0, which occurs when
   // we queue an empty buffer for the purposes of flushing the pipe.
 
   // Flush if we're too big
   if (decoder_current_input_buffer_ != -1) {
     InputRecord& input_record =
         input_buffer_map_[decoder_current_input_buffer_];
     if (input_record.bytes_used + size > input_record.length) {
       if (!FlushInputFrame())
         return false;
       decoder_current_input_buffer_ = -1;
     }
   }
 
   // Try to get an available input buffer
   if (decoder_current_input_buffer_ == -1) {
     if (free_input_buffers_.empty()) {
       // See if we can get more free buffers from HW
       Dequeue();
       if (free_input_buffers_.empty()) {
         // Nope!
         DVLOGF(2) << "stalled for input buffers";

[Pawel Osciak, 2017/05/23 09:49:21]

3, this is a very frequent print that doesn't give much information, just that
we have processed all pending inputs.

[Owen Lin, 2017/06/02 08:51:44]

Thanks.

         return false;
       }
     }
     decoder_current_input_buffer_ = free_input_buffers_.back();
     free_input_buffers_.pop_back();
     InputRecord& input_record =
         input_buffer_map_[decoder_current_input_buffer_];
     DCHECK_EQ(input_record.bytes_used, 0);
     DCHECK_EQ(input_record.input_id, -1);
     DCHECK(decoder_current_bitstream_buffer_ != NULL);
@@ skipping 17 matching lines @@
   }
   memcpy(reinterpret_cast<uint8_t*>(input_record.address) +
              input_record.bytes_used,
          data, size);
   input_record.bytes_used += size;
 
   return true;
 }
 
 bool V4L2VideoDecodeAccelerator::FlushInputFrame() {
-  DVLOGF(3);
+  DVLOGF(2);

[Pawel Osciak, 2017/05/23 09:49:22]

I think this is actually a part of each frame task, not the flush sequence, so
should be 4?

[Owen Lin, 2017/06/02 08:51:44]

Ah, Right. I was confused with Flush. It is not about Flush(), but sending input
to decoder.

   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
   DCHECK_NE(decoder_state_, kUninitialized);
   DCHECK_NE(decoder_state_, kResetting);
   DCHECK_NE(decoder_state_, kError);
 
   if (decoder_current_input_buffer_ == -1)
     return true;
 
   InputRecord& input_record = input_buffer_map_[decoder_current_input_buffer_];
   DCHECK_NE(input_record.input_id, -1);
   DCHECK(input_record.input_id != kFlushBufferId ||
          input_record.bytes_used == 0);
   // * if input_id >= 0, this input buffer was prompted by a bitstream buffer we
   //   got from the client.  We can skip it if it is empty.
   // * if input_id < 0 (should be kFlushBufferId in this case), this input
   //   buffer was prompted by a flush buffer, and should be queued even when
   //   empty.
   if (input_record.input_id >= 0 && input_record.bytes_used == 0) {
     input_record.input_id = -1;
     free_input_buffers_.push_back(decoder_current_input_buffer_);
     decoder_current_input_buffer_ = -1;
     return true;
   }
 
   // Queue it.
   input_ready_queue_.push(decoder_current_input_buffer_);
   decoder_current_input_buffer_ = -1;
-  DVLOGF(3) << "submitting input_id=" << input_record.input_id;
+  DVLOGF(2) << "submitting input_id=" << input_record.input_id;

[Pawel Osciak, 2017/05/23 09:49:21]

Ditto.

[Owen Lin, 2017/06/02 08:51:43]

Done.

   // Enqueue once since there's new available input for it.
   Enqueue();
 
   return (decoder_state_ != kError);
 }
 
 void V4L2VideoDecodeAccelerator::ServiceDeviceTask(bool event_pending) {
   DVLOGF(3);
   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
   DCHECK_NE(decoder_state_, kUninitialized);
   TRACE_EVENT0("Video Decoder", "V4L2VDA::ServiceDeviceTask");
 
   if (decoder_state_ == kResetting) {
-    DVLOGF(2) << "early out: kResetting state";
+    DVLOGF(3) << "early out: kResetting state";
     return;
   } else if (decoder_state_ == kError) {
-    DVLOGF(2) << "early out: kError state";
+    DVLOGF(3) << "early out: kError state";
     return;
   } else if (decoder_state_ == kChangingResolution) {
-    DVLOGF(2) << "early out: kChangingResolution state";
+    DVLOGF(3) << "early out: kChangingResolution state";
     return;
   }
 
   bool resolution_change_pending = false;
   if (event_pending)
     resolution_change_pending = DequeueResolutionChangeEvent();
   Dequeue();
   Enqueue();
 
   // Clear the interrupt fd.
@@ skipping 13 matching lines @@
   // * device_poll_thread_ is running normally
   // * device_poll_thread_ scheduled us, but then a ResetTask() or DestroyTask()
   //   shut it down, in which case we're either in kResetting or kError states
   //   respectively, and we should have early-outed already.
   DCHECK(device_poll_thread_.message_loop());
   // Queue the DevicePollTask() now.
   device_poll_thread_.task_runner()->PostTask(
       FROM_HERE, base::Bind(&V4L2VideoDecodeAccelerator::DevicePollTask,
                             base::Unretained(this), poll_device));
 
-  DVLOG(1) << "ServiceDeviceTask(): buffer counts: DEC["
-           << decoder_input_queue_.size() << "->"
-           << input_ready_queue_.size() << "] => DEVICE["
-           << free_input_buffers_.size() << "+"
-           << input_buffer_queued_count_ << "/"
-           << input_buffer_map_.size() << "->"
-           << free_output_buffers_.size() << "+"
-           << output_buffer_queued_count_ << "/"
-           << output_buffer_map_.size() << "] => PROCESSOR["
-           << image_processor_bitstream_buffer_ids_.size() << "] => CLIENT["
-           << decoder_frames_at_client_ << "]";
+  DVLOG(3) << "ServiceDeviceTask(): buffer counts: DEC["

[Pawel Osciak, 2017/05/23 09:49:21]

This is per frame, but actually quite useful at 3 I'd say, as the only per-frame
output above 4. Perhaps we should keep it at 3.

[Owen Lin, 2017/06/02 08:51:43]

Done.

+           << decoder_input_queue_.size() << "->" << input_ready_queue_.size()

[Pawel Osciak, 2017/05/23 09:49:21]

Could we keep the original formatting please, I feel it's more readable?

[Owen Lin, 2017/06/02 08:51:43]

OK. But it is the result of "git cl format", we will need to keep the format
manually after every "cl format".

[Pawel Osciak, 2017/06/08 03:57:11]

Yes, unfortunately.

+           << "] => DEVICE[" << free_input_buffers_.size() << "+"
+           << input_buffer_queued_count_ << "/" << input_buffer_map_.size()
+           << "->" << free_output_buffers_.size() << "+"
+           << output_buffer_queued_count_ << "/" << output_buffer_map_.size()
+           << "] => PROCESSOR[" << image_processor_bitstream_buffer_ids_.size()
+           << "] => CLIENT[" << decoder_frames_at_client_ << "]";
 
   ScheduleDecodeBufferTaskIfNeeded();
   if (resolution_change_pending)
     StartResolutionChange();
 }
 
 void V4L2VideoDecodeAccelerator::Enqueue() {
   DVLOGF(3);

[Pawel Osciak, 2017/05/23 09:49:21]

4?

[Owen Lin, 2017/06/02 08:51:43]

Done.

   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
   DCHECK_NE(decoder_state_, kUninitialized);
   TRACE_EVENT0("Video Decoder", "V4L2VDA::Enqueue");
 
   // Drain the pipe of completed decode buffers.
   const int old_inputs_queued = input_buffer_queued_count_;
   while (!input_ready_queue_.empty()) {
     const int buffer = input_ready_queue_.front();
     InputRecord& input_record = input_buffer_map_[buffer];
     if (input_record.input_id == kFlushBufferId && decoder_cmd_supported_) {
@@ skipping 54 matching lines @@
       __u32 type = V4L2_BUF_TYPE_VIDEO_CAPTURE_MPLANE;
       IOCTL_OR_ERROR_RETURN(VIDIOC_STREAMON, &type);
       output_streamon_ = true;
     }
   }
 }
 
 bool V4L2VideoDecodeAccelerator::DequeueResolutionChangeEvent() {
   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
   DCHECK_NE(decoder_state_, kUninitialized);
   DVLOGF(3);

[Pawel Osciak, 2017/05/23 09:49:21]

2?

[Owen Lin, 2017/06/02 08:51:44]

Done.

 
   struct v4l2_event ev;
   memset(&ev, 0, sizeof(ev));
 
   while (device_->Ioctl(VIDIOC_DQEVENT, &ev) == 0) {
     if (ev.type == V4L2_EVENT_SOURCE_CHANGE) {
       if (ev.u.src_change.changes & V4L2_EVENT_SRC_CH_RESOLUTION) {
         DVLOGF(3) << "got resolution change event.";

[Pawel Osciak, 2017/05/23 09:49:21]

2?

[Owen Lin, 2017/06/02 08:51:43]

Done.

         return true;
       }
     } else {
       LOGF(ERROR) << "got an event (" << ev.type
                   << ") we haven't subscribed to.";
     }
   }
   return false;
 }
 
 void V4L2VideoDecodeAccelerator::Dequeue() {
   DVLOGF(3);

[Pawel Osciak, 2017/05/23 09:49:21]

Perhaps 4?

[Owen Lin, 2017/06/02 08:51:43]

Done.

   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
   DCHECK_NE(decoder_state_, kUninitialized);
   TRACE_EVENT0("Video Decoder", "V4L2VDA::Dequeue");
 
   while (input_buffer_queued_count_ > 0) {
     if (!DequeueInputBuffer())
       break;
   }
   while (output_buffer_queued_count_ > 0) {
     if (!DequeueOutputBuffer())
@@ skipping 69 matching lines @@
   DCHECK_EQ(output_record.state, kAtDevice);
   DCHECK_NE(output_record.picture_id, -1);
   output_buffer_queued_count_--;
   if (dqbuf.m.planes[0].bytesused == 0) {
     // This is an empty output buffer returned as part of a flush.
     output_record.state = kFree;
     free_output_buffers_.push_back(dqbuf.index);
   } else {
     int32_t bitstream_buffer_id = dqbuf.timestamp.tv_sec;
     DCHECK_GE(bitstream_buffer_id, 0);
     DVLOGF(3) << "Dequeue output buffer: dqbuf index=" << dqbuf.index

[Pawel Osciak, 2017/05/23 09:49:22]

Perhaps 4?

[Owen Lin, 2017/06/02 08:51:43]

Done.

               << " bitstream input_id=" << bitstream_buffer_id;
     if (image_processor_device_) {
       if (!ProcessFrame(bitstream_buffer_id, dqbuf.index)) {
         DLOGF(ERROR) << "Processing frame failed";
         NOTIFY_ERROR(PLATFORM_FAILURE);
         return false;
       }
     } else {
       output_record.state = kAtClient;
       decoder_frames_at_client_++;
@@ skipping 14 matching lines @@
       struct v4l2_decoder_cmd cmd;
       memset(&cmd, 0, sizeof(cmd));
       cmd.cmd = V4L2_DEC_CMD_START;
       IOCTL_OR_ERROR_RETURN_FALSE(VIDIOC_DECODER_CMD, &cmd);
     }
   }
   return true;
 }
 
 bool V4L2VideoDecodeAccelerator::EnqueueInputRecord() {
   DVLOGF(3);

[Pawel Osciak, 2017/05/23 09:49:22]

Perhaps 4?

[Owen Lin, 2017/06/02 08:51:43]

Done.

   DCHECK(!input_ready_queue_.empty());
 
   // Enqueue an input (VIDEO_OUTPUT) buffer.
   const int buffer = input_ready_queue_.front();
   InputRecord& input_record = input_buffer_map_[buffer];
   DCHECK(!input_record.at_device);
   struct v4l2_buffer qbuf;
   struct v4l2_plane qbuf_plane;
   memset(&qbuf, 0, sizeof(qbuf));
   memset(&qbuf_plane, 0, sizeof(qbuf_plane));
   qbuf.index = buffer;
   qbuf.type = V4L2_BUF_TYPE_VIDEO_OUTPUT_MPLANE;
   qbuf.timestamp.tv_sec = input_record.input_id;
   qbuf.memory = V4L2_MEMORY_MMAP;
   qbuf.m.planes = &qbuf_plane;
   qbuf.m.planes[0].bytesused = input_record.bytes_used;
   qbuf.length = 1;
   IOCTL_OR_ERROR_RETURN_FALSE(VIDIOC_QBUF, &qbuf);
   input_ready_queue_.pop();
   input_record.at_device = true;
   input_buffer_queued_count_++;
   DVLOGF(3) << "enqueued input_id=" << input_record.input_id

[Pawel Osciak, 2017/05/23 09:49:21]

Perhaps 4?

[Owen Lin, 2017/06/02 08:51:43]

Done.

             << " size=" << input_record.bytes_used;
   return true;
 }
 
 bool V4L2VideoDecodeAccelerator::EnqueueOutputRecord() {
   DCHECK(!free_output_buffers_.empty());
 
   // Enqueue an output (VIDEO_CAPTURE) buffer.
   const int buffer = free_output_buffers_.front();
   DVLOGF(3) << "buffer " << buffer;

[Pawel Osciak, 2017/05/23 09:49:21]

Perhaps 4?

[Owen Lin, 2017/06/02 08:51:43]

Done.

   OutputRecord& output_record = output_buffer_map_[buffer];
   DCHECK_EQ(output_record.state, kFree);
   DCHECK_NE(output_record.picture_id, -1);
   if (output_record.egl_sync != EGL_NO_SYNC_KHR) {
     TRACE_EVENT0("Video Decoder",
                  "V4L2VDA::EnqueueOutputRecord: eglClientWaitSyncKHR");
     // If we have to wait for completion, wait.  Note that
     // free_output_buffers_ is a FIFO queue, so we always wait on the
     // buffer that has been in the queue the longest.
     if (eglClientWaitSyncKHR(egl_display_, output_record.egl_sync, 0,
@@ skipping 12 matching lines @@
   std::unique_ptr<struct v4l2_plane[]> qbuf_planes(
       new v4l2_plane[output_planes_count_]);
   memset(&qbuf, 0, sizeof(qbuf));
   memset(qbuf_planes.get(), 0,
          sizeof(struct v4l2_plane) * output_planes_count_);
   qbuf.index = buffer;
   qbuf.type = V4L2_BUF_TYPE_VIDEO_CAPTURE_MPLANE;
   qbuf.memory = V4L2_MEMORY_MMAP;
   qbuf.m.planes = qbuf_planes.get();
   qbuf.length = output_planes_count_;
-  DVLOGF(2) << "qbuf.index=" << qbuf.index;
+  DVLOGF(3) << "qbuf.index=" << qbuf.index;

[Pawel Osciak, 2017/05/23 09:49:21]

Perhaps 4?

[Owen Lin, 2017/06/02 08:51:43]

Done.

   IOCTL_OR_ERROR_RETURN_FALSE(VIDIOC_QBUF, &qbuf);
   free_output_buffers_.pop_front();
   output_record.state = kAtDevice;
   output_buffer_queued_count_++;
   return true;
 }
 
 void V4L2VideoDecodeAccelerator::ReusePictureBufferTask(
     int32_t picture_buffer_id,
     std::unique_ptr<EGLSyncKHRRef> egl_sync_ref) {
-  DVLOGF(3) << "picture_buffer_id=" << picture_buffer_id;
+  DVLOGF(4) << "picture_buffer_id=" << picture_buffer_id;
   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
   TRACE_EVENT0("Video Decoder", "V4L2VDA::ReusePictureBufferTask");
 
   // We run ReusePictureBufferTask even if we're in kResetting.
   if (decoder_state_ == kError) {
-    DVLOGF(2) << "early out: kError state";
+    DVLOGF(4) << "early out: kError state";
     return;
   }
 
   if (decoder_state_ == kChangingResolution) {
-    DVLOGF(2) << "early out: kChangingResolution";
+    DVLOGF(4) << "early out: kChangingResolution";
     return;
   }
 
   size_t index;
   for (index = 0; index < output_buffer_map_.size(); ++index)
     if (output_buffer_map_[index].picture_id == picture_buffer_id)
       break;
 
   if (index >= output_buffer_map_.size()) {
     // It's possible that we've already posted a DismissPictureBuffer for this
@@ skipping 20 matching lines @@
   if (egl_sync_ref) {
     output_record.egl_sync = egl_sync_ref->egl_sync;
     // Take ownership of the EGLSync.
     egl_sync_ref->egl_sync = EGL_NO_SYNC_KHR;
   }
   // We got a buffer back, so enqueue it back.
   Enqueue();
 }
 
 void V4L2VideoDecodeAccelerator::FlushTask() {
-  DVLOGF(3);
+  DVLOGF(2);
   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
   TRACE_EVENT0("Video Decoder", "V4L2VDA::FlushTask");
 
   // Flush outstanding buffers.
   if (decoder_state_ == kInitialized) {
     // There's nothing in the pipe, so return done immediately.
-    DVLOGF(3) << "returning flush";
+    DVLOGF(2) << "returning flush";
     child_task_runner_->PostTask(FROM_HERE,
                                  base::Bind(&Client::NotifyFlushDone, client_));
     return;
   } else if (decoder_state_ == kError) {
     DVLOGF(2) << "early out: kError state";
     return;
   }
 
   // We don't support stacked flushing.
   DCHECK(!decoder_flushing_);
@@ skipping 53 matching lines @@
   // For now, do the streamoff-streamon cycle to satisfy Exynos and not freeze
   // when doing MSE. This should be harmless otherwise.
   if (!(StopDevicePoll() && StopOutputStream() && StopInputStream()))
     return;
 
   if (!StartDevicePoll())
     return;
 
   decoder_delay_bitstream_buffer_id_ = -1;
   decoder_flushing_ = false;
-  DVLOGF(3) << "returning flush";
+  DVLOGF(2) << "returning flush";
   child_task_runner_->PostTask(FROM_HERE,
                                base::Bind(&Client::NotifyFlushDone, client_));
 
   // While we were flushing, we early-outed DecodeBufferTask()s.
   ScheduleDecodeBufferTaskIfNeeded();
 }
 
 bool V4L2VideoDecodeAccelerator::IsDecoderCmdSupported() {
   // CMD_STOP should always succeed. If the decoder is started, the command can
   // flush it. If the decoder is stopped, the command does nothing. We use this
   // to know if a driver supports V4L2_DEC_CMD_STOP to flush.
   struct v4l2_decoder_cmd cmd;
   memset(&cmd, 0, sizeof(cmd));
   cmd.cmd = V4L2_DEC_CMD_STOP;
   if (device_->Ioctl(VIDIOC_TRY_DECODER_CMD, &cmd) != 0) {
-    DVLOGF(3) "V4L2_DEC_CMD_STOP is not supported.";
+    DVLOGF(2) "V4L2_DEC_CMD_STOP is not supported.";
     return false;
   }
 
   return true;
 }
 
 bool V4L2VideoDecodeAccelerator::SendDecoderCmdStop() {
   DVLOGF(2);
   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
   DCHECK(!flush_awaiting_last_output_buffer_);
 
   struct v4l2_decoder_cmd cmd;
   memset(&cmd, 0, sizeof(cmd));
   cmd.cmd = V4L2_DEC_CMD_STOP;
   IOCTL_OR_ERROR_RETURN_FALSE(VIDIOC_DECODER_CMD, &cmd);
   flush_awaiting_last_output_buffer_ = true;
 
   return true;
 }
 
 void V4L2VideoDecodeAccelerator::ResetTask() {
-  DVLOGF(3);
+  DVLOGF(2);
   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
   TRACE_EVENT0("Video Decoder", "V4L2VDA::ResetTask");
 
   if (decoder_state_ == kError) {
     DVLOGF(2) << "early out: kError state";
     return;
   }
   decoder_current_bitstream_buffer_.reset();
   while (!decoder_input_queue_.empty())
     decoder_input_queue_.pop();
 
   decoder_current_input_buffer_ = -1;
 
   // If we are in the middle of switching resolutions or awaiting picture
   // buffers, postpone reset until it's done. We don't have to worry about
   // timing of this wrt to decoding, because output pipe is already
   // stopped if we are changing resolution. We will come back here after
   // we are done.
   DCHECK(!reset_pending_);
   if (decoder_state_ == kChangingResolution ||
       decoder_state_ == kAwaitingPictureBuffers) {
     reset_pending_ = true;
     return;
   }
   FinishReset();
 }
 
 void V4L2VideoDecodeAccelerator::FinishReset() {
-  DVLOGF(3);
+  DVLOGF(2);
   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
 
   reset_pending_ = false;
   // After the output stream is stopped, the codec should not post any
   // resolution change events. So we dequeue the resolution change event
   // afterwards. The event could be posted before or while stopping the output
   // stream. The codec will expect the buffer of new size after the seek, so
   // we need to handle the resolution change event first.
   if (!(StopDevicePoll() && StopOutputStream()))
     return;
@@ skipping 21 matching lines @@
   // Mark that we're resetting, then enqueue a ResetDoneTask().  All intervening
   // jobs will early-out in the kResetting state.
   decoder_state_ = kResetting;
   SendPictureReady();  // Send all pending PictureReady.
   decoder_thread_.task_runner()->PostTask(
       FROM_HERE, base::Bind(&V4L2VideoDecodeAccelerator::ResetDoneTask,
                             base::Unretained(this)));
 }
 
 void V4L2VideoDecodeAccelerator::ResetDoneTask() {
-  DVLOGF(3);
+  DVLOGF(2);
   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
   TRACE_EVENT0("Video Decoder", "V4L2VDA::ResetDoneTask");
 
   if (decoder_state_ == kError) {
     DVLOGF(2) << "early out: kError state";
     return;
   }
 
   // Start poll thread if NotifyFlushDoneIfNeeded has not already.
   if (!device_poll_thread_.IsRunning()) {
@@ skipping 13 matching lines @@
   decoder_partial_frame_pending_ = false;
   decoder_delay_bitstream_buffer_id_ = -1;
   child_task_runner_->PostTask(FROM_HERE,
                                base::Bind(&Client::NotifyResetDone, client_));
 
   // While we were resetting, we early-outed DecodeBufferTask()s.
   ScheduleDecodeBufferTaskIfNeeded();
 }
 
 void V4L2VideoDecodeAccelerator::DestroyTask() {
-  DVLOGF(3);
+  DVLOGF(2);
   TRACE_EVENT0("Video Decoder", "V4L2VDA::DestroyTask");
 
   // DestroyTask() should run regardless of decoder_state_.
 
   StopDevicePoll();
   StopOutputStream();
   StopInputStream();
 
   decoder_current_bitstream_buffer_.reset();
   decoder_current_input_buffer_ = -1;
@@ skipping 50 matching lines @@
   // Clear the interrupt now, to be sure.
   if (!device_->ClearDevicePollInterrupt()) {
     NOTIFY_ERROR(PLATFORM_FAILURE);
     return false;
   }
   DVLOGF(3) << "device poll stopped";
   return true;
 }
 
 bool V4L2VideoDecodeAccelerator::StopOutputStream() {
-  DVLOGF(3);
+  DVLOGF(2);
   if (!output_streamon_)
     return true;
 
   __u32 type = V4L2_BUF_TYPE_VIDEO_CAPTURE_MPLANE;
   IOCTL_OR_ERROR_RETURN_FALSE(VIDIOC_STREAMOFF, &type);
   output_streamon_ = false;
 
   // Output stream is stopped. No need to wait for the buffer anymore.
   flush_awaiting_last_output_buffer_ = false;
 
   for (size_t i = 0; i < output_buffer_map_.size(); ++i) {
     // After streamoff, the device drops ownership of all buffers, even if we
     // don't dequeue them explicitly. Some of them may still be owned by the
     // client however. Reuse only those that aren't.
     OutputRecord& output_record = output_buffer_map_[i];
     if (output_record.state == kAtDevice) {
       output_record.state = kFree;
       free_output_buffers_.push_back(i);
       DCHECK_EQ(output_record.egl_sync, EGL_NO_SYNC_KHR);
     }
   }
   output_buffer_queued_count_ = 0;
   return true;
 }
 
 bool V4L2VideoDecodeAccelerator::StopInputStream() {
-  DVLOGF(3);
+  DVLOGF(2);
   if (!input_streamon_)
     return true;
 
   __u32 type = V4L2_BUF_TYPE_VIDEO_OUTPUT_MPLANE;
   IOCTL_OR_ERROR_RETURN_FALSE(VIDIOC_STREAMOFF, &type);
   input_streamon_ = false;
 
   // Reset accounting info for input.
   while (!input_ready_queue_.empty())
     input_ready_queue_.pop();
   free_input_buffers_.clear();
   for (size_t i = 0; i < input_buffer_map_.size(); ++i) {
     free_input_buffers_.push_back(i);
     input_buffer_map_[i].at_device = false;
     input_buffer_map_[i].bytes_used = 0;
     input_buffer_map_[i].input_id = -1;
   }
   input_buffer_queued_count_ = 0;
 
   return true;
 }
 
 void V4L2VideoDecodeAccelerator::StartResolutionChange() {
   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
   DCHECK_NE(decoder_state_, kUninitialized);
   DCHECK_NE(decoder_state_, kResetting);
 
-  DVLOGF(3) << "Initiate resolution change";
+  DVLOGF(2) << "Initiate resolution change";
 
   if (!(StopDevicePoll() && StopOutputStream()))
     return;
 
   decoder_state_ = kChangingResolution;
   SendPictureReady();  // Send all pending PictureReady.
 
   if (!image_processor_bitstream_buffer_ids_.empty()) {
-    DVLOGF(3) << "Wait image processor to finish before destroying buffers.";
+    DVLOGF(2) << "Wait image processor to finish before destroying buffers.";
     return;
   }
 
   if (image_processor_)
     image_processor_.release()->Destroy();
 
   if (!DestroyOutputBuffers()) {
     LOGF(ERROR) << "Failed destroying output buffers.";
     NOTIFY_ERROR(PLATFORM_FAILURE);
     return;
   }
 
   FinishResolutionChange();
 }
 
 void V4L2VideoDecodeAccelerator::FinishResolutionChange() {
   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
   DCHECK_EQ(decoder_state_, kChangingResolution);
-  DVLOGF(3);
+  DVLOGF(2);
 
   if (decoder_state_ == kError) {
     DVLOGF(2) << "early out: kError state";
     return;
   }
 
   struct v4l2_format format;
   bool again;
   gfx::Size visible_size;
   bool ret = GetFormatInfo(&format, &visible_size, &again);
   if (!ret || again) {
     LOGF(ERROR) << "Couldn't get format information after resolution change";
     NOTIFY_ERROR(PLATFORM_FAILURE);
     return;
   }
 
   if (!CreateBuffersForFormat(format, visible_size)) {
     LOGF(ERROR) << "Couldn't reallocate buffers after resolution change";
     NOTIFY_ERROR(PLATFORM_FAILURE);
     return;
   }
 
   if (!StartDevicePoll())
     return;
 }
 
 void V4L2VideoDecodeAccelerator::DevicePollTask(bool poll_device) {
   DVLOGF(3);

[Pawel Osciak, 2017/05/23 09:49:21]

4 perhaps?

[Owen Lin, 2017/06/02 08:51:43]

Done.

   DCHECK(device_poll_thread_.task_runner()->BelongsToCurrentThread());
   TRACE_EVENT0("Video Decoder", "V4L2VDA::DevicePollTask");
 
   bool event_pending = false;
 
   if (!device_->Poll(poll_device, &event_pending)) {
     NOTIFY_ERROR(PLATFORM_FAILURE);
     return;
   }
 
@@ skipping 85 matching lines @@
     if (!V4L2ImageProcessor::TryOutputFormat(
             output_format_fourcc_, egl_image_format_fourcc_, &egl_image_size_,
             &egl_image_planes_count_)) {
       LOGF(ERROR) << "Fail to get output size and plane count of processor";
       return false;
     }
   } else {
     egl_image_size_ = coded_size_;
     egl_image_planes_count_ = output_planes_count_;
   }
-  DVLOGF(3) << "new resolution: " << coded_size_.ToString()
+  DVLOGF(2) << "new resolution: " << coded_size_.ToString()
             << ", visible size: " << visible_size_.ToString()
             << ", decoder output planes count: " << output_planes_count_
             << ", EGLImage size: " << egl_image_size_.ToString()
             << ", EGLImage plane count: " << egl_image_planes_count_;
 
   return CreateOutputBuffers();
 }
 
 gfx::Size V4L2VideoDecodeAccelerator::GetVisibleSize(
     const gfx::Size& coded_size) {
   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
 
   struct v4l2_crop crop_arg;
   memset(&crop_arg, 0, sizeof(crop_arg));
   crop_arg.type = V4L2_BUF_TYPE_VIDEO_CAPTURE_MPLANE;
 
   if (device_->Ioctl(VIDIOC_G_CROP, &crop_arg) != 0) {
     PLOGF(ERROR) << "ioctl() VIDIOC_G_CROP failed";
     return coded_size;
   }
 
   gfx::Rect rect(crop_arg.c.left, crop_arg.c.top, crop_arg.c.width,
                  crop_arg.c.height);
-  DVLOGF(3) << "visible rectangle is " << rect.ToString();
+  DVLOGF(2) << "visible rectangle is " << rect.ToString();
   if (!gfx::Rect(coded_size).Contains(rect)) {
     DLOGF(ERROR) << "visible rectangle " << rect.ToString()
                  << " is not inside coded size " << coded_size.ToString();
     return coded_size;
   }
   if (rect.IsEmpty()) {
     DLOGF(ERROR) << "visible size is empty";
     return coded_size;
   }
 
   // Chrome assume picture frame is coded at (0, 0).
   if (!rect.origin().IsOrigin()) {
     DLOGF(ERROR) << "Unexpected visible rectangle " << rect.ToString()
                  << ", top-left is not origin";
     return coded_size;
   }
 
   return rect.size();
 }
 
 bool V4L2VideoDecodeAccelerator::CreateInputBuffers() {
-  DVLOGF(3);
+  DVLOGF(2);
   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
   // We always run this as we prepare to initialize.
   DCHECK_EQ(decoder_state_, kInitialized);
   DCHECK(!input_streamon_);
   DCHECK(input_buffer_map_.empty());
 
   struct v4l2_requestbuffers reqbufs;
   memset(&reqbufs, 0, sizeof(reqbufs));
   reqbufs.count = kInputBufferCount;
   reqbufs.type = V4L2_BUF_TYPE_VIDEO_OUTPUT_MPLANE;
@@ skipping 133 matching lines @@
   std::vector<uint32_t> processor_input_formats =
       V4L2ImageProcessor::GetSupportedInputFormats();
 
   struct v4l2_fmtdesc fmtdesc;
   memset(&fmtdesc, 0, sizeof(fmtdesc));
   fmtdesc.type = V4L2_BUF_TYPE_VIDEO_CAPTURE_MPLANE;
   while (device_->Ioctl(VIDIOC_ENUM_FMT, &fmtdesc) == 0) {
     if (std::find(processor_input_formats.begin(),
                   processor_input_formats.end(),
                   fmtdesc.pixelformat) != processor_input_formats.end()) {
-      DVLOGF(1) << "Image processor input format=" << fmtdesc.description;
+      DVLOGF(2) << "Image processor input format=" << fmtdesc.description;
       return fmtdesc.pixelformat;
     }
     ++fmtdesc.index;
   }
   return 0;
 }
 
 uint32_t V4L2VideoDecodeAccelerator::FindImageProcessorOutputFormat() {
   // Prefer YVU420 and NV12 because ArcGpuVideoDecodeAccelerator only supports
   // single physical plane. Prefer YVU420 over NV12 because chrome rendering
@@ skipping 10 matching lines @@
 
   std::vector<uint32_t> processor_output_formats =
       V4L2ImageProcessor::GetSupportedOutputFormats();
 
   // Move the preferred formats to the front.
   std::sort(processor_output_formats.begin(), processor_output_formats.end(),
             preferred_formats_first);
 
   for (uint32_t processor_output_format : processor_output_formats) {
     if (device_->CanCreateEGLImageFrom(processor_output_format)) {
-      DVLOGF(1) << "Image processor output format=" << processor_output_format;
+      DVLOGF(2) << "Image processor output format=" << processor_output_format;
       return processor_output_format;
     }
   }
 
   return 0;
 }
 
 bool V4L2VideoDecodeAccelerator::ResetImageProcessor() {
-  DVLOGF(3);
+  DVLOGF(2);
   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
 
   if (!image_processor_->Reset())
     return false;
   for (size_t i = 0; i < output_buffer_map_.size(); ++i) {
     OutputRecord& output_record = output_buffer_map_[i];
     if (output_record.state == kAtProcessor) {
       output_record.state = kFree;
       free_output_buffers_.push_back(i);
     }
   }
   while (!image_processor_bitstream_buffer_ids_.empty())
     image_processor_bitstream_buffer_ids_.pop();
 
   return true;
 }
 
 bool V4L2VideoDecodeAccelerator::CreateImageProcessor() {
-  DVLOGF(3);
+  DVLOGF(2);
   DCHECK(!image_processor_);
   image_processor_.reset(new V4L2ImageProcessor(image_processor_device_));
   v4l2_memory output_memory_type =
       (output_mode_ == Config::OutputMode::ALLOCATE ? V4L2_MEMORY_MMAP
                                                     : V4L2_MEMORY_DMABUF);
   // Unretained is safe because |this| owns image processor and there will be
   // no callbacks after processor destroys.
   if (!image_processor_->Initialize(
           V4L2Device::V4L2PixFmtToVideoPixelFormat(output_format_fourcc_),
           V4L2Device::V4L2PixFmtToVideoPixelFormat(egl_image_format_fourcc_),
           V4L2_MEMORY_DMABUF, output_memory_type, visible_size_, coded_size_,
           visible_size_, egl_image_size_, output_buffer_map_.size(),
           base::Bind(&V4L2VideoDecodeAccelerator::ImageProcessorError,
                      base::Unretained(this)))) {
     LOGF(ERROR) << "Initialize image processor failed";
     NOTIFY_ERROR(PLATFORM_FAILURE);
     return false;
   }
-  DVLOGF(3) << "image_processor_->output_allocated_size()="
+  DVLOGF(2) << "image_processor_->output_allocated_size()="
             << image_processor_->output_allocated_size().ToString();
   DCHECK(image_processor_->output_allocated_size() == egl_image_size_);
   if (image_processor_->input_allocated_size() != coded_size_) {
     LOGF(ERROR) << "Image processor should be able to take the output coded "
                 << "size of decoder " << coded_size_.ToString()
                 << " without adjusting to "
                 << image_processor_->input_allocated_size().ToString();
     NOTIFY_ERROR(PLATFORM_FAILURE);
     return false;
   }
   return true;
 }
 
 bool V4L2VideoDecodeAccelerator::ProcessFrame(int32_t bitstream_buffer_id,
                                               int output_buffer_index) {
-  DVLOGF(3);
+  DVLOGF(4);
   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
 
   OutputRecord& output_record = output_buffer_map_[output_buffer_index];
   DCHECK_EQ(output_record.state, kAtDevice);
   output_record.state = kAtProcessor;
   image_processor_bitstream_buffer_ids_.push(bitstream_buffer_id);
   std::vector<int> processor_input_fds;
   for (auto& fd : output_record.processor_input_fds) {
     processor_input_fds.push_back(fd.get());
   }
@@ skipping 16 matching lines @@
   // Unretained is safe because |this| owns image processor and there will
   // be no callbacks after processor destroys.
   image_processor_->Process(
       input_frame, output_buffer_index, std::move(processor_output_fds),
       base::Bind(&V4L2VideoDecodeAccelerator::FrameProcessed,
                  base::Unretained(this), bitstream_buffer_id));
   return true;
 }
 
 bool V4L2VideoDecodeAccelerator::CreateOutputBuffers() {
-  DVLOGF(3);
+  DVLOGF(2);
   DCHECK(decoder_state_ == kInitialized ||
          decoder_state_ == kChangingResolution);
   DCHECK(!output_streamon_);
   DCHECK(output_buffer_map_.empty());
 
   // Number of output buffers we need.
   struct v4l2_control ctrl;
   memset(&ctrl, 0, sizeof(ctrl));
   ctrl.id = V4L2_CID_MIN_BUFFERS_FOR_CAPTURE;
   IOCTL_OR_ERROR_RETURN_FALSE(VIDIOC_G_CTRL, &ctrl);
@@ skipping 27 matching lines @@
   // non-slice NALUs and could even get another resolution change before we were
   // done with this one. After we get the buffers, we'll go back into kIdle and
   // kick off further event processing, and eventually go back into kDecoding
   // once no more events are pending (if any).
   decoder_state_ = kAwaitingPictureBuffers;
 
   return true;
 }
 
 void V4L2VideoDecodeAccelerator::DestroyInputBuffers() {
-  DVLOGF(3);
+  DVLOGF(2);
   DCHECK(!decoder_thread_.IsRunning() ||
          decoder_thread_.task_runner()->BelongsToCurrentThread());
   DCHECK(!input_streamon_);
 
   if (input_buffer_map_.empty())
     return;
 
   for (size_t i = 0; i < input_buffer_map_.size(); ++i) {
     if (input_buffer_map_[i].address != NULL) {
       device_->Munmap(input_buffer_map_[i].address,
                       input_buffer_map_[i].length);
     }
   }
 
   struct v4l2_requestbuffers reqbufs;
   memset(&reqbufs, 0, sizeof(reqbufs));
   reqbufs.count = 0;
   reqbufs.type = V4L2_BUF_TYPE_VIDEO_OUTPUT_MPLANE;
   reqbufs.memory = V4L2_MEMORY_MMAP;
   IOCTL_OR_LOG_ERROR(VIDIOC_REQBUFS, &reqbufs);
 
   input_buffer_map_.clear();
   free_input_buffers_.clear();
 }
 
 bool V4L2VideoDecodeAccelerator::DestroyOutputBuffers() {
-  DVLOGF(3);
+  DVLOGF(2);
   DCHECK(!decoder_thread_.IsRunning() ||
          decoder_thread_.task_runner()->BelongsToCurrentThread());
   DCHECK(!output_streamon_);
   bool success = true;
 
   if (output_buffer_map_.empty())
     return true;
 
   for (size_t i = 0; i < output_buffer_map_.size(); ++i) {
     OutputRecord& output_record = output_buffer_map_[i];
@@ skipping 34 matching lines @@
     free_output_buffers_.pop_front();
   output_buffer_queued_count_ = 0;
   // The client may still hold some buffers. The texture holds a reference to
   // the buffer. It is OK to free the buffer and destroy EGLImage here.
   decoder_frames_at_client_ = 0;
 
   return success;
 }
 
 void V4L2VideoDecodeAccelerator::SendPictureReady() {
-  DVLOGF(3);
+  DVLOGF(4);
   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
   bool send_now = (decoder_state_ == kChangingResolution ||
                    decoder_state_ == kResetting || decoder_flushing_);
   while (pending_picture_ready_.size() > 0) {
     bool cleared = pending_picture_ready_.front().cleared;
     const Picture& picture = pending_picture_ready_.front().picture;
     if (cleared && picture_clearing_count_ == 0) {
       // This picture is cleared. It can be posted to a thread different than
       // the main GPU thread to reduce latency. This should be the case after
       // all pictures are cleared at the beginning.
       decode_task_runner_->PostTask(
           FROM_HERE,
           base::Bind(&Client::PictureReady, decode_client_, picture));
       pending_picture_ready_.pop();
     } else if (!cleared || send_now) {
-      DVLOGF(3) << "cleared=" << pending_picture_ready_.front().cleared
+      DVLOGF(4) << "cleared=" << pending_picture_ready_.front().cleared
                 << ", decoder_state_=" << decoder_state_
                 << ", decoder_flushing_=" << decoder_flushing_
                 << ", picture_clearing_count_=" << picture_clearing_count_;
       // If the picture is not cleared, post it to the child thread because it
       // has to be cleared in the child thread. A picture only needs to be
       // cleared once. If the decoder is changing resolution, resetting or
       // flushing, send all pictures to ensure PictureReady arrive before
       // ProvidePictureBuffers, NotifyResetDone, or NotifyFlushDone.
       child_task_runner_->PostTaskAndReply(
           FROM_HERE, base::Bind(&Client::PictureReady, client_, picture),
           // Unretained is safe. If Client::PictureReady gets to run, |this| is
           // alive. Destroy() will wait the decode thread to finish.
           base::Bind(&V4L2VideoDecodeAccelerator::PictureCleared,
                      base::Unretained(this)));
       picture_clearing_count_++;
       pending_picture_ready_.pop();
     } else {
       // This picture is cleared. But some pictures are about to be cleared on
       // the child thread. To preserve the order, do not send this until those
       // pictures are cleared.
       break;
     }
   }
 }
 
 void V4L2VideoDecodeAccelerator::PictureCleared() {
-  DVLOGF(3) << "clearing count=" << picture_clearing_count_;
+  DVLOGF(4) << "clearing count=" << picture_clearing_count_;
   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
   DCHECK_GT(picture_clearing_count_, 0);
   picture_clearing_count_--;
   SendPictureReady();
 }
 
 void V4L2VideoDecodeAccelerator::FrameProcessed(int32_t bitstream_buffer_id,
                                                 int output_buffer_index) {
-  DVLOGF(3) << "output_buffer_index=" << output_buffer_index
+  DVLOGF(4) << "output_buffer_index=" << output_buffer_index
             << ", bitstream_buffer_id=" << bitstream_buffer_id;
   DCHECK(decoder_thread_.task_runner()->BelongsToCurrentThread());
   DCHECK(!image_processor_bitstream_buffer_ids_.empty());
   DCHECK(image_processor_bitstream_buffer_ids_.front() == bitstream_buffer_id);
   DCHECK_GE(output_buffer_index, 0);
   DCHECK_LT(output_buffer_index, static_cast<int>(output_buffer_map_.size()));
 
   OutputRecord& output_record = output_buffer_map_[output_buffer_index];
-  DVLOGF(3) << "picture_id=" << output_record.picture_id;
+  DVLOGF(4) << "picture_id=" << output_record.picture_id;
   DCHECK_EQ(output_record.state, kAtProcessor);
   DCHECK_NE(output_record.picture_id, -1);
 
   // Send the processed frame to render.
   output_record.state = kAtClient;
   decoder_frames_at_client_++;
   image_processor_bitstream_buffer_ids_.pop();
   // TODO(hubbe): Insert correct color space. http://crbug.com/647725
   const Picture picture(output_record.picture_id, bitstream_buffer_id,
                         gfx::Rect(visible_size_), gfx::ColorSpace(), false);
   pending_picture_ready_.push(PictureRecord(output_record.cleared, picture));
   SendPictureReady();
   output_record.cleared = true;
   // Flush or resolution change may be waiting image processor to finish.
   if (image_processor_bitstream_buffer_ids_.empty()) {
     NotifyFlushDoneIfNeeded();
     if (decoder_state_ == kChangingResolution)
       StartResolutionChange();
   }
 }
 
 void V4L2VideoDecodeAccelerator::ImageProcessorError() {
   LOGF(ERROR) << "Image processor error";
   NOTIFY_ERROR(PLATFORM_FAILURE);
 }
 
 }  // namespace media