Add UMA to measure how late delayed and non-delayed tasks are

This patch adds two new UMA histograms.

RendererScheduler.TaskQueueManager.DelayedTaskLateness measures how much
later delayed tasks are run after their scheduled run time.

RendererScheduler.TaskQueueManager.ImmediateTaskQueueingDuration
measures how long a non-delayed tasks is queued before its run.  Note
this metric is only recorded if TrackingInfo::time_posted is set.

To reduce overhead only 10% of tasks are recorded.

We also only records tasks from auto-pumped queues since other types of
queues can have tasks arbitrarily delayed which will skew the
histograms.

BUG=574343

Review URL: https://codereview.chromium.org/1615143003

Cr-Commit-Position: refs/heads/master@{#371236}

6 files changed, 76 insertions, 4 deletions

diff --git a/components/scheduler/base/task_queue.h b/components/scheduler/base/task_queue.h
index ac21b29..c557b7d 100644
--- a/components/scheduler/base/task_queue.h
+++ b/components/scheduler/base/task_queue.h
@@ -159,6 +159,10 @@ class SCHEDULER_EXPORT TaskQueue : public base::SingleThreadTaskRunner {
   // called on the thread this TaskQueue was created by.
   virtual void SetPumpPolicy(PumpPolicy pump_policy) = 0;
 
+  // Returns the current PumpPolicy. NOTE this must be called on the thread this
+  // TaskQueue was created by.
+  virtual PumpPolicy GetPumpPolicy() const = 0;
+
   // Reloads new tasks from the incoming queue into the work queue, regardless
   // of whether the work queue is empty or not. After this, the function ensures
   // that the tasks in the work queue, if any, are scheduled for execution.
diff --git a/components/scheduler/base/task_queue_impl.cc b/components/scheduler/base/task_queue_impl.cc
index 9979d9945..5508c9b 100644
--- a/components/scheduler/base/task_queue_impl.cc
+++ b/components/scheduler/base/task_queue_impl.cc
@@ -61,12 +61,11 @@ TaskQueueImpl::Task::Task(const tracked_objects::Location& posted_from,
                           base::TimeTicks desired_run_time,
                           EnqueueOrder sequence_number,
                           bool nestable)
-    : PendingTask(posted_from, task, base::TimeTicks(), nestable),
+    : PendingTask(posted_from, task, desired_run_time, nestable),
 #ifndef NDEBUG
       enqueue_order_set_(false),
 #endif
       enqueue_order_(0) {
-  delayed_run_time = desired_run_time;
   sequence_num = sequence_number;
 }
 
@@ -76,12 +75,11 @@ TaskQueueImpl::Task::Task(const tracked_objects::Location& posted_from,
                           EnqueueOrder sequence_number,
                           bool nestable,
                           EnqueueOrder enqueue_order)
-    : PendingTask(posted_from, task, base::TimeTicks(), nestable),
+    : PendingTask(posted_from, task, desired_run_time, nestable),
 #ifndef NDEBUG
       enqueue_order_set_(true),
 #endif
       enqueue_order_(enqueue_order) {
-  delayed_run_time = desired_run_time;
   sequence_num = sequence_number;
 }
 
@@ -441,6 +439,10 @@ void TaskQueueImpl::SetPumpPolicy(PumpPolicy pump_policy) {
   main_thread_only().pump_policy = pump_policy;
 }
 
+TaskQueue::PumpPolicy TaskQueueImpl::GetPumpPolicy() const {
+  return main_thread_only().pump_policy;
+}
+
 void TaskQueueImpl::PumpQueueLocked(bool may_post_dowork) {
   TRACE_EVENT1(disabled_by_default_tracing_category_,
                "TaskQueueImpl::PumpQueueLocked", "queue", name_);
diff --git a/components/scheduler/base/task_queue_impl.h b/components/scheduler/base/task_queue_impl.h
index 9861552..504fa9d 100644
--- a/components/scheduler/base/task_queue_impl.h
+++ b/components/scheduler/base/task_queue_impl.h
@@ -99,6 +99,7 @@ class SCHEDULER_EXPORT TaskQueueImpl final : public TaskQueue {
   QueuePriority GetQueuePriority() const override;
   void PumpQueue(bool may_post_dowork) override;
   void SetPumpPolicy(PumpPolicy pump_policy) override;
+  PumpPolicy GetPumpPolicy() const override;
   void AddTaskObserver(base::MessageLoop::TaskObserver* task_observer) override;
   void RemoveTaskObserver(
       base::MessageLoop::TaskObserver* task_observer) override;
diff --git a/components/scheduler/base/task_queue_manager.cc b/components/scheduler/base/task_queue_manager.cc
index 62111e69..584eb703 100644
--- a/components/scheduler/base/task_queue_manager.cc
+++ b/components/scheduler/base/task_queue_manager.cc
@@ -8,6 +8,7 @@
 #include <set>
 
 #include "base/bind.h"
+#include "base/metrics/histogram_macros.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"
@@ -17,6 +18,21 @@
 
 namespace scheduler {
 
+namespace {
+const size_t kRecordRecordTaskDelayHistogramsEveryNTasks = 10;
+
+void RecordDelayedTaskLateness(base::TimeDelta lateness) {
+  UMA_HISTOGRAM_TIMES("RendererScheduler.TaskQueueManager.DelayedTaskLateness",
+                      lateness);
+}
+
+void RecordImmediateTaskQueueingDuration(tracked_objects::Duration duration) {
+  UMA_HISTOGRAM_TIMES(
+      "RendererScheduler.TaskQueueManager.ImmediateTaskQueueingDuration",
+      base::TimeDelta::FromMilliseconds(duration.InMilliseconds()));
+}
+}
+
 TaskQueueManager::TaskQueueManager(
     scoped_refptr<TaskQueueManagerDelegate> delegate,
     const char* tracing_category,
@@ -26,6 +42,7 @@ TaskQueueManager::TaskQueueManager(
       delegate_(delegate),
       task_was_run_on_quiescence_monitored_queue_(false),
       work_batch_size_(1),
+      task_count_(0),
       tracing_category_(tracing_category),
       disabled_by_default_tracing_category_(
           disabled_by_default_tracing_category),
@@ -252,6 +269,8 @@ TaskQueueManager::ProcessTaskResult TaskQueueManager::ProcessTaskFromWorkQueue(
     return ProcessTaskResult::DEFERRED;
   }
 
+  MaybeRecordTaskDelayHistograms(pending_task, queue);
+
   TRACE_TASK_EXECUTION("TaskQueueManager::ProcessTaskFromWorkQueue",
                        pending_task);
   if (queue->GetShouldNotifyObservers()) {
@@ -279,6 +298,26 @@ TaskQueueManager::ProcessTaskResult TaskQueueManager::ProcessTaskFromWorkQueue(
   return ProcessTaskResult::EXECUTED;
 }
 
+void TaskQueueManager::MaybeRecordTaskDelayHistograms(
+    const internal::TaskQueueImpl::Task& pending_task,
+    const internal::TaskQueueImpl* queue) {
+  if ((task_count_++ % kRecordRecordTaskDelayHistogramsEveryNTasks) != 0)
+    return;
+
+  // Record delayed task lateness and immediate task queueing durations, but
+  // only for auto-pumped queues.  Manually pumped and after wakeup queues can
+  // have arbitarially large delayes, which would cloud any analysis.
+  if (queue->GetPumpPolicy() == TaskQueue::PumpPolicy::AUTO) {
+    if (!pending_task.delayed_run_time.is_null()) {
+      RecordDelayedTaskLateness(delegate_->NowTicks() -
+                                pending_task.delayed_run_time);
+    } else if (!pending_task.time_posted.is_null()) {
+      RecordImmediateTaskQueueingDuration(tracked_objects::TrackedTime::Now() -
+                                          pending_task.time_posted);
+    }
+  }
+}
+
 bool TaskQueueManager::RunsTasksOnCurrentThread() const {
   return delegate_->RunsTasksOnCurrentThread();
 }
diff --git a/components/scheduler/base/task_queue_manager.h b/components/scheduler/base/task_queue_manager.h
index e41e86a..7a7d6d4 100644
--- a/components/scheduler/base/task_queue_manager.h
+++ b/components/scheduler/base/task_queue_manager.h
@@ -190,6 +190,10 @@ class SCHEDULER_EXPORT TaskQueueManager
   // was able to advance.
   bool TryAdvanceTimeDomains();
 
+  void MaybeRecordTaskDelayHistograms(
+      const internal::TaskQueueImpl::Task& pending_task,
+      const internal::TaskQueueImpl* queue);
+
   scoped_refptr<base::trace_event::ConvertableToTraceFormat>
   AsValueWithSelectorResult(bool should_run,
                             internal::WorkQueue* selected_work_queue) const;
@@ -224,6 +228,7 @@ class SCHEDULER_EXPORT TaskQueueManager
   std::set<base::TimeTicks> other_thread_pending_wakeups_;
 
   int work_batch_size_;
+  size_t task_count_;
 
   base::ObserverList<base::MessageLoop::TaskObserver> task_observers_;
 
diff --git a/tools/metrics/histograms/histograms.xml b/tools/metrics/histograms/histograms.xml
index 89be2d0..cd9d2bc 100644
--- a/tools/metrics/histograms/histograms.xml
+++ b/tools/metrics/histograms/histograms.xml
@@ -39614,6 +39614,27 @@ http://cs/file:chrome/histograms.xml - but prefer this file for new entries.
   </summary>
 </histogram>
 
+<histogram name="RendererScheduler.TaskQueueManager.DelayedTaskLateness"
+    units="ms">
+  <owner>alexclarke@chromium.org</owner>
+  <summary>
+    The delta between when a delayed task was scheduled to run and when the
+    RendererScheduler actually ran it. Note: to reduce overhead only 10% of
+    tasks are sampled.
+  </summary>
+</histogram>
+
+<histogram
+    name="RendererScheduler.TaskQueueManager.ImmediateTaskQueueingDuration"
+    units="ms">
+  <owner>alexclarke@chromium.org</owner>
+  <summary>
+    The queueing duration for non-delayed tasks posted to the RendererScheduler.
+    This metric is only recorded if TrackingInfo::time_posted is set (i.e. not
+    on android). Note: to reduce overhead only 10% of tasks are sampled.
+  </summary>
+</histogram>
+
 <histogram name="RendererScheduler.UserModel.GestureDuration" units="ms">
   <owner>alexclarke@chromium.org</owner>
   <summary>Duration of gestures (scrolls and pinches).</summary>