Add UMA histogram for VideoDecodeStatsDB operation timing.

Clearing the DB sometimes hangs on Android. Timing should reveal what
steps operations are hanging (clearing and otherwise).

Also adds additional tests to VideoDecodePerfHistory to verify no logic
bugs if Clearing is the first operation performed (triggers initialize).

Bug: 1040098
Change-Id: Ica13972256c883a840ebf66d03fddadc01add3ae
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2135528
Commit-Queue: Chrome Cunningham <chcunningham@chromium.org>
Auto-Submit: Chrome Cunningham <chcunningham@chromium.org>
Reviewed-by: Frank Liberato <liberato@chromium.org>
Reviewed-by: Steven Holte <holte@chromium.org>
Cr-Commit-Position: refs/heads/master@{#758064}

media/capabilities/video_decode_stats_db_impl.cc

@@ -5,6 +5,7 @@
 #include "media/capabilities/video_decode_stats_db_impl.h"
 
 #include <memory>
+#include <string>
 #include <tuple>
 
 #include "base/bind.h"
@@ -13,10 +14,12 @@
 #include "base/logging.h"
 #include "base/memory/ptr_util.h"
 #include "base/metrics/field_trial_params.h"
+#include "base/metrics/histogram_functions.h"
 #include "base/metrics/histogram_macros.h"
 #include "base/sequence_checker.h"
 #include "base/task/post_task.h"
 #include "base/task/thread_pool.h"
+#include "base/threading/thread_task_runner_handle.h"
 #include "base/time/default_clock.h"
 #include "components/leveldb_proto/public/proto_database_provider.h"
 #include "media/base/media_switches.h"
@@ -28,12 +31,23 @@ using ProtoDecodeStatsEntry = leveldb_proto::ProtoDatabase<DecodeStatsProto>;
 
 namespace {
 
+// Timeout threshold for DB operations. See OnOperationTimeout().
+// NOTE: Used by UmaHistogramOpTime. Change the name if you change the time.
+static constexpr base::TimeDelta kPendingOpTimeout =
+    base::TimeDelta::FromSeconds(30);
+
 const int kMaxFramesPerBufferDefault = 2500;
 
 const int kMaxDaysToKeepStatsDefault = 30;
 
 const bool kEnableUnweightedEntriesDefault = false;
 
+void UmaHistogramOpTime(const std::string& op_name, base::TimeDelta duration) {
+  base::UmaHistogramCustomMicrosecondsTimes(
+      "Media.VideoDecodeStatsDB.OpTiming." + op_name, duration,
+      base::TimeDelta::FromMilliseconds(1), kPendingOpTimeout, 50);
+}
+
 }  // namespace
 
 const char VideoDecodeStatsDBImpl::kMaxFramesPerBufferParamName[] =
@@ -45,6 +59,41 @@ const char VideoDecodeStatsDBImpl::kMaxDaysToKeepStatsParamName[] =
 const char VideoDecodeStatsDBImpl::kEnableUnweightedEntriesParamName[] =
     "db_enable_unweighted_entries";
 
+VideoDecodeStatsDBImpl::PendingOperation::PendingOperation(
+    std::string uma_str,
+    std::unique_ptr<base::CancelableOnceClosure> timeout_closure)
+    : uma_str_(uma_str),
+      timeout_closure_(std::move(timeout_closure)),
+      start_ticks_(base::TimeTicks::Now()) {
+  DVLOG(3) << __func__ << " Started " << uma_str_;
+}
+
+VideoDecodeStatsDBImpl::PendingOperation::~PendingOperation() {
+  // Destroying a pending operation that hasn't timed out yet implies the
+  // operation has completed.
+  if (timeout_closure_ && !timeout_closure_->IsCancelled()) {
+    base::TimeDelta op_duration = base::TimeTicks::Now() - start_ticks_;
+    UmaHistogramOpTime(uma_str_, op_duration);
+    DVLOG(3) << __func__ << " Completed " << uma_str_ << " ("
+             << op_duration.InMilliseconds() << ")";
+
+    // Ensure the timeout doesn't fire. Destruction should cancel the callback
+    // implicitly, but that's not a documented contract, so just taking the safe
+    // route.
+    timeout_closure_->Cancel();
+  }
+}
+
+void VideoDecodeStatsDBImpl::PendingOperation::OnTimeout() {
+  UmaHistogramOpTime(uma_str_, kPendingOpTimeout);
+  LOG(WARNING) << " Timeout performing " << uma_str_
+               << " operation on VideoDecodeStatsDB";
+
+  // Cancel the closure to ensure we don't double report the task as completed
+  // in ~PendingOperation().
+  timeout_closure_->Cancel();
+}
+
 // static
 int VideoDecodeStatsDBImpl::GetMaxFramesPerBuffer() {
   return base::GetFieldTrialParamByFeatureAsDouble(
@@ -97,6 +146,43 @@ VideoDecodeStatsDBImpl::~VideoDecodeStatsDBImpl() {
   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
 }
 
+VideoDecodeStatsDBImpl::PendingOpId VideoDecodeStatsDBImpl::StartPendingOp(
+    std::string uma_str) {
+  PendingOpId op_id = next_op_id_++;
+
+  auto timeout_closure = std::make_unique<base::CancelableOnceClosure>(
+      base::BindOnce(&VideoDecodeStatsDBImpl::OnPendingOpTimeout,
+                     weak_ptr_factory_.GetWeakPtr(), op_id));
+
+  base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
+      FROM_HERE, timeout_closure->callback(), kPendingOpTimeout);
+
+  pending_ops_.emplace(op_id, std::make_unique<PendingOperation>(
+                                  uma_str, std::move(timeout_closure)));
+
+  return op_id;
+}
+
+void VideoDecodeStatsDBImpl::CompletePendingOp(PendingOpId op_id) {
+  // Destructing the PendingOperation will trigger UMA for completion timing.
+  int count = pending_ops_.erase(op_id);
+
+  // No big deal, but very unusual. Timeout is very generous, so tasks that
+  // timeout are generally assumed to be permanently hung.
+  if (!count)
+    DVLOG(2) << __func__ << " DB operation completed after timeout.";
+}
+
+void VideoDecodeStatsDBImpl::OnPendingOpTimeout(PendingOpId op_id) {
+  DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
+
+  auto it = pending_ops_.find(op_id);
+  DCHECK(it != pending_ops_.end());
+
+  it->second->OnTimeout();
+  pending_ops_.erase(it);
+}
+
 void VideoDecodeStatsDBImpl::Initialize(InitializeCB init_cb) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
   DCHECK(init_cb);
@@ -107,15 +193,18 @@ void VideoDecodeStatsDBImpl::Initialize(InitializeCB init_cb) {
   // spamming the cache.
   // TODO(chcunningham): Keep an eye on the size as the table evolves.
   db_->Init(base::BindOnce(&VideoDecodeStatsDBImpl::OnInit,
-                           weak_ptr_factory_.GetWeakPtr(), std::move(init_cb)));
+                           weak_ptr_factory_.GetWeakPtr(),
+                           StartPendingOp("Initialize"), std::move(init_cb)));
 }
 
-void VideoDecodeStatsDBImpl::OnInit(InitializeCB init_cb,
+void VideoDecodeStatsDBImpl::OnInit(PendingOpId op_id,
+                                    InitializeCB init_cb,
                                     leveldb_proto::Enums::InitStatus status) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
   DCHECK_NE(status, leveldb_proto::Enums::InitStatus::kInvalidOperation);
   bool success = status == leveldb_proto::Enums::InitStatus::kOK;
   DVLOG(2) << __func__ << (success ? " succeeded" : " FAILED!");
+  CompletePendingOp(op_id);
   UMA_HISTOGRAM_BOOLEAN("Media.VideoDecodeStatsDB.OpSuccess.Initialize",
                         success);
 
@@ -143,10 +232,11 @@ void VideoDecodeStatsDBImpl::AppendDecodeStats(
   DVLOG(3) << __func__ << " Reading key " << key.ToLogString()
            << " from DB with intent to update with " << entry.ToLogString();
 
-  db_->GetEntry(key.Serialize(),
-                base::BindOnce(&VideoDecodeStatsDBImpl::WriteUpdatedEntry,
-                               weak_ptr_factory_.GetWeakPtr(), key, entry,
-                               std::move(append_done_cb)));
+  db_->GetEntry(
+      key.Serialize(),
+      base::BindOnce(&VideoDecodeStatsDBImpl::WriteUpdatedEntry,
+                     weak_ptr_factory_.GetWeakPtr(), StartPendingOp("Read"),
+                     key, entry, std::move(append_done_cb)));
 }
 
 void VideoDecodeStatsDBImpl::GetDecodeStats(const VideoDescKey& key,
@@ -159,7 +249,8 @@ void VideoDecodeStatsDBImpl::GetDecodeStats(const VideoDescKey& key,
   db_->GetEntry(
       key.Serialize(),
       base::BindOnce(&VideoDecodeStatsDBImpl::OnGotDecodeStats,
-                     weak_ptr_factory_.GetWeakPtr(), std::move(get_stats_cb)));
+                     weak_ptr_factory_.GetWeakPtr(), StartPendingOp("Read"),
+                     std::move(get_stats_cb)));
 }
 
 bool VideoDecodeStatsDBImpl::AreStatsUsable(
@@ -211,6 +302,7 @@ bool VideoDecodeStatsDBImpl::AreStatsUsable(
 }
 
 void VideoDecodeStatsDBImpl::WriteUpdatedEntry(
+    PendingOpId op_id,
     const VideoDescKey& key,
     const DecodeStatsEntry& new_entry,
     AppendDecodeStatsCB append_done_cb,
@@ -218,6 +310,7 @@ void VideoDecodeStatsDBImpl::WriteUpdatedEntry(
     std::unique_ptr<DecodeStatsProto> stats_proto) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
   DCHECK(IsInitialized());
+  CompletePendingOp(op_id);
 
   // Note: outcome of "Write" operation logged in OnEntryUpdated().
   UMA_HISTOGRAM_BOOLEAN("Media.VideoDecodeStatsDB.OpSuccess.Read",
@@ -355,26 +448,31 @@ void VideoDecodeStatsDBImpl::WriteUpdatedEntry(
   std::unique_ptr<DBType::KeyEntryVector> entries =
       std::make_unique<DBType::KeyEntryVector>();
   entries->emplace_back(key.Serialize(), *stats_proto);
-  db_->UpdateEntries(std::move(entries),
-                     std::make_unique<leveldb_proto::KeyVector>(),
-                     base::BindOnce(&VideoDecodeStatsDBImpl::OnEntryUpdated,
-                                    weak_ptr_factory_.GetWeakPtr(),
-                                    std::move(append_done_cb)));
+  db_->UpdateEntries(
+      std::move(entries), std::make_unique<leveldb_proto::KeyVector>(),
+      base::BindOnce(&VideoDecodeStatsDBImpl::OnEntryUpdated,
+                     weak_ptr_factory_.GetWeakPtr(), StartPendingOp("Write"),
+                     std::move(append_done_cb)));
 }
 
-void VideoDecodeStatsDBImpl::OnEntryUpdated(AppendDecodeStatsCB append_done_cb,
+void VideoDecodeStatsDBImpl::OnEntryUpdated(PendingOpId op_id,
+                                            AppendDecodeStatsCB append_done_cb,
                                             bool success) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
-  UMA_HISTOGRAM_BOOLEAN("Media.VideoDecodeStatsDB.OpSuccess.Write", success);
   DVLOG(3) << __func__ << " update " << (success ? "succeeded" : "FAILED!");
+  CompletePendingOp(op_id);
+  UMA_HISTOGRAM_BOOLEAN("Media.VideoDecodeStatsDB.OpSuccess.Write", success);
   std::move(append_done_cb).Run(success);
 }
 
 void VideoDecodeStatsDBImpl::OnGotDecodeStats(
+    PendingOpId op_id,
     GetDecodeStatsCB get_stats_cb,
     bool success,
     std::unique_ptr<DecodeStatsProto> stats_proto) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
+  DVLOG(3) << __func__ << " get " << (success ? "succeeded" : "FAILED!");
+  CompletePendingOp(op_id);
   UMA_HISTOGRAM_BOOLEAN("Media.VideoDecodeStatsDB.OpSuccess.Read", success);
 
   std::unique_ptr<DecodeStatsEntry> entry;
@@ -437,16 +535,20 @@ void VideoDecodeStatsDBImpl::ClearStats(base::OnceClosure clear_done_cb) {
 
   db_->LoadKeys(
       base::BindOnce(&VideoDecodeStatsDBImpl::OnLoadAllKeysForClearing,
-                     weak_ptr_factory_.GetWeakPtr(), std::move(clear_done_cb)));
+                     weak_ptr_factory_.GetWeakPtr(), StartPendingOp("LoadKeys"),
+                     std::move(clear_done_cb)));
 }
 
 void VideoDecodeStatsDBImpl::OnLoadAllKeysForClearing(
+    PendingOpId op_id,
     base::OnceClosure clear_done_cb,
     bool success,
     std::unique_ptr<std::vector<std::string>> keys) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
   DVLOG(2) << __func__ << (success ? " succeeded" : " FAILED!");
 
+  CompletePendingOp(op_id);
+
   UMA_HISTOGRAM_BOOLEAN("Media.VideoDecodeStatsDB.OpSuccess.LoadKeys", success);
 
   if (success) {
@@ -455,7 +557,7 @@ void VideoDecodeStatsDBImpl::OnLoadAllKeysForClearing(
         std::make_unique<ProtoDecodeStatsEntry::KeyEntryVector>(),
         std::move(keys) /* keys_to_remove */,
         base::BindOnce(&VideoDecodeStatsDBImpl::OnStatsCleared,
-                       weak_ptr_factory_.GetWeakPtr(),
+                       weak_ptr_factory_.GetWeakPtr(), StartPendingOp("Clear"),
                        std::move(clear_done_cb)));
   } else {
     // Fail silently. See comment in OnStatsCleared().
@@ -463,12 +565,15 @@ void VideoDecodeStatsDBImpl::OnLoadAllKeysForClearing(
   }
 }
 
-void VideoDecodeStatsDBImpl::OnStatsCleared(base::OnceClosure clear_done_cb,
+void VideoDecodeStatsDBImpl::OnStatsCleared(PendingOpId op_id,
+                                            base::OnceClosure clear_done_cb,
                                             bool success) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
   DVLOG(2) << __func__ << (success ? " succeeded" : " FAILED!");
 
-  UMA_HISTOGRAM_BOOLEAN("Media.VideoDecodeStatsDB.OpSuccess.Destroy", success);
+  CompletePendingOp(op_id);
+
+  UMA_HISTOGRAM_BOOLEAN("Media.VideoDecodeStatsDB.OpSuccess.Clear", success);
 
   // We don't pass success to |clear_done_cb|. Clearing is best effort and
   // there is no additional action for callers to take in case of failure.

media/capabilities/video_decode_stats_db_impl.h

@@ -7,6 +7,8 @@
 
 #include <memory>
 
+#include "base/cancelable_callback.h"
+#include "base/containers/flat_map.h"
 #include "base/files/file_path.h"
 #include "base/memory/weak_ptr.h"
 #include "components/leveldb_proto/public/proto_database.h"
@@ -58,6 +60,8 @@ class MEDIA_EXPORT VideoDecodeStatsDBImpl : public VideoDecodeStatsDB {
  private:
   friend class VideoDecodeStatsDBImplTest;
 
+  using PendingOpId = int;
+
   // Private constructor only called by tests (friends). Production code
   // should always use the static Create() method.
   VideoDecodeStatsDBImpl(
@@ -82,16 +86,63 @@ class MEDIA_EXPORT VideoDecodeStatsDBImpl : public VideoDecodeStatsDB {
   // regardless of how many frames were decoded.
   static bool GetEnableUnweightedEntries();
 
+  // Creates a PendingOperation using |uma_str| and adds it to |pending_ops_|
+  // map. Returns PendingOpId for newly started operation. Callers must later
+  // call CompletePendingOp() with this id to destroy the PendingOperation and
+  // finalize timing UMA.
+  PendingOpId StartPendingOp(std::string uma_str);
+
+  // Removes PendingOperation from |pending_ops_| using |op_id_| as a key. This
+  // destroys the object and triggers timing UMA.
+  void CompletePendingOp(PendingOpId op_id);
+
+  // Unified handler for timeouts of pending DB operations. PendingOperation
+  // will be notified that it timed out (to trigger timing UMA) and removed from
+  // |penidng_ops_|.
+  void OnPendingOpTimeout(PendingOpId id);
+
+  // Helper to report timing information for DB operations, including when they
+  // hang indefinitely.
+  class PendingOperation {
+   public:
+    PendingOperation(
+        std::string uma_str,
+        std::unique_ptr<base::CancelableOnceClosure> timeout_closure);
+    // Records task timing UMA if it hasn't already timed out.
+    virtual ~PendingOperation();
+
+    // Copies disallowed. Incompatible with move-only members and UMA logging in
+    // the destructor.
+    PendingOperation(const PendingOperation&) = delete;
+    PendingOperation& operator=(const PendingOperation&) = delete;
+
+    // Trigger UMA recording for timeout.
+    void OnTimeout();
+
+   private:
+    friend class VideoDecodeStatsDBImplTest;
+
+    std::string uma_str_;
+    std::unique_ptr<base::CancelableOnceClosure> timeout_closure_;
+    base::TimeTicks start_ticks_;
+  };
+
+  // Map of operation id -> outstanding PendingOperations.
+  base::flat_map<PendingOpId, std::unique_ptr<PendingOperation>> pending_ops_;
+
   // Called when the database has been initialized. Will immediately call
   // |init_cb| to forward |success|.
-  void OnInit(InitializeCB init_cb, leveldb_proto::Enums::InitStatus status);
+  void OnInit(PendingOpId id,
+              InitializeCB init_cb,
+              leveldb_proto::Enums::InitStatus status);
 
   // Returns true if the DB is successfully initialized.
   bool IsInitialized();
 
   // Passed as the callback for |OnGotDecodeStats| by |AppendDecodeStats| to
   // update the database once we've read the existing stats entry.
-  void WriteUpdatedEntry(const VideoDescKey& key,
+  void WriteUpdatedEntry(PendingOpId op_id,
+                         const VideoDescKey& key,
                          const DecodeStatsEntry& entry,
                          AppendDecodeStatsCB append_done_cb,
                          bool read_success,
@@ -99,24 +150,30 @@ class MEDIA_EXPORT VideoDecodeStatsDBImpl : public VideoDecodeStatsDB {
 
   // Called when the database has been modified after a call to
   // |WriteUpdatedEntry|. Will run |append_done_cb| when done.
-  void OnEntryUpdated(AppendDecodeStatsCB append_done_cb, bool success);
+  void OnEntryUpdated(PendingOpId op_id,
+                      AppendDecodeStatsCB append_done_cb,
+                      bool success);
 
   // Called when GetDecodeStats() operation was performed. |get_stats_cb|
   // will be run with |success| and a |DecodeStatsEntry| created from
   // |stats_proto| or nullptr if no entry was found for the requested key.
-  void OnGotDecodeStats(GetDecodeStatsCB get_stats_cb,
+  void OnGotDecodeStats(PendingOpId op_id,
+                        GetDecodeStatsCB get_stats_cb,
                         bool success,
                         std::unique_ptr<DecodeStatsProto> stats_proto);
 
   // Internal callback for first step of ClearStats(). Will clear all stats If
   // |keys| fetched successfully.
-  void OnLoadAllKeysForClearing(base::OnceClosure clear_done_cb,
+  void OnLoadAllKeysForClearing(PendingOpId op_id,
+                                base::OnceClosure clear_done_cb,
                                 bool success,
                                 std::unique_ptr<std::vector<std::string>> keys);
 
   // Internal callback for OnLoadAllKeysForClearing(), initially triggered by
   // ClearStats(). Method simply logs |success| and runs |clear_done_cb|.
-  void OnStatsCleared(base::OnceClosure clear_done_cb, bool success);
+  void OnStatsCleared(PendingOpId op_id,
+                      base::OnceClosure clear_done_cb,
+                      bool success);
 
   // Return true if:
   //    values aren't corrupted nonsense (e.g. way more frames dropped than
@@ -130,6 +187,9 @@ class MEDIA_EXPORT VideoDecodeStatsDBImpl : public VideoDecodeStatsDB {
     wall_clock_ = tick_clock;
   }
 
+  // Next PendingOpId for use in |pending_ops_| map. See StartPendingOp().
+  PendingOpId next_op_id_ = 0;
+
   // Indicates whether initialization is completed. Does not indicate whether it
   // was successful. Will be reset upon calling DestroyStats(). Failed
   // initialization is signaled by setting |db_| to null.

media/capabilities/video_decode_stats_db_impl_unittest.cc

@@ -65,6 +65,20 @@ class VideoDecodeStatsDBImplTest : public ::testing::Test {
         std::unique_ptr<FakeDB<DecodeStatsProto>>(fake_db_)));
   }
 
+  ~VideoDecodeStatsDBImplTest() override {
+    // Tests should always complete any pending operations
+    VerifyNoPendingOps();
+  }
+
+  void VerifyOnePendingOp(std::string op_name) {
+    EXPECT_EQ(stats_db_->pending_ops_.size(), 1u);
+    VideoDecodeStatsDBImpl::PendingOperation* pending_op =
+        stats_db_->pending_ops_.begin()->second.get();
+    EXPECT_EQ(pending_op->uma_str_, op_name);
+  }
+
+  void VerifyNoPendingOps() { EXPECT_TRUE(stats_db_->pending_ops_.empty()); }
+
   int GetMaxFramesPerBuffer() {
     return VideoDecodeStatsDBImpl::GetMaxFramesPerBuffer();
   }
@@ -95,7 +109,9 @@ class VideoDecodeStatsDBImplTest : public ::testing::Test {
         key, entry,
         base::BindOnce(&VideoDecodeStatsDBImplTest::MockAppendDecodeStatsCb,
                        base::Unretained(this)));
+    VerifyOnePendingOp("Read");
     fake_db_->GetCallback(true);
+    VerifyOnePendingOp("Write");
     fake_db_->UpdateCallback(true);
     testing::Mock::VerifyAndClearExpectations(this);
   }
@@ -106,6 +122,7 @@ class VideoDecodeStatsDBImplTest : public ::testing::Test {
     stats_db_->GetDecodeStats(
         key, base::BindOnce(&VideoDecodeStatsDBImplTest::GetDecodeStatsCb,
                             base::Unretained(this)));
+    VerifyOnePendingOp("Read");
     fake_db_->GetCallback(true);
     testing::Mock::VerifyAndClearExpectations(this);
   }
@@ -115,6 +132,7 @@ class VideoDecodeStatsDBImplTest : public ::testing::Test {
     stats_db_->GetDecodeStats(
         key, base::BindOnce(&VideoDecodeStatsDBImplTest::GetDecodeStatsCb,
                             base::Unretained(this)));
+    VerifyOnePendingOp("Read");
     fake_db_->GetCallback(true);
     testing::Mock::VerifyAndClearExpectations(this);
   }
@@ -157,7 +175,8 @@ class VideoDecodeStatsDBImplTest : public ::testing::Test {
   MOCK_METHOD0(MockClearStatsCb, void());
 
  protected:
-  base::test::TaskEnvironment task_environment_;
+  base::test::TaskEnvironment task_environment_{
+      base::test::TaskEnvironment::TimeSource::MOCK_TIME};
 
   const VideoDescKey kStatsKeyVp9;
   const VideoDescKey kStatsKeyAvc;
@@ -175,13 +194,34 @@ class VideoDecodeStatsDBImplTest : public ::testing::Test {
   DISALLOW_COPY_AND_ASSIGN(VideoDecodeStatsDBImplTest);
 };
 
-TEST_F(VideoDecodeStatsDBImplTest, FailedInitialize) {
+TEST_F(VideoDecodeStatsDBImplTest, InitializeFailed) {
   stats_db_->Initialize(base::BindOnce(
       &VideoDecodeStatsDBImplTest::OnInitialize, base::Unretained(this)));
   EXPECT_CALL(*this, OnInitialize(false));
   fake_db_->InitStatusCallback(leveldb_proto::Enums::InitStatus::kError);
 }
 
+TEST_F(VideoDecodeStatsDBImplTest, InitializeTimedOut) {
+  // Queue up an Initialize.
+  stats_db_->Initialize(base::BindOnce(
+      &VideoDecodeStatsDBImplTest::OnInitialize, base::Unretained(this)));
+  VerifyOnePendingOp("Initialize");
+
+  // Move time forward enough to trigger timeout.
+  EXPECT_CALL(*this, OnInitialize(_)).Times(0);
+  task_environment_.FastForwardBy(base::TimeDelta::FromSeconds(100));
+  task_environment_.RunUntilIdle();
+
+  // Verify we didn't get an init callback and task is no longer considered
+  // pending (because it timed out).
+  testing::Mock::VerifyAndClearExpectations(this);
+  VerifyNoPendingOps();
+
+  // Verify callback still works if init completes very late.
+  EXPECT_CALL(*this, OnInitialize(false));
+  fake_db_->InitStatusCallback(leveldb_proto::Enums::InitStatus::kError);
+}
+
 TEST_F(VideoDecodeStatsDBImplTest, ReadExpectingNothing) {
   InitializeDB();
   VerifyEmptyStats(kStatsKeyVp9);
@@ -204,9 +244,12 @@ TEST_F(VideoDecodeStatsDBImplTest, WriteReadAndClear) {
   VerifyReadStats(kStatsKeyVp9, aggregate_entry);
 
   // Clear all stats from the DB.
+  EXPECT_CALL(*this, MockClearStatsCb);
   stats_db_->ClearStats(base::BindOnce(
       &VideoDecodeStatsDBImplTest::MockClearStatsCb, base::Unretained(this)));
+  VerifyOnePendingOp("LoadKeys");
   fake_db_->LoadKeysCallback(true);
+  VerifyOnePendingOp("Clear");
   fake_db_->UpdateCallback(true);
 
   // Database is now empty. Expect null entry.

media/mojo/services/video_decode_perf_history_unittest.cc

@@ -52,6 +52,7 @@ class FakeVideoDecodeStatsDB : public VideoDecodeStatsDB {
 
   // Call CompleteInitialize(...) to run |init_cb| callback.
   void Initialize(base::OnceCallback<void(bool)> init_cb) override {
+    EXPECT_FALSE(!!pendnding_init_cb_);
     pendnding_init_cb_ = std::move(init_cb);
   }
 
@@ -59,7 +60,7 @@ class FakeVideoDecodeStatsDB : public VideoDecodeStatsDB {
   // for success.
   void CompleteInitialize(bool success) {
     DVLOG(2) << __func__ << " running with success = " << success;
-    EXPECT_FALSE(!pendnding_init_cb_);
+    EXPECT_TRUE(!!pendnding_init_cb_);
     std::move(pendnding_init_cb_).Run(success);
   }
 
@@ -1037,4 +1038,50 @@ INSTANTIATE_TEST_SUITE_P(VaryDBInitTiming,
                          VideoDecodePerfHistoryParamTest,
                          ::testing::ValuesIn(kPerfHistoryTestParams));
 
-}  // namespace media
+//
+// The following test are not parameterized. They instead always hard code
+// deferred initialization.
+//
+
+TEST_F(VideoDecodePerfHistoryTest, ClearHistoryTriggersSuccessfulInitialize) {
+  // Clear the DB. Completion callback shouldn't fire until initialize
+  // completes.
+  EXPECT_CALL(*this, MockOnClearedHistory()).Times(0);
+  perf_history_->ClearHistory(
+      base::BindOnce(&VideoDecodePerfHistoryParamTest::MockOnClearedHistory,
+                     base::Unretained(this)));
+
+  // Give completion callback a chance to fire. Confirm it did not fire.
+  task_environment_.RunUntilIdle();
+  testing::Mock::VerifyAndClearExpectations(this);
+
+  // Expect completion callback after we successfully initialize.
+  EXPECT_CALL(*this, MockOnClearedHistory());
+  GetFakeDB()->CompleteInitialize(true);
+
+  // Give deferred callback a chance to fire.
+  task_environment_.RunUntilIdle();
+}
+
+TEST_F(VideoDecodePerfHistoryTest, ClearHistoryTriggersFailedInitialize) {
+  // Clear the DB. Completion callback shouldn't fire until initialize
+  // completes.
+  EXPECT_CALL(*this, MockOnClearedHistory()).Times(0);
+  perf_history_->ClearHistory(
+      base::BindOnce(&VideoDecodePerfHistoryParamTest::MockOnClearedHistory,
+                     base::Unretained(this)));
+
+  // Give completion callback a chance to fire. Confirm it did not fire.
+  task_environment_.RunUntilIdle();
+  testing::Mock::VerifyAndClearExpectations(this);
+
+  // Expect completion callback after completing initialize. "Failure" is still
+  // a form of completion.
+  EXPECT_CALL(*this, MockOnClearedHistory());
+  GetFakeDB()->CompleteInitialize(false);
+
+  // Give deferred callback a chance to fire.
+  task_environment_.RunUntilIdle();
+}
+
+}  // namespace media

tools/metrics/histograms/histograms.xml

@@ -76564,10 +76564,12 @@ reviews. Googlers can read more about this at go/gwsq-gerrit.
   </summary>
 </histogram>
 
-<histogram name="Media.VideoDecodeStatsDB.OpSuccess" enum="BooleanSuccess"
-    expires_after="never">
+<histogram base="true" name="Media.VideoDecodeStatsDB.OpSuccess"
+    enum="BooleanSuccess" expires_after="never">
 <!-- expires-never: MediaCapabilities DB health metric. -->
 
+<!-- Name completed by histogram_suffixes name="VideoDecodeStatsDBOperations" -->
+
   <owner>chcunningham@chromium.org</owner>
   <owner>media-dev@chromium.org</owner>
   <summary>
@@ -76576,6 +76578,19 @@ reviews. Googlers can read more about this at go/gwsq-gerrit.
   </summary>
 </histogram>
 
+<histogram name="Media.VideoDecodeStatsDB.OpTiming" units="ms"
+    expires_after="never">
+<!-- expires-never: MediaCapabilities DB health metric. -->
+
+<!-- Name completed by histogram_suffixes name="VideoDecodeStatsDBOperations" -->
+
+  <owner>chcunningham@chromium.org</owner>
+  <owner>media-dev@chromium.org</owner>
+  <summary>
+    Indicates duration of time performing some database operation.
+  </summary>
+</histogram>
+
 <histogram name="Media.VideoFormat" enum="VideoFormat"
     expires_after="2015-05-29">
   <obsolete>
@@ -201615,16 +201630,19 @@ regressions. -->
 </histogram_suffixes>
 
 <histogram_suffixes name="VideoDecodeStatsDBOperations" separator=".">
-  <suffix name="Clear" label="Success status for clearing the DB"/>
-  <suffix name="Destroy"
-      label="Success status for destroying the DB - DEPRECATED Sept 2018"/>
-  <suffix name="Initialize" label="Success status for initializing the DB."/>
-  <suffix name="LoadKeys" label="Success status for loading all DB keys"/>
-  <suffix name="Read" label="Success status for reading from the DB"/>
-  <suffix name="Validate"
-      label="Success validating that an entry from the DB is not corrupt"/>
-  <suffix name="Write" label="Success status for writing to the DB"/>
+  <suffix name="Clear" label="Remove all keys"/>
+  <suffix name="Destroy" label="Destroy DB">
+    <obsolete>
+      Deprecated in favor of [LoadKeys, Clear] as of 2020-04-03.
+    </obsolete>
+  </suffix>
+  <suffix name="Initialize" label="Initialize the DB."/>
+  <suffix name="LoadKeys" label="Load all DB keys"/>
+  <suffix name="Read" label="Read an entry from the DB"/>
+  <suffix name="Validate" label="Check for DB entry corruption"/>
+  <suffix name="Write" label="Write an entry to the DB"/>
   <affected-histogram name="Media.VideoDecodeStatsDB.OpSuccess"/>
+  <affected-histogram name="Media.VideoDecodeStatsDB.OpTiming"/>
 </histogram_suffixes>
 
 <histogram_suffixes name="VideoEncodedQpStats" separator=".">