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..ea0d2ae1f653941879062ea91eb51f42b5f8ee0b 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.TaskDurationMs();

[jar (doing other things), 2014/08/08 01:34:48]

I don't think "run_duration" is always milliseconds.  I think it is sometimes
time, but sometimes allocation, so the word "duration" is probably better.

[vadimt, 2014/08/08 20:39:34]

Not sure I dotally got it. So, I'm listing some facts, hoping that they somehow
addres your concerns.

(1) in the old code, run_duration was always milliseconds, because it was always
a result of calculation like this:
run_duration = (end_of_run - start_of_run).InMilliseconds();

(2) I try including units in identifiers, since this reduce chance of mistakes.

(3) I'll rename TaskDurationMs to RunDurationMs for consistency.

(4) Are you suggesting renaming run_duration to duration? But in the old code,
the parameter was named run_duration, and I keep the name and semantics. Again,
probably I din't get it...

+
   // 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.
 
@@ -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.
 
@@ -540,21 +540,18 @@ void ThreadData::TallyRunOnWorkerThreadIfTracking(
   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())

[jar (doing other things), 2014/08/08 01:34:48]

There seems to be a bunch of code dealing with the case where the end_of_run is
null, just as there is code worrying about the start_of_run being null.  I don't
recall the scenarios where this happens (and maybe it doesn't anymore??), but I
suspect it was put there carefully (by me).

For instance, it may have to do with scenarios where the profiler is not
initialized sufficiently, including the setting of the time-source, when the
first tasks are run.  That could cause some of the durations to be nulled out,
and meaningless.

[vadimt, 2014/08/08 20:39:34]

I preserved all nullness checks:
(1) You can see them preserved here, for 'queue_duration' calculations.

(2) Checks for the run duration moved to TaskStopwatch::Stop():
  if (!start_time_.is_null() && !end_time.is_null()) {
    wallclock_duration_ms_ = (end_time - start_time_).InMilliseconds();
  }
(wallclock_duration_ms_ os 0 prior to this code)

-      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.
 
@@ -569,10 +566,7 @@ void ThreadData::TallyRunInAScopedRegionIfTracking(
     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,93 @@ 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);
+  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;

[jar (doing other things), 2014/08/08 01:34:48]

Given that you said that stopwatches could be started and stopped, I'm surprised
that you're clearing out these values at a Start() call, as it would seemingly
destroy all history from prior starts and stops.

Maybe I was confused when you said they were "reusable," and they are not really
reused in common lifetime usage.

[vadimt, 2014/08/08 20:39:34]

Stopwatches indeed can be reused i.e.:
Start
Stop
Tally task 1
Start
Stop
Tally task 2
...

Each start, we want to totally reset ourselves since measurements for task1
shouldn't affect task2. Resetting also clears the duration of nested stopwatches
between Start and Stop.
Note, however, that both measurements in the above example will add to
'nested_stopwatches_duration_ms_' of the PARENT task for them, and resetting
won't affect THAT value.

+  start_time_ = start_time;
+  wallclock_duration_ms_ = 0;
+  current_thread_data_ = ThreadData::Get();

[jar (doing other things), 2014/08/08 01:34:48]

This is a TLS access, and hence plausibly expensive.  I don't think it was
necessary to access this for each start, and it could have been hidden in the
cost of the access that was needed for calling the profiler.

[vadimt, 2014/08/08 20:39:34]

Ah, OK. I assumed that TLS is cheap (like you get a variable pointed by some
register, add some offset, and you are done). Probably, I was wrong.
I modified methods from the Tally* family to use the thread data stored in the
stopwatch. Now, we have 1 TLS access per task, like before (if
kTrackParentChildLinks == false).

+  if (current_thread_data_) {
+    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_) {
+    DCHECK(current_thread_data_->current_stopwatch_ == this);
+    current_thread_data_->current_stopwatch_ = parent_stopwatch_;
+
+    if (parent_stopwatch_) {
+#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_;
+      parent_stopwatch_ = NULL;
+    }
+
+    current_thread_data_ = NULL;
+  }
+}
+
+TrackedTime TaskStopwatch::StartTime() const {
+#ifndef NDEBUG
+  DCHECK(state_ != CREATED);
+#endif
+  return start_time_;
+}
+
+int32 TaskStopwatch::TaskDurationMs() const {
+#ifndef NDEBUG
+  DCHECK(state_ == STOPPED);
+#endif
+
+  return wallclock_duration_ms_ - nested_stopwatches_duration_ms_;
+}
+
+//------------------------------------------------------------------------------
 TaskSnapshot::TaskSnapshot() {
 }