Creating a framework for suppressing pollution of the profiler data

base/tracked_objects_unittest.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.
 
 // Test of classes in the tracked_objects.h classes.
 
 #include "base/tracked_objects.h"
 
 #include <stddef.h>
 
@@ skipping 150 matching lines @@
   // Now instigate another birth, while we are timing the run of the first
   // execution.
   ThreadData::NowForStartOfRun(first_birth);
   // Create a child (using the same birth location).
   // TrackingInfo will call TallyABirth() during construction.
   base::TimeTicks kBogusBirthTime;
   base::TrackingInfo pending_task(location, kBogusBirthTime);
   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();
   parent_child_set.clear();
   data->SnapshotMaps(false, &birth_map, &death_map, &parent_child_set);
   EXPECT_EQ(1u, birth_map.size());                         // 1 birth location.
   EXPECT_EQ(2, birth_map.begin()->second->birth_count());  // 2 births.
   EXPECT_EQ(1u, death_map.size());                         // 1 location.
   EXPECT_EQ(1, death_map.begin()->second.count());         // 1 death.
   if (ThreadData::TrackingParentChildStatus()) {
@@ skipping 160 matching lines @@
   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(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);
   ExpectSimpleProcessData(process_data, kFunction, kMainThreadName,
                           kMainThreadName, 1, 2, 4);
 }
 
 // We will deactivate tracking after the birth, and before the death, and
 // demonstrate that the lifecycle is completely tallied. This ensures that
 // our tallied births are matched by tallied deaths (except for when the
@@ skipping 14 matching lines @@
   base::TrackingInfo pending_task(location, kDelayedStartTime);
   pending_task.time_posted = kTimePosted;  // Overwrite implied Now().
 
   // Turn off tracking now that we have births.
   EXPECT_TRUE(ThreadData::InitializeAndSetTrackingStatus(
       ThreadData::DEACTIVATED));
 
   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);
   ExpectSimpleProcessData(process_data, kFunction, kMainThreadName,
                           kMainThreadName, 1, 2, 4);
 }
 
 // We will deactivate tracking before starting a life cycle, and neither
 // the birth nor the death will be recorded.
 TEST_F(TrackedObjectsTest, LifeCyclePreDeactivatedToSnapshotMainThread) {
   // Start in the deactivated state.
   if (!ThreadData::InitializeAndSetTrackingStatus(ThreadData::DEACTIVATED))
     return;
 
   const char kFunction[] = "LifeCyclePreDeactivatedToSnapshotMainThread";
   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(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);
   EXPECT_EQ(0u, process_data.tasks.size());
   EXPECT_EQ(0u, process_data.descendants.size());
   EXPECT_EQ(base::GetCurrentProcId(), process_data.process_id);
 }
 
 TEST_F(TrackedObjectsTest, LifeCycleToSnapshotWorkerThread) {
   if (!ThreadData::InitializeAndSetTrackingStatus(
           ThreadData::PROFILING_CHILDREN_ACTIVE))
     return;
 
   const char kFunction[] = "LifeCycleToSnapshotWorkerThread";
   Location location(kFunction, kFile, kLineNumber, NULL);
   // Do not delete |birth|.  We don't own it.
   Births* birth = ThreadData::TallyABirthIfActive(location);
   EXPECT_NE(reinterpret_cast<Births*>(NULL), birth);
 
   const TrackedTime kTimePosted = TrackedTime() + Duration::FromMilliseconds(1);
   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;
   ThreadData::Snapshot(false, &process_data);
   ExpectSimpleProcessData(process_data, kFunction, kWorkerThreadName,
                           kWorkerThreadName, 1, 2, 4);
 
   // Call for the ToSnapshot, but tell it to reset the maxes after scanning.
   // We'll still get the same values, but the data will be reset (which we'll
   // see in a moment).
@@ skipping 40 matching lines @@
   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(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);
   ExpectSimpleProcessData(process_data, kFunction, kMainThreadName,
                           kMainThreadName, 2, 2, 4);
 }
 
 TEST_F(TrackedObjectsTest, DifferentLives) {
   if (!ThreadData::InitializeAndSetTrackingStatus(
           ThreadData::PROFILING_CHILDREN_ACTIVE))
     return;
 
   // Use a well named thread.
   ThreadData::InitializeThreadContext(kMainThreadName);
   const char kFunction[] = "DifferentLives";
   Location location(kFunction, kFile, kLineNumber, NULL);
 
   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(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);
 
   // TrackingInfo will call TallyABirth() during construction.
   base::TrackingInfo pending_task2(second_location, kDelayedStartTime);
   pending_task2.time_posted = kTimePosted;  // Overwrite implied Now().
 
   ProcessDataSnapshot process_data;
   ThreadData::Snapshot(false, &process_data);
@@ skipping 20 matching lines @@
   EXPECT_EQ(0, process_data.tasks[1].death_data.run_duration_max);
   EXPECT_EQ(0, process_data.tasks[1].death_data.run_duration_sample);
   EXPECT_EQ(0, process_data.tasks[1].death_data.queue_duration_sum);
   EXPECT_EQ(0, process_data.tasks[1].death_data.queue_duration_max);
   EXPECT_EQ(0, process_data.tasks[1].death_data.queue_duration_sample);
   EXPECT_EQ(kStillAlive, process_data.tasks[1].death_thread_name);
   EXPECT_EQ(0u, process_data.descendants.size());
   EXPECT_EQ(base::GetCurrentProcId(), process_data.process_id);
 }
 
+TEST_F(TrackedObjectsTest, TaskWithNestedExclusion) {
+  if (!ThreadData::InitializeAndSetTrackingStatus(
+          ThreadData::PROFILING_CHILDREN_ACTIVE))
+    return;

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

nit: When the conditional of the if runs across more than one line,  folks seem
to use curlies around conditioned statement (just as though the statement ran
for several lines). 

I couldn't find justification in the style guide... but I've heard this
discussed often... and could have sworn it was there :-/.  IMO, the code looks
pretty funky as is.... and braces would only help ;-).

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

Agree, braces help when 'if' with condition takes several lines.

+
+  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