Introducing phased profiling framework

base/tracked_objects.cc

 // 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.
 
 #include "base/tracked_objects.h"
 
 #include <limits.h>
 #include <stdlib.h>
 
 #include "base/atomicops.h"
@@ skipping 209 matching lines @@
 
 //------------------------------------------------------------------------------
 Births::Births(const Location& location, const ThreadData& current)
     : BirthOnThread(location, current),
       birth_count_(1) { }
 
 int Births::birth_count() const { return birth_count_; }
 
 void Births::RecordBirth() { ++birth_count_; }
 
+void Births::SubtractBirths(int count) {
+  birth_count_ -= count;
+}
+
 //------------------------------------------------------------------------------
 // ThreadData maintains the central data for all births and deaths on a single
 // thread.
 
 // TODO(jar): We should pull all these static vars together, into a struct, and
 // optimize layout so that we benefit from locality of reference during accesses
 // to them.
 
 // static
 NowFunction* ThreadData::now_function_ = NULL;
@@ skipping 22 matching lines @@
 // static
 ThreadData* ThreadData::first_retired_worker_ = NULL;
 
 // static
 base::LazyInstance<base::Lock>::Leaky
     ThreadData::list_lock_ = LAZY_INSTANCE_INITIALIZER;
 
 // static
 ThreadData::Status ThreadData::status_ = ThreadData::UNINITIALIZED;
 
+// static
+base::LazyInstance<PhasedProcessDataSnapshots>
+    ThreadData::completed_phases_snapshots_ = LAZY_INSTANCE_INITIALIZER;
+
 ThreadData::ThreadData(const std::string& suggested_name)
     : next_(NULL),
       next_retired_worker_(NULL),
       worker_thread_number_(0),
       incarnation_count_for_pool_(-1),
       current_stopwatch_(NULL) {
   DCHECK_GE(suggested_name.size(), 0u);
   thread_name_ = suggested_name;
   PushToHeadOfList();  // Which sets real incarnation_count_for_pool_.
 }
@@ skipping 101 matching lines @@
     return;
   }
   // We must NOT do any allocations during this callback.
   // Using the simple linked lists avoids all allocations.
   DCHECK_EQ(this->next_retired_worker_, reinterpret_cast<ThreadData*>(NULL));
   this->next_retired_worker_ = first_retired_worker_;
   first_retired_worker_ = this;
 }
 
 // static
-void ThreadData::Snapshot(ProcessDataSnapshot* process_data) {
-  // 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, &birth_counts);
+void ThreadData::GetProcessDataSnapshot(
+    int current_profiling_phase,
+    ProcessDataSnapshot* process_data_snapshot) {
+  process_data_snapshot->phased_process_data_snapshots =
+      completed_phases_snapshots_.Get();
+  ThreadData::Snapshot(
+      false, &process_data_snapshot
+                  ->phased_process_data_snapshots[current_profiling_phase]);
+}
 
-  // 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 (BirthCountMap::const_iterator it = birth_counts.begin();
-       it != birth_counts.end(); ++it) {
-    if (it->second > 0) {
-      process_data->tasks.push_back(
-          TaskSnapshot(*it->first, DeathData(it->second), "Still_Alive"));
-    }
-  }
+// static
+void ThreadData::OnProfilingPhaseCompletion(int profiling_phase) {
+  if (!kTrackAllTaskObjects)
+    return;  // Not compiled in.
+
+  ThreadData::Snapshot(true,
+                       &completed_phases_snapshots_.Get()[profiling_phase]);

[Alexei Svitkine (slow), 2015/03/06 20:06:40]

Can this function check that this isn't calling with the same profiling phase
multiple times?

[vadimt, 2015/03/06 21:34:58]

Done.

 }
 
 Births* ThreadData::TallyABirth(const Location& location) {
   BirthMap::iterator it = birth_map_.find(location);
   Births* child;
   if (it != birth_map_.end()) {
     child =  it->second;
     child->RecordBirth();
   } else {
     child = new Births(location, *this);  // Leak this.
@@ skipping 11 matching lines @@
       // Lock since the map may get relocated now, and other threads sometimes
       // snapshot it (but they lock before copying it).
       base::AutoLock lock(map_lock_);
       parent_child_set_.insert(pair);
     }
   }
 
   return child;
 }
 
-void ThreadData::TallyADeath(const Births& birth,
-                             int32 queue_duration,
-                             const TaskStopwatch& stopwatch) {
+void ThreadData::TallyADeath(int32 queue_duration,
+                             const TaskStopwatch& stopwatch,
+                             Births* birth) {
   int32 run_duration = stopwatch.RunDurationMs();
 
   // Stir in some randomness, plus add constant in case durations are zero.
   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>(birth - 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
   // queue times are invalid, unless it was explicitly said that we can trust
   // the alternate timer.
   if (kAllowAlternateTimeSourceHandling &&
       now_function_ &&
       !now_function_is_time_) {
     queue_duration = 0;
   }
 
-  DeathMap::iterator it = death_map_.find(&birth);
+  DeathMap::iterator it = death_map_.find(birth);
   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_[birth];
   }  // 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(), birth);
     parent_stack_.pop();
   }
 }
 
 // static
 Births* ThreadData::TallyABirthIfActive(const Location& location) {
   if (!kTrackAllTaskObjects)
     return NULL;  // Not compiled in.
 
   if (!TrackingStatus())
     return NULL;
   ThreadData* current_thread_data = Get();
   if (!current_thread_data)
     return NULL;
   return current_thread_data->TallyABirth(location);
 }
 
 // static
 void ThreadData::TallyRunOnNamedThreadIfTracking(
     const base::TrackingInfo& completed_task,
     const TaskStopwatch& stopwatch) {
   if (!kTrackAllTaskObjects)
     return;  // Not compiled in.
 
   // 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;
+  Births* birth = completed_task.birth_tally;
   if (!birth)
     return;
   ThreadData* current_thread_data = stopwatch.GetThreadData();
   if (!current_thread_data)
     return;
 
   // Watch out for a race where status_ is changing, and hence one or both
   // of start_of_run or end_of_run is zero.  In that case, we didn't bother to
   // get a time value since we "weren't tracking" and we were trying to be
   // efficient by not calling for a genuine time value. For simplicity, we'll
   // use a default zero duration when we can't calculate a true value.
   TrackedTime start_of_run = stopwatch.StartTime();
   int32 queue_duration = 0;
   if (!start_of_run.is_null()) {
     queue_duration = (start_of_run - completed_task.EffectiveTimePosted())
         .InMilliseconds();
   }
-  current_thread_data->TallyADeath(*birth, queue_duration, stopwatch);
+  current_thread_data->TallyADeath(queue_duration, stopwatch, birth);
 }
 
 // static
 void ThreadData::TallyRunOnWorkerThreadIfTracking(
-    const Births* birth,
     const TrackedTime& time_posted,
-    const TaskStopwatch& stopwatch) {
+    const TaskStopwatch& stopwatch,
+    Births* birth) {
   if (!kTrackAllTaskObjects)
     return;  // Not compiled in.
 
   // 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)
     return;
 
   // TODO(jar): Support the option to coalesce all worker-thread activity under
   // one ThreadData instance that uses locks to protect *all* access.  This will
   // reduce memory (making it provably bounded), but run incrementally slower
   // (since we'll use locks on TallyABirth and TallyADeath).  The good news is
   // that the locks on TallyADeath will be *after* the worker thread has run,
   // and hence nothing will be waiting for the completion (... besides some
   // other thread that might like to run).  Also, the worker threads tasks are
   // generally longer, and hence the cost of the lock may perchance be amortized
   // over the long task's lifetime.
   ThreadData* current_thread_data = stopwatch.GetThreadData();
   if (!current_thread_data)
     return;
 
   TrackedTime start_of_run = stopwatch.StartTime();
   int32 queue_duration = 0;
   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(queue_duration, stopwatch, birth);
 }
 
 // static
 void ThreadData::TallyRunInAScopedRegionIfTracking(
-    const Births* birth,
-    const TaskStopwatch& stopwatch) {
+    const TaskStopwatch& stopwatch,
+    Births* birth) {
   if (!kTrackAllTaskObjects)
     return;  // Not compiled in.
 
   // 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)
     return;
 
   ThreadData* current_thread_data = stopwatch.GetThreadData();
   if (!current_thread_data)
     return;
 
   int32 queue_duration = 0;
-  current_thread_data->TallyADeath(*birth, queue_duration, stopwatch);
+  current_thread_data->TallyADeath(queue_duration, stopwatch, birth);
 }
 
 // static
-void ThreadData::SnapshotAllExecutedTasks(ProcessDataSnapshot* process_data,
-                                          BirthCountMap* birth_counts) {
+void ThreadData::SnapshotAllExecutedTasks(
+    bool reset,
+    ProcessDataPhaseSnapshot* process_data_phase,
+    BirthCountMap* birth_counts) {
   if (!kTrackAllTaskObjects)
     return;  // Not compiled in.
 
   // 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, birth_counts);
+    thread_data->SnapshotExecutedTasks(reset, process_data_phase, birth_counts);
   }
 }
 
-void ThreadData::SnapshotExecutedTasks(ProcessDataSnapshot* process_data,
-                                       BirthCountMap* birth_counts) {
+// static
+void ThreadData::Snapshot(bool reset,
+                          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(reset, 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& i : birth_counts) {
+    if (i.second > 0) {
+      process_data_phase->tasks.push_back(
+          TaskSnapshot(*i.first, DeathData(i.second), "Still_Alive"));
+    }
+  }
+}
+
+void ThreadData::SnapshotExecutedTasks(
+    bool reset,
+    ProcessDataPhaseSnapshot* process_data_phase,
+    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);
+  SnapshotMaps(reset, &birth_map, &death_map, &parent_child_set);
 
-  for (ThreadData::DeathMap::const_iterator it = death_map.begin();
-       it != death_map.end(); ++it) {
-    process_data->tasks.push_back(
-        TaskSnapshot(*it->first, it->second, thread_name()));
-    (*birth_counts)[it->first] -= it->first->birth_count();
+  for (const auto& i : death_map) {
+    process_data_phase->tasks.push_back(
+        TaskSnapshot(*i.first, i.second, thread_name()));
+    // We don't populate birth_counts if |reset| is true.
+    if (!reset)
+      (*birth_counts)[i.first] -= i.first->birth_count();
   }
 
-  for (ThreadData::BirthMap::const_iterator it = birth_map.begin();
-       it != birth_map.end(); ++it) {
-    (*birth_counts)[it->second] += it->second->birth_count();
+  for (const auto& i : birth_map) {
+    (*birth_counts)[i.second] += i.second->birth_count();
   }
 
   if (!kTrackParentChildLinks)
     return;
 
-  for (ThreadData::ParentChildSet::const_iterator it = parent_child_set.begin();
-       it != parent_child_set.end(); ++it) {
-    process_data->descendants.push_back(ParentChildPairSnapshot(*it));
+  for (const auto& i : parent_child_set) {
+    process_data_phase->descendants.push_back(ParentChildPairSnapshot(i));
   }
 }
 
 // This may be called from another thread.
-void ThreadData::SnapshotMaps(BirthMap* birth_map,
+void ThreadData::SnapshotMaps(bool reset,
+                              BirthMap* birth_map,
                               DeathMap* death_map,
                               ParentChildSet* parent_child_set) {
   base::AutoLock lock(map_lock_);
-  for (BirthMap::const_iterator it = birth_map_.begin();
-       it != birth_map_.end(); ++it)
-    (*birth_map)[it->first] = it->second;
-  for (DeathMap::iterator it = death_map_.begin();
-       it != death_map_.end(); ++it) {
-    (*death_map)[it->first] = it->second;
+  if (!reset) {
+    // When reset is not requested, snapshot births.
+    for (const auto& i : birth_map_)
+      (*birth_map)[i.first] = i.second;
+  }
+  for (auto& i : death_map_) {
+    // Don't snapshot deaths with 0 count. Deaths with 0 count can result from
+    // prior calls to SnapshotMaps with reset=true param.
+    if (i.second.count() <= 0)
+      continue;
+
+    (*death_map)[i.first] = i.second;
+    if (reset) {
+      i.first->SubtractBirths(i.second.count());
+      i.second.Clear();
+    }
   }
 
   if (!kTrackParentChildLinks)
     return;
 
-  for (ParentChildSet::iterator it = parent_child_set_.begin();
-       it != parent_child_set_.end(); ++it)
-    parent_child_set->insert(*it);
+  for (const auto& i : parent_child_set_)
+    parent_child_set->insert(i);
 }
 
 static void OptionallyInitializeAlternateTimer() {
   NowFunction* alternate_time_source = GetAlternateTimeSource();
   if (alternate_time_source)
     ThreadData::SetAlternateTimeSource(alternate_time_source);
 }
 
 bool ThreadData::Initialize() {
   if (!kTrackAllTaskObjects)
@@ skipping 163 matching lines @@
   // Do actual recursive delete in all ThreadData instances.
   while (thread_data_list) {
     ThreadData* next_thread_data = thread_data_list;
     thread_data_list = thread_data_list->next();
 
     for (BirthMap::iterator it = next_thread_data->birth_map_.begin();
          next_thread_data->birth_map_.end() != it; ++it)
       delete it->second;  // Delete the Birth Records.
     delete next_thread_data;  // Includes all Death Records.
   }
+
+  completed_phases_snapshots_.Get().clear();
 }
 
 //------------------------------------------------------------------------------
 TaskStopwatch::TaskStopwatch()
     : wallclock_duration_ms_(0),
       current_thread_data_(NULL),
       excluded_duration_ms_(0),
       parent_(NULL) {
 #if DCHECK_IS_ON()
   state_ = CREATED;
@@ skipping 108 matching lines @@
 ParentChildPairSnapshot::ParentChildPairSnapshot(
     const ThreadData::ParentChildPair& parent_child)
     : parent(*parent_child.first),
       child(*parent_child.second) {
 }
 
 ParentChildPairSnapshot::~ParentChildPairSnapshot() {
 }
 
 //------------------------------------------------------------------------------
-// ProcessDataSnapshot
+// ProcessDataPhaseSnapshot
+
+ProcessDataPhaseSnapshot::ProcessDataPhaseSnapshot() {
+}
+
+ProcessDataPhaseSnapshot::~ProcessDataPhaseSnapshot() {
+}
+
+//------------------------------------------------------------------------------
+// ProcessDataPhaseSnapshot
 
 ProcessDataSnapshot::ProcessDataSnapshot()
 #if !defined(OS_NACL)
     : process_id(base::GetCurrentProcId()) {
 #else
     : process_id(0) {
 #endif
 }
 
 ProcessDataSnapshot::~ProcessDataSnapshot() {
 }
 
 }  // namespace tracked_objects