Record task metrics for cooperative scheduling

- RendererScheduler.TasksWithSafepoints.SafepointCount
- RendererScheduler.TasksWithSafepoints.TaskSliceTime
- RendererScheduler.TasksWithSafepoints.TaskTime

Bug: 804661

Change-Id: Ib4a5fbdca90caddc8b6820216e86333f1316b725
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1578720Reviewed-by: Keishi Hattori <keishi@chromium.org>
Reviewed-by: Alexander Timin <altimin@chromium.org>
Commit-Queue: Takashi Sakamoto <tasak@google.com>
Cr-Commit-Position: refs/heads/master@{#670023}

third_party/blink/renderer/platform/scheduler/common/cooperative_scheduling_manager.cc

@@ -58,13 +58,17 @@ void CooperativeSchedulingManager::LeaveAllowedStackScope() {
 
 void CooperativeSchedulingManager::SafepointSlow() {
   // Avoid nesting more than two levels.
-  if (running_nested_loop_)
+  if (running_nested_loop_ || base::RunLoop::IsNestedOnCurrentThread())
     return;
 
   // TODO(keishi): Also bail if V8 EnteredContextCount is more than 1
-  Thread::MainThread()->Scheduler()->SetHasSafepoint();
+  // This task slice completes here.
+  Thread::MainThread()->Scheduler()->OnSafepointEntered();
 
   RunNestedLoop();
+
+  // A new task slice starts here.
+  Thread::MainThread()->Scheduler()->OnSafepointExited();
 }
 
 void CooperativeSchedulingManager::RunNestedLoop() {

third_party/blink/renderer/platform/scheduler/main_thread/main_thread_metrics_helper.cc

@@ -139,7 +139,9 @@ MainThreadMetricsHelper::MainThreadMetricsHelper(
       total_task_time_reporter_(
           "Scheduler.Experimental.Renderer.TotalTime.Wall.MainThread.Positive",
           "Scheduler.Experimental.Renderer.TotalTime.Wall.MainThread.Negative"),
-      main_thread_task_load_state_(MainThreadTaskLoadState::kUnknown) {
+      main_thread_task_load_state_(MainThreadTaskLoadState::kUnknown),
+      current_task_slice_start_time_(now),
+      safepoints_in_current_toplevel_task_count_(0) {
   main_thread_load_tracker_.Resume(now);
   if (renderer_backgrounded) {
     background_main_thread_load_tracker_.Resume(now);
@@ -204,6 +206,37 @@ base::TimeDelta DurationOfIntervalOverlap(base::TimeTicks start1,
 
 }  // namespace
 
+void MainThreadMetricsHelper::OnSafepointEntered(base::TimeTicks now) {
+  current_task_slice_start_time_ = now;
+}
+
+void MainThreadMetricsHelper::OnSafepointExited(base::TimeTicks now) {
+  safepoints_in_current_toplevel_task_count_++;
+  RecordTaskSliceMetrics(now);
+}
+
+void MainThreadMetricsHelper::RecordTaskSliceMetrics(base::TimeTicks now) {
+  UMA_HISTOGRAM_TIMES("RendererScheduler.TasksWithSafepoints.TaskSliceTime",
+                      now - current_task_slice_start_time_);
+}
+
+void MainThreadMetricsHelper::RecordMetricsForTasksWithSafepoints(
+    const base::sequence_manager::TaskQueue::TaskTiming& task_timing) {
+  if (safepoints_in_current_toplevel_task_count_ == 0)
+    return;
+
+  RecordTaskSliceMetrics(task_timing.end_time());
+
+  UMA_HISTOGRAM_CUSTOM_MICROSECONDS_TIMES(
+      "RendererScheduler.TasksWithSafepoints.TaskTime",
+      task_timing.wall_duration(), base::TimeDelta::FromMicroseconds(1),
+      base::TimeDelta::FromSeconds(1), 50);
+  UMA_HISTOGRAM_COUNTS_100(
+      "RendererScheduler.TasksWithSafepoints.SafepointCount",
+      safepoints_in_current_toplevel_task_count_);
+  safepoints_in_current_toplevel_task_count_ = 0;
+}
+
 void MainThreadMetricsHelper::RecordTaskMetrics(
     MainThreadTaskQueue* queue,
     const base::sequence_manager::Task& task,
@@ -476,7 +509,7 @@ void MainThreadMetricsHelper::RecordTaskMetrics(
                               frame_status, FrameStatus::kCount);
   }
 
-  if (main_thread_scheduler_->main_thread_only().has_safepoint) {
+  if (safepoints_in_current_toplevel_task_count_ > 0) {
     UMA_HISTOGRAM_ENUMERATION(COUNT_PER_FRAME_METRIC_NAME_WITH_SAFEPOINT,
                               frame_status, FrameStatus::kCount);
     if (duration >= base::TimeDelta::FromMilliseconds(16)) {
@@ -508,6 +541,7 @@ void MainThreadMetricsHelper::RecordTaskMetrics(
                                 ".LongerThan1s",
                                 frame_status, FrameStatus::kCount);
     }
+    RecordMetricsForTasksWithSafepoints(task_timing);
   }
 
   UseCase use_case =

third_party/blink/renderer/platform/scheduler/main_thread/main_thread_metrics_helper.h

@@ -49,11 +49,15 @@ class PLATFORM_EXPORT MainThreadMetricsHelper : public MetricsHelper {
       MainThreadTaskQueue* queue,
       const base::sequence_manager::Task& task,
       const base::sequence_manager::TaskQueue::TaskTiming& task_timing);
+  void RecordTaskSliceMetrics(base::TimeTicks now);
 
   void OnRendererForegrounded(base::TimeTicks now);
   void OnRendererBackgrounded(base::TimeTicks now);
   void OnRendererShutdown(base::TimeTicks now);
 
+  void OnSafepointEntered(base::TimeTicks now);
+  void OnSafepointExited(base::TimeTicks now);
+
   void RecordMainThreadTaskLoad(base::TimeTicks time, double load);
   void RecordForegroundMainThreadTaskLoad(base::TimeTicks time, double load);
   void RecordBackgroundMainThreadTaskLoad(base::TimeTicks time, double load);
@@ -67,6 +71,10 @@ class PLATFORM_EXPORT MainThreadMetricsHelper : public MetricsHelper {
 
   void ReportLowThreadLoadForPageAlmostIdleSignal(int load_percentage);
 
+  // Record metrics of only top-level tasks with safepoints.
+  void RecordMetricsForTasksWithSafepoints(
+      const base::sequence_manager::TaskQueue::TaskTiming& task_timing);
+
   MainThreadSchedulerImpl* main_thread_scheduler_;  // NOT OWNED
 
   // Set to true when OnRendererShutdown is called. Used to ensure that metrics
@@ -143,6 +151,13 @@ class PLATFORM_EXPORT MainThreadMetricsHelper : public MetricsHelper {
 
   MainThreadTaskLoadState main_thread_task_load_state_;
 
+  base::TimeTicks current_task_slice_start_time_;
+
+  // Number of safepoints during inside the current top-level tasks in which
+  // cooperative scheduling had a chance to run a task (as we don't necessarily
+  // run a task in each safepoint).
+  int safepoints_in_current_toplevel_task_count_;
+
   DISALLOW_COPY_AND_ASSIGN(MainThreadMetricsHelper);
 };
 

third_party/blink/renderer/platform/scheduler/main_thread/main_thread_metrics_helper_unittest.cc

@@ -546,5 +546,8 @@ TEST_F(MainThreadMetricsHelperTest, TaskCountPerFrameTypeLongerThan) {
 // TODO(crbug.com/754656): Add tests for non-TaskDuration
 // histograms.
 
+// TODO(crbug.com/754656): Add tests for
+// RendererScheduler.TasksWithSafepoints histograms.
+
 }  // namespace scheduler
 }  // namespace blink

third_party/blink/renderer/platform/scheduler/main_thread/main_thread_scheduler_impl.cc

@@ -473,8 +473,7 @@ MainThreadSchedulerImpl::MainThreadOnly::MainThreadOnly(
       virtual_time_stopped(false),
       nested_runloop(false),
       compositing_experiment(main_thread_scheduler_impl),
-      should_prioritize_compositing(false),
-      has_safepoint(false) {}
+      should_prioritize_compositing(false) {}
 
 MainThreadSchedulerImpl::MainThreadOnly::~MainThreadOnly() = default;
 
@@ -2394,7 +2393,6 @@ void MainThreadSchedulerImpl::OnTaskStarted(
   if (main_thread_only().nested_runloop)
     return;
 
-  main_thread_only().has_safepoint = false;
   main_thread_only().current_task_start_time = task_timing.start_time();
   main_thread_only().task_description_for_tracing = TaskDescriptionForTracing{
       static_cast<TaskType>(task.task_type),
@@ -2441,8 +2439,6 @@ void MainThreadSchedulerImpl::OnTaskCompleted(
   // TODO(altimin): Per-page metrics should also be considered.
   main_thread_only().metrics_helper.RecordTaskMetrics(queue.get(), task,
                                                       *task_timing);
-  main_thread_only().has_safepoint = false;
-
   main_thread_only().task_description_for_tracing = base::nullopt;
 
   // Unset the state of |task_priority_for_tracing|.
@@ -2713,9 +2709,16 @@ void MainThreadSchedulerImpl::SetShouldPrioritizeCompositing(
   UpdatePolicy();
 }
 
-void MainThreadSchedulerImpl::SetHasSafepoint() {
+void MainThreadSchedulerImpl::OnSafepointEntered() {
+  DCHECK(WTF::IsMainThread());
+  DCHECK(!main_thread_only().nested_runloop);
+  main_thread_only().metrics_helper.OnSafepointEntered(helper_.NowTicks());
+}
+
+void MainThreadSchedulerImpl::OnSafepointExited() {
   DCHECK(WTF::IsMainThread());
-  main_thread_only().has_safepoint = true;
+  DCHECK(!main_thread_only().nested_runloop);
+  main_thread_only().metrics_helper.OnSafepointExited(helper_.NowTicks());
 }
 
 void MainThreadSchedulerImpl::ExecuteAfterCurrentTask(

third_party/blink/renderer/platform/scheduler/main_thread/main_thread_scheduler_impl.h

@@ -589,7 +589,8 @@ class PLATFORM_EXPORT MainThreadSchedulerImpl
   void OnIdlePeriodStarted() override;
   void OnIdlePeriodEnded() override;
   void OnPendingTasksChanged(bool has_tasks) override;
-  void SetHasSafepoint() override;
+  void OnSafepointEntered() override;
+  void OnSafepointExited() override;
 
   void DispatchRequestBeginMainFrameNotExpected(bool has_tasks);
 
@@ -890,9 +891,6 @@ class PLATFORM_EXPORT MainThreadSchedulerImpl
     PrioritizeCompositingAfterInputExperiment compositing_experiment;
     bool should_prioritize_compositing;
 
-    // True if a task has a safepoint.
-    bool has_safepoint;
-
     // List of callbacks to execute after the current task.
     WTF::Vector<base::OnceClosure> on_task_completion_callbacks;
   };

third_party/blink/renderer/platform/scheduler/public/thread_scheduler.h

@@ -133,7 +133,8 @@ class PLATFORM_EXPORT ThreadScheduler {
   // Associates |isolate| to the scheduler.
   virtual void SetV8Isolate(v8::Isolate* isolate) = 0;
 
-  virtual void SetHasSafepoint() {}
+  virtual void OnSafepointEntered() {}
+  virtual void OnSafepointExited() {}
 
   // Test helpers.
 

tools/metrics/histograms/histograms.xml

@@ -105782,6 +105782,47 @@ uploading your change for review.
   </summary>
 </histogram>
 
+<histogram name="RendererScheduler.TasksWithSafepoints.SafepointCount"
+    units="count" expires_after="2020-04-01">
+  <owner>tasak@google.com</owner>
+  <owner>keishi@chromium.org</owner>
+  <summary>
+    Number of safepoints (defined by cooperative scheduling manager) inside a
+    single non-nested task executed on the main thread of a renderer process.
+    This is recorded when each non-nested task stops executing.
+  </summary>
+</histogram>
+
+<histogram name="RendererScheduler.TasksWithSafepoints.TaskSliceTime"
+    units="ms" expires_after="2020-04-01">
+  <owner>tasak@google.com</owner>
+  <owner>keishi@chromium.org</owner>
+  <summary>
+    The duration of every task slices. The non-nested task executed in main
+    thread of the renderer process scheduler is split into slices by the
+    safepoints defined by cooperative scheduling manager. This metrics doesn't
+    record the duration of task without any safepoints. This is recorded both
+    inside a safepoint and when the tasak finishes.
+
+    Note that this metric discards tasks longer than 30 seconds because they are
+    considered to be a result of measurement glitch.
+  </summary>
+</histogram>
+
+<histogram name="RendererScheduler.TasksWithSafepoints.TaskTime"
+    units="microseconds" expires_after="2020-04-01">
+  <owner>tasak@google.com</owner>
+  <owner>keishi@chromium.org</owner>
+  <summary>
+    The duration of every non-nested task executed in main thread of the
+    renderer process which has more than one safepoint. This is recorded when
+    the task finishes.
+
+    Note that this metric discards tasks longer than 30 seconds because they are
+    considered to be a result of measurement glitch.
+  </summary>
+</histogram>
+
 <histogram name="RendererScheduler.TaskTime" units="microseconds"
     expires_after="2017-05-23">
   <obsolete>