Creating a framework for suppressing pollution of the profiler data

base/tracked_objects.cc

 // Copyright (c) 2012 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 "base/tracked_objects.h"
 
 #include <limits.h>
 #include <stdlib.h>
 
 #include "base/atomicops.h"
@@ skipping 251 matching lines @@
 base::LazyInstance<base::Lock>::Leaky
     ThreadData::list_lock_ = LAZY_INSTANCE_INITIALIZER;
 
 // static
 ThreadData::Status ThreadData::status_ = ThreadData::UNINITIALIZED;
 
 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_.
 }
 
 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_.
 }
 
 ThreadData::~ThreadData() {}
 
 void ThreadData::PushToHeadOfList() {
   // Toss in a hint of randomness (atop the uniniitalized value).
   (void)VALGRIND_MAKE_MEM_DEFINED_IF_ADDRESSABLE(&random_number_,
@@ skipping 134 matching lines @@
       base::AutoLock lock(map_lock_);
       parent_child_set_.insert(pair);
     }
   }
 
   return child;
 }
 
 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;
   // An address is going to have some randomness to it as well ;-).
   random_number_ ^= static_cast<int32>(&birth - reinterpret_cast<Births*>(0));
 
   // 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_)
@@ skipping 26 matching lines @@
     return NULL;
   ThreadData* current_thread_data = Get();
   if (!current_thread_data)
     return NULL;
   return current_thread_data->TallyABirth(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.
 
   // Even if we have been DEACTIVATED, we will process any pending births so
   // that our data structures (which counted the outstanding births) remain
   // consistent.
   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;
 
   // Watch out for a race where status_ is changing, and hence one or both
   // of start_of_run or end_of_run is zero.  In that case, we didn't bother to
   // 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.
 
   // Even if we have been DEACTIVATED, we will process any pending births so
   // that our data structures (which counted the outstanding births) remain
   // consistent.
   if (!birth)
     return;
 
   // TODO(jar): Support the option to coalesce all worker-thread activity under
   // one ThreadData instance that uses locks to protect *all* access.  This will
   // reduce memory (making it provably bounded), but run incrementally slower
   // (since we'll use locks on TallyABirth and TallyADeath).  The good news is
   // that the locks on TallyADeath will be *after* the worker thread has run,
   // and hence nothing will be waiting for the completion (... besides some
   // 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.
 
   // Even if we have been DEACTIVATED, we will process any pending births so
   // that our data structures (which counted the outstanding births) remain
   // consistent.
   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
 void ThreadData::SnapshotAllExecutedTasks(bool reset_max,
                                           ProcessDataSnapshot* process_data,
                                           BirthCountMap* birth_counts) {
   if (!kTrackAllTaskObjects)
     return;  // Not compiled in.
 
   // Get an unchanging copy of a ThreadData list.
@@ skipping 265 matching lines @@
     thread_data_list = thread_data_list->next();
 
     for (BirthMap::iterator it = next_thread_data->birth_map_.begin();
          next_thread_data->birth_map_.end() != it; ++it)
       delete it->second;  // Delete the Birth Records.
     delete next_thread_data;  // Includes all Death Records.
   }
 }
 
 //------------------------------------------------------------------------------
+TaskStopwatch::TaskStopwatch()
+    : current_thread_data_(NULL),
+      nested_stopwatches_duration_ms_(0),
+      parent_stopwatch_(NULL) {
+#ifndef NDEBUG
+  state_ = CREATED;
+  running_child_ = NULL;
+#endif
+}
+
+TaskStopwatch::~TaskStopwatch() {
+#ifndef NDEBUG
+  DCHECK(state_ != RUNNING);

[jar (doing other things), 2014/08/26 04:09:09]

This is adding a lot of conditional test code, which makes reading the real code
more difficult.

[vadimt, 2014/08/26 19:15:04]

I believe it's still worth having this code, because:
(1) It actually helps understanding by giving an idea about the object state
transitions;
(2) Saves you from headaches by detecting issues earlier, just after you changed
the code.

+  DCHECK(running_child_ == NULL);
+#endif
+}
+
+void TaskStopwatch::Start(const TrackedTime& start_time) {
+#ifndef NDEBUG
+  DCHECK(state_ != RUNNING);
+  state_ = RUNNING;
+  DCHECK(running_child_ == NULL);
+#endif
+
+  nested_stopwatches_duration_ms_ = 0;
+  start_time_ = start_time;
+  wallclock_duration_ms_ = 0;
+  current_thread_data_ = ThreadData::Get();

[jar (doing other things), 2014/08/26 04:09:09]

This is a nice example of something that probably should have been done in the
constructor... no reason to keep asking (if we were to use this again!).  IMO,
almost all of this should be in the constructor, and you probably won't need a
Start() method.

[vadimt, 2014/08/26 19:15:04]

See my first answer about Start and Stop calls.
Note that reusability was just a side effect of that decision, not one of
primary goals.
But since the object is reusable, I can imagine that it could be used and reused
by a task runner on worked threads, and each time it would be another worker
thread. So, it's dangerous to get thread data in constructor.

+  if (current_thread_data_) {

[jar (doing other things), 2014/08/26 04:09:09]

nit: Personal preference: Earlier returns make code more readable.  Better may
be:

if (!current_thread_data_)
  return;

...and no need to indent the rest of the method.

[vadimt, 2014/08/26 19:15:04]

Done.

+    parent_stopwatch_ = current_thread_data_->current_stopwatch_;
+#ifndef NDEBUG
+    if (parent_stopwatch_) {
+      DCHECK(parent_stopwatch_->state_ == RUNNING);
+      DCHECK(parent_stopwatch_->running_child_ == NULL);
+      parent_stopwatch_->running_child_ = this;
+    }
+#endif
+    current_thread_data_->current_stopwatch_ = this;
+  }
+}
+
+void TaskStopwatch::Stop(const TrackedTime& end_time) {
+#ifndef NDEBUG
+  DCHECK(state_ == RUNNING);
+  state_ = STOPPED;
+  DCHECK(running_child_ == NULL);
+#endif
+
+  if (!start_time_.is_null() && !end_time.is_null()) {
+    wallclock_duration_ms_ = (end_time - start_time_).InMilliseconds();
+  }
+
+  if (current_thread_data_) {

[jar (doing other things), 2014/08/26 04:09:09]

nit: early return is probably cleaner.

[vadimt, 2014/08/26 19:15:04]

Done.

+    DCHECK(current_thread_data_->current_stopwatch_ == this);
+    current_thread_data_->current_stopwatch_ = parent_stopwatch_;
+
+    if (parent_stopwatch_) {

[jar (doing other things), 2014/08/26 04:09:09]

nit: early return again.

[vadimt, 2014/08/26 19:15:04]

Done.

+#ifndef NDEBUG
+      DCHECK(parent_stopwatch_->state_ == RUNNING);
+      DCHECK(parent_stopwatch_->running_child_ == this);
+      parent_stopwatch_->running_child_ = NULL;
+#endif
+      parent_stopwatch_->nested_stopwatches_duration_ms_ +=
+          wallclock_duration_ms_;

[jar (doing other things), 2014/08/26 04:09:09]

I'm pretty sure this is the correct way to calculate the sum... as it
accumulates all nested stopwatches (via wallclock duration), rather the the
header comment's note about only immediate nested stop watches being excluded.

[vadimt, 2014/08/26 19:15:04]

This code calculates as described in the header, i.e. only immediately nested
message loops and nested tasks are excluded. parent_stopwatch is our immediate
parent, and we don't go to a grandparent.

Example:
Task A ran 10 ms
Task B is nested in A, and ran 8 ms
Task C is nested in B, and ran 6 ms

Task B is immediately nested in A, and C is nested in A, but not immediately.

We subtract only B from A, leaving A with 2 ms. If we subtracted both B and C,
we'd end up with negative -4 ms.

+      parent_stopwatch_ = NULL;
+    }
+  }
+}
+
+TrackedTime TaskStopwatch::StartTime() const {
+#ifndef NDEBUG
+  DCHECK(state_ != CREATED);
+#endif
+  return start_time_;
+}
+
+int32 TaskStopwatch::RunDurationMs() const {
+#ifndef NDEBUG
+  DCHECK(state_ == STOPPED);
+#endif
+
+  return wallclock_duration_ms_ - nested_stopwatches_duration_ms_;

[jar (doing other things), 2014/08/26 04:09:09]

This is the more common (by far) use of wallclock_duration_ms.  As a result, it
is probably better to calculate it here, when needed, than it is to store it
away hoping it will be used again (super rare case).  If it is needed, then it
can be recalculated.  You might have a tiny local function that does this... or
a private method... and hope the compiler inlines it.

[vadimt, 2014/08/26 19:15:04]

Note that we don't store end time, so by eliminating this member, we'd have to
introduce another one. What is the motivation behind this?

+}
+
+ThreadData * TaskStopwatch::GetThreadData() const {
+#ifndef NDEBUG
+  DCHECK(state_ != CREATED);
+#endif
+
+  return current_thread_data_;
+}
+
+//------------------------------------------------------------------------------
 TaskSnapshot::TaskSnapshot() {
 }
 
 TaskSnapshot::TaskSnapshot(const BirthOnThread& birth,
                            const DeathData& death_data,
                            const std::string& death_thread_name)
     : birth(birth),
       death_data(death_data),
       death_thread_name(death_thread_name) {
 }
@@ skipping 24 matching lines @@
     : process_id(base::GetCurrentProcId()) {
 #else
     : process_id(0) {
 #endif
 }
 
 ProcessDataSnapshot::~ProcessDataSnapshot() {
 }
 
 }  // namespace tracked_objects