Add demuxer level traces for Initialize, Seek, Read.

This is another core component of media, we should have trace events
to help diagnose issues in the field. This adds the following traces:
- (Chunk|FFmpeg)Demuxer::Initialize
- (Chunk|FFmpeg)Demuxer::Seek
- (AudioBuffer|VideoFrame)Stream::(Decode|Read|ReadFromDemuxerStream)
- VideoFrameStream::Prepare (for audio too, but never prepares)

This also renames the DecoderStream<AUDIO>, DecoderStream<VIDEO> traces
to use the normal names AudioBufferStream, VideoFrameStream.

BUG=879970
TEST=none
R=wolenetz, xhwang

Cq-Include-Trybots: luci.chromium.try:android_optional_gpu_tests_rel;luci.chromium.try:linux_optional_gpu_tests_rel;luci.chromium.try:mac_optional_gpu_tests_rel;luci.chromium.try:win_optional_gpu_tests_rel
Change-Id: Ie9ca7474bc5684117820b219012f0455d044eabc
Reviewed-on: https://chromium-review.googlesource.com/1237573
Commit-Queue: Dale Curtis <dalecurtis@chromium.org>
Reviewed-by: Xiaohan Wang <xhwang@chromium.org>
Cr-Commit-Position: refs/heads/master@{#593374}

media/base/demuxer_stream.cc

@@ -20,6 +20,20 @@ const char* DemuxerStream::GetTypeName(Type type) {
   }
 }
 
+// static
+const char* DemuxerStream::GetStatusName(Status status) {
+  switch (status) {
+    case DemuxerStream::kOk:
+      return "okay";
+    case DemuxerStream::kAborted:
+      return "aborted";
+    case DemuxerStream::kConfigChanged:
+      return "config_changed";
+    case DemuxerStream::kError:
+      return "error";
+  }
+}
+
 DemuxerStream::~DemuxerStream() = default;
 
 // Most DemuxerStream implementations don't specify liveness. Returns unknown

media/base/demuxer_stream.h

@@ -63,6 +63,8 @@ class MEDIA_EXPORT DemuxerStream {
     kStatusMax = kError,
   };
 
+  static const char* GetStatusName(Status status);
+
   // Request a buffer to returned via the provided callback.
   //
   // The first parameter indicates the status of the read.

media/filters/chunk_demuxer.cc

@@ -16,6 +16,7 @@
 #include "base/metrics/histogram_macros.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/threading/thread_task_runner_handle.h"
+#include "base/trace_event/trace_event.h"
 #include "media/base/audio_decoder_config.h"
 #include "media/base/bind_to_current_loop.h"
 #include "media/base/media_switches.h"
@@ -486,12 +487,13 @@ std::string ChunkDemuxer::GetDisplayName() const {
 void ChunkDemuxer::Initialize(DemuxerHost* host,
                               const PipelineStatusCB& init_cb) {
   DVLOG(1) << "Init(), buffering_by_pts_=" << buffering_by_pts_;
+  TRACE_EVENT_ASYNC_BEGIN0("media", "ChunkDemuxer::Initialize", this);
 
   base::AutoLock auto_lock(lock_);
   if (state_ == SHUTDOWN) {
     // Init cb must only be run after this method returns, so post.
-    base::ThreadTaskRunnerHandle::Get()->PostTask(
-        FROM_HERE, base::BindOnce(init_cb, DEMUXER_ERROR_COULD_NOT_OPEN));
+    init_cb_ = BindToCurrentLoop(init_cb);
+    RunInitCB_Locked(DEMUXER_ERROR_COULD_NOT_OPEN);
     return;
   }
 
@@ -516,19 +518,20 @@ void ChunkDemuxer::Stop() {
 void ChunkDemuxer::Seek(TimeDelta time, const PipelineStatusCB& cb) {
   DVLOG(1) << "Seek(" << time.InSecondsF() << ")";
   DCHECK(time >= TimeDelta());
+  TRACE_EVENT_ASYNC_BEGIN0("media", "ChunkDemuxer::Seek", this);
 
   base::AutoLock auto_lock(lock_);
   DCHECK(!seek_cb_);
 
   seek_cb_ = BindToCurrentLoop(cb);
   if (state_ != INITIALIZED && state_ != ENDED) {
-    std::move(seek_cb_).Run(PIPELINE_ERROR_INVALID_STATE);
+    RunSeekCB_Locked(PIPELINE_ERROR_INVALID_STATE);
     return;
   }
 
   if (cancel_next_seek_) {
     cancel_next_seek_ = false;
-    std::move(seek_cb_).Run(PIPELINE_OK);
+    RunSeekCB_Locked(PIPELINE_OK);
     return;
   }
 
@@ -540,7 +543,7 @@ void ChunkDemuxer::Seek(TimeDelta time, const PipelineStatusCB& cb) {
     return;
   }
 
-  std::move(seek_cb_).Run(PIPELINE_OK);
+  RunSeekCB_Locked(PIPELINE_OK);
 }
 
 // Demuxer implementation.
@@ -634,7 +637,7 @@ void ChunkDemuxer::CancelPendingSeek(TimeDelta seek_time) {
     return;
   }
 
-  std::move(seek_cb_).Run(PIPELINE_OK);
+  RunSeekCB_Locked(PIPELINE_OK);
 }
 
 ChunkDemuxer::Status ChunkDemuxer::AddId(const std::string& id,
@@ -898,10 +901,10 @@ bool ChunkDemuxer::AppendData(const std::string& id,
     }
 
     // Check to see if data was appended at the pending seek point. This
-    // indicates we have parsed enough data to complete the seek.
-    if (old_waiting_for_data && !IsSeekWaitingForData_Locked() && seek_cb_) {
-      std::move(seek_cb_).Run(PIPELINE_OK);
-    }
+    // indicates we have parsed enough data to complete the seek. Work is still
+    // in progress at this point, but it's okay since |seek_cb_| will post.
+    if (old_waiting_for_data && !IsSeekWaitingForData_Locked() && seek_cb_)
+      RunSeekCB_Locked(PIPELINE_OK);
 
     ranges = GetBufferedRanges_Locked();
   }
@@ -925,9 +928,8 @@ void ChunkDemuxer::ResetParserState(const std::string& id,
                                           timestamp_offset);
   // ResetParserState can possibly emit some buffers.
   // Need to check whether seeking can be completed.
-  if (old_waiting_for_data && !IsSeekWaitingForData_Locked() && seek_cb_) {
-    std::move(seek_cb_).Run(PIPELINE_OK);
-  }
+  if (old_waiting_for_data && !IsSeekWaitingForData_Locked() && seek_cb_)
+    RunSeekCB_Locked(PIPELINE_OK);
 }
 
 void ChunkDemuxer::Remove(const std::string& id, TimeDelta start,
@@ -1133,9 +1135,8 @@ void ChunkDemuxer::MarkEndOfStream(PipelineStatus status) {
   ChangeState_Locked(ENDED);
   DecreaseDurationIfNecessary();
 
-  if (old_waiting_for_data && !IsSeekWaitingForData_Locked() && seek_cb_) {
-    std::move(seek_cb_).Run(PIPELINE_OK);
-  }
+  if (old_waiting_for_data && !IsSeekWaitingForData_Locked() && seek_cb_)
+    RunSeekCB_Locked(PIPELINE_OK);
 }
 
 void ChunkDemuxer::UnmarkEndOfStream() {
@@ -1170,7 +1171,7 @@ void ChunkDemuxer::Shutdown() {
   ChangeState_Locked(SHUTDOWN);
 
   if (seek_cb_)
-    std::move(seek_cb_).Run(PIPELINE_ERROR_ABORT);
+    RunSeekCB_Locked(PIPELINE_ERROR_ABORT);
 }
 
 void ChunkDemuxer::SetMemoryLimitsForTest(DemuxerStream::Type type,
@@ -1205,19 +1206,14 @@ void ChunkDemuxer::ReportError_Locked(PipelineStatus error) {
 
   ChangeState_Locked(PARSE_ERROR);
 
-  PipelineStatusCB cb;
-
   if (init_cb_) {
-    std::swap(cb, init_cb_);
-  } else {
-    if (seek_cb_)
-      std::swap(cb, seek_cb_);
-
-    ShutdownAllStreams();
+    RunInitCB_Locked(error);
+    return;
   }
 
-  if (!cb.is_null()) {
-    cb.Run(error);
+  ShutdownAllStreams();
+  if (seek_cb_) {
+    RunSeekCB_Locked(error);
     return;
   }
 
@@ -1313,8 +1309,7 @@ void ChunkDemuxer::OnSourceInitDone(
   // build is needed. See https://crbug.com/786975.
   CHECK_EQ(state_, INITIALIZING);
   ChangeState_Locked(INITIALIZED);
-  CHECK(init_cb_);
-  std::move(init_cb_).Run(PIPELINE_OK);
+  RunInitCB_Locked(PIPELINE_OK);
 }
 
 // static
@@ -1476,4 +1471,20 @@ void ChunkDemuxer::ShutdownAllStreams() {
   }
 }
 
+void ChunkDemuxer::RunInitCB_Locked(PipelineStatus status) {
+  lock_.AssertAcquired();
+  DCHECK(init_cb_);
+  TRACE_EVENT_ASYNC_END1("media", "ChunkDemuxer::Initialize", this, "status",
+                         MediaLog::PipelineStatusToString(status));
+  std::move(init_cb_).Run(status);
+}
+
+void ChunkDemuxer::RunSeekCB_Locked(PipelineStatus status) {
+  lock_.AssertAcquired();
+  DCHECK(seek_cb_);
+  TRACE_EVENT_ASYNC_END1("media", "ChunkDemuxer::Seek", this, "status",
+                         MediaLog::PipelineStatusToString(status));
+  std::move(seek_cb_).Run(status);
+}
+
 }  // namespace media

media/filters/chunk_demuxer.h

@@ -458,6 +458,12 @@ class MEDIA_EXPORT ChunkDemuxer : public Demuxer {
   // all objects in |source_state_map_|.
   void ShutdownAllStreams();
 
+  // Executes |init_cb_| with |status| and closes out the async trace.
+  void RunInitCB_Locked(PipelineStatus status);
+
+  // Executes |seek_cb_| with |status| and closes out the async trace.
+  void RunSeekCB_Locked(PipelineStatus status);
+
   mutable base::Lock lock_;
   State state_;
   bool cancel_next_seek_;

media/filters/decoder_stream.cc

@@ -24,20 +24,70 @@
 
 namespace media {
 
-template <DemuxerStream::Type StreamType>
-static const char* GetTraceString();
-
 #define FUNCTION_DVLOG(level) \
   DVLOG(level) << __func__ << "<" << GetStreamTypeString() << ">"
 
+template <DemuxerStream::Type StreamType>
+static const char* GetDecodeTraceString();
+template <DemuxerStream::Type StreamType>
+static const char* GetReadTraceString();
+template <DemuxerStream::Type StreamType>
+static const char* GetDemuxerReadTraceString();
+template <DemuxerStream::Type StreamType>
+static const char* GetPrepareTraceString();
+
 template <>
-const char* GetTraceString<DemuxerStream::VIDEO>() {
-  return "DecoderStream<VIDEO>::Decode";
+const char* GetDecodeTraceString<DemuxerStream::VIDEO>() {
+  return "VideoFrameStream::Decode";
 }
 
 template <>
-const char* GetTraceString<DemuxerStream::AUDIO>() {
-  return "DecoderStream<AUDIO>::Decode";
+const char* GetDecodeTraceString<DemuxerStream::AUDIO>() {
+  return "AudioBufferStream::Decode";
+}
+
+template <>
+const char* GetReadTraceString<DemuxerStream::VIDEO>() {
+  return "VideoFrameStream::Read";
+}
+
+template <>
+const char* GetReadTraceString<DemuxerStream::AUDIO>() {
+  return "AudioBufferStream::Read";
+}
+
+template <>
+const char* GetDemuxerReadTraceString<DemuxerStream::VIDEO>() {
+  return "VideoFrameStream::ReadFromDemuxerStream";
+}
+
+template <>
+const char* GetDemuxerReadTraceString<DemuxerStream::AUDIO>() {
+  return "AudioBufferStream::ReadFromDemuxerStream";
+}
+
+template <>
+const char* GetPrepareTraceString<DemuxerStream::VIDEO>() {
+  return "VideoFrameStream::PrepareOutput";
+}
+
+template <>
+const char* GetPrepareTraceString<DemuxerStream::AUDIO>() {
+  return "AudioBufferStream::PrepareOutput";
+}
+
+template <DemuxerStream::Type StreamType>
+const char* GetStatusString(typename DecoderStream<StreamType>::Status status) {
+  switch (status) {
+    case DecoderStream<StreamType>::OK:
+      return "okay";
+    case DecoderStream<StreamType>::ABORTED:
+      return "aborted";
+    case DecoderStream<StreamType>::DEMUXER_READ_ABORTED:
+      return "demuxer_read_aborted";
+    case DecoderStream<StreamType>::DECODE_ERROR:
+      return "decode_error";
+  }
 }
 
 template <DemuxerStream::Type StreamType>
@@ -76,13 +126,15 @@ DecoderStream<StreamType>::~DecoderStream() {
                            base::BindOnce(std::move(init_cb_), false));
   }
   if (read_cb_) {
-    task_runner_->PostTask(
-        FROM_HERE,
-        base::BindOnce(std::move(read_cb_), ABORTED, scoped_refptr<Output>()));
+    read_cb_ = BindToCurrentLoop(std::move(read_cb_));
+    SatisfyRead(ABORTED, nullptr);
   }
   if (reset_cb_)
     task_runner_->PostTask(FROM_HERE, std::move(reset_cb_));
 
+  if (preparing_output_)
+    CompletePrepare(nullptr);
+
   // Don't manually reset anything here; rely on the order of member variables
   // within the header, which enforces WeakPtrFactory invalidation first.
 }
@@ -130,24 +182,23 @@ void DecoderStream<StreamType>::Read(ReadCB read_cb) {
   // No read during resetting or stopping process.
   DCHECK(!reset_cb_);
 
+  TRACE_EVENT_ASYNC_BEGIN0("media", GetReadTraceString<StreamType>(), this);
   if (state_ == STATE_ERROR) {
-    task_runner_->PostTask(FROM_HERE,
-                           base::BindOnce(std::move(read_cb), DECODE_ERROR,
-                                          scoped_refptr<Output>()));
+    read_cb_ = BindToCurrentLoop(std::move(read_cb));
+    SatisfyRead(DECODE_ERROR, nullptr);
     return;
   }
 
   if (state_ == STATE_END_OF_STREAM && ready_outputs_.empty() &&
       unprepared_outputs_.empty()) {
-    task_runner_->PostTask(FROM_HERE,
-                           base::BindOnce(std::move(read_cb), OK,
-                                          StreamTraits::CreateEOSOutput()));
+    read_cb_ = BindToCurrentLoop(std::move(read_cb));
+    SatisfyRead(OK, StreamTraits::CreateEOSOutput());
     return;
   }
 
   if (!ready_outputs_.empty()) {
-    task_runner_->PostTask(FROM_HERE, base::BindOnce(std::move(read_cb), OK,
-                                                     ready_outputs_.front()));
+    read_cb_ = BindToCurrentLoop(std::move(read_cb));
+    SatisfyRead(OK, ready_outputs_.front());
     ready_outputs_.pop_front();
     MaybePrepareAnotherOutput();
   } else {
@@ -168,9 +219,8 @@ void DecoderStream<StreamType>::Reset(base::OnceClosure closure) {
   reset_cb_ = std::move(closure);
 
   if (read_cb_) {
-    task_runner_->PostTask(
-        FROM_HERE,
-        base::BindOnce(std::move(read_cb_), ABORTED, scoped_refptr<Output>()));
+    read_cb_ = BindToCurrentLoop(std::move(read_cb_));
+    SatisfyRead(ABORTED, nullptr);
   }
 
   ClearOutputs();
@@ -358,6 +408,8 @@ void DecoderStream<StreamType>::SatisfyRead(
     Status status,
     const scoped_refptr<Output>& output) {
   DCHECK(read_cb_);
+  TRACE_EVENT_ASYNC_END1("media", GetReadTraceString<StreamType>(), this,
+                         "status", GetStatusString<StreamType>(status));
   std::move(read_cb_).Run(status, output);
 }
 
@@ -399,9 +451,9 @@ void DecoderStream<StreamType>::DecodeInternal(
   int buffer_size = buffer->end_of_stream() ? 0 : buffer->data_size();
 
   TRACE_EVENT_ASYNC_BEGIN2(
-      "media", GetTraceString<StreamType>(), this, "key frame",
-      !buffer->end_of_stream() && buffer->is_key_frame(), "timestamp (ms)",
-      !buffer->end_of_stream() ? buffer->timestamp().InMilliseconds() : 0);
+      "media", GetDecodeTraceString<StreamType>(), this, "is_key_frame",
+      !buffer->end_of_stream() && buffer->is_key_frame(), "timestamp_us",
+      !buffer->end_of_stream() ? buffer->timestamp().InMicroseconds() : 0);
 
   if (buffer->end_of_stream())
     decoding_eos_ = true;
@@ -434,7 +486,7 @@ void DecoderStream<StreamType>::OnDecodeDone(int buffer_size,
 
   --pending_decode_requests_;
 
-  TRACE_EVENT_ASYNC_END0("media", GetTraceString<StreamType>(), this);
+  TRACE_EVENT_ASYNC_END0("media", GetDecodeTraceString<StreamType>(), this);
 
   if (end_of_stream) {
     DCHECK(!pending_decode_requests_);
@@ -582,6 +634,8 @@ void DecoderStream<StreamType>::ReadFromDemuxerStream() {
   if (pending_demuxer_read_)
     return;
 
+  TRACE_EVENT_ASYNC_BEGIN0("media", GetDemuxerReadTraceString<StreamType>(),
+                           this);
   pending_demuxer_read_ = true;
   stream_->Read(base::BindRepeating(&DecoderStream<StreamType>::OnBufferReady,
                                     weak_factory_.GetWeakPtr()));
@@ -591,6 +645,8 @@ template <DemuxerStream::Type StreamType>
 void DecoderStream<StreamType>::OnBufferReady(
     DemuxerStream::Status status,
     scoped_refptr<DecoderBuffer> buffer) {
+  TRACE_EVENT_ASYNC_END1("media", GetDemuxerReadTraceString<StreamType>(), this,
+                         "status", DemuxerStream::GetStatusName(status));
   FUNCTION_DVLOG(3) << ": " << status << ", "
                     << (buffer ? buffer->AsHumanReadableString() : "nullptr");
 
@@ -852,7 +908,8 @@ void DecoderStream<StreamType>::OnDecoderReset() {
 
 template <DemuxerStream::Type StreamType>
 void DecoderStream<StreamType>::ClearOutputs() {
-  preparing_output_ = false;
+  if (preparing_output_)
+    CompletePrepare(nullptr);
   ready_outputs_.clear();
   unprepared_outputs_.clear();
   prepare_weak_factory_.InvalidateWeakPtrs();
@@ -875,6 +932,9 @@ void DecoderStream<StreamType>::MaybePrepareAnotherOutput() {
   if (ready_outputs_.size() >= static_cast<size_t>(GetMaxDecodeRequests()))
     return;
 
+  TRACE_EVENT_ASYNC_BEGIN1(
+      "media", GetPrepareTraceString<StreamType>(), this, "timestamp_us",
+      unprepared_outputs_.front()->timestamp().InMicroseconds());
   preparing_output_ = true;
   prepare_cb_.Run(
       unprepared_outputs_.front(),
@@ -898,7 +958,7 @@ void DecoderStream<StreamType>::OnPreparedOutputReady(
   DCHECK(!unprepared_outputs_.empty());
   DCHECK(preparing_output_);
 
-  preparing_output_ = false;
+  CompletePrepare(output.get());
   unprepared_outputs_.pop_front();
   if (!read_cb_)
     ready_outputs_.emplace_back(output);
@@ -913,6 +973,15 @@ void DecoderStream<StreamType>::OnPreparedOutputReady(
     ReadFromDemuxerStream();
 }
 
+template <DemuxerStream::Type StreamType>
+void DecoderStream<StreamType>::CompletePrepare(const Output* output) {
+  DCHECK(preparing_output_);
+  TRACE_EVENT_ASYNC_END1(
+      "media", GetPrepareTraceString<StreamType>(), this, "timestamp_us",
+      (output ? output->timestamp() : kNoTimestamp).InMicroseconds());
+  preparing_output_ = false;
+}
+
 template class DecoderStream<DemuxerStream::VIDEO>;
 template class DecoderStream<DemuxerStream::AUDIO>;
 

media/filters/decoder_stream.h

@@ -212,6 +212,7 @@ class MEDIA_EXPORT DecoderStream {
   void ClearOutputs();
   void MaybePrepareAnotherOutput();
   void OnPreparedOutputReady(const scoped_refptr<Output>& frame);
+  void CompletePrepare(const Output* output);
 
   std::unique_ptr<DecoderStreamTraits<StreamType>> traits_;
 

media/filters/ffmpeg_demuxer.cc

@@ -25,6 +25,7 @@
 #include "base/task_runner_util.h"
 #include "base/threading/thread_task_runner_handle.h"
 #include "base/time/time.h"
+#include "base/trace_event/trace_event.h"
 #include "build/build_config.h"
 #include "media/base/bind_to_current_loop.h"
 #include "media/base/decrypt_config.h"
@@ -700,13 +701,13 @@ void FFmpegDemuxerStream::Abort() {
 void FFmpegDemuxerStream::Stop() {
   DCHECK(task_runner_->BelongsToCurrentThread());
   buffer_queue_.Clear();
+  demuxer_ = nullptr;
+  stream_ = nullptr;
+  end_of_stream_ = true;
   if (read_cb_) {
     std::move(read_cb_).Run(DemuxerStream::kOk,
                             DecoderBuffer::CreateEOSBuffer());
   }
-  demuxer_ = NULL;
-  stream_ = NULL;
-  end_of_stream_ = true;
 }
 
 DemuxerStream::Type FFmpegDemuxerStream::type() const {
@@ -927,6 +928,9 @@ FFmpegDemuxer::FFmpegDemuxer(
 }
 
 FFmpegDemuxer::~FFmpegDemuxer() {
+  DCHECK(!init_cb_);
+  DCHECK(!pending_seek_cb_);
+
   // NOTE: This class is not destroyed on |task_runner|, so we must ensure that
   // there are no outstanding WeakPtrs by the time we reach here.
   DCHECK(!weak_factory_.HasWeakPtrs());
@@ -943,10 +947,11 @@ std::string FFmpegDemuxer::GetDisplayName() const {
 }
 
 void FFmpegDemuxer::Initialize(DemuxerHost* host,
-                               const PipelineStatusCB& status_cb) {
+                               const PipelineStatusCB& init_cb) {
   DCHECK(task_runner_->BelongsToCurrentThread());
   host_ = host;
   weak_this_ = cancel_pending_seek_factory_.GetWeakPtr();
+  init_cb_ = init_cb;
 
   // Give a WeakPtr to BlockingUrlProtocol since we'll need to release it on the
   // blocking thread pool.
@@ -973,7 +978,7 @@ void FFmpegDemuxer::Initialize(DemuxerHost* host,
       base::BindOnce(&FFmpegGlue::OpenContext, base::Unretained(glue_.get()),
                      is_local_file_),
       base::BindOnce(&FFmpegDemuxer::OnOpenContextDone,
-                     weak_factory_.GetWeakPtr(), status_cb));
+                     weak_factory_.GetWeakPtr()));
 }
 
 void FFmpegDemuxer::AbortPendingReads() {
@@ -1007,12 +1012,17 @@ void FFmpegDemuxer::AbortPendingReads() {
   // instead to avoid any preroll work that may be started upon return, but
   // currently the PipelineImpl does not know how to handle this.
   if (pending_seek_cb_)
-    std::move(pending_seek_cb_).Run(PIPELINE_OK);
+    RunPendingSeekCB(PIPELINE_OK);
 }
 
 void FFmpegDemuxer::Stop() {
   DCHECK(task_runner_->BelongsToCurrentThread());
 
+  if (init_cb_)
+    RunInitCB(PIPELINE_ERROR_ABORT);
+  if (pending_seek_cb_)
+    RunPendingSeekCB(PIPELINE_ERROR_ABORT);
+
   // The order of Stop() and Abort() is important here.  If Abort() is called
   // first, control may pass into FFmpeg where it can destruct buffers that are
   // in the process of being fulfilled by the DataSource.
@@ -1049,8 +1059,8 @@ void FFmpegDemuxer::CancelPendingSeek(base::TimeDelta seek_time) {
 
 void FFmpegDemuxer::Seek(base::TimeDelta time, const PipelineStatusCB& cb) {
   DCHECK(task_runner_->BelongsToCurrentThread());
-  CHECK(!pending_seek_cb_);
-
+  DCHECK(!pending_seek_cb_);
+  TRACE_EVENT_ASYNC_BEGIN0("media", "FFmpegDemuxer::Seek", this);
   pending_seek_cb_ = cb;
   SeekInternal(time, base::BindOnce(&FFmpegDemuxer::OnSeekFrameSuccess,
                                     weak_factory_.GetWeakPtr()));
@@ -1215,12 +1225,11 @@ static int CalculateBitrate(AVFormatContext* format_context,
   return bytes * 8000000.0 / duration_us;
 }
 
-void FFmpegDemuxer::OnOpenContextDone(const PipelineStatusCB& status_cb,
-                                      bool result) {
+void FFmpegDemuxer::OnOpenContextDone(bool result) {
   DCHECK(task_runner_->BelongsToCurrentThread());
   if (stopped_) {
     MEDIA_LOG(ERROR, media_log_) << GetDisplayName() << ": bad state";
-    status_cb.Run(PIPELINE_ERROR_ABORT);
+    RunInitCB(PIPELINE_ERROR_ABORT);
     return;
   }
 
@@ -1228,14 +1237,14 @@ void FFmpegDemuxer::OnOpenContextDone(const PipelineStatusCB& status_cb,
   if (glue_->detected_hls()) {
     MEDIA_LOG(INFO, media_log_)
         << GetDisplayName() << ": detected HLS manifest";
-    status_cb.Run(DEMUXER_ERROR_DETECTED_HLS);
+    RunInitCB(DEMUXER_ERROR_DETECTED_HLS);
     return;
   }
 #endif
 
   if (!result) {
     MEDIA_LOG(ERROR, media_log_) << GetDisplayName() << ": open context failed";
-    status_cb.Run(DEMUXER_ERROR_COULD_NOT_OPEN);
+    RunInitCB(DEMUXER_ERROR_COULD_NOT_OPEN);
     return;
   }
 
@@ -1243,24 +1252,23 @@ void FFmpegDemuxer::OnOpenContextDone(const PipelineStatusCB& status_cb,
   base::PostTaskAndReplyWithResult(
       blocking_task_runner_.get(), FROM_HERE,
       base::Bind(&avformat_find_stream_info, glue_->format_context(),
-                 static_cast<AVDictionary**>(NULL)),
+                 static_cast<AVDictionary**>(nullptr)),
       base::Bind(&FFmpegDemuxer::OnFindStreamInfoDone,
-                 weak_factory_.GetWeakPtr(), status_cb));
+                 weak_factory_.GetWeakPtr()));
 }
 
-void FFmpegDemuxer::OnFindStreamInfoDone(const PipelineStatusCB& status_cb,
-                                         int result) {
+void FFmpegDemuxer::OnFindStreamInfoDone(int result) {
   DCHECK(task_runner_->BelongsToCurrentThread());
   if (stopped_ || !data_source_) {
     MEDIA_LOG(ERROR, media_log_) << GetDisplayName() << ": bad state";
-    status_cb.Run(PIPELINE_ERROR_ABORT);
+    RunInitCB(PIPELINE_ERROR_ABORT);
     return;
   }
 
   if (result < 0) {
     MEDIA_LOG(ERROR, media_log_) << GetDisplayName()
                                  << ": find stream info failed";
-    status_cb.Run(DEMUXER_ERROR_COULD_NOT_PARSE);
+    RunInitCB(DEMUXER_ERROR_COULD_NOT_PARSE);
     return;
   }
 
@@ -1457,7 +1465,7 @@ void FFmpegDemuxer::OnFindStreamInfoDone(const PipelineStatusCB& status_cb,
   if (media_tracks->tracks().empty()) {
     MEDIA_LOG(ERROR, media_log_) << GetDisplayName()
                                  << ": no supported streams";
-    status_cb.Run(DEMUXER_ERROR_NO_SUPPORTED_STREAMS);
+    RunInitCB(DEMUXER_ERROR_NO_SUPPORTED_STREAMS);
     return;
   }
 
@@ -1549,7 +1557,7 @@ void FFmpegDemuxer::OnFindStreamInfoDone(const PipelineStatusCB& status_cb,
   LogMetadata(format_context, max_duration);
   media_tracks_updated_cb_.Run(std::move(media_tracks));
 
-  status_cb.Run(PIPELINE_OK);
+  RunInitCB(PIPELINE_OK);
 }
 
 void FFmpegDemuxer::LogMetadata(AVFormatContext* avctx,
@@ -1676,11 +1684,11 @@ FFmpegDemuxerStream* FFmpegDemuxer::FindPreferredStreamForSeeking(
 
 void FFmpegDemuxer::OnSeekFrameSuccess() {
   DCHECK(task_runner_->BelongsToCurrentThread());
-  CHECK(pending_seek_cb_);
+  DCHECK(pending_seek_cb_);
 
   if (stopped_) {
     MEDIA_LOG(ERROR, media_log_) << GetDisplayName() << ": bad state";
-    std::move(pending_seek_cb_).Run(PIPELINE_ERROR_ABORT);
+    RunPendingSeekCB(PIPELINE_ERROR_ABORT);
     return;
   }
 
@@ -1694,7 +1702,7 @@ void FFmpegDemuxer::OnSeekFrameSuccess() {
   ReadFrameIfNeeded();
 
   // Notify we're finished seeking.
-  std::move(pending_seek_cb_).Run(PIPELINE_OK);
+  RunPendingSeekCB(PIPELINE_OK);
 }
 
 void FFmpegDemuxer::FindAndEnableProperTracks(
@@ -1925,4 +1933,20 @@ void FFmpegDemuxer::SetLiveness(DemuxerStream::Liveness liveness) {
   }
 }
 
+void FFmpegDemuxer::RunInitCB(PipelineStatus status) {
+  DCHECK(task_runner_->BelongsToCurrentThread());
+  DCHECK(init_cb_);
+  TRACE_EVENT_ASYNC_END1("media", "FFmpegDemuxer::Initialize", this, "status",
+                         MediaLog::PipelineStatusToString(status));
+  std::move(init_cb_).Run(status);
+}
+
+void FFmpegDemuxer::RunPendingSeekCB(PipelineStatus status) {
+  DCHECK(task_runner_->BelongsToCurrentThread());
+  DCHECK(pending_seek_cb_);
+  TRACE_EVENT_ASYNC_END1("media", "FFmpegDemuxer::Seek", this, "status",
+                         MediaLog::PipelineStatusToString(status));
+  std::move(pending_seek_cb_).Run(status);
+}
+
 }  // namespace media

media/filters/ffmpeg_demuxer.h

@@ -218,8 +218,7 @@ class MEDIA_EXPORT FFmpegDemuxer : public Demuxer {
 
   // Demuxer implementation.
   std::string GetDisplayName() const override;
-  void Initialize(DemuxerHost* host,
-                  const PipelineStatusCB& status_cb) override;
+  void Initialize(DemuxerHost* host, const PipelineStatusCB& init_cb) override;
   void AbortPendingReads() override;
   void Stop() override;
   void StartWaitingForSeek(base::TimeDelta seek_time) override;
@@ -276,11 +275,22 @@ class MEDIA_EXPORT FFmpegDemuxer : public Demuxer {
                                  TrackChangeCB change_completed_cb);
 
   // FFmpeg callbacks during initialization.
-  void OnOpenContextDone(const PipelineStatusCB& status_cb, bool result);
-  void OnFindStreamInfoDone(const PipelineStatusCB& status_cb, int result);
+  void OnOpenContextDone(bool result);
+  void OnFindStreamInfoDone(int result);
 
   void LogMetadata(AVFormatContext* avctx, base::TimeDelta max_duration);
 
+  // Finds the stream with the lowest known start time (i.e. not kNoTimestamp
+  // start time) with enabled status matching |enabled|.
+  FFmpegDemuxerStream* FindStreamWithLowestStartTimestamp(bool enabled);
+
+  // Finds a preferred stream for seeking to |seek_time|. Preference is
+  // typically given to video streams, unless the |seek_time| is earlier than
+  // the start time of the video stream. In that case a stream with the earliest
+  // start time is preferred. Disabled streams are considered only as the last
+  // fallback option.
+  FFmpegDemuxerStream* FindPreferredStreamForSeeking(base::TimeDelta seek_time);
+
   // FFmpeg callbacks during seeking.
   void OnSeekFrameSuccess();
 
@@ -320,6 +330,12 @@ class MEDIA_EXPORT FFmpegDemuxer : public Demuxer {
                               DemuxerStream::Type stream_type,
                               const std::vector<DemuxerStream*>& streams);
 
+  // Executes |init_cb_| with |status| and closes out the async trace.
+  void RunInitCB(PipelineStatus status);
+
+  // Executes |pending_seek_cb_| with |status| and closes out the async trace.
+  void RunPendingSeekCB(PipelineStatus status);
+
   DemuxerHost* host_;
 
   scoped_refptr<base::SingleThreadTaskRunner> task_runner_;
@@ -328,6 +344,8 @@ class MEDIA_EXPORT FFmpegDemuxer : public Demuxer {
   // from base::TaskScheduler.
   scoped_refptr<base::SequencedTaskRunner> blocking_task_runner_;
 
+  PipelineStatusCB init_cb_;
+
   // Indicates if Stop() has been called.
   bool stopped_;
 
@@ -367,17 +385,6 @@ class MEDIA_EXPORT FFmpegDemuxer : public Demuxer {
   // based timeline.
   base::TimeDelta start_time_;
 
-  // Finds the stream with the lowest known start time (i.e. not kNoTimestamp
-  // start time) with enabled status matching |enabled|.
-  FFmpegDemuxerStream* FindStreamWithLowestStartTimestamp(bool enabled);
-
-  // Finds a preferred stream for seeking to |seek_time|. Preference is
-  // typically given to video streams, unless the |seek_time| is earlier than
-  // the start time of the video stream. In that case a stream with the earliest
-  // start time is preferred. Disabled streams are considered only as the last
-  // fallback option.
-  FFmpegDemuxerStream* FindPreferredStreamForSeeking(base::TimeDelta seek_time);
-
   // The Time associated with timestamp 0. Set to a null
   // time if the file doesn't have an association to Time.
   base::Time timeline_offset_;