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 15 matching lines @@
   static Status status();
 
   // Indicate if any sort of profiling is being done (i.e., we are more than
   // DEACTIVATED).
   static bool TrackingStatus();
 
   // For testing only, indicate if the status of parent-child tracking is turned
   // on.  This is currently a compiled option, atop TrackingStatus().
   static bool TrackingParentChildStatus();
 
-  // Special versions of Now() for getting times at start and end of a tracked
-  // run.  They are super fast when tracking is disabled, and have some internal
-  // side effects when we are tracking, so that we can deduce the amount of time
-  // accumulated outside of execution of tracked runs.
+  // Marks a start of a tracked run. It's super fast when tracking is disabled,
+  // and has some internal side effects when we are tracking, so that we can
+  // deduce the amount of time accumulated outside of execution of tracked runs.
   // The task that will be tracked is passed in as |parent| so that parent-child
   // relationships can be (optionally) calculated.
-  static TrackedTime NowForStartOfRun(const Births* parent);
-  static TrackedTime NowForEndOfRun();
+  static void PrepareForStartOfRun(const Births* parent);
 
   // Provide a time function that does nothing (runs fast) when we don't have
   // the profiler enabled.  It will generally be optimized away when it is
   // ifdef'ed to be small enough (allowing the profiler to be "compiled out" of
   // the code).
   static TrackedTime Now();
 
   // Use the function |now| to provide current times, instead of calling the
   // TrackedTime::Now() function.  Since this alternate function is being used,
   // 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);
+  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 38 matching lines @@
   // threads since the time that InitializeAndSetTrackingStatus() was called,
   // then you can pass in a |leak| value of false, and this function will
   // delete recursively all data structures, starting with the list of
   // ThreadData instances.
   static void ShutdownSingleThreadedCleanup(bool leak);
 
   // When non-null, this specifies an external function that supplies monotone
   // increasing time functcion.
   static NowFunction* now_function_;
 
+  // If true, now_function_ returns values that can be used to calculate queue
+  // time.
+  static bool now_function_is_time_;
+
   // We use thread local store to identify which ThreadData to interact with.
   static base::ThreadLocalStorage::StaticSlot tls_index_;
 
   // List of ThreadData instances for use with worker threads. When a worker
   // thread is done (terminated), we push it onto this llist.  When a new worker
   // thread is created, we first try to re-use a ThreadData instance from the
   // list, and if none are available, construct a new one.
   // This is only accessed while list_lock_ is held.
   static ThreadData* first_retired_worker_;
 
@@ skipping 63 matching lines @@
 
   // Lock to protect *some* access to BirthMap and DeathMap.  The maps are
   // regularly read and written on this thread, but may only be read from other
   // threads.  To support this, we acquire this lock if we are writing from this
   // thread, or reading from another thread.  For reading from this thread we
   // don't need a lock, as there is no potential for a conflict since the
   // writing is only done from this thread.
   mutable base::Lock map_lock_;
 
   // The stack of parents that are currently being profiled. This includes only
-  // tasks that have started a timer recently via NowForStartOfRun(), but not
-  // yet concluded with a NowForEndOfRun().  Usually this stack is one deep, but
-  // if a scoped region is profiled, or <sigh> a task runs a nested-message
+  // tasks that have started a timer recently via PrepareForStartOfRun(), but
+  // not yet concluded with a NowForEndOfRun().  Usually this stack is one deep,
+  // but if a scoped region is profiled, or <sigh> a task runs a nested-message
   // loop, then the stack can grow larger.  Note that we don't try to deduct
   // time in nested porfiles, as our current timer is based on wall-clock time,
   // and not CPU time (and we're hopeful that nested timing won't be a
   // significant additional cost).
   ParentStack parent_stack_;
 
   // A random number that we used to select decide which sample to keep as a
   // representative sample in each DeathData instance.  We can't start off with
   // 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. Stopwatches
+// coordinate with the stopwatches in which they are nested to avoid
+// double-counting nested tasks run times.
+
+class BASE_EXPORT TaskStopwatch {
+ public:
+  // Starts the stopwatch.
+  TaskStopwatch();
+  ~TaskStopwatch();
+
+  // Stops stopwatch.
+  void Stop();
+
+  // Returns the start time.
+  TrackedTime StartTime() const;
+
+  // Task's duration is calculated as the wallclock duration between starting
+  // and stopping this stopwatch, minus the wallclock durations of any other
+  // instances that are immediately nested in this one, started and stopped on
+  // this thread during that period.
+  int32 RunDurationMs() const;
+
+  // Returns tracking info for the current thread.
+  ThreadData* GetThreadData() 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_;
+
+  // Sum of wallclock durations of all stopwatches that were directly nested in
+  // this one.
+  int32 excluded_duration_ms_;
+
+  // Stopwatch which was running on our thread when this stopwatch was started.
+  // That preexisting stopwatch must be adjusted to the exclude the wallclock
+  // duration of this stopwatch.
+  TaskStopwatch* parent_;
+
+#if DCHECK_IS_ON
+  // State of the stopwatch. Stopwatch is first constructed in a running state,
+  // then stopped, then destructed.
+  enum {
+    RUNNING,
+    STOPPED
+  } state_;
+
+  // Currently running stopwatch that is directly nested in this one, if such
+  // stopwatch exists. NULL otherwise.
+  TaskStopwatch* 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_