Creating a framework for suppressing pollution of the profiler data

base/tracked_objects.h

 // 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.
 
 #ifndef BASE_TRACKED_OBJECTS_H_
 #define BASE_TRACKED_OBJECTS_H_
 
 #include <map>
 #include <set>
 #include <stack>
@@ skipping 334 matching lines @@
 };
 
 //------------------------------------------------------------------------------
 // For each thread, we have a ThreadData that stores all tracking info generated
 // on this thread.  This prevents the need for locking as data accumulates.
 // We use ThreadLocalStorage to quickly identfy the current ThreadData context.
 // We also have a linked list of ThreadData instances, and that list is used to
 // harvest data from all existing instances.
 
 struct ProcessDataSnapshot;
+class BASE_EXPORT TaskStopwatch;
+
 class BASE_EXPORT ThreadData {
  public:
   // Current allowable states of the tracking system.  The states can vary
   // between ACTIVE and DEACTIVATED, but can never go back to UNINITIALIZED.
   enum Status {
     UNINITIALIZED,              // PRistine, link-time state before running.
     DORMANT_DURING_TESTS,       // Only used during testing.
     DEACTIVATED,                // No longer recording profling.
     PROFILING_ACTIVE,           // Recording profiles (no parent-child links).
     PROFILING_CHILDREN_ACTIVE,  // Fully active, recording parent-child links.
@@ skipping 31 matching lines @@
   // Records the end of a timed run of an object.  The |completed_task| contains
   // a pointer to a Births, the time_posted, and a delayed_start_time if any.
   // The |start_of_run| indicates when we started to perform the run of the
   // task.  The delayed_start_time is non-null for tasks that were posted as
   // delayed tasks, and it indicates when the task should have run (i.e., when
   // it should have posted out of the timer queue, and into the work queue.
   // The |end_of_run| was just obtained by a call to Now() (just after the task
   // finished). It is provided as an argument to help with testing.
   static void TallyRunOnNamedThreadIfTracking(
       const base::TrackingInfo& completed_task,
-      const TrackedTime& start_of_run,
-      const TrackedTime& end_of_run);
+      const TaskStopwatch& stopwatch);
 
   // Record the end of a timed run of an object.  The |birth| is the record for
   // the instance, the |time_posted| records that instant, which is presumed to
   // be when the task was posted into a queue to run on a worker thread.
   // The |start_of_run| is when the worker thread started to perform the run of
   // the task.
   // The |end_of_run| was just obtained by a call to Now() (just after the task
   // finished).
   static void TallyRunOnWorkerThreadIfTracking(
       const Births* birth,
       const TrackedTime& time_posted,
-      const TrackedTime& start_of_run,
-      const TrackedTime& end_of_run);
+      const TaskStopwatch& stopwatch);
 
   // Record the end of execution in region, generally corresponding to a scope
   // being exited.
   static void TallyRunInAScopedRegionIfTracking(
       const Births* birth,
-      const TrackedTime& start_of_run,
-      const TrackedTime& end_of_run);
+      const TaskStopwatch& stopwatch);
 
   const std::string& thread_name() const { return thread_name_; }
 
   // Hack: asynchronously clear all birth counts and death tallies data values
   // in all ThreadData instances.  The numerical (zeroing) part is done without
   // use of a locks or atomics exchanges, and may (for int64 values) produce
   // bogus counts VERY rarely.
   static void ResetAllThreadData();
 
   // Initializes all statics if needed (this initialization call should be made
@@ skipping 42 matching lines @@
   // the other time arguments (used for calculating queueing delay) will be
   // ignored.
   static void SetAlternateTimeSource(NowFunction* now);
 
   // This function can be called at process termination to validate that thread
   // cleanup routines have been called for at least some number of named
   // threads.
   static void EnsureCleanupWasCalled(int major_threads_shutdown_count);
 
  private:
+  friend class TaskStopwatch;
   // Allow only tests to call ShutdownSingleThreadedCleanup.  We NEVER call it
   // in production code.
   // TODO(jar): Make this a friend in DEBUG only, so that the optimizer has a
   // better change of optimizing (inlining? etc.) private methods (knowing that
   // there will be no need for an external entry point).
   friend class TrackedObjectsTest;
   FRIEND_TEST_ALL_PREFIXES(TrackedObjectsTest, MinimalStartupShutdown);
   FRIEND_TEST_ALL_PREFIXES(TrackedObjectsTest, TinyStartupShutdown);
   FRIEND_TEST_ALL_PREFIXES(TrackedObjectsTest, ParentChildTest);
 
@@ skipping 16 matching lines @@
   static ThreadData* first();
 
   // Iterate through the null terminated list of ThreadData instances.
   ThreadData* next() const;
 
 
   // In this thread's data, record a new birth.
   Births* TallyABirth(const Location& location);
 
   // Find a place to record a death on this thread.
-  void TallyADeath(const Births& birth, int32 queue_duration, int32 duration);

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

Care was taken to use a 32 bit quantity.  As I recall, this was done for both
atomicity of access, and also to provide for faster implementations (on
platforms where 64 bit arithmetic is implemented by super expensive library
calls!).

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

TaskStopwatch still uses int32, so this is taken care of.

+  void TallyADeath(const Births& birth,
+                   int32 queue_duration,
+                   const TaskStopwatch& stopwatch);
 
   // Snapshot (under a lock) the profiled data for the tasks in each ThreadData
   // instance.  Also updates the |birth_counts| tally for each task to keep
   // track of the number of living instances of the task.  If |reset_max| is
   // true, then the max values in each DeathData instance are reset during the
   // scan.
   static void SnapshotAllExecutedTasks(bool reset_max,
                                        ProcessDataSnapshot* process_data,
                                        BirthCountMap* birth_counts);
 
@@ skipping 142 matching lines @@
   // much randomness (because we can't call RandInt() on all our threads), so
   // we stir in more and more as we go.
   int32 random_number_;
 
   // Record of what the incarnation_counter_ was when this instance was created.
   // If the incarnation_counter_ has changed, then we avoid pushing into the
   // pool (this is only critical in tests which go through multiple
   // incarnations).
   int incarnation_count_for_pool_;
 
+  // Most recently started (i.e. most nested) stopwatch on the current thread,
+  // if it exists; NULL otherwise.
+  TaskStopwatch* current_stopwatch_;
+
   DISALLOW_COPY_AND_ASSIGN(ThreadData);
 };
 
 //------------------------------------------------------------------------------
+// Stopwatch to measure task run time or simply create a time interval that will
+// be subtracted from the current most nested task's run time. Nested
+// stopwatches coordinate with their parent stopwatches to avoid double-counting
+// nested tasks run times.
+
+class BASE_EXPORT TaskStopwatch {
+ public:
+  TaskStopwatch();
+  ~TaskStopwatch();
+
+  // Starts stopwatch with the specified |start_time|.
+  void Start(const TrackedTime& start_time);
+
+  // Starts stopwatch with the current time.
+  void Start() { Start(ThreadData::Now()); }
+
+  // Stops stopwatch with the specified |start_time|.
+  void Stop(const TrackedTime& end_time);
+
+  // Stops stopwatch with the current time.
+  void Stop() { Stop(ThreadData::Now()); }
+
+  // Returns the start time.
+  TrackedTime StartTime() const;
+
+  // Returns task's duration. This method should be used when measuring run
+  // time for tasks. Task's durataion is calculated as the wallclock time
+  // difference between stopping the stopwatch and starting it, minus time
+  // spent in immediately nested stopwatches.
+  int32 TaskDurationMs() const;
+
+ private:
+  // Time when the stopwatch was started.
+  TrackedTime start_time_;
+
+  // Wallclock duration of the task.
+  int32 wallclock_duration_ms_;
+
+  // Tracking info for the current thread.
+  ThreadData* current_thread_data_;
+
+  // Total duration of all completed that were immediate children of this one.
+  int32 nested_stopwatches_duration_ms_;
+
+  // Stopwatch of which this one is an immediate child.

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

The words "parent" and "child" seem confusing.  I suspect you wanted to say;

// Stopwatch which was running on our thread when this stopwatch was started. 
That preexisting stopwatch must be adjusted to the exclude the duration of
existance of this stopwatch.

Maybe you can define parent and child, but I suspect it will be even more
complicated.

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

Done.

+  TaskStopwatch* parent_stopwatch_;
+
+#ifndef NDEBUG
+  // State of the stopwatch. Stopwatch is reusable, i.e. it can be started after
+  // it was stopped.
+  enum {
+    CREATED,
+    RUNNING,
+    STOPPED
+  } state_;
+
+  // Currently running stopwatch that an immediate child of this one, if such
+  // child exists. NULL otherwise.
+  TaskStopwatch* running_child_;
+#endif
+};
+
+//------------------------------------------------------------------------------
 // A snapshotted representation of a (parent, child) task pair, for tracking
 // hierarchical profiles.
 
 struct BASE_EXPORT ParentChildPairSnapshot {
  public:
   ParentChildPairSnapshot();
   explicit ParentChildPairSnapshot(
       const ThreadData::ParentChildPair& parent_child);
   ~ParentChildPairSnapshot();
 
@@ skipping 10 matching lines @@
   ~ProcessDataSnapshot();
 
   std::vector<TaskSnapshot> tasks;
   std::vector<ParentChildPairSnapshot> descendants;
   int process_id;
 };
 
 }  // namespace tracked_objects
 
 #endif  // BASE_TRACKED_OBJECTS_H_