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);
+  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. Stopwatches
+// coordinate with the stopwatches in which they are nested 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);

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

nit: I mentioned this elsewhere... Any reason why we don't feed the start_time
into the constructor, and avoid having this method?

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

See my answer in another comment.

+
+  // Starts stopwatch with the current time.
+  void Start() { Start(ThreadData::Now()); }

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

nit: You can't overload... but I suspect that only one of these methods is
needed (or maybe just the constructor will do it all by default).

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

Done.

+
+  // Stops stopwatch with the specified |start_time|.

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

nit: typo: start_time --> end_time

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

Done.

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

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

nits: There is no real guarantee this is "wallclock time" so perhaps:


 Task's durataion is calculated as the wallclock time
 difference between stopping the stopwatch and starting it, minus time
 spent in immediately nested stopwatches.

Might become:

  Task's duration is calculated as the duration between starting and stopping
this stopwatch, minus the lifetime durations of any other instances constructed
and destroyed on this thread during that period.

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

Done, but I added a passage about being directly nested. Another comment
explains why I need to care about direct nesting.

+  int32 RunDurationMs() const;
+
+  // Returns tracking info for the current thread.
+  ThreadData * GetThreadData() const;

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

nit: no space before the "*".

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

Done.

+
+ private:
+  // Time when the stopwatch was started.
+  TrackedTime start_time_;
+
+  // Wallclock duration of the task.
+  int32 wallclock_duration_ms_;

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

I don't see why this is stored, rather than being calculated dynamically at the
one point where it is requested.

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

Then I'd have to replace it with storing end_time, which has higher overhead.

+
+  // Tracking info for the current thread.
+  ThreadData* current_thread_data_;
+
+  // Total duration of all completed stopwatches that were directly nested in
+  // this one.

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

I expect you'll really need to sum (recursively) all stopwatches on this thread,
not just the directly nested ones.

I think you do it correctly... but this prose seems confusing.  Perhaps get rid
of the word "directly".  WDYT?

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

I believe summing only first-level nested stopwatches is correct, otherwise, as
shown in another comment, we can get strange things like negative task times.
The code works as the comment says, i.e. doesn't do it recursively.

+  int32 nested_stopwatches_duration_ms_;

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

nit: better name might be "excluded_duration_"

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

Done, but I added units to the name.

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

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

IMO, should be:

...exclude the duration the lifetime of this stopwatch (which may be more than
the duration of this stopwatch!).

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

I added "of the lifetime".

It's not clear what's difference between duration of the stopwatch and duration
of the lifetime of the stopwatch, though. Could you clarify?

[jar (doing other things), 2014/08/26 19:33:36]

I meant "lifetime" to be time from construction to destruction, with no
adjustments.

I meant "duration of the stopwatch" to be the return of the RunDuration()
method, which excludes time(s) in any nested stopwatch.

The "lifetime" implicitly sums (includes?) RunDuration() plus all the durations
in nested stopwatches (without any need for recursive arithmetic).

[vadimt, 2014/08/26 19:47:45]

OK. Since I believe that there are reasons to have Start and Stop methods, I
suggest to aboid using "lifetime" word. I suggest to use:

(1) "Wallclock duration" for non-adjusted diration;
(2) "Duration" for adjusted duration.

I'm starting changing names and comments according to these, but feel free to
interrupt me with better suggestions.

+  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 is directly nested in this one, if such
+  // stopwatch exists. NULL otherwise.
+  TaskStopwatch* running_child_;

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

nit: My preference would be to avoid putting test code into the class.  If you
really want these backwards pointers, you could (in your tests) maintain an
external set of pointers to the nested stopwatches, etc.

The code will get especially messy when you need to optionally provide
constructors to initialize this pointer... but even if you used something
fancier, it would make the live code messier.

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

This is not a test code. This is a code that helps quickly catching bugs while
you are in a debug mode. It will be MUCH-MUCH_MUCH harder to find issues after
you've missed the chance to get them diagnosed as an assert in debug mode.

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