Long tasks: add a trace event for long tasks

third_party/WebKit/Source/platform/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 "platform/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 "platform/scheduler/base/real_time_domain.h"
 #include "platform/scheduler/base/task_queue_impl.h"
 #include "platform/scheduler/base/task_queue_manager_delegate.h"
 #include "platform/scheduler/base/task_queue_selector.h"
 #include "platform/scheduler/base/task_time_observer.h"
 #include "platform/scheduler/base/work_queue.h"
 #include "platform/scheduler/base/work_queue_sets.h"
 
+static const double kLongTaskTraceEventThreshold = 0.05;
+
 namespace blink {
 namespace scheduler {
 
 namespace {
 const size_t kRecordRecordTaskDelayHistogramsEveryNTasks = 10;
 
 void RecordDelayedTaskLateness(base::TimeDelta lateness) {
   UMA_HISTOGRAM_TIMES("RendererScheduler.TaskQueueManager.DelayedTaskLateness",
                       lateness);
 }
@@ skipping 498 matching lines @@
       currently_executing_task_queue_;
   currently_executing_task_queue_ = queue;
   task_annotator_.RunTask("TaskQueueManager::PostTask", &pending_task);
   // Detect if the TaskQueueManager just got deleted.  If this happens we must
   // not access any member variables after this point.
   if (protect->HasOneRef())
     return ProcessTaskResult::TASK_QUEUE_MANAGER_DELETED;
 
   currently_executing_task_queue_ = prev_executing_task_queue;
 
-
+  double task_end_time = 0;
   if (queue->GetShouldNotifyObservers()) {
     if (task_start_time) {
       *time_after_task = real_time_domain()->Now();
-      double task_end_time = MonotonicTimeInSeconds(*time_after_task);
+      task_end_time = MonotonicTimeInSeconds(*time_after_task);
       for (auto& observer : task_time_observers_)
         observer.DidProcessTask(queue, task_start_time, task_end_time);
     }
 
     for (auto& observer : task_observers_)
       observer.DidProcessTask(pending_task);
     queue->NotifyDidProcessTask(pending_task);
   }
 
+  if (task_start_time && task_end_time &&
+      task_end_time - task_start_time > kLongTaskTraceEventThreshold) {
+    TRACE_EVENT2("blink", "LongTask", "start_time", task_start_time, "end_time",

[altimin, 2017/07/07 18:24:17]

This will be shown in the UI as an extremely short event. This seems rather odd
and counterintuitive.

+primiano@ as a tracing owner — do we have better mechanisms that this?

[caseq, 2017/07/07 18:54:44]

+1 to this, I don't think it makes sense in the present form. One way to address
this would be to just emit an instant event, then use custom logic in the UI to
render the existing top-level event differently. Or, better, don't emit anything
at all and just have the logic entirely on the client side -- we already have
trace events for all tasks anyway.

[Liquan (Max) Gu, 2017/07/07 20:01:25]

I have changed to emit an instant event. 

From the issue description, it intends to surface this signal to devtools as
well. If it's implemented on the client side, can it be surfaced to devtools.?

+                 task_end_time);
+  }
+
   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 queuing durations.
@@ skipping 141 matching lines @@
   for (const scoped_refptr<internal::TaskQueueImpl>& queue : queues_) {
     TimeDomain* time_domain = queue->GetTimeDomain();
     if (time_domain_now.find(time_domain) == time_domain_now.end())
       time_domain_now.insert(std::make_pair(time_domain, time_domain->Now()));
     queue->SweepCanceledDelayedTasks(time_domain_now[time_domain]);
   }
 }
 
 }  // namespace scheduler
 }  // namespace blink