Delivering the FIRST_NONEMPTY_PAINT phase changing event to base/

base/tracked_objects.cc

Index: base/tracked_objects.cc
diff --git a/base/tracked_objects.cc b/base/tracked_objects.cc
index a60e260b23660b31140593f6b7e0b63652a18f8b..a7c8c79e649d4640134f31dacb7ee727fbac41f0 100644
--- a/base/tracked_objects.cc
+++ b/base/tracked_objects.cc
@@ -15,6 +15,7 @@
 #include "base/logging.h"
 #include "base/process/process_handle.h"
 #include "base/profiler/alternate_timer.h"
+#include "base/stl_util.h"
 #include "base/strings/stringprintf.h"
 #include "base/third_party/valgrind/memcheck.h"
 #include "base/tracking_info.h"
@@ -93,14 +94,29 @@ inline bool IsProfilerTimingEnabled() {
 // DeathData tallies durations when a death takes place.
 
 DeathData::DeathData() {
-  Clear();
+  count_ = 0;
+  sample_probability_count_ = 0;
+  run_duration_sum_ = 0;
+  run_duration_max_ = 0;
+  run_duration_sample_ = 0;
+  queue_duration_sum_ = 0;
+  queue_duration_max_ = 0;
+  queue_duration_sample_ = 0;

[Alexei Svitkine (slow), 2015/04/08 15:55:39]

Instead of having all of these as members - which also exist in
DeathDataSnapshot - why not actually have DeathDataSnapshot be a member of this?

[vadimt, 2015/04/08 20:32:34]

As the comment says, "Members are ordered from most regularly read and updated,
to least". Looks like an optimization, like to get them to same cache line.
Placing DeathDataSnapshot to replace snapshotable fields in principle kills this
optimization, or has a potency to introduce inefficiencies if future, when/if we
introduce more non-snapshotable fields between snapshotable ones.
I'd leave the separation between serialized data and low-level-optimized
realtime data representations.

[Alexei Svitkine (slow), 2015/04/08 20:54:25]

I am actually very skeptical of that original comment, especially since it says
"it might help" - but there doesn't appear to be data to back that up.

But - we can totally order the fields in the same way in the DeathDataSnapshot
struct (with this same comment) and by including it at the same place in
DeathData, the memory layout and machine code to update those values will be the
same.

Given that it's entirely possible to maintain the previous concerns about layout
and that I believe it will improve the code quite a bit, I think its worth
making this change.

(The other alternative would be to introduce a 3rd struct - one that's only used
for the in-memory data and use it within DeathData in the same way I suggest
DeathDataSnapshot be used - this will also fix the same circular dependency
issue that I mentioned, so I would still prefer that over the current approach -
but I don't buy the value of keeping the runtime and snapshot data separate if
the same struct can be used to represent both.)

[vadimt, 2015/04/08 21:27:17]

jar@ told me that cache lines on Android may be very small. I'd not risk with
reordering the fields.

It's not hard for me to reorder the fields in DeathData etc, and the could would
indeed become more elegant. However, consider a non-snapshottable field
sample_probability_count_. You can't include it in DeathDataSnapshot (no need to
snapshot). So, you'd have to place it before DeathDataSnapshot.
That's OK for now, but may a an early sign of future problems. Some
non-snapshottable fields may need to be inserted in the middle of DeathData, and
at that point, we are broken.
This separation seems to be essentially right thing, and we don't leak runtime
considerations to the serialized structure.

[Alexei Svitkine (slow), 2015/04/08 21:57:49]

Fine, but I'm still not OK with the circular dependency between the two classes.
I suggest then either passing all the values as params to the ctor of the
snapshot - instead of *this - or just setting them on the snapshot after
construction. That way, there's only a dependency in a single direction.

[vadimt, 2015/04/08 23:31:24]

Done, but not sure I like the result...
Since DeathDataSnapshot and DeathDataPhaseSnapshot are created in several
places, I chose to pass all fields as params, for safety.

So, we see long lists of params here and there. Perhaps, there is a way to
introduce an additional structure, but this'd come with added complexity (for
understanding), too.

Here we go.

+  last_phase_snapshot_ = nullptr;
 }
 
-DeathData::DeathData(int count) {
-  Clear();
+DeathData::DeathData(int count) : DeathData() {
   count_ = count;
 }
 
+DeathData::~DeathData() {
+  while (last_phase_snapshot_) {
+    DeathDataPhaseSnapshot* snapshot = last_phase_snapshot_;
+    last_phase_snapshot_ = snapshot->prev;
+    delete snapshot;
+  }
+}
+
 // TODO(jar): I need to see if this macro to optimize branching is worth using.
 //
 // This macro has no branching, so it is surely fast, and is equivalent to:
@@ -117,6 +133,8 @@ void DeathData::RecordDeath(const int32 queue_duration,
   // We'll just clamp at INT_MAX, but we should note this in the UI as such.
   if (count_ < INT_MAX)
     ++count_;
+  if (sample_probability_count_ < INT_MAX)
+    ++sample_probability_count_;
   queue_duration_sum_ += queue_duration;
   run_duration_sum_ += run_duration;
 
@@ -125,14 +143,16 @@ void DeathData::RecordDeath(const int32 queue_duration,
   if (run_duration_max_ < run_duration)
     run_duration_max_ = run_duration;
 
-  // Take a uniformly distributed sample over all durations ever supplied.
-  // The probability that we (instead) use this new sample is 1/count_.  This
-  // results in a completely uniform selection of the sample (at least when we
-  // don't clamp count_... but that should be inconsequentially likely).
-  // We ignore the fact that we correlated our selection of a sample to the run
-  // and queue times (i.e., we used them to generate random_number).
-  CHECK_GT(count_, 0);
-  if (0 == (random_number % count_)) {
+  // Take a uniformly distributed sample over all durations ever supplied during
+  // currrent profiling phase.
+  // The probability that we (instead) use this new sample is
+  // 1/sample_probability_count_. This results in a completely uniform selection
+  // of the sample (at least when we don't clamp sample_probability_count_...
+  // but that should be inconsequentially likely). We ignore the fact that we
+  // correlated our selection of a sample to the run and queue times (i.e., we
+  // used them to generate random_number).
+  CHECK_GT(sample_probability_count_, 0);
+  if (0 == (random_number % sample_probability_count_)) {
     queue_duration_sample_ = queue_duration;
     run_duration_sample_ = run_duration;
   }
@@ -160,14 +180,21 @@ int32 DeathData::queue_duration_sample() const {
   return queue_duration_sample_;
 }
 
-void DeathData::Clear() {
-  count_ = 0;
-  run_duration_sum_ = 0;
+DeathDataPhaseSnapshot* DeathData::last_phase_snapshot() const {
+  return last_phase_snapshot_;
+}
+
+void DeathData::OnProfilingPhaseCompleted(int profiling_phase) {
+  // Snapshotting and storing current state.
+  last_phase_snapshot_ = new DeathDataPhaseSnapshot(profiling_phase, *this);

[Alexei Svitkine (slow), 2015/04/08 15:55:38]

Eek, I really don't like this circular reference between DeathData and
DeathDataPhaseSnapshot.

However, if DeathData instead has a DeathDataSnapshot as a member, this circle
can be broken by making the ctor take the DeathDataSnapshot member param and the
last_phase_snapshot, instead of *this.

[vadimt, 2015/04/08 20:32:34]

Beautiful, but perhaps suboptimal, as per previous comment.

+
+  // Not touching fields for which a delta can be computed by comparing with a
+  // snapshot from previos phase. Resetting other fields. Sample values will be
+  // reset upon next death recording because sample_probability_count_ is set to
+  // 0.
+  sample_probability_count_ = 0;
   run_duration_max_ = 0;
-  run_duration_sample_ = 0;
-  queue_duration_sum_ = 0;
   queue_duration_max_ = 0;
-  queue_duration_sample_ = 0;
 }
 
 //------------------------------------------------------------------------------
@@ -195,6 +222,12 @@ DeathDataSnapshot::DeathDataSnapshot(
 DeathDataSnapshot::~DeathDataSnapshot() {
 }
 
+void DeathDataSnapshot::CalculateDelta(const DeathDataSnapshot& older) {
+  count -= older.count;
+  run_duration_sum -= older.run_duration_sum;
+  queue_duration_sum -= older.queue_duration_sum;
+}
+
 //------------------------------------------------------------------------------
 BirthOnThread::BirthOnThread(const Location& location,
                              const ThreadData& current)
@@ -385,9 +418,54 @@ void ThreadData::OnThreadTerminationCleanup() {
 }
 
 // static
-void ThreadData::Snapshot(ProcessDataSnapshot* process_data_snapshot) {
-  ThreadData::SnapshotCurrentPhase(
-      &process_data_snapshot->phased_process_data_snapshots[0]);
+void ThreadData::Snapshot(int current_profiling_phase,
+                          ProcessDataSnapshot* process_data_snapshot) {
+  BirthCountMap birth_counts;
+
+  // Get an unchanging copy of a ThreadData list.
+  ThreadData* my_list = ThreadData::first();
+
+  // Gather data serially.
+  // This hackish approach *can* get some slighly corrupt tallies, as we are
+  // grabbing values without the protection of a lock, but it has the advantage
+  // of working even with threads that don't have message loops.  If a user
+  // sees any strangeness, they can always just run their stats gathering a
+  // second time.
+  for (ThreadData* thread_data = my_list; thread_data;
+       thread_data = thread_data->next()) {
+    thread_data->SnapshotExecutedTasks(
+        current_profiling_phase,
+        &process_data_snapshot->phased_process_data_snapshots, &birth_counts);
+  }
+
+  // Add births that are still active -- i.e. objects that have tallied a birth,
+  // but have not yet tallied a matching death, and hence must be either
+  // running, queued up, or being held in limbo for future posting.
+  for (const auto& birth_count : birth_counts) {
+    if (birth_count.second > 0) {
+      process_data_snapshot
+          ->phased_process_data_snapshots[current_profiling_phase]
+          .tasks.push_back(TaskSnapshot(
+              BirthOnThreadSnapshot(*birth_count.first),
+              DeathDataSnapshot(DeathData(birth_count.second)), "Still_Alive"));
+    }
+  }
+}
+
+// static
+void ThreadData::OnProfilingPhaseCompleted(int profiling_phase) {
+  // Get an unchanging copy of a ThreadData list.
+  ThreadData* my_list = ThreadData::first();
+
+  // Add snapshots for all death datas in all threads serially.
+  // This hackish approach *can* get some slighly corrupt tallies, as we are
+  // grabbing values without the protection of a lock, but it has the advantage
+  // of working even with threads that don't have message loops. Any corruption
+  // shouldn't cause "cascading damage" to anything else (in later phases).
+  for (ThreadData* thread_data = my_list; thread_data;
+       thread_data = thread_data->next()) {
+    thread_data->OnProfilingPhaseCompletionOnThread(profiling_phase);
+  }
 }
 
 Births* ThreadData::TallyABirth(const Location& location) {
@@ -419,7 +497,7 @@ Births* ThreadData::TallyABirth(const Location& location) {
   return child;
 }
 
-void ThreadData::TallyADeath(const Births& birth,
+void ThreadData::TallyADeath(const Births& births,
                              int32 queue_duration,
                              const TaskStopwatch& stopwatch) {
   int32 run_duration = stopwatch.RunDurationMs();
@@ -428,7 +506,7 @@ void ThreadData::TallyADeath(const Births& birth,
   const uint32 kSomePrimeNumber = 2147483647;
   random_number_ += queue_duration + run_duration + kSomePrimeNumber;
   // An address is going to have some randomness to it as well ;-).
-  random_number_ ^= static_cast<uint32>(&birth - reinterpret_cast<Births*>(0));
+  random_number_ ^= static_cast<uint32>(&births - reinterpret_cast<Births*>(0));
 
   // We don't have queue durations without OS timer. OS timer is automatically
   // used for task-post-timing, so the use of an alternate timer implies all
@@ -440,20 +518,20 @@ void ThreadData::TallyADeath(const Births& birth,
     queue_duration = 0;
   }
 
-  DeathMap::iterator it = death_map_.find(&birth);
+  DeathMap::iterator it = death_map_.find(&births);
   DeathData* death_data;
   if (it != death_map_.end()) {
     death_data = &it->second;
   } else {
     base::AutoLock lock(map_lock_);  // Lock as the map may get relocated now.
-    death_data = &death_map_[&birth];
+    death_data = &death_map_[&births];
   }  // Release lock ASAP.
   death_data->RecordDeath(queue_duration, run_duration, random_number_);
 
   if (!kTrackParentChildLinks)
     return;
   if (!parent_stack_.empty()) {  // We might get turned off.
-    DCHECK_EQ(parent_stack_.top(), &birth);
+    DCHECK_EQ(parent_stack_.top(), &births);
     parent_stack_.pop();
   }
 }
@@ -475,8 +553,8 @@ void ThreadData::TallyRunOnNamedThreadIfTracking(
   // Even if we have been DEACTIVATED, we will process any pending births so
   // that our data structures (which counted the outstanding births) remain
   // consistent.
-  const Births* birth = completed_task.birth_tally;
-  if (!birth)
+  const Births* births = completed_task.birth_tally;
+  if (!births)
     return;
   ThreadData* current_thread_data = stopwatch.GetThreadData();
   if (!current_thread_data)
@@ -493,18 +571,18 @@ void ThreadData::TallyRunOnNamedThreadIfTracking(
     queue_duration = (start_of_run - completed_task.EffectiveTimePosted())
         .InMilliseconds();
   }
-  current_thread_data->TallyADeath(*birth, queue_duration, stopwatch);
+  current_thread_data->TallyADeath(*births, queue_duration, stopwatch);
 }
 
 // static
 void ThreadData::TallyRunOnWorkerThreadIfTracking(
-    const Births* birth,
+    const Births* births,
     const TrackedTime& time_posted,
     const TaskStopwatch& stopwatch) {
   // Even if we have been DEACTIVATED, we will process any pending births so
   // that our data structures (which counted the outstanding births) remain
   // consistent.
-  if (!birth)
+  if (!births)
     return;
 
   // TODO(jar): Support the option to coalesce all worker-thread activity under
@@ -525,17 +603,17 @@ void ThreadData::TallyRunOnWorkerThreadIfTracking(
   if (!start_of_run.is_null()) {
     queue_duration = (start_of_run - time_posted).InMilliseconds();
   }
-  current_thread_data->TallyADeath(*birth, queue_duration, stopwatch);
+  current_thread_data->TallyADeath(*births, queue_duration, stopwatch);
 }
 
 // static
 void ThreadData::TallyRunInAScopedRegionIfTracking(
-    const Births* birth,
+    const Births* births,
     const TaskStopwatch& stopwatch) {
   // Even if we have been DEACTIVATED, we will process any pending births so
   // that our data structures (which counted the outstanding births) remain
   // consistent.
-  if (!birth)
+  if (!births)
     return;
 
   ThreadData* current_thread_data = stopwatch.GetThreadData();
@@ -543,87 +621,56 @@ void ThreadData::TallyRunInAScopedRegionIfTracking(
     return;
 
   int32 queue_duration = 0;
-  current_thread_data->TallyADeath(*birth, queue_duration, stopwatch);
-}
-
-// static
-void ThreadData::SnapshotAllExecutedTasks(
-    ProcessDataPhaseSnapshot* process_data_phase,
-    BirthCountMap* birth_counts) {
-  // Get an unchanging copy of a ThreadData list.
-  ThreadData* my_list = ThreadData::first();
-
-  // Gather data serially.
-  // This hackish approach *can* get some slighly corrupt tallies, as we are
-  // grabbing values without the protection of a lock, but it has the advantage
-  // of working even with threads that don't have message loops.  If a user
-  // sees any strangeness, they can always just run their stats gathering a
-  // second time.
-  for (ThreadData* thread_data = my_list;
-       thread_data;
-       thread_data = thread_data->next()) {
-    thread_data->SnapshotExecutedTasks(process_data_phase, birth_counts);
-  }
-}
-
-// static
-void ThreadData::SnapshotCurrentPhase(
-    ProcessDataPhaseSnapshot* process_data_phase) {
-  // Add births that have run to completion to |collected_data|.
-  // |birth_counts| tracks the total number of births recorded at each location
-  // for which we have not seen a death count.
-  BirthCountMap birth_counts;
-  ThreadData::SnapshotAllExecutedTasks(process_data_phase, &birth_counts);
-
-  // Add births that are still active -- i.e. objects that have tallied a birth,
-  // but have not yet tallied a matching death, and hence must be either
-  // running, queued up, or being held in limbo for future posting.
-  for (const auto& birth_count : birth_counts) {
-    if (birth_count.second > 0) {
-      process_data_phase->tasks.push_back(TaskSnapshot(
-          *birth_count.first, DeathData(birth_count.second), "Still_Alive"));
-    }
-  }
+  current_thread_data->TallyADeath(*births, queue_duration, stopwatch);
 }
 
 void ThreadData::SnapshotExecutedTasks(
-    ProcessDataPhaseSnapshot* process_data_phase,
+    int current_profiling_phase,
+    PhasedProcessDataSnapshotMap* phased_process_data_snapshots,
     BirthCountMap* birth_counts) {
   // Get copy of data, so that the data will not change during the iterations
   // and processing.
-  ThreadData::BirthMap birth_map;
-  ThreadData::DeathMap death_map;
-  ThreadData::ParentChildSet parent_child_set;
-  SnapshotMaps(&birth_map, &death_map, &parent_child_set);
-
-  for (const auto& death : death_map) {
-    process_data_phase->tasks.push_back(
-        TaskSnapshot(*death.first, death.second, thread_name()));
-    (*birth_counts)[death.first] -= death.first->birth_count();
-  }
+  BirthMap birth_map;
+  DeathsSnapshot deaths;
+  ParentChildSet parent_child_set;
+  SnapshotMaps(current_profiling_phase, &birth_map, &deaths, &parent_child_set);
 
   for (const auto& birth : birth_map) {
     (*birth_counts)[birth.second] += birth.second->birth_count();
   }
 
-  if (!kTrackParentChildLinks)
-    return;
+  for (const auto& death : deaths) {
+    (*birth_counts)[death.first] -= death.first->birth_count();
+
+    for (const DeathDataPhaseSnapshot* phase = &death.second; phase;
+         phase = phase->prev) {
+      DeathDataSnapshot death_data = phase->death_data;
+
+      if (phase->prev)
+        death_data.CalculateDelta(phase->prev->death_data);
 
-  for (const auto& parent_child : parent_child_set) {
-    process_data_phase->descendants.push_back(
-        ParentChildPairSnapshot(parent_child));
+      if (death_data.count > 0)

[Alexei Svitkine (slow), 2015/04/08 15:55:39]

Nit: {}

[vadimt, 2015/04/08 20:32:34]

Done.

+        (*phased_process_data_snapshots)[phase->profiling_phase]
+            .tasks.push_back(TaskSnapshot(BirthOnThreadSnapshot(*death.first),
+                                          death_data, thread_name()));
+    }
   }
 }
 
 // This may be called from another thread.
-void ThreadData::SnapshotMaps(BirthMap* birth_map,
-                              DeathMap* death_map,
+void ThreadData::SnapshotMaps(int profiling_phase,
+                              BirthMap* birth_map,
+                              DeathsSnapshot* deaths,
                               ParentChildSet* parent_child_set) {
   base::AutoLock lock(map_lock_);
+
   for (const auto& birth : birth_map_)
     (*birth_map)[birth.first] = birth.second;
-  for (const auto& death : death_map_)
-    (*death_map)[death.first] = death.second;
+
+  for (const auto& death : death_map_) {
+    deaths->push_back(DeathsSnapshot::value_type(
+        death.first, DeathDataPhaseSnapshot(profiling_phase, death.second)));
+  }
 
   if (!kTrackParentChildLinks)
     return;
@@ -632,6 +679,14 @@ void ThreadData::SnapshotMaps(BirthMap* birth_map,
     parent_child_set->insert(parent_child);
 }
 
+void ThreadData::OnProfilingPhaseCompletionOnThread(int profiling_phase) {
+  base::AutoLock lock(map_lock_);
+
+  for (auto& death : death_map_) {
+    death.second.OnProfilingPhaseCompleted(profiling_phase);
+  }
+}
+
 static void OptionallyInitializeAlternateTimer() {
   NowFunction* alternate_time_source = GetAlternateTimeSource();
   if (alternate_time_source)
@@ -909,11 +964,23 @@ ThreadData* TaskStopwatch::GetThreadData() const {
 }
 
 //------------------------------------------------------------------------------
+// DeathDataPhaseSnapshot
+
+DeathDataPhaseSnapshot::DeathDataPhaseSnapshot(int profiling_phase,
+                                               const DeathData& death_data)
+    : profiling_phase(profiling_phase),
+      death_data(death_data),
+      prev(death_data.last_phase_snapshot()) {
+}
+
+//------------------------------------------------------------------------------
+// TaskSnapshot
+
 TaskSnapshot::TaskSnapshot() {
 }
 
-TaskSnapshot::TaskSnapshot(const BirthOnThread& birth,
-                           const DeathData& death_data,
+TaskSnapshot::TaskSnapshot(const BirthOnThreadSnapshot& birth,
+                           const DeathDataSnapshot& death_data,
                            const std::string& death_thread_name)
     : birth(birth),
       death_data(death_data),