Report expected task queueing time via UMA

components/scheduler/base/task_queue_manager.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 <queue>
 #include <set>
 
 #include "base/bind.h"
 #include "base/metrics/histogram_macros.h"
 #include "base/trace_event/trace_event.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.h"
 #include "components/scheduler/base/task_queue_selector.h"
+#include "components/scheduler/base/task_time_tracker.h"
 #include "components/scheduler/base/work_queue.h"
 #include "components/scheduler/base/work_queue_sets.h"
 
 namespace scheduler {
 
 namespace {
 const size_t kRecordRecordTaskDelayHistogramsEveryNTasks = 10;
 
 void RecordDelayedTaskLateness(base::TimeDelta lateness) {
   UMA_HISTOGRAM_TIMES("RendererScheduler.TaskQueueManager.DelayedTaskLateness",
@@ skipping 10 matching lines @@
 TaskQueueManager::TaskQueueManager(
     scoped_refptr<TaskQueueManagerDelegate> delegate,
     const char* tracing_category,
     const char* disabled_by_default_tracing_category,
     const char* disabled_by_default_verbose_tracing_category)
     : real_time_domain_(new RealTimeDomain(tracing_category)),
       delegate_(delegate),
       task_was_run_on_quiescence_monitored_queue_(false),
       work_batch_size_(1),
       task_count_(0),
+      task_time_tracker_(nullptr),
       tracing_category_(tracing_category),
       disabled_by_default_tracing_category_(
           disabled_by_default_tracing_category),
       disabled_by_default_verbose_tracing_category_(
           disabled_by_default_verbose_tracing_category),
       currently_executing_task_queue_(nullptr),
       observer_(nullptr),
       deletion_sentinel_(new DeletionSentinel()),
       weak_factory_(this) {
   DCHECK(delegate->RunsTasksOnCurrentThread());
@@ skipping 64 matching lines @@
 
   // Add |task_queue| to |queues_to_delete_| so we can prevent it from being
   // freed while any of our structures hold hold a raw pointer to it.
   queues_to_delete_.insert(task_queue);
   queues_.erase(task_queue);
   selector_.RemoveQueue(task_queue.get());
 }
 
 void TaskQueueManager::UpdateWorkQueues(
     bool should_trigger_wakeup,
-    const internal::TaskQueueImpl::Task* previous_task) {
+    const internal::TaskQueueImpl::Task* previous_task,
+    LazyNow lazy_now) {
   TRACE_EVENT0(disabled_by_default_tracing_category_,
                "TaskQueueManager::UpdateWorkQueues");
 
   for (TimeDomain* time_domain : time_domains_) {
-    time_domain->UpdateWorkQueues(should_trigger_wakeup, previous_task);
+    LazyNow lazy_now_in_domain = time_domain == real_time_domain_.get()
+                                     ? lazy_now
+                                     : time_domain->CreateLazyNow();
+    time_domain->UpdateWorkQueues(should_trigger_wakeup, previous_task,
+                                  lazy_now_in_domain);
   }
 }
 
 void TaskQueueManager::MaybeScheduleImmediateWork(
     const tracked_objects::Location& from_here) {
   bool on_main_thread = delegate_->BelongsToCurrentThread();
   // De-duplicate DoWork posts.
   if (on_main_thread) {
     if (!main_thread_pending_wakeups_.insert(base::TimeTicks()).second) {
       return;
@@ skipping 33 matching lines @@
   if (from_main_thread) {
     main_thread_pending_wakeups_.erase(run_time);
   } else {
     base::AutoLock lock(other_thread_lock_);
     other_thread_pending_wakeups_.erase(run_time);
   }
 
   if (!delegate_->IsNested())
     queues_to_delete_.clear();
 
+  LazyNow lazy_now(real_time_domain()->CreateLazyNow());
+  base::TimeTicks task_start_time;
+
+  if (!delegate_->IsNested() && task_time_tracker_)
+    task_start_time = lazy_now.Now();
+
   // Pass false and nullptr to UpdateWorkQueues here to prevent waking up a
   // pump-after-wakeup queue.
-  UpdateWorkQueues(false, nullptr);
+  UpdateWorkQueues(false, nullptr, lazy_now);
 
   internal::TaskQueueImpl::Task previous_task;
+
   for (int i = 0; i < work_batch_size_; i++) {
     internal::WorkQueue* work_queue;
     if (!SelectWorkQueueToService(&work_queue)) {
       break;
     }
 
     bool should_trigger_wakeup = work_queue->task_queue()->wakeup_policy() ==
                                  TaskQueue::WakeupPolicy::CAN_WAKE_OTHER_QUEUES;
+
     switch (ProcessTaskFromWorkQueue(work_queue, &previous_task)) {
       case ProcessTaskResult::DEFERRED:
         // If a task was deferred, try again with another task. Note that this
         // means deferred tasks (i.e. non-nestable tasks) will never trigger
         // queue wake-ups.
         continue;
       case ProcessTaskResult::EXECUTED:
         break;
       case ProcessTaskResult::TASK_QUEUE_MANAGER_DELETED:
         return;  // The TaskQueueManager got deleted, we must bail out.
     }
+
+    lazy_now = real_time_domain()->CreateLazyNow();
+    if (!delegate_->IsNested() && task_time_tracker_) {
+      // Only report top level task durations.
+      base::TimeTicks task_end_time = real_time_domain()->Now();

[alex clarke (OOO till 29th), 2016/07/06 09:51:39]

Can you do this?

if (!delegate_->IsNested() && task_time_tracker_) {
  // Only report top level task durations.
  base::TimeTicks task_end_time = lazy_now.Now();
  task_time_tracker_->ReportTaskTime(task_start_time, task_end_time);
  task_start_time = task_end_time
}

[tdresser, 2016/07/06 13:25:34]

Done.

+      task_time_tracker_->ReportTaskTime(task_start_time, task_end_time);
+      task_start_time = task_end_time;
+      lazy_now = LazyNow(task_end_time);
+    }
+
     work_queue = nullptr; // The queue may have been unregistered.
 
-    UpdateWorkQueues(should_trigger_wakeup, &previous_task);
+    UpdateWorkQueues(should_trigger_wakeup, &previous_task, lazy_now);
 
     // Only run a single task per batch in nested run loops so that we can
     // properly exit the nested loop when someone calls RunLoop::Quit().
     if (delegate_->IsNested())
       break;
   }
 
   // TODO(alexclarke): Consider refactoring the above loop to terminate only
   // when there's no more work left to be done, rather than posting a
   // continuation task.
@@ skipping 182 matching lines @@
     internal::WorkQueue* work_queue) {
   DCHECK(main_thread_checker_.CalledOnValidThread());
   DCHECK(!work_queue->Empty());
   if (observer_) {
     observer_->OnTriedToExecuteBlockedTask(*work_queue->task_queue(),
                                            *work_queue->GetFrontTask());
   }
 }
 
 }  // namespace scheduler