Creating a framework for suppressing pollution of the profiler data

base/tracked_objects.cc

Index: base/tracked_objects.cc
diff --git a/base/tracked_objects.cc b/base/tracked_objects.cc
index 56b44c10b2c389fbb053bee442769c0eda51941a..eff8b0718045dae1a5d47915af11feec8e7d46f0 100644
--- a/base/tracked_objects.cc
+++ b/base/tracked_objects.cc
@@ -269,7 +269,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 +280,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 +436,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;
@@ -481,8 +485,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 +495,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 +504,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 +536,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 +561,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
@@ -858,6 +852,99 @@ void ThreadData::ShutdownSingleThreadedCleanup(bool leak) {
 }
 
 //------------------------------------------------------------------------------
+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() {
 }