Creating a framework for suppressing pollution of the profiler data and...

Creating a framework for suppressing pollution of the profiler data and applying for know cases of pollution.
See the bug.

The CL introduces TaskStopwatch that has to be used to measure run time for tasks. It takes care of double-counting
run time in the nested-tasks case by subtracting run time of nested tasks from their parents. TaskStopwatch can be
also used for subtracting other nested intervals, such as the time while a nested message pump runs. ThreadData::TallyADeath
now takes a stopwatch parameter instead of start_time and end_time. This helps avoid mistakes when the interval passed up to
the parent for exclusion is different from the interval for the current task duration.

BUG=401560

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

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

base/debug/task_annotator.cc

@@ -28,10 +28,10 @@ void TaskAnnotator::DidQueueTask(const char* queue_function,
 void TaskAnnotator::RunTask(const char* queue_function,
                             const char* run_function,
                             const PendingTask& pending_task) {
-  tracked_objects::TrackedTime start_time =
-      tracked_objects::ThreadData::NowForStartOfRun(pending_task.birth_tally);
+  tracked_objects::ThreadData::PrepareForStartOfRun(pending_task.birth_tally);
+  tracked_objects::TaskStopwatch stopwatch;
   tracked_objects::Duration queue_duration =
-      start_time - pending_task.EffectiveTimePosted();
+      stopwatch.StartTime() - pending_task.EffectiveTimePosted();
 
   TRACE_EVENT_FLOW_END1(TRACE_DISABLED_BY_DEFAULT("toplevel.flow"),
                         queue_function,
@@ -61,8 +61,9 @@ void TaskAnnotator::RunTask(const char* queue_function,
 
   pending_task.task.Run();
 
+  stopwatch.Stop();
   tracked_objects::ThreadData::TallyRunOnNamedThreadIfTracking(
-      pending_task, start_time, tracked_objects::ThreadData::NowForEndOfRun());
+      pending_task, stopwatch);
 }
 
 uint64 TaskAnnotator::GetTaskTraceID(const PendingTask& task) const {

base/profiler/scoped_profile.cc

@@ -12,8 +12,8 @@ namespace tracked_objects {
 
 
 ScopedProfile::ScopedProfile(const Location& location)
-    : birth_(ThreadData::TallyABirthIfActive(location)),
-      start_of_run_(ThreadData::NowForStartOfRun(birth_)) {
+    : birth_(ThreadData::TallyABirthIfActive(location)) {
+  ThreadData::PrepareForStartOfRun(birth_);
 }
 
 ScopedProfile::~ScopedProfile() {
@@ -21,10 +21,11 @@ ScopedProfile::~ScopedProfile() {
 }
 
 void ScopedProfile::StopClockAndTally() {
+  stopwatch_.Stop();
+
   if (!birth_)
     return;
-  ThreadData::TallyRunInAScopedRegionIfTracking(birth_, start_of_run_,
-                                                ThreadData::NowForEndOfRun());
+  ThreadData::TallyRunInAScopedRegionIfTracking(birth_, stopwatch_);
   birth_ = NULL;
 }
 

base/profiler/scoped_profile.h

@@ -15,6 +15,7 @@
 #include "base/base_export.h"
 #include "base/location.h"
 #include "base/profiler/tracked_time.h"
+#include "base/tracked_objects.h"
 
 #if defined(GOOGLE_CHROME_BUILD)
 
@@ -57,7 +58,7 @@ class BASE_EXPORT ScopedProfile {
 
  private:
   Births* birth_;  // Place in code where tracking started.
-  const TrackedTime start_of_run_;
+  TaskStopwatch stopwatch_;
 
   DISALLOW_COPY_AND_ASSIGN(ScopedProfile);
 };

base/profiler/tracked_time_unittest.cc

@@ -75,10 +75,6 @@ TEST(TrackedTimeTest, TrackedTimerDisabled) {
   // Since we disabled tracking, we should get a null response.
   TrackedTime track_now = ThreadData::Now();
   EXPECT_TRUE(track_now.is_null());
-  track_now = ThreadData::NowForStartOfRun(NULL);
-  EXPECT_TRUE(track_now.is_null());
-  track_now = ThreadData::NowForEndOfRun();
-  EXPECT_TRUE(track_now.is_null());
 }
 
 TEST(TrackedTimeTest, TrackedTimerEnabled) {

base/run_loop.cc

@@ -5,6 +5,7 @@
 #include "base/run_loop.h"
 
 #include "base/bind.h"
+#include "base/tracked_objects.h"
 
 #if defined(OS_WIN)
 #include "base/message_loop/message_pump_dispatcher.h"
@@ -46,7 +47,13 @@ RunLoop::~RunLoop() {
 void RunLoop::Run() {
   if (!BeforeRun())
     return;
+
+  // Use task stopwatch to exclude the loop run time from the current task, if
+  // any.
+  tracked_objects::TaskStopwatch stopwatch;
   loop_->RunHandler();
+  stopwatch.Stop();
+
   AfterRun();
 }
 

base/threading/sequenced_worker_pool.cc

@@ -755,13 +755,13 @@ void SequencedWorkerPool::Inner::ThreadLoop(Worker* this_worker) {
           this_worker->set_running_task_info(
               SequenceToken(task.sequence_token_id), task.shutdown_behavior);
 
-          tracked_objects::TrackedTime start_time =
-              tracked_objects::ThreadData::NowForStartOfRun(task.birth_tally);
-
+          tracked_objects::ThreadData::PrepareForStartOfRun(task.birth_tally);
+          tracked_objects::TaskStopwatch stopwatch;
           task.task.Run();
+          stopwatch.Stop();
 
-          tracked_objects::ThreadData::TallyRunOnNamedThreadIfTracking(task,
-              start_time, tracked_objects::ThreadData::NowForEndOfRun());
+          tracked_objects::ThreadData::TallyRunOnNamedThreadIfTracking(
+              task, stopwatch);
 
           // Make sure our task is erased outside the lock for the
           // same reason we do this with delete_these_oustide_lock.

base/threading/worker_pool_posix.cc

@@ -95,14 +95,14 @@ void WorkerThread::ThreadMain() {
         "src_file", pending_task.posted_from.file_name(),
         "src_func", pending_task.posted_from.function_name());
 
-    TrackedTime start_time =
-        tracked_objects::ThreadData::NowForStartOfRun(pending_task.birth_tally);
-
+    tracked_objects::ThreadData::PrepareForStartOfRun(pending_task.birth_tally);
+    tracked_objects::TaskStopwatch stopwatch;
     pending_task.task.Run();
+    stopwatch.Stop();
 
     tracked_objects::ThreadData::TallyRunOnWorkerThreadIfTracking(
         pending_task.birth_tally, TrackedTime(pending_task.time_posted),
-        start_time, tracked_objects::ThreadData::NowForEndOfRun());
+        stopwatch);
   }
 
   // The WorkerThread is non-joinable, so it deletes itself.

base/threading/worker_pool_win.cc

@@ -25,17 +25,20 @@ DWORD CALLBACK WorkItemCallback(void* param) {
                "src_file", pending_task->posted_from.file_name(),
                "src_func", pending_task->posted_from.function_name());
 
-  tracked_objects::TrackedTime start_time =
-      tracked_objects::ThreadData::NowForStartOfRun(pending_task->birth_tally);
+  tracked_objects::ThreadData::PrepareForStartOfRun(pending_task->birth_tally);
 
   g_worker_pool_running_on_this_thread.Get().Set(true);
+
+  tracked_objects::TaskStopwatch stopwatch;
   pending_task->task.Run();
+  stopwatch.Stop();
+
   g_worker_pool_running_on_this_thread.Get().Set(false);
 
   tracked_objects::ThreadData::TallyRunOnWorkerThreadIfTracking(
       pending_task->birth_tally,
-      tracked_objects::TrackedTime(pending_task->time_posted), start_time,
-      tracked_objects::ThreadData::NowForEndOfRun());
+      tracked_objects::TrackedTime(pending_task->time_posted),
+      stopwatch);
 
   delete pending_task;
   return 0;

base/tracked_objects.cc

@@ -237,6 +237,9 @@ void Births::Clear() { birth_count_ = 0; }
 // static
 NowFunction* ThreadData::now_function_ = NULL;
 
+// static
+bool ThreadData::now_function_is_time_ = false;
+
 // A TLS slot which points to the ThreadData instance for the current thread. We
 // do a fake initialization here (zeroing out data), and then the real in-place
 // construction happens when we call tls_index_.Initialize().
@@ -269,7 +272,8 @@ ThreadData::ThreadData(const std::string& suggested_name)
     : next_(NULL),
       next_retired_worker_(NULL),
       worker_thread_number_(0),
-      incarnation_count_for_pool_(-1) {
+      incarnation_count_for_pool_(-1),
+      current_stopwatch_(NULL) {
   DCHECK_GE(suggested_name.size(), 0u);
   thread_name_ = suggested_name;
   PushToHeadOfList();  // Which sets real incarnation_count_for_pool_.
@@ -279,7 +283,8 @@ ThreadData::ThreadData(int thread_number)
     : next_(NULL),
       next_retired_worker_(NULL),
       worker_thread_number_(thread_number),
-      incarnation_count_for_pool_(-1)  {
+      incarnation_count_for_pool_(-1),
+      current_stopwatch_(NULL) {
   CHECK_GT(thread_number, 0);
   base::StringAppendF(&thread_name_, "WorkerThread-%d", thread_number);
   PushToHeadOfList();  // Which sets real incarnation_count_for_pool_.
@@ -434,7 +439,9 @@ Births* ThreadData::TallyABirth(const Location& location) {
 
 void ThreadData::TallyADeath(const Births& birth,
                              int32 queue_duration,
-                             int32 run_duration) {
+                             const TaskStopwatch& stopwatch) {
+  int32 run_duration = stopwatch.RunDurationMs();
+
   // Stir in some randomness, plus add constant in case durations are zero.
   const int32 kSomePrimeNumber = 2147483647;
   random_number_ += queue_duration + run_duration + kSomePrimeNumber;
@@ -443,9 +450,13 @@ void ThreadData::TallyADeath(const Births& birth,
 
   // We don't have queue durations without OS timer. OS timer is automatically
   // used for task-post-timing, so the use of an alternate timer implies all
-  // queue times are invalid.
-  if (kAllowAlternateTimeSourceHandling && now_function_)
+  // queue times are invalid, unless it was explicitly said that we can trust
+  // the alternate timer.
+  if (kAllowAlternateTimeSourceHandling &&
+      now_function_ &&
+      !now_function_is_time_) {
     queue_duration = 0;
+  }
 
   DeathMap::iterator it = death_map_.find(&birth);
   DeathData* death_data;
@@ -481,8 +492,7 @@ Births* ThreadData::TallyABirthIfActive(const Location& location) {
 // static
 void ThreadData::TallyRunOnNamedThreadIfTracking(
     const base::TrackingInfo& completed_task,
-    const TrackedTime& start_of_run,
-    const TrackedTime& end_of_run) {
+    const TaskStopwatch& stopwatch) {
   if (!kTrackAllTaskObjects)
     return;  // Not compiled in.
 
@@ -492,7 +502,7 @@ void ThreadData::TallyRunOnNamedThreadIfTracking(
   const Births* birth = completed_task.birth_tally;
   if (!birth)
     return;
-  ThreadData* current_thread_data = Get();
+  ThreadData* current_thread_data = stopwatch.GetThreadData();
   if (!current_thread_data)
     return;
 
@@ -501,23 +511,20 @@ void ThreadData::TallyRunOnNamedThreadIfTracking(
   // get a time value since we "weren't tracking" and we were trying to be
   // efficient by not calling for a genuine time value. For simplicity, we'll
   // use a default zero duration when we can't calculate a true value.
+  TrackedTime start_of_run = stopwatch.StartTime();
   int32 queue_duration = 0;
-  int32 run_duration = 0;
   if (!start_of_run.is_null()) {
     queue_duration = (start_of_run - completed_task.EffectiveTimePosted())
         .InMilliseconds();
-    if (!end_of_run.is_null())
-      run_duration = (end_of_run - start_of_run).InMilliseconds();
   }
-  current_thread_data->TallyADeath(*birth, queue_duration, run_duration);
+  current_thread_data->TallyADeath(*birth, queue_duration, stopwatch);
 }
 
 // static
 void ThreadData::TallyRunOnWorkerThreadIfTracking(
     const Births* birth,
     const TrackedTime& time_posted,
-    const TrackedTime& start_of_run,
-    const TrackedTime& end_of_run) {
+    const TaskStopwatch& stopwatch) {
   if (!kTrackAllTaskObjects)
     return;  // Not compiled in.
 
@@ -536,25 +543,22 @@ void ThreadData::TallyRunOnWorkerThreadIfTracking(
   // other thread that might like to run).  Also, the worker threads tasks are
   // generally longer, and hence the cost of the lock may perchance be amortized
   // over the long task's lifetime.
-  ThreadData* current_thread_data = Get();
+  ThreadData* current_thread_data = stopwatch.GetThreadData();
   if (!current_thread_data)
     return;
 
+  TrackedTime start_of_run = stopwatch.StartTime();
   int32 queue_duration = 0;
-  int32 run_duration = 0;
   if (!start_of_run.is_null()) {
     queue_duration = (start_of_run - time_posted).InMilliseconds();
-    if (!end_of_run.is_null())
-      run_duration = (end_of_run - start_of_run).InMilliseconds();
   }
-  current_thread_data->TallyADeath(*birth, queue_duration, run_duration);
+  current_thread_data->TallyADeath(*birth, queue_duration, stopwatch);
 }
 
 // static
 void ThreadData::TallyRunInAScopedRegionIfTracking(
     const Births* birth,
-    const TrackedTime& start_of_run,
-    const TrackedTime& end_of_run) {
+    const TaskStopwatch& stopwatch) {
   if (!kTrackAllTaskObjects)
     return;  // Not compiled in.
 
@@ -564,15 +568,12 @@ void ThreadData::TallyRunInAScopedRegionIfTracking(
   if (!birth)
     return;
 
-  ThreadData* current_thread_data = Get();
+  ThreadData* current_thread_data = stopwatch.GetThreadData();
   if (!current_thread_data)
     return;
 
   int32 queue_duration = 0;
-  int32 run_duration = 0;
-  if (!start_of_run.is_null() && !end_of_run.is_null())
-    run_duration = (end_of_run - start_of_run).InMilliseconds();
-  current_thread_data->TallyADeath(*birth, queue_duration, run_duration);
+  current_thread_data->TallyADeath(*birth, queue_duration, stopwatch);
 }
 
 // static
@@ -758,18 +759,12 @@ bool ThreadData::TrackingParentChildStatus() {
 }
 
 // static
-TrackedTime ThreadData::NowForStartOfRun(const Births* parent) {
+void ThreadData::PrepareForStartOfRun(const Births* parent) {
   if (kTrackParentChildLinks && parent && status_ > PROFILING_ACTIVE) {
     ThreadData* current_thread_data = Get();
     if (current_thread_data)
       current_thread_data->parent_stack_.push(parent);
   }
-  return Now();
-}
-
-// static
-TrackedTime ThreadData::NowForEndOfRun() {
-  return Now();
 }
 
 // static
@@ -857,6 +852,85 @@ void ThreadData::ShutdownSingleThreadedCleanup(bool leak) {
   }
 }
 
+//------------------------------------------------------------------------------
+TaskStopwatch::TaskStopwatch()
+    : start_time_(ThreadData::Now()),
+      current_thread_data_(ThreadData::Get()),
+      excluded_duration_ms_(0),
+      parent_(NULL) {
+#if DCHECK_IS_ON
+  state_ = RUNNING;
+  child_ = NULL;
+#endif
+
+  wallclock_duration_ms_ = 0;
+  if (!current_thread_data_)
+    return;
+
+  parent_ = current_thread_data_->current_stopwatch_;
+#if DCHECK_IS_ON
+  if (parent_) {
+    DCHECK(parent_->state_ == RUNNING);
+    DCHECK(parent_->child_ == NULL);
+    parent_->child_ = this;
+  }
+#endif
+  current_thread_data_->current_stopwatch_ = this;
+}
+
+TaskStopwatch::~TaskStopwatch() {
+#if DCHECK_IS_ON
+  DCHECK(state_ != RUNNING);
+  DCHECK(child_ == NULL);
+#endif
+}
+
+void TaskStopwatch::Stop() {
+  const TrackedTime end_time = ThreadData::Now();
+#if DCHECK_IS_ON
+  DCHECK(state_ == RUNNING);
+  state_ = STOPPED;
+  DCHECK(child_ == NULL);
+#endif
+
+  if (!start_time_.is_null() && !end_time.is_null()) {
+    wallclock_duration_ms_ = (end_time - start_time_).InMilliseconds();
+  }
+
+  if (!current_thread_data_)
+    return;
+
+  DCHECK(current_thread_data_->current_stopwatch_ == this);
+  current_thread_data_->current_stopwatch_ = parent_;
+  if (!parent_)
+    return;
+
+#if DCHECK_IS_ON
+  DCHECK(parent_->state_ == RUNNING);
+  DCHECK(parent_->child_ == this);
+  parent_->child_ = NULL;
+#endif
+  parent_->excluded_duration_ms_ +=
+      wallclock_duration_ms_;
+  parent_ = NULL;
+}
+
+TrackedTime TaskStopwatch::StartTime() const {
+  return start_time_;
+}
+
+int32 TaskStopwatch::RunDurationMs() const {
+#if DCHECK_IS_ON
+  DCHECK(state_ == STOPPED);
+#endif
+
+  return wallclock_duration_ms_ - excluded_duration_ms_;
+}
+
+ThreadData* TaskStopwatch::GetThreadData() const {
+  return current_thread_data_;
+}
+
 //------------------------------------------------------------------------------
 TaskSnapshot::TaskSnapshot() {
 }

base/tracked_objects.h

@@ -352,6 +352,8 @@ struct BASE_EXPORT TaskSnapshot {
 // harvest data from all existing instances.
 
 struct ProcessDataSnapshot;
+class BASE_EXPORT TaskStopwatch;
+
 class BASE_EXPORT ThreadData {
  public:
   // Current allowable states of the tracking system.  The states can vary
@@ -403,8 +405,7 @@ class BASE_EXPORT ThreadData {
   // finished). It is provided as an argument to help with testing.
   static void TallyRunOnNamedThreadIfTracking(
       const base::TrackingInfo& completed_task,
-      const TrackedTime& start_of_run,
-      const TrackedTime& end_of_run);
+      const TaskStopwatch& stopwatch);
 
   // Record the end of a timed run of an object.  The |birth| is the record for
   // the instance, the |time_posted| records that instant, which is presumed to
@@ -416,15 +417,13 @@ class BASE_EXPORT ThreadData {
   static void TallyRunOnWorkerThreadIfTracking(
       const Births* birth,
       const TrackedTime& time_posted,
-      const TrackedTime& start_of_run,
-      const TrackedTime& end_of_run);
+      const TaskStopwatch& stopwatch);
 
   // Record the end of execution in region, generally corresponding to a scope
   // being exited.
   static void TallyRunInAScopedRegionIfTracking(
       const Births* birth,
-      const TrackedTime& start_of_run,
-      const TrackedTime& end_of_run);
+      const TaskStopwatch& stopwatch);
 
   const std::string& thread_name() const { return thread_name_; }
 
@@ -460,14 +459,12 @@ class BASE_EXPORT ThreadData {
   // on.  This is currently a compiled option, atop TrackingStatus().
   static bool TrackingParentChildStatus();
 
-  // Special versions of Now() for getting times at start and end of a tracked
-  // run.  They are super fast when tracking is disabled, and have some internal
-  // side effects when we are tracking, so that we can deduce the amount of time
-  // accumulated outside of execution of tracked runs.
+  // Marks a start of a tracked run. It's super fast when tracking is disabled,
+  // and has some internal side effects when we are tracking, so that we can
+  // deduce the amount of time accumulated outside of execution of tracked runs.
   // The task that will be tracked is passed in as |parent| so that parent-child
   // relationships can be (optionally) calculated.
-  static TrackedTime NowForStartOfRun(const Births* parent);
-  static TrackedTime NowForEndOfRun();
+  static void PrepareForStartOfRun(const Births* parent);
 
   // Provide a time function that does nothing (runs fast) when we don't have
   // the profiler enabled.  It will generally be optimized away when it is
@@ -487,6 +484,7 @@ class BASE_EXPORT ThreadData {
   static void EnsureCleanupWasCalled(int major_threads_shutdown_count);
 
  private:
+  friend class TaskStopwatch;
   // Allow only tests to call ShutdownSingleThreadedCleanup.  We NEVER call it
   // in production code.
   // TODO(jar): Make this a friend in DEBUG only, so that the optimizer has a
@@ -523,7 +521,9 @@ class BASE_EXPORT ThreadData {
   Births* TallyABirth(const Location& location);
 
   // Find a place to record a death on this thread.
-  void TallyADeath(const Births& birth, int32 queue_duration, int32 duration);
+  void TallyADeath(const Births& birth,
+                   int32 queue_duration,
+                   const TaskStopwatch& stopwatch);
 
   // Snapshot (under a lock) the profiled data for the tasks in each ThreadData
   // instance.  Also updates the |birth_counts| tally for each task to keep
@@ -582,6 +582,10 @@ class BASE_EXPORT ThreadData {
   // increasing time functcion.
   static NowFunction* now_function_;
 
+  // If true, now_function_ returns values that can be used to calculate queue
+  // time.
+  static bool now_function_is_time_;
+
   // We use thread local store to identify which ThreadData to interact with.
   static base::ThreadLocalStorage::StaticSlot tls_index_;
 
@@ -665,9 +669,9 @@ class BASE_EXPORT ThreadData {
   mutable base::Lock map_lock_;
 
   // The stack of parents that are currently being profiled. This includes only
-  // tasks that have started a timer recently via NowForStartOfRun(), but not
-  // yet concluded with a NowForEndOfRun().  Usually this stack is one deep, but
-  // if a scoped region is profiled, or <sigh> a task runs a nested-message
+  // tasks that have started a timer recently via PrepareForStartOfRun(), but
+  // not yet concluded with a NowForEndOfRun().  Usually this stack is one deep,
+  // but if a scoped region is profiled, or <sigh> a task runs a nested-message
   // loop, then the stack can grow larger.  Note that we don't try to deduct
   // time in nested porfiles, as our current timer is based on wall-clock time,
   // and not CPU time (and we're hopeful that nested timing won't be a
@@ -686,9 +690,73 @@ class BASE_EXPORT ThreadData {
   // incarnations).
   int incarnation_count_for_pool_;
 
+  // Most recently started (i.e. most nested) stopwatch on the current thread,
+  // if it exists; NULL otherwise.
+  TaskStopwatch* current_stopwatch_;
+
   DISALLOW_COPY_AND_ASSIGN(ThreadData);
 };
 
+//------------------------------------------------------------------------------
+// Stopwatch to measure task run time or simply create a time interval that will
+// be subtracted from the current most nested task's run time. Stopwatches
+// coordinate with the stopwatches in which they are nested to avoid
+// double-counting nested tasks run times.
+
+class BASE_EXPORT TaskStopwatch {
+ public:
+  // Starts the stopwatch.
+  TaskStopwatch();
+  ~TaskStopwatch();
+
+  // Stops stopwatch.
+  void Stop();
+
+  // Returns the start time.
+  TrackedTime StartTime() const;
+
+  // Task's duration is calculated as the wallclock duration between starting
+  // and stopping this stopwatch, minus the wallclock durations of any other
+  // instances that are immediately nested in this one, started and stopped on
+  // this thread during that period.
+  int32 RunDurationMs() const;
+
+  // Returns tracking info for the current thread.
+  ThreadData* GetThreadData() const;
+
+ private:
+  // Time when the stopwatch was started.
+  TrackedTime start_time_;
+
+  // Wallclock duration of the task.
+  int32 wallclock_duration_ms_;
+
+  // Tracking info for the current thread.
+  ThreadData* current_thread_data_;
+
+  // Sum of wallclock durations of all stopwatches that were directly nested in
+  // this one.
+  int32 excluded_duration_ms_;
+
+  // Stopwatch which was running on our thread when this stopwatch was started.
+  // That preexisting stopwatch must be adjusted to the exclude the wallclock
+  // duration of this stopwatch.
+  TaskStopwatch* parent_;
+
+#if DCHECK_IS_ON
+  // State of the stopwatch. Stopwatch is first constructed in a running state,
+  // then stopped, then destructed.
+  enum {
+    RUNNING,
+    STOPPED
+  } state_;
+
+  // Currently running stopwatch that is directly nested in this one, if such
+  // stopwatch exists. NULL otherwise.
+  TaskStopwatch* child_;
+#endif
+};
+
 //------------------------------------------------------------------------------
 // A snapshotted representation of a (parent, child) task pair, for tracking
 // hierarchical profiles.

content/browser/gpu/browser_gpu_channel_host_factory.cc

@@ -8,6 +8,7 @@
 #include "base/debug/trace_event.h"
 #include "base/synchronization/waitable_event.h"
 #include "base/threading/thread_restrictions.h"
+#include "base/tracked_objects.h"
 #include "content/browser/gpu/gpu_data_manager_impl.h"
 #include "content/browser/gpu/gpu_memory_buffer_factory_host_impl.h"
 #include "content/browser/gpu/gpu_process_host.h"
@@ -196,6 +197,11 @@ void BrowserGpuChannelHostFactory::EstablishRequest::FinishOnMain() {
 void BrowserGpuChannelHostFactory::EstablishRequest::Wait() {
   DCHECK(main_loop_->BelongsToCurrentThread());
   {
+    // Since the current task synchronously waits for establishing a GPU
+    // channel, it shouldn't be tallied because its execution time has nothing
+    // to do with its efficiency. Using task stopwatch to exclude the waiting
+    // time from the current task run time.
+    tracked_objects::TaskStopwatch stopwatch;
     // We're blocking the UI thread, which is generally undesirable.
     // In this case we need to wait for this before we can show any UI
     // /anyway/, so it won't cause additional jank.
@@ -204,6 +210,8 @@ void BrowserGpuChannelHostFactory::EstablishRequest::Wait() {
                  "BrowserGpuChannelHostFactory::EstablishGpuChannelSync");
     base::ThreadRestrictions::ScopedAllowWait allow_wait;
     event_.Wait();
+
+    stopwatch.Stop();
   }
   FinishOnMain();
 }