Expand traces for decrypt-only and decrypt+video_decoder.

DecryptingDemuxerStream had no traces and the DecyrptingVideoDecoder
had some old-style, incomplete traces. This adds traces to the
former and expands the latter. Specifically we now have:
- DecryptingDemuxerStream::DecryptPendingBuffer [async]
- DecryptingDemuxerStream::WaitingForDecryptionKey [async]
- DecryptingVideoDecoder::DecodePendingBuffer [async]
- DecryptingVideoDecoder::WaitingForDecryptionKey [async]

The DVD traces used to use a trace_id and provide a buffer size,
but this isn't really necessary since the start trace is tagged
correctly just by using |this| and providing the timestamp.

BUG=879970
TEST=passes cq

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: If21288e6c47414ec038f034bba381fcebf5ca99b
Reviewed-on: https://chromium-review.googlesource.com/1244164Reviewed-by: Xiaohan Wang <xhwang@chromium.org>
Commit-Queue: Dale Curtis <dalecurtis@chromium.org>
Cr-Commit-Position: refs/heads/master@{#594393}

media/base/decryptor.cc

@@ -6,6 +6,20 @@
 
 namespace media {
 
+// static
+const char* Decryptor::GetStatusName(Status status) {
+  switch (status) {
+    case kSuccess:
+      return "success";
+    case kNoKey:
+      return "no_key";
+    case kNeedMoreData:
+      return "need_more_data";
+    case kError:
+      return "error";
+  }
+}
+
 Decryptor::Decryptor() = default;
 
 Decryptor::~Decryptor() = default;

media/base/decryptor.h

@@ -36,6 +36,8 @@ class MEDIA_EXPORT Decryptor {
     kStatusMax = kError
   };
 
+  static const char* GetStatusName(Status status);
+
   // TODO(xhwang): Unify this with DemuxerStream::Type.
   enum StreamType { kAudio, kVideo, kStreamTypeMax = kVideo };
 

media/filters/decoder_selector.cc

@@ -12,6 +12,7 @@
 #include "base/logging.h"
 #include "base/metrics/histogram_functions.h"
 #include "base/single_thread_task_runner.h"
+#include "base/strings/stringprintf.h"
 #include "base/trace_event/trace_event.h"
 #include "build/build_config.h"
 #include "media/base/audio_decoder.h"
@@ -227,10 +228,12 @@ void DecoderSelector<StreamType>::OnDecryptingDemuxerStreamInitializeDone(
 template <DemuxerStream::Type StreamType>
 void DecoderSelector<StreamType>::RunSelectDecoderCB() {
   DCHECK(select_decoder_cb_);
-  TRACE_EVENT_ASYNC_END2("media", "DecoderSelector::SelectDecoder", this,
-                         "type", DemuxerStream::GetTypeName(StreamType),
-                         "decoder_name",
-                         decoder_ ? decoder_->GetDisplayName() : "null");
+  TRACE_EVENT_ASYNC_END2(
+      "media", "DecoderSelector::SelectDecoder", this, "type",
+      DemuxerStream::GetTypeName(StreamType), "decoder",
+      base::StringPrintf(
+          "%s (%s)", decoder_ ? decoder_->GetDisplayName().c_str() : "null",
+          decrypting_demuxer_stream_ ? "encrypted" : "unencrypted"));
 
   task_runner_->PostTask(
       FROM_HERE,

media/filters/decrypting_demuxer_stream.cc

@@ -10,6 +10,7 @@
 #include "base/logging.h"
 #include "base/single_thread_task_runner.h"
 #include "base/strings/string_number_conversions.h"
+#include "base/trace_event/trace_event.h"
 #include "media/base/bind_to_current_loop.h"
 #include "media/base/decoder_buffer.h"
 #include "media/base/media_log.h"
@@ -108,6 +109,7 @@ void DecryptingDemuxerStream::Reset(const base::Closure& closure) {
   }
 
   if (state_ == kWaitingForKey) {
+    CompleteWaitingForDecryptionKey();
     DCHECK(read_cb_);
     pending_buffer_to_decrypt_ = NULL;
     std::move(read_cb_).Run(kAborted, NULL);
@@ -154,6 +156,11 @@ DecryptingDemuxerStream::~DecryptingDemuxerStream() {
   if (state_ == kUninitialized)
     return;
 
+  if (state_ == kWaitingForKey)
+    CompleteWaitingForDecryptionKey();
+  if (state_ == kPendingDecrypt)
+    CompletePendingDecrypt(Decryptor::kError);
+
   if (decryptor_) {
     decryptor_->CancelDecrypt(GetDecryptorStreamType());
     decryptor_ = NULL;
@@ -234,6 +241,11 @@ void DecryptingDemuxerStream::DecryptBuffer(
 void DecryptingDemuxerStream::DecryptPendingBuffer() {
   DCHECK(task_runner_->BelongsToCurrentThread());
   DCHECK_EQ(state_, kPendingDecrypt) << state_;
+  DCHECK(!pending_buffer_to_decrypt_->end_of_stream());
+  TRACE_EVENT_ASYNC_BEGIN2(
+      "media", "DecryptingDemuxerStream::DecryptPendingBuffer", this, "type",
+      DemuxerStream::GetTypeName(demuxer_stream_->type()), "timestamp_us",
+      pending_buffer_to_decrypt_->timestamp().InMicroseconds());
   decryptor_->Decrypt(
       GetDecryptorStreamType(), pending_buffer_to_decrypt_,
       BindToCurrentLoop(
@@ -249,6 +261,7 @@ void DecryptingDemuxerStream::DeliverBuffer(
   DCHECK_NE(status, Decryptor::kNeedMoreData);
   DCHECK(read_cb_);
   DCHECK(pending_buffer_to_decrypt_);
+  CompletePendingDecrypt(status);
 
   bool need_to_try_again_if_nokey = key_added_while_decrypt_pending_;
   key_added_while_decrypt_pending_ = false;
@@ -289,6 +302,9 @@ void DecryptingDemuxerStream::DeliverBuffer(
     }
 
     state_ = kWaitingForKey;
+
+    TRACE_EVENT_ASYNC_BEGIN0(
+        "media", "DecryptingDemuxerStream::WaitingForDecryptionKey", this);
     waiting_for_decryption_key_cb_.Run();
     return;
   }
@@ -314,6 +330,7 @@ void DecryptingDemuxerStream::OnKeyAdded() {
   }
 
   if (state_ == kWaitingForKey) {
+    CompleteWaitingForDecryptionKey();
     MEDIA_LOG(INFO, media_log_)
         << GetDisplayName() << ": key was added, resuming decrypt";
     state_ = kPendingDecrypt;
@@ -367,4 +384,17 @@ void DecryptingDemuxerStream::InitializeDecoderConfig() {
   }
 }
 
+void DecryptingDemuxerStream::CompletePendingDecrypt(Decryptor::Status status) {
+  DCHECK_EQ(state_, kPendingDecrypt);
+  TRACE_EVENT_ASYNC_END1("media",
+                         "DecryptingDemuxerStream::DecryptPendingBuffer", this,
+                         "status", Decryptor::GetStatusName(status));
+}
+
+void DecryptingDemuxerStream::CompleteWaitingForDecryptionKey() {
+  DCHECK_EQ(state_, kWaitingForKey);
+  TRACE_EVENT_ASYNC_END0(
+      "media", "DecryptingDemuxerStream::WaitingForDecryptionKey", this);
+}
+
 }  // namespace media

media/filters/decrypting_demuxer_stream.h

@@ -99,6 +99,10 @@ class MEDIA_EXPORT DecryptingDemuxerStream : public DemuxerStream {
   // |demuxer_stream_|.
   void InitializeDecoderConfig();
 
+  // Completes traces for various pending states.
+  void CompletePendingDecrypt(Decryptor::Status status);
+  void CompleteWaitingForDecryptionKey();
+
   scoped_refptr<base::SingleThreadTaskRunner> task_runner_;
 
   MediaLog* media_log_;

media/filters/decrypting_video_decoder.cc

@@ -29,7 +29,6 @@ DecryptingVideoDecoder::DecryptingVideoDecoder(
       state_(kUninitialized),
       decryptor_(NULL),
       key_added_while_decode_pending_(false),
-      trace_id_(0),
       support_clear_content_(false),
       weak_factory_(this) {}
 
@@ -149,6 +148,7 @@ void DecryptingVideoDecoder::Reset(const base::Closure& closure) {
   }
 
   if (state_ == kWaitingForKey) {
+    CompleteWaitingForDecryptionKey();
     DCHECK(decode_cb_);
     pending_buffer_to_decode_ = NULL;
     std::move(decode_cb_).Run(DecodeStatus::ABORTED);
@@ -164,6 +164,11 @@ DecryptingVideoDecoder::~DecryptingVideoDecoder() {
   if (state_ == kUninitialized)
     return;
 
+  if (state_ == kWaitingForKey)
+    CompleteWaitingForDecryptionKey();
+  if (state_ == kPendingDecode)
+    CompletePendingDecode(Decryptor::kError);
+
   if (decryptor_) {
     decryptor_->DeinitializeDecoder(Decryptor::kVideo);
     decryptor_ = NULL;
@@ -205,22 +210,24 @@ void DecryptingVideoDecoder::FinishInitialization(bool success) {
 void DecryptingVideoDecoder::DecodePendingBuffer() {
   DCHECK(task_runner_->BelongsToCurrentThread());
   DCHECK_EQ(state_, kPendingDecode) << state_;
-  TRACE_EVENT_ASYNC_BEGIN0(
-      "media", "DecryptingVideoDecoder::DecodePendingBuffer", ++trace_id_);
 
-  int buffer_size = 0;
-  if (!pending_buffer_to_decode_->end_of_stream()) {
-    buffer_size = pending_buffer_to_decode_->data_size();
-  }
+  // Note: Traces require a unique ID per decode, if we ever support multiple
+  // in flight decodes, the trace begin+end macros need the same unique id.
+  DCHECK_EQ(GetMaxDecodeRequests(), 1);
+  TRACE_EVENT_ASYNC_BEGIN1(
+      "media", "DecryptingVideoDecoder::DecodePendingBuffer", this,
+      "timestamp_us",
+      pending_buffer_to_decode_->end_of_stream()
+          ? 0
+          : pending_buffer_to_decode_->timestamp().InMicroseconds());
 
   decryptor_->DecryptAndDecodeVideo(
       pending_buffer_to_decode_,
-      BindToCurrentLoop(base::Bind(&DecryptingVideoDecoder::DeliverFrame,
-                                   weak_this_, buffer_size)));
+      BindToCurrentLoop(base::BindRepeating(
+          &DecryptingVideoDecoder::DeliverFrame, weak_this_)));
 }
 
 void DecryptingVideoDecoder::DeliverFrame(
-    int buffer_size,
     Decryptor::Status status,
     const scoped_refptr<VideoFrame>& frame) {
   DVLOG(3) << "DeliverFrame() - status: " << status;
@@ -228,10 +235,7 @@ void DecryptingVideoDecoder::DeliverFrame(
   DCHECK_EQ(state_, kPendingDecode) << state_;
   DCHECK(decode_cb_);
   DCHECK(pending_buffer_to_decode_.get());
-
-  TRACE_EVENT_ASYNC_END2("media", "DecryptingVideoDecoder::DecodePendingBuffer",
-                         trace_id_, "buffer_size", buffer_size, "status",
-                         status);
+  CompletePendingDecode(status);
 
   bool need_to_try_again_if_nokey_is_returned = key_added_while_decode_pending_;
   key_added_while_decode_pending_ = false;
@@ -276,6 +280,8 @@ void DecryptingVideoDecoder::DeliverFrame(
       return;
     }
 
+    TRACE_EVENT_ASYNC_BEGIN0(
+        "media", "DecryptingVideoDecoder::WaitingForDecryptionKey", this);
     state_ = kWaitingForKey;
     waiting_for_decryption_key_cb_.Run();
     return;
@@ -341,6 +347,7 @@ void DecryptingVideoDecoder::OnKeyAdded() {
   }
 
   if (state_ == kWaitingForKey) {
+    CompleteWaitingForDecryptionKey();
     MEDIA_LOG(INFO, media_log_)
         << GetDisplayName() << ": key added, resuming decode";
     state_ = kPendingDecode;
@@ -355,4 +362,16 @@ void DecryptingVideoDecoder::DoReset() {
   std::move(reset_cb_).Run();
 }
 
+void DecryptingVideoDecoder::CompletePendingDecode(Decryptor::Status status) {
+  DCHECK_EQ(state_, kPendingDecode);
+  TRACE_EVENT_ASYNC_END1("media", "DecryptingVideoDecoder::DecodePendingBuffer",
+                         this, "status", Decryptor::GetStatusName(status));
+}
+
+void DecryptingVideoDecoder::CompleteWaitingForDecryptionKey() {
+  DCHECK_EQ(state_, kWaitingForKey);
+  TRACE_EVENT_ASYNC_END0(
+      "media", "DecryptingVideoDecoder::WaitingForDecryptionKey", this);
+}
+
 }  // namespace media

media/filters/decrypting_video_decoder.h

@@ -71,8 +71,7 @@ class MEDIA_EXPORT DecryptingVideoDecoder : public VideoDecoder {
   void DecodePendingBuffer();
 
   // Callback for Decryptor::DecryptAndDecodeVideo().
-  void DeliverFrame(int buffer_size,
-                    Decryptor::Status status,
+  void DeliverFrame(Decryptor::Status status,
                     const scoped_refptr<VideoFrame>& frame);
 
   // Callback for the |decryptor_| to notify this object that a new key has been
@@ -82,6 +81,10 @@ class MEDIA_EXPORT DecryptingVideoDecoder : public VideoDecoder {
   // Reset decoder and call |reset_cb_|.
   void DoReset();
 
+  // Completes traces for various pending states.
+  void CompletePendingDecode(Decryptor::Status status);
+  void CompleteWaitingForDecryptionKey();
+
   scoped_refptr<base::SingleThreadTaskRunner> task_runner_;
 
   MediaLog* media_log_;
@@ -108,10 +111,6 @@ class MEDIA_EXPORT DecryptingVideoDecoder : public VideoDecoder {
   // decryption key.
   bool key_added_while_decode_pending_;
 
-  // A unique ID to trace Decryptor::DecryptAndDecodeVideo() call and the
-  // matching DecryptCB call (in DoDeliverFrame()).
-  uint32_t trace_id_;
-
   // Once Initialized() with encrypted content support, if the stream changes to
   // clear content, we want to ensure this decoder remains used.
   bool support_clear_content_;