Detect child tasks born during a profiled tasks

base/tracked_objects.cc

 // Copyright (c) 2011 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 <math.h>
 
 #include "base/format_macros.h"
 #include "base/message_loop.h"
 #include "base/stringprintf.h"
 #include "base/third_party/valgrind/memcheck.h"
 #include "base/threading/thread_restrictions.h"
 #include "build/build_config.h"
 #include "base/port.h"
 
 using base::TimeDelta;
 
 namespace tracked_objects {
 
 namespace {
 // Flag to compile out almost all of the task tracking code.
 static const bool kTrackAllTaskObjects = true;
 
+// Flag to compile out parent-child link recording.
+static const bool kTrackParentChildLinks = false;
+
 // When ThreadData is first initialized, should we start in an ACTIVE state to
 // record all of the startup-time tasks, or should we start up DEACTIVATED, so
 // that we only record after parsing the command line flag --enable-tracking.
 // Note that the flag may force either state, so this really controls only the
 // period of time up until that flag is parsed. If there is no flag seen, then
 // this state may prevail for much or all of the process lifetime.
-static const ThreadData::Status kInitialStartupState = ThreadData::ACTIVE;
-}  // anonymous namespace.
+static const ThreadData::Status kInitialStartupState = ThreadData::FULLY_ACTIVE;
+}  // namespace
 
 //------------------------------------------------------------------------------
 // DeathData tallies durations when a death takes place.
 
 DeathData::DeathData() {
   Clear();
 }
 
 DeathData::DeathData(int count) {
   Clear();
@@ skipping 92 matching lines @@
 //------------------------------------------------------------------------------
 BirthOnThread::BirthOnThread(const Location& location,
                              const ThreadData& current)
     : location_(location),
       birth_thread_(&current) {
 }
 
 const Location BirthOnThread::location() const { return location_; }
 const ThreadData* BirthOnThread::birth_thread() const { return birth_thread_; }
 
+void BirthOnThread::ToValue(const std::string& prefix,
+                            base::DictionaryValue* dictionary) const {
+  dictionary->Set(prefix + "_location", location_.ToValue());
+  dictionary->Set(prefix + "_thread",
+                  base::Value::CreateStringValue(birth_thread_->thread_name()));
+}
+
 //------------------------------------------------------------------------------
 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::ForgetBirth() { --birth_count_; }
@@ skipping 31 matching lines @@
 
 // static
 base::LazyInstance<base::Lock,
                    base::LeakyLazyInstanceTraits<base::Lock> >
     ThreadData::list_lock_ = LAZY_INSTANCE_INITIALIZER;
 
 // static
 ThreadData::Status ThreadData::status_ = ThreadData::UNINITIALIZED;
 
 ThreadData::ThreadData(const std::string& suggested_name)
-    : incarnation_count_for_pool_(-1),
-      next_(NULL),
+    : next_(NULL),
       next_retired_worker_(NULL),
-      worker_thread_number_(0) {
+      worker_thread_number_(0),
+      incarnation_count_for_pool_(-1) {
   DCHECK_GE(suggested_name.size(), 0u);
   thread_name_ = suggested_name;
   PushToHeadOfList();  // Which sets real incarnation_count_for_pool_.
 }
 
 ThreadData::ThreadData(int thread_number)
-    : incarnation_count_for_pool_(-1),
-      next_(NULL),
+    : next_(NULL),
       next_retired_worker_(NULL),
-      worker_thread_number_(thread_number) {
+      worker_thread_number_(thread_number),
+      incarnation_count_for_pool_(-1)  {
   CHECK_GT(thread_number, 0);
   base::StringAppendF(&thread_name_, "WorkerThread-%d", thread_number);
   PushToHeadOfList();  // Which sets real incarnation_count_for_pool_.
 }
 
 ThreadData::~ThreadData() {}
 
 void ThreadData::PushToHeadOfList() {
   // Toss in a hint of randomness (atop the uniniitalized value).
   (void)VALGRIND_MAKE_MEM_DEFINED_IF_ADDRESSABLE(&random_number_,
@@ skipping 60 matching lines @@
   tls_index_.Set(worker_thread_data);
   return worker_thread_data;
 }
 
 // static
 void ThreadData::OnThreadTermination(void* thread_data) {
   // We must NOT do any allocations during this callback. There is a chance
   // that the allocator is no longer active on this thread.
   if (!kTrackAllTaskObjects)
     return;  // Not compiled in.
-  if (!thread_data)
-    return;
   reinterpret_cast<ThreadData*>(thread_data)->OnThreadTerminationCleanup();

[ramant (doing other things), 2011/12/13 19:14:45]

nit: could we add a DCHECK for thread_data? thanks.

[jar (doing other things), 2011/12/13 20:29:10]

Done.

 }
 
 void ThreadData::OnThreadTerminationCleanup() {
   // The list_lock_ was created when we registered the callback, so it won't be
   // allocated here despite the lazy reference.
   base::AutoLock lock(*list_lock_.Pointer());
   if (incarnation_counter_ != incarnation_count_for_pool_)
     return;  // ThreadData was constructed in an earlier unit test.
   ++cleanup_count_;
   // Only worker threads need to be retired and reused.
   if (!worker_thread_number_) {
     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
 base::DictionaryValue* ThreadData::ToValue(bool reset_max) {
   DataCollector collected_data;  // Gather data.
   // Request multiple calls to collected_data.Append() for all threads.
   SendAllMaps(reset_max, &collected_data);
   collected_data.AddListOfLivingObjects();  // Add births that are still alive.
-  base::ListValue* list = collected_data.ToValue();
   base::DictionaryValue* dictionary = new base::DictionaryValue();
-  dictionary->Set("list", list);
+  collected_data.ToValue(dictionary);
   return dictionary;
 }
 
 Births* ThreadData::TallyABirth(const Location& location) {
   BirthMap::iterator it = birth_map_.find(location);
+  Births* child;
   if (it != birth_map_.end()) {
-    it->second->RecordBirth();
-    return it->second;
+    child =  it->second;
+    child->RecordBirth();
+  } else {
+    child = new Births(location, *this);  // Leak this.
+    // 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_);
+    birth_map_[location] = child;
   }
 
-  Births* tracker = new Births(location, *this);
-  // 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_);
-  birth_map_[location] = tracker;
-  return tracker;
+  if (kTrackParentChildLinks && status_ > PROFILING_ACTIVE &&
+      !parent_stack_.empty()) {
+    const Births* parent = parent_stack_.top();
+    ParentChildPair pair(parent, child);
+    if (parent_child_set_.find(pair) == parent_child_set_.end()) {
+      // 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,
                              DurationInt queue_duration,
                              DurationInt run_duration) {
   // Stir in some randomness, plus add constant in case durations are zero.
-  const DurationInt kSomePrimeNumber = 5939;  // To big is 4294967279;
+  const DurationInt 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<int32>(&birth - reinterpret_cast<Births*>(0));
 
   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];
   }  // 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);
+    parent_stack_.pop();
+  }
 }
 
 // static
 Births* ThreadData::TallyABirthIfActive(const Location& location) {
   if (!kTrackAllTaskObjects)
     return NULL;  // Not compiled in.
 
   if (!tracking_status())
     return NULL;
   ThreadData* current_thread_data = Get();
@@ skipping 24 matching lines @@
   // we identify such tasks, and replace their post_time with the time they
   // were scheduled (requested?) to emerge from the delayed task queue. This
   // means that queueing delay for such tasks will show how long they went
   // unserviced, after they *could* be serviced.  This is the same stat as we
   // have for non-delayed tasks, and we consistently call it queueing delay.
   TrackedTime effective_post_time = completed_task.delayed_run_time.is_null()
       ? tracked_objects::TrackedTime(completed_task.time_posted)
       : tracked_objects::TrackedTime(completed_task.delayed_run_time);
 
   // 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
+  // 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.
   DurationInt queue_duration = 0;
   DurationInt run_duration = 0;
   if (!start_of_run.is_null()) {
     queue_duration = (start_of_run - effective_post_time).InMilliseconds();
     if (!end_of_run.is_null())
       run_duration = (end_of_run - start_of_run).InMilliseconds();
   }
@@ skipping 61 matching lines @@
   if (!start_of_run.is_null() && !end_of_run.is_null())
     run_duration = (end_of_run - start_of_run).InMilliseconds();
   current_thread_data->TallyADeath(*birth, queue_duration, run_duration);
 }
 
 const std::string ThreadData::thread_name() const { return thread_name_; }
 
 // This may be called from another thread.
 void ThreadData::SnapshotMaps(bool reset_max,
                               BirthMap* birth_map,
-                              DeathMap* death_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_max)
       it->second.ResetMax();
   }
+
+  if (!kTrackParentChildLinks)
+    return;
+
+  for (ParentChildSet::iterator it = parent_child_set_.begin();
+       it != parent_child_set_.end(); ++it)
+    parent_child_set->insert(*it);
 }
 
 // static
 void ThreadData::SendAllMaps(bool reset_max, class DataCollector* target) {
   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()) {
     // Get copy of data.
     ThreadData::BirthMap birth_map;
     ThreadData::DeathMap death_map;
-    thread_data->SnapshotMaps(reset_max, &birth_map, &death_map);
-    target->Append(*thread_data, birth_map, death_map);
+    ThreadData::ParentChildSet parent_child_set;
+    thread_data->SnapshotMaps(reset_max, &birth_map, &death_map,
+                              &parent_child_set);
+    target->Append(*thread_data, birth_map, death_map, parent_child_set);
   }
 }
 
 // static
 void ThreadData::ResetAllThreadData() {
   ThreadData* my_list = first();
 
   for (ThreadData* thread_data = my_list;
        thread_data;
        thread_data = thread_data->next())
     thread_data->Reset();
 }
 
 void ThreadData::Reset() {
   base::AutoLock lock(map_lock_);
   for (DeathMap::iterator it = death_map_.begin();
        it != death_map_.end(); ++it)
     it->second.Clear();
   for (BirthMap::iterator it = birth_map_.begin();
        it != birth_map_.end(); ++it)
     it->second->Clear();
 }
 
 bool ThreadData::Initialize() {
   if (!kTrackAllTaskObjects)
     return false;  // Not compiled in.
-  if (status_ != UNINITIALIZED)
+  if (status_ >= DEACTIVATED)
     return true;  // Someone else did the initialization.
   // Due to racy lazy initialization in tests, we'll need to recheck status_
   // after we acquire the lock.
 
   // Ensure that we don't double initialize tls.  We are called when single
   // threaded in the product, but some tests may be racy and lazy about our
   // initialization.
   base::AutoLock lock(*list_lock_.Pointer());
-  if (status_ != UNINITIALIZED)
+  if (status_ >= DEACTIVATED)
     return true;  // Someone raced in here and beat us.
 
   // Perform the "real" TLS initialization now, and leave it intact through
   // process termination.
   if (!tls_index_.initialized()) {  // Testing may have initialized this.
+    DCHECK_EQ(status_, UNINITIALIZED);
     tls_index_.Initialize(&ThreadData::OnThreadTermination);
     if (!tls_index_.initialized())
       return false;
+  } else {
+    // TLS was initialzed for us earlier.
+    DCHECK_EQ(status_, DORMANT_DURING_TESTS);
   }
 
   // Incarnation counter is only significant to testing, as it otherwise will
   // never again change in this process.
   ++incarnation_counter_;
 
   // The lock is not critical for setting status_, but it doesn't hurt. It also
   // ensures that if we have a racy initialization, that we'll bail as soon as
   // we get the lock earlier in this method.
   status_ = kInitialStartupState;
+  if (kTrackParentChildLinks && kInitialStartupState == FULLY_ACTIVE)

[ramant (doing other things), 2011/12/13 19:14:45]

should this be if (!kTrackParentChildLinks ...)?

[jar (doing other things), 2011/12/13 20:29:10]

Done  .... and I renamed the enums to help make the code clearer, so I won't
make this mistake again.

+    status_ = PROFILING_ACTIVE;
   DCHECK(status_ != UNINITIALIZED);
   return true;
 }
 
 // static
 bool ThreadData::InitializeAndSetTrackingStatus(bool status) {
   if (!Initialize())  // No-op if already initialized.
     return false;  // Not compiled in.
 
-  status_ = status ? ACTIVE : DEACTIVATED;
+  if (!status) {
+    status_ = DEACTIVATED;
+  } else {
+    if (kTrackParentChildLinks)
+      status_ = FULLY_ACTIVE;
+    else
+      status_ = PROFILING_ACTIVE;
+  }
   return true;
 }
 
 // static
 bool ThreadData::tracking_status() {
-  return status_ == ACTIVE;
+  return status_ > DEACTIVATED;
 }
 
 // static
-TrackedTime ThreadData::NowForStartOfRun() {
+bool ThreadData::tracking_parent_child_status() {
+  return status_ >= FULLY_ACTIVE;
+}
+
+// static
+TrackedTime ThreadData::NowForStartOfRun(const Births* parent) {
+  if (kTrackParentChildLinks && parent && status_ > PROFILING_ACTIVE) {
+    ThreadData* current_thread_data = Get();

[ramant (doing other things), 2011/12/13 19:14:45]

nit: could we add DCHECK for current_thread_data? It looks like for unittests
Get() could return NULL. In such cases, they shouldn't call this method. It is
your call.

[jar (doing other things), 2011/12/13 20:29:10]

Done.

+    current_thread_data->parent_stack_.push(parent);
+  }
   return Now();
 }
 
 // static
 TrackedTime ThreadData::NowForEndOfRun() {
   return Now();
 }
 
 // static
 TrackedTime ThreadData::Now() {
@@ skipping 33 matching lines @@
       CHECK_GT(worker->worker_thread_number_, 0);
       first_retired_worker_ = worker->next_retired_worker_;
       worker->next_retired_worker_ = NULL;
     }
   }
 
   // Put most global static back in pristine shape.
   worker_thread_data_creation_count_ = 0;
   cleanup_count_ = 0;
   tls_index_.Set(NULL);
-  status_ = UNINITIALIZED;
+  status_ = DORMANT_DURING_TESTS;  // Almost UNINITIALIZED

[ramant (doing other things), 2011/12/13 19:14:45]

nit: period at the end.

[jar (doing other things), 2011/12/13 20:29:10]

Done.

 
   // To avoid any chance of racing in unit tests, which is the only place we
   // call this function, we may sometimes leak all the data structures we
   // recovered, as they may still be in use on threads from prior tests!
   if (leak)
     return;
 
   // When we want to cleanup (on a single thread), here is what we do.
 
   // 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.
-    next_thread_data->birth_map_.clear();
-    next_thread_data->death_map_.clear();
     delete next_thread_data;  // Includes all Death Records.
   }
 }
 
 //------------------------------------------------------------------------------
 // Individual 3-tuple of birth (place and thread) along with death thread, and
 // the accumulated stats for instances (DeathData).
 
 Snapshot::Snapshot(const BirthOnThread& birth_on_thread,
                    const ThreadData& death_thread,
@@ skipping 10 matching lines @@
 }
 
 const std::string Snapshot::DeathThreadName() const {
   if (death_thread_)
     return death_thread_->thread_name();
   return "Still_Alive";
 }
 
 base::DictionaryValue* Snapshot::ToValue() const {
   base::DictionaryValue* dictionary = new base::DictionaryValue;
-  dictionary->Set("death_data", death_data_.ToValue());
+  // TODO(jar): Switch the next two lines to:
+  // birth_->ToValue("birth", dictionary);
+  // ...but that will require fixing unit tests, and JS to take
+  // "birth_location" rather than "location"
   dictionary->Set("birth_thread",
       base::Value::CreateStringValue(birth_->birth_thread()->thread_name()));
+  dictionary->Set("location", birth_->location().ToValue());
+
+  dictionary->Set("death_data", death_data_.ToValue());
   dictionary->Set("death_thread",
       base::Value::CreateStringValue(DeathThreadName()));
-  dictionary->Set("location", birth_->location().ToValue());
   return dictionary;
 }
 
 //------------------------------------------------------------------------------
 // DataCollector
 
 DataCollector::DataCollector() {}
 
 DataCollector::~DataCollector() {
 }
 
 void DataCollector::Append(const ThreadData &thread_data,

[ramant (doing other things), 2011/12/13 19:14:45]

nit: ThreadData & ->: ThreadData&

[jar (doing other things), 2011/12/13 20:29:10]

Done.

-                           const ThreadData::BirthMap &birth_map,
-                           const ThreadData::DeathMap &death_map) {
+                           const ThreadData::BirthMap& birth_map,
+                           const ThreadData::DeathMap& death_map,
+                           const ThreadData::ParentChildSet& parent_child_set) {
   for (ThreadData::DeathMap::const_iterator it = death_map.begin();
        it != death_map.end(); ++it) {
     collection_.push_back(Snapshot(*it->first, thread_data, it->second));
     global_birth_count_[it->first] -= it->first->birth_count();
   }
 
   for (ThreadData::BirthMap::const_iterator it = birth_map.begin();
        it != birth_map.end(); ++it) {
     global_birth_count_[it->second] += it->second->birth_count();
   }
+
+  if (!kTrackParentChildLinks)
+    return;
+
+  for (ThreadData::ParentChildSet::const_iterator it = parent_child_set.begin();
+       it != parent_child_set.end(); ++it) {
+    parent_child_set_.insert(*it);
+  }
 }
 
 DataCollector::Collection* DataCollector::collection() {
   return &collection_;
 }
 
 void DataCollector::AddListOfLivingObjects() {
   for (BirthCount::iterator it = global_birth_count_.begin();
        it != global_birth_count_.end(); ++it) {
     if (it->second > 0)
       collection_.push_back(Snapshot(*it->first, it->second));
   }
 }
 
-base::ListValue* DataCollector::ToValue() const {
+void DataCollector::ToValue(base::DictionaryValue* dictionary) const {
   base::ListValue* list = new base::ListValue;
   for (size_t i = 0; i < collection_.size(); ++i) {
     list->Append(collection_[i].ToValue());
   }
-  return list;
+  dictionary->Set("list", list);
+
+  base::ListValue* descendants = new base::ListValue;
+  for (ThreadData::ParentChildSet::const_iterator it =
+           parent_child_set_.begin();
+       it != parent_child_set_.end();
+       ++it) {
+    base::DictionaryValue* parent_child = new base::DictionaryValue;
+    it->first->ToValue("parent", parent_child);
+    it->second->ToValue("child", parent_child);
+    descendants->Append(parent_child);
+  }
+  dictionary->Set("descendants", descendants);
 }
 
 }  // namespace tracked_objects