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..2d051d9f1b1f9d1eb2f05c2560ae547fe29ec524 100644
--- a/base/tracked_objects.cc
+++ b/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();

[jar (doing other things), 2014/09/05 04:36:05]

I liked the way you replaced several other Get() calls (which use TLS) with
calls that harvest the data from a StopWatch (so we don't have to call this
twice).

Is there any nice way we can share this Get() with the one needed for the
StopWatch?  Perhaps return the ThreadData* and use it to construct the
StopWatch()?  Perhaps the StopWatch constructor can be overloaded to optionally
take this as a constructor arg?  ... or we can always pass it in as a
constructor arg?

[vadimt, 2014/09/05 20:25:55]

My understanding is that parent-child tracking is disabled.
If you enable it, I understand that it will hurt perf much worse than
double-accessing TLS.

Given that all options you mentioned lead to complicating the code, I'd prefer
to leave everything as is, at least until parent-child tracking is enabled in
official builds.

     if (current_thread_data)
       current_thread_data->parent_stack_.push(parent);
   }
-  return Now();
-}
-
-// static
-TrackedTime ThreadData::NowForEndOfRun() {
-  return Now();
 }
 
 // static
@@ -858,6 +853,85 @@ void ThreadData::ShutdownSingleThreadedCleanup(bool leak) {
 }
 
 //------------------------------------------------------------------------------
+TaskStopwatch::TaskStopwatch()
+    : start_time_(ThreadData::Now()),
+      current_thread_data_(ThreadData::Get()),
+      excluded_duration_ms_(0),
+      parent_stopwatch_(NULL) {
+#ifndef NDEBUG
+  state_ = RUNNING;
+  running_child_ = NULL;
+#endif
+
+  wallclock_duration_ms_ = 0;
+  if (!current_thread_data_)
+    return;
+
+  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;
+}
+
+TaskStopwatch::~TaskStopwatch() {
+#ifndef NDEBUG

[jar (doing other things), 2014/09/05 04:36:05]

nit: We probably don't need the ifdef around DCHECKs

[vadimt, 2014/09/05 20:25:55]

We actually need it, since otherwise we get compiler errors in release mode.
This is because DCHECK references its condition even in release mode, to avoid
"unused variable" warnings.

+  DCHECK(state_ != RUNNING);
+  DCHECK(running_child_ == NULL);
+#endif
+}
+
+void TaskStopwatch::Stop() {
+  const TrackedTime end_time = ThreadData::Now();
+#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_)
+    return;
+
+  DCHECK(current_thread_data_->current_stopwatch_ == this);
+  current_thread_data_->current_stopwatch_ = parent_stopwatch_;
+  if (!parent_stopwatch_)
+    return;
+
+#ifndef NDEBUG
+  DCHECK(parent_stopwatch_->state_ == RUNNING);
+  DCHECK(parent_stopwatch_->running_child_ == this);
+  parent_stopwatch_->running_child_ = NULL;
+#endif
+  parent_stopwatch_->excluded_duration_ms_ +=
+      wallclock_duration_ms_;
+  parent_stopwatch_ = NULL;
+}
+
+TrackedTime TaskStopwatch::StartTime() const {
+  return start_time_;
+}
+
+int32 TaskStopwatch::RunDurationMs() const {
+#ifndef NDEBUG
+  DCHECK(state_ == STOPPED);
+#endif
+
+  return wallclock_duration_ms_ - excluded_duration_ms_;
+}
+
+ThreadData* TaskStopwatch::GetThreadData() const {
+  return current_thread_data_;
+}
+
+//------------------------------------------------------------------------------
 TaskSnapshot::TaskSnapshot() {
 }