Creating a framework for suppressing pollution of the profiler data

base/tracked_objects_unittest.cc

Index: base/tracked_objects_unittest.cc
diff --git a/base/tracked_objects_unittest.cc b/base/tracked_objects_unittest.cc
index 7cbce908e0aa1afe908a01c129852fdaa8ffd391..594539f1c419cd79c5332422b089b70ea5c03f10 100644
--- a/base/tracked_objects_unittest.cc
+++ b/base/tracked_objects_unittest.cc
@@ -96,8 +96,9 @@ class TrackedObjectsTest : public testing::Test {
 TEST_F(TrackedObjectsTest, MinimalStartupShutdown) {
   // Minimal test doesn't even create any tasks.
   if (!ThreadData::InitializeAndSetTrackingStatus(
-          ThreadData::PROFILING_CHILDREN_ACTIVE))
+          ThreadData::PROFILING_CHILDREN_ACTIVE)) {
     return;
+  }
 
   EXPECT_FALSE(ThreadData::first());  // No activity even on this thread.
   ThreadData* data = ThreadData::Get();
@@ -136,8 +137,9 @@ TEST_F(TrackedObjectsTest, MinimalStartupShutdown) {
 
 TEST_F(TrackedObjectsTest, TinyStartupShutdown) {
   if (!ThreadData::InitializeAndSetTrackingStatus(
-          ThreadData::PROFILING_CHILDREN_ACTIVE))
+          ThreadData::PROFILING_CHILDREN_ACTIVE)) {
     return;
+  }
 
   // Instigate tracking on a single tracked object, on our thread.
   const char kFunction[] = "TinyStartupShutdown";
@@ -168,8 +170,11 @@ TEST_F(TrackedObjectsTest, TinyStartupShutdown) {
   TrackedTime start_time(pending_task.time_posted);
   // Finally conclude the outer run.
   TrackedTime end_time = ThreadData::NowForEndOfRun();
-  ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, start_time,
-                                              end_time);
+  TaskStopwatch stopwatch;
+  stopwatch.Start(start_time);
+  stopwatch.Stop(end_time);
+
+  ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, stopwatch);
 
   birth_map.clear();
   death_map.clear();
@@ -230,8 +235,9 @@ TEST_F(TrackedObjectsTest, TinyStartupShutdown) {
 
 TEST_F(TrackedObjectsTest, DeathDataTest) {
   if (!ThreadData::InitializeAndSetTrackingStatus(
-          ThreadData::PROFILING_CHILDREN_ACTIVE))
+          ThreadData::PROFILING_CHILDREN_ACTIVE)) {
     return;
+  }
 
   scoped_ptr<DeathData> data(new DeathData());
   ASSERT_NE(data, reinterpret_cast<DeathData*>(NULL));
@@ -271,8 +277,9 @@ TEST_F(TrackedObjectsTest, DeathDataTest) {
 
 TEST_F(TrackedObjectsTest, DeactivatedBirthOnlyToSnapshotWorkerThread) {
   // Start in the deactivated state.
-  if (!ThreadData::InitializeAndSetTrackingStatus(ThreadData::DEACTIVATED))
+  if (!ThreadData::InitializeAndSetTrackingStatus(ThreadData::DEACTIVATED)) {
     return;
+  }
 
   const char kFunction[] = "DeactivatedBirthOnlyToSnapshotWorkerThread";
   Location location(kFunction, kFile, kLineNumber, NULL);
@@ -287,8 +294,9 @@ TEST_F(TrackedObjectsTest, DeactivatedBirthOnlyToSnapshotWorkerThread) {
 
 TEST_F(TrackedObjectsTest, DeactivatedBirthOnlyToSnapshotMainThread) {
   // Start in the deactivated state.
-  if (!ThreadData::InitializeAndSetTrackingStatus(ThreadData::DEACTIVATED))
+  if (!ThreadData::InitializeAndSetTrackingStatus(ThreadData::DEACTIVATED)) {
     return;
+  }
 
   const char kFunction[] = "DeactivatedBirthOnlyToSnapshotMainThread";
   Location location(kFunction, kFile, kLineNumber, NULL);
@@ -303,8 +311,9 @@ TEST_F(TrackedObjectsTest, DeactivatedBirthOnlyToSnapshotMainThread) {
 
 TEST_F(TrackedObjectsTest, BirthOnlyToSnapshotWorkerThread) {
   if (!ThreadData::InitializeAndSetTrackingStatus(
-          ThreadData::PROFILING_CHILDREN_ACTIVE))
+          ThreadData::PROFILING_CHILDREN_ACTIVE)) {
     return;
+  }
 
   const char kFunction[] = "BirthOnlyToSnapshotWorkerThread";
   Location location(kFunction, kFile, kLineNumber, NULL);
@@ -318,8 +327,9 @@ TEST_F(TrackedObjectsTest, BirthOnlyToSnapshotWorkerThread) {
 
 TEST_F(TrackedObjectsTest, BirthOnlyToSnapshotMainThread) {
   if (!ThreadData::InitializeAndSetTrackingStatus(
-          ThreadData::PROFILING_CHILDREN_ACTIVE))
+          ThreadData::PROFILING_CHILDREN_ACTIVE)) {
     return;
+  }
 
   const char kFunction[] = "BirthOnlyToSnapshotMainThread";
   Location location(kFunction, kFile, kLineNumber, NULL);
@@ -333,8 +343,9 @@ TEST_F(TrackedObjectsTest, BirthOnlyToSnapshotMainThread) {
 
 TEST_F(TrackedObjectsTest, LifeCycleToSnapshotMainThread) {
   if (!ThreadData::InitializeAndSetTrackingStatus(
-          ThreadData::PROFILING_CHILDREN_ACTIVE))
+          ThreadData::PROFILING_CHILDREN_ACTIVE)) {
     return;
+  }
 
   const char kFunction[] = "LifeCycleToSnapshotMainThread";
   Location location(kFunction, kFile, kLineNumber, NULL);
@@ -350,8 +361,11 @@ TEST_F(TrackedObjectsTest, LifeCycleToSnapshotMainThread) {
   const TrackedTime kStartOfRun = TrackedTime() +
       Duration::FromMilliseconds(5);
   const TrackedTime kEndOfRun = TrackedTime() + Duration::FromMilliseconds(7);
-  ThreadData::TallyRunOnNamedThreadIfTracking(pending_task,
-      kStartOfRun, kEndOfRun);
+  TaskStopwatch stopwatch;
+  stopwatch.Start(kStartOfRun);
+  stopwatch.Stop(kEndOfRun);
+
+  ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, stopwatch);
 
   ProcessDataSnapshot process_data;
   ThreadData::Snapshot(false, &process_data);
@@ -365,8 +379,9 @@ TEST_F(TrackedObjectsTest, LifeCycleToSnapshotMainThread) {
 // task is still running, or is queued).
 TEST_F(TrackedObjectsTest, LifeCycleMidDeactivatedToSnapshotMainThread) {
   if (!ThreadData::InitializeAndSetTrackingStatus(
-          ThreadData::PROFILING_CHILDREN_ACTIVE))
+          ThreadData::PROFILING_CHILDREN_ACTIVE)) {
     return;
+  }
 
   const char kFunction[] = "LifeCycleMidDeactivatedToSnapshotMainThread";
   Location location(kFunction, kFile, kLineNumber, NULL);
@@ -386,8 +401,11 @@ TEST_F(TrackedObjectsTest, LifeCycleMidDeactivatedToSnapshotMainThread) {
   const TrackedTime kStartOfRun = TrackedTime() +
       Duration::FromMilliseconds(5);
   const TrackedTime kEndOfRun = TrackedTime() + Duration::FromMilliseconds(7);
-  ThreadData::TallyRunOnNamedThreadIfTracking(pending_task,
-      kStartOfRun, kEndOfRun);
+  TaskStopwatch stopwatch;
+  stopwatch.Start(kStartOfRun);
+  stopwatch.Stop(kEndOfRun);
+
+  ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, stopwatch);
 
   ProcessDataSnapshot process_data;
   ThreadData::Snapshot(false, &process_data);
@@ -399,8 +417,9 @@ TEST_F(TrackedObjectsTest, LifeCycleMidDeactivatedToSnapshotMainThread) {
 // the birth nor the death will be recorded.
 TEST_F(TrackedObjectsTest, LifeCyclePreDeactivatedToSnapshotMainThread) {
   // Start in the deactivated state.
-  if (!ThreadData::InitializeAndSetTrackingStatus(ThreadData::DEACTIVATED))
+  if (!ThreadData::InitializeAndSetTrackingStatus(ThreadData::DEACTIVATED)) {
     return;
+  }
 
   const char kFunction[] = "LifeCyclePreDeactivatedToSnapshotMainThread";
   Location location(kFunction, kFile, kLineNumber, NULL);
@@ -416,8 +435,11 @@ TEST_F(TrackedObjectsTest, LifeCyclePreDeactivatedToSnapshotMainThread) {
   const TrackedTime kStartOfRun = TrackedTime() +
       Duration::FromMilliseconds(5);
   const TrackedTime kEndOfRun = TrackedTime() + Duration::FromMilliseconds(7);
-  ThreadData::TallyRunOnNamedThreadIfTracking(pending_task,
-      kStartOfRun, kEndOfRun);
+  TaskStopwatch stopwatch;
+  stopwatch.Start(kStartOfRun);
+  stopwatch.Stop(kEndOfRun);
+
+  ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, stopwatch);
 
   ProcessDataSnapshot process_data;
   ThreadData::Snapshot(false, &process_data);
@@ -428,8 +450,9 @@ TEST_F(TrackedObjectsTest, LifeCyclePreDeactivatedToSnapshotMainThread) {
 
 TEST_F(TrackedObjectsTest, LifeCycleToSnapshotWorkerThread) {
   if (!ThreadData::InitializeAndSetTrackingStatus(
-          ThreadData::PROFILING_CHILDREN_ACTIVE))
+          ThreadData::PROFILING_CHILDREN_ACTIVE)) {
     return;
+  }
 
   const char kFunction[] = "LifeCycleToSnapshotWorkerThread";
   Location location(kFunction, kFile, kLineNumber, NULL);
@@ -441,8 +464,11 @@ TEST_F(TrackedObjectsTest, LifeCycleToSnapshotWorkerThread) {
   const TrackedTime kStartOfRun = TrackedTime() +
       Duration::FromMilliseconds(5);
   const TrackedTime kEndOfRun = TrackedTime() + Duration::FromMilliseconds(7);
-  ThreadData::TallyRunOnWorkerThreadIfTracking(birth, kTimePosted,
-      kStartOfRun, kEndOfRun);
+  TaskStopwatch stopwatch;
+  stopwatch.Start(kStartOfRun);
+  stopwatch.Stop(kEndOfRun);
+
+  ThreadData::TallyRunOnWorkerThreadIfTracking(birth, kTimePosted, stopwatch);
 
   // Call for the ToSnapshot, but tell it to not reset the maxes after scanning.
   ProcessDataSnapshot process_data;
@@ -486,8 +512,9 @@ TEST_F(TrackedObjectsTest, LifeCycleToSnapshotWorkerThread) {
 
 TEST_F(TrackedObjectsTest, TwoLives) {
   if (!ThreadData::InitializeAndSetTrackingStatus(
-          ThreadData::PROFILING_CHILDREN_ACTIVE))
+          ThreadData::PROFILING_CHILDREN_ACTIVE)) {
     return;
+  }
 
   const char kFunction[] = "TwoLives";
   Location location(kFunction, kFile, kLineNumber, NULL);
@@ -503,15 +530,19 @@ TEST_F(TrackedObjectsTest, TwoLives) {
   const TrackedTime kStartOfRun = TrackedTime() +
       Duration::FromMilliseconds(5);
   const TrackedTime kEndOfRun = TrackedTime() + Duration::FromMilliseconds(7);
-  ThreadData::TallyRunOnNamedThreadIfTracking(pending_task,
-      kStartOfRun, kEndOfRun);
+  TaskStopwatch stopwatch;
+  stopwatch.Start(kStartOfRun);
+  stopwatch.Stop(kEndOfRun);
+
+  ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, stopwatch);
 
   // TrackingInfo will call TallyABirth() during construction.
   base::TrackingInfo pending_task2(location, kDelayedStartTime);
   pending_task2.time_posted = kTimePosted;  // Overwrite implied Now().
+  stopwatch.Start(kStartOfRun);
+  stopwatch.Stop(kEndOfRun);
 
-  ThreadData::TallyRunOnNamedThreadIfTracking(pending_task2,
-      kStartOfRun, kEndOfRun);
+  ThreadData::TallyRunOnNamedThreadIfTracking(pending_task2, stopwatch);
 
   ProcessDataSnapshot process_data;
   ThreadData::Snapshot(false, &process_data);
@@ -521,8 +552,9 @@ TEST_F(TrackedObjectsTest, TwoLives) {
 
 TEST_F(TrackedObjectsTest, DifferentLives) {
   if (!ThreadData::InitializeAndSetTrackingStatus(
-          ThreadData::PROFILING_CHILDREN_ACTIVE))
+          ThreadData::PROFILING_CHILDREN_ACTIVE)) {
     return;
+  }
 
   // Use a well named thread.
   ThreadData::InitializeThreadContext(kMainThreadName);
@@ -539,8 +571,11 @@ TEST_F(TrackedObjectsTest, DifferentLives) {
   const TrackedTime kStartOfRun = TrackedTime() +
       Duration::FromMilliseconds(5);
   const TrackedTime kEndOfRun = TrackedTime() + Duration::FromMilliseconds(7);
-  ThreadData::TallyRunOnNamedThreadIfTracking(pending_task,
-      kStartOfRun, kEndOfRun);
+  TaskStopwatch stopwatch;
+  stopwatch.Start(kStartOfRun);
+  stopwatch.Stop(kEndOfRun);
+
+  ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, stopwatch);
 
   const int kSecondFakeLineNumber = 999;
   Location second_location(kFunction, kFile, kSecondFakeLineNumber, NULL);
@@ -581,4 +616,161 @@ TEST_F(TrackedObjectsTest, DifferentLives) {
   EXPECT_EQ(base::GetCurrentProcId(), process_data.process_id);
 }
 
+TEST_F(TrackedObjectsTest, TaskWithNestedExclusion) {
+  if (!ThreadData::InitializeAndSetTrackingStatus(
+          ThreadData::PROFILING_CHILDREN_ACTIVE)) {
+    return;
+  }
+
+  const char kFunction[] = "TaskWithNestedExclusion";
+  Location location(kFunction, kFile, kLineNumber, NULL);
+  TallyABirth(location, kMainThreadName);
+
+  const base::TimeTicks kTimePosted = base::TimeTicks() +
+      base::TimeDelta::FromMilliseconds(1);
+  const base::TimeTicks kDelayedStartTime = base::TimeTicks();
+  // TrackingInfo will call TallyABirth() during construction.
+  base::TrackingInfo pending_task(location, kDelayedStartTime);
+  pending_task.time_posted = kTimePosted;  // Overwrite implied Now().
+
+  const TrackedTime kStartOfRun = TrackedTime() +
+      Duration::FromMilliseconds(5);
+  const TrackedTime kEndOfRun = TrackedTime() + Duration::FromMilliseconds(15);
+  TaskStopwatch task_stopwatch;
+  task_stopwatch.Start(kStartOfRun);
+  {
+    TaskStopwatch exclusion_stopwatch;
+    exclusion_stopwatch.Start(TrackedTime() + Duration::FromMilliseconds(8));
+    exclusion_stopwatch.Stop(TrackedTime() + Duration::FromMilliseconds(12));
+  }
+  task_stopwatch.Stop(kEndOfRun);
+
+  ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, task_stopwatch);
+
+  ProcessDataSnapshot process_data;
+  ThreadData::Snapshot(false, &process_data);
+  ExpectSimpleProcessData(process_data, kFunction, kMainThreadName,
+                          kMainThreadName, 1, 6, 4);
+}
+
+TEST_F(TrackedObjectsTest, TaskWith2NestedExclusions) {
+  if (!ThreadData::InitializeAndSetTrackingStatus(
+          ThreadData::PROFILING_CHILDREN_ACTIVE)) {
+    return;
+  }
+
+  const char kFunction[] = "TaskWith2NestedExclusions";
+  Location location(kFunction, kFile, kLineNumber, NULL);
+  TallyABirth(location, kMainThreadName);
+
+  const base::TimeTicks kTimePosted = base::TimeTicks() +
+      base::TimeDelta::FromMilliseconds(1);
+  const base::TimeTicks kDelayedStartTime = base::TimeTicks();
+  // TrackingInfo will call TallyABirth() during construction.
+  base::TrackingInfo pending_task(location, kDelayedStartTime);
+  pending_task.time_posted = kTimePosted;  // Overwrite implied Now().
+
+  const TrackedTime kStartOfRun = TrackedTime() +
+      Duration::FromMilliseconds(5);
+  const TrackedTime kEndOfRun = TrackedTime() + Duration::FromMilliseconds(25);
+  TaskStopwatch task_stopwatch;
+  task_stopwatch.Start(kStartOfRun);
+  {
+    TaskStopwatch exclusion_stopwatch;
+    exclusion_stopwatch.Start(TrackedTime() + Duration::FromMilliseconds(8));
+    exclusion_stopwatch.Stop(TrackedTime() + Duration::FromMilliseconds(12));
+
+    exclusion_stopwatch.Start(TrackedTime() + Duration::FromMilliseconds(15));
+    exclusion_stopwatch.Stop(TrackedTime() + Duration::FromMilliseconds(18));
+  }
+  task_stopwatch.Stop(kEndOfRun);
+
+  ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, task_stopwatch);
+
+  ProcessDataSnapshot process_data;
+  ThreadData::Snapshot(false, &process_data);
+  ExpectSimpleProcessData(process_data, kFunction, kMainThreadName,
+                          kMainThreadName, 1, 13, 4);
+}
+
+TEST_F(TrackedObjectsTest, TaskWithNestedExclusionWithNestedTask) {
+  if (!ThreadData::InitializeAndSetTrackingStatus(
+          ThreadData::PROFILING_CHILDREN_ACTIVE)) {
+    return;
+  }
+
+  const char kFunction[] = "TaskWithNestedExclusionWithNestedTask";
+  Location location(kFunction, kFile, kLineNumber, NULL);
+
+  const int kSecondFakeLineNumber = 999;
+
+  TallyABirth(location, kMainThreadName);
+
+  const base::TimeTicks kTimePosted = base::TimeTicks() +
+      base::TimeDelta::FromMilliseconds(1);
+  const base::TimeTicks kDelayedStartTime = base::TimeTicks();
+  // TrackingInfo will call TallyABirth() during construction.
+  base::TrackingInfo pending_task(location, kDelayedStartTime);
+  pending_task.time_posted = kTimePosted;  // Overwrite implied Now().
+
+  const TrackedTime kStartOfRun = TrackedTime() +
+      Duration::FromMilliseconds(5);
+  const TrackedTime kEndOfRun = TrackedTime() + Duration::FromMilliseconds(15);
+  TaskStopwatch task_stopwatch;
+  task_stopwatch.Start(kStartOfRun);
+  {
+    TaskStopwatch exclusion_stopwatch;
+    exclusion_stopwatch.Start(TrackedTime() + Duration::FromMilliseconds(8));
+    {
+      Location second_location(kFunction, kFile, kSecondFakeLineNumber, NULL);
+      base::TrackingInfo nested_task(second_location, kDelayedStartTime);
+       // Overwrite implied Now().
+      nested_task.time_posted =
+          base::TimeTicks() + base::TimeDelta::FromMilliseconds(8);
+      TaskStopwatch nested_task_stopwatch;
+      nested_task_stopwatch.Start(
+          TrackedTime() + Duration::FromMilliseconds(9));
+      nested_task_stopwatch.Stop(
+          TrackedTime() + Duration::FromMilliseconds(11));
+      ThreadData::TallyRunOnNamedThreadIfTracking(
+          nested_task, nested_task_stopwatch);
+    }
+    exclusion_stopwatch.Stop(TrackedTime() + Duration::FromMilliseconds(12));
+  }
+  task_stopwatch.Stop(kEndOfRun);
+
+  ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, task_stopwatch);
+
+  ProcessDataSnapshot process_data;
+  ThreadData::Snapshot(false, &process_data);
+  ASSERT_EQ(2u, process_data.tasks.size());
+  EXPECT_EQ(kFile, process_data.tasks[0].birth.location.file_name);
+  EXPECT_EQ(kFunction, process_data.tasks[0].birth.location.function_name);
+  EXPECT_EQ(kLineNumber, process_data.tasks[0].birth.location.line_number);
+  EXPECT_EQ(kMainThreadName, process_data.tasks[0].birth.thread_name);
+  EXPECT_EQ(1, process_data.tasks[0].death_data.count);
+  EXPECT_EQ(6, process_data.tasks[0].death_data.run_duration_sum);
+  EXPECT_EQ(6, process_data.tasks[0].death_data.run_duration_max);
+  EXPECT_EQ(6, process_data.tasks[0].death_data.run_duration_sample);
+  EXPECT_EQ(4, process_data.tasks[0].death_data.queue_duration_sum);
+  EXPECT_EQ(4, process_data.tasks[0].death_data.queue_duration_max);
+  EXPECT_EQ(4, process_data.tasks[0].death_data.queue_duration_sample);
+  EXPECT_EQ(kMainThreadName, process_data.tasks[0].death_thread_name);
+  EXPECT_EQ(kFile, process_data.tasks[1].birth.location.file_name);
+  EXPECT_EQ(kFunction, process_data.tasks[1].birth.location.function_name);
+  EXPECT_EQ(kSecondFakeLineNumber,
+            process_data.tasks[1].birth.location.line_number);
+  EXPECT_EQ(kMainThreadName, process_data.tasks[1].birth.thread_name);
+  EXPECT_EQ(1, process_data.tasks[1].death_data.count);
+  EXPECT_EQ(2, process_data.tasks[1].death_data.run_duration_sum);
+  EXPECT_EQ(2, process_data.tasks[1].death_data.run_duration_max);
+  EXPECT_EQ(2, process_data.tasks[1].death_data.run_duration_sample);
+  EXPECT_EQ(1, process_data.tasks[1].death_data.queue_duration_sum);
+  EXPECT_EQ(1, process_data.tasks[1].death_data.queue_duration_max);
+  EXPECT_EQ(1, process_data.tasks[1].death_data.queue_duration_sample);
+  EXPECT_EQ(kMainThreadName, process_data.tasks[1].death_thread_name);
+  EXPECT_EQ(0u, process_data.descendants.size());
+  EXPECT_EQ(base::GetCurrentProcId(), process_data.process_id);
+}
+
 }  // namespace tracked_objects