Creating a framework for suppressing pollution of the profiler data

base/tracked_objects.h

Index: base/tracked_objects.h
diff --git a/base/tracked_objects.h b/base/tracked_objects.h
index 511a289066184074110405bb254d568473d8423a..f3412f0871ba7d5436eddae739cf55dd1e231294 100644
--- a/base/tracked_objects.h
+++ b/base/tracked_objects.h
@@ -352,6 +352,8 @@ struct BASE_EXPORT TaskSnapshot {
 // 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
@@ -403,8 +405,7 @@ class BASE_EXPORT ThreadData {
   // 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
@@ -416,15 +417,13 @@ class BASE_EXPORT ThreadData {
   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_; }
 
@@ -487,6 +486,7 @@ class BASE_EXPORT ThreadData {
   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
@@ -523,7 +523,9 @@ class BASE_EXPORT ThreadData {
   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
@@ -686,10 +688,83 @@ class BASE_EXPORT ThreadData {
   // 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.