Report expected task queueing time via UMA

components/scheduler/base/task_queue_manager_unittest.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 "components/scheduler/base/task_queue_manager.h"
 
 #include <stddef.h>
 
 #include <utility>
 
 #include "base/location.h"
 #include "base/memory/ptr_util.h"
 #include "base/memory/ref_counted_memory.h"
 #include "base/run_loop.h"
 #include "base/single_thread_task_runner.h"
 #include "base/test/simple_test_tick_clock.h"
 #include "base/test/trace_event_analyzer.h"
 #include "base/threading/thread.h"
 #include "base/trace_event/blame_context.h"
 #include "base/trace_event/trace_buffer.h"
 #include "cc/test/ordered_simple_task_runner.h"
 #include "components/scheduler/base/real_time_domain.h"
 #include "components/scheduler/base/task_queue_impl.h"
 #include "components/scheduler/base/task_queue_manager_delegate_for_test.h"
 #include "components/scheduler/base/task_queue_selector.h"
-#include "components/scheduler/base/test_always_fail_time_source.h"
+#include "components/scheduler/base/task_time_tracker.h"
+#include "components/scheduler/base/test_count_uses_time_source.h"
 #include "components/scheduler/base/test_time_source.h"
 #include "components/scheduler/base/virtual_time_domain.h"
 #include "components/scheduler/base/work_queue.h"
 #include "components/scheduler/base/work_queue_sets.h"
 #include "testing/gmock/include/gmock/gmock.h"
 
 using testing::ElementsAre;
 using testing::ElementsAreArray;
 using testing::_;
 using scheduler::internal::EnqueueOrder;
@@ skipping 25 matching lines @@
   void DeleteTaskQueueManager() { manager_.reset(); }
 
  protected:
   void InitializeWithClock(size_t num_queues,
                            std::unique_ptr<base::TickClock> test_time_source) {
     test_task_runner_ = make_scoped_refptr(
         new cc::OrderedSimpleTaskRunner(now_src_.get(), false));
     main_task_runner_ = TaskQueueManagerDelegateForTest::Create(
         test_task_runner_.get(),
         base::WrapUnique(new TestTimeSource(now_src_.get())));
-    manager_ = base::WrapUnique(
-        new TaskQueueManager(main_task_runner_, "test.scheduler",
-                             "test.scheduler", "test.scheduler.debug"));
+
+    manager_ = base::WrapUnique(new TaskQueueManager(
+        main_task_runner_, "test.scheduler", "test.scheduler",
+        "test.scheduler.debug", &task_time_tracker_));
 
     for (size_t i = 0; i < num_queues; i++)
       runners_.push_back(manager_->NewTaskQueue(TaskQueue::Spec("test_queue")));
   }
 
   void Initialize(size_t num_queues) {
     now_src_.reset(new base::SimpleTestTickClock());
     now_src_->Advance(base::TimeDelta::FromMicroseconds(1000));
     InitializeWithClock(num_queues,
                         base::WrapUnique(new TestTimeSource(now_src_.get())));
   }
 
   void InitializeWithRealMessageLoop(size_t num_queues) {
     now_src_.reset(new base::SimpleTestTickClock());
     message_loop_.reset(new base::MessageLoop());
     manager_ = base::WrapUnique(new TaskQueueManager(
         MessageLoopTaskRunner::Create(
             base::WrapUnique(new TestTimeSource(now_src_.get()))),
-        "test.scheduler", "test.scheduler", "test.scheduler.debug"));
+        "test.scheduler", "test.scheduler", "test.scheduler.debug",
+        &task_time_tracker_));
 
     for (size_t i = 0; i < num_queues; i++)
       runners_.push_back(manager_->NewTaskQueue(TaskQueue::Spec("test_queue")));
   }
 
   std::unique_ptr<base::MessageLoop> message_loop_;
   std::unique_ptr<base::SimpleTestTickClock> now_src_;
   scoped_refptr<TaskQueueManagerDelegateForTest> main_task_runner_;
   scoped_refptr<cc::OrderedSimpleTaskRunner> test_task_runner_;
   std::unique_ptr<TaskQueueManager> manager_;
   std::vector<scoped_refptr<internal::TaskQueueImpl>> runners_;
+  TaskTimeTracker task_time_tracker_;
 };
 
 void PostFromNestedRunloop(base::MessageLoop* message_loop,
                            base::SingleThreadTaskRunner* runner,
                            std::vector<std::pair<base::Closure, bool>>* tasks) {
   base::MessageLoop::ScopedNestableTaskAllower allow(message_loop);
   for (std::pair<base::Closure, bool>& pair : *tasks) {
     if (pair.second) {
       runner->PostTask(FROM_HERE, pair.first);
     } else {
       runner->PostNonNestableTask(FROM_HERE, pair.first);
     }
   }
   base::RunLoop().RunUntilIdle();
 }
 
 void NopTask() {}
 
-TEST_F(TaskQueueManagerTest, NowNotCalledWhenThereAreNoDelayedTasks) {
+TEST_F(TaskQueueManagerTest,
+       NowCalledMinimumNumberOfTimesToComputeTaskDurations) {
   message_loop_.reset(new base::MessageLoop());
+  // This memory is managed by the TaskQueueManager, but we need to hold a
+  // pointer to this object to read out how many times Now was called.
+  TestCountUsesTimeSource* test_count_uses_time_source =
+      new TestCountUsesTimeSource();
+
   manager_ = base::WrapUnique(new TaskQueueManager(
       MessageLoopTaskRunner::Create(
-          base::WrapUnique(new TestAlwaysFailTimeSource())),
-      "test.scheduler", "test.scheduler", "test.scheduler.debug"));
+          base::WrapUnique(test_count_uses_time_source)),
+      "test.scheduler", "test.scheduler", "test.scheduler.debug",
+      &task_time_tracker_));
+  manager_->SetWorkBatchSize(6);
 
   for (size_t i = 0; i < 3; i++)
     runners_.push_back(manager_->NewTaskQueue(TaskQueue::Spec("test_queue")));
 
   runners_[0]->PostTask(FROM_HERE, base::Bind(&NopTask));
   runners_[0]->PostTask(FROM_HERE, base::Bind(&NopTask));
   runners_[1]->PostTask(FROM_HERE, base::Bind(&NopTask));
   runners_[1]->PostTask(FROM_HERE, base::Bind(&NopTask));
   runners_[2]->PostTask(FROM_HERE, base::Bind(&NopTask));
   runners_[2]->PostTask(FROM_HERE, base::Bind(&NopTask));
 
   message_loop_->RunUntilIdle();
+  // We need to call Now for the beginning of the first task, and then the end
+  // of every task after. We reuse the end time of one task for the start time
+  // of the next task. In this case, there were 6 tasks, so we expect 7 calls to
+  // Now.
+  EXPECT_EQ(7, test_count_uses_time_source->now_calls_count());
+}
+
+TEST_F(TaskQueueManagerTest,
+       NowNotCalledForNestedTasks) {
+  message_loop_.reset(new base::MessageLoop());
+  // This memory is managed by the TaskQueueManager, but we need to hold a
+  // pointer to this object to read out how many times Now was called.
+  TestCountUsesTimeSource* test_count_uses_time_source =
+      new TestCountUsesTimeSource();
+
+  manager_ = base::WrapUnique(new TaskQueueManager(
+      MessageLoopTaskRunner::Create(
+          base::WrapUnique(test_count_uses_time_source)),
+      "test.scheduler", "test.scheduler", "test.scheduler.debug",
+      &task_time_tracker_));
+
+  runners_.push_back(manager_->NewTaskQueue(TaskQueue::Spec("test_queue")));
+
+  std::vector<std::pair<base::Closure, bool>> tasks_to_post_from_nested_loop;
+  for (int i = 0; i <= 6; ++i) {
+    tasks_to_post_from_nested_loop.push_back(
+        std::make_pair(base::Bind(&NopTask), true));
+  }
+
+  runners_[0]->PostTask(
+      FROM_HERE, base::Bind(&PostFromNestedRunloop, message_loop_.get(),
+                            base::RetainedRef(runners_[0]),
+                            base::Unretained(&tasks_to_post_from_nested_loop)));
+
+  message_loop_->RunUntilIdle();
+  // We need to call Now twice, to measure the start and end of the outermost
+  // task. We shouldn't call it for any of the nested tasks.
+  EXPECT_EQ(2, test_count_uses_time_source->now_calls_count());
 }
 
 void NullTask() {}
 
 void TestTask(EnqueueOrder value, std::vector<EnqueueOrder>* out_result) {
   out_result->push_back(value);
 }
 
 TEST_F(TaskQueueManagerTest, SingleQueuePosting) {
   Initialize(1u);
@@ skipping 1761 matching lines @@
 
   trace_analyzer::TraceEventVector events;
   Query q = Query::EventPhaseIs(TRACE_EVENT_PHASE_ENTER_CONTEXT) ||
             Query::EventPhaseIs(TRACE_EVENT_PHASE_LEAVE_CONTEXT);
   analyzer->FindEvents(q, &events);
 
   EXPECT_EQ(2u, events.size());
 }
 
 }  // namespace scheduler