Support use of third party time function to profiler

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 <math.h>
 
 #include "base/format_macros.h"
 #include "base/message_loop.h"
+#include "base/profiler/alternate_timer.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.
 const bool kTrackAllTaskObjects = true;
 
 // Flag to compile out parent-child link recording.
 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.
 const ThreadData::Status kInitialStartupState =
     ThreadData::PROFILING_CHILDREN_ACTIVE;
 
+// Control whether an alternate time source (Now() function) is supported by
+// the ThreadData class.  This compile time flag should be set to try if we want

[ramant (doing other things), 2012/02/15 18:33:46]

nit: try -> true

[jar (doing other things), 2012/02/15 20:26:32]

Done.  I added a lot of text to try to be even clearer... please have another
look.

+// other modules, such as an allocator, to call with a new thread-specific
+// Now() function to use (instead of of calling into tracked_time).
+static const bool kAllowAlternateTimeSourceHandling = true;
+
+// Environment variable name that is used to activate alternate timer profiling
+// (such as using TCMalloc allocations to provide a pseudo-timer) for tasks
+// instead of wall clock profiling.
+static const char k_alternate_profile_timer[] = "CHROME_PROFILER_TIME";

[ramant (doing other things), 2012/02/15 18:33:46]

nit: should we consider commenting that "k_alternate_profile_timer" is declared
at two places (here and base/allocator/allocator_shim.cc) and if one changes it
at one place, that they should consider changing at the other place?

[jar (doing other things), 2012/02/15 20:26:32]

I went back and tried to move it to shared place.  I think it will now work ;-).
 Thanks for reminding/pushing me!

On 2012/02/15 18:33:46, ramant wrote:

+
 }  // namespace
 
 //------------------------------------------------------------------------------
 // DeathData tallies durations when a death takes place.
 
 DeathData::DeathData() {
   Clear();
 }
 
 DeathData::DeathData(int count) {
@@ skipping 121 matching lines @@
 void Births::Clear() { birth_count_ = 0; }
 
 //------------------------------------------------------------------------------
 // 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;
+
 // A TLS slot which points to the ThreadData instance for the current thread. We
 // do a fake initialization here (zeroing out data), and then the real in-place
 // construction happens when we call tls_index_.Initialize().
 // static
 base::ThreadLocalStorage::StaticSlot ThreadData::tls_index_ = TLS_INITIALIZER;
 
 // static
 int ThreadData::worker_thread_data_creation_count_ = 0;
 
 // static
@@ skipping 174 matching lines @@
 
 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 = 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));
 
+  // 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.
+  if (kAllowAlternateTimeSourceHandling && now_function_)
+    queue_duration = 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_);
 
@@ skipping 189 matching lines @@
 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();
 }
 
+static void OptionallyInitializeAlternateTimer() {
+  char* alternate_selector = getenv(k_alternate_profile_timer);
+  if (!alternate_selector)
+    return;
+  switch (*alternate_selector) {
+    case '0':  // This is the default value, and uses the wall clock time.
+      break;
+    case '1':  {
+      // Use the TCMalloc allocations-on-thread as a pseudo-time.
+      NowFunction* now_function = GetAlternateTimeSource();
+      if (!now_function)
+        break;
+      ThreadData::SetAlternateTimeSource(now_function);

[ramant (doing other things), 2012/02/15 18:33:46]

nit: should we consider moving the following check into SetAlternateTimeSource?
(wondered while reading SetAlternateTimeSource if we should have a DCHECK for
now_function) thanks

if (!now_function)
      break;

[jar (doing other things), 2012/02/15 20:26:32]

Done.

+      break;
+      }
+
+    default:
+      NOTREACHED();
+      break;
+  }
+}
+
 bool ThreadData::Initialize() {
   if (!kTrackAllTaskObjects)
     return false;  // Not compiled in.
   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_ >= DEACTIVATED)
     return true;  // Someone raced in here and beat us.
 
+  // Put an alternate timer in place if the environment calls for it, such as
+  // for tracking TCMalloc allocations.  This insertion is idempotent, so we
+  // don't mind if there is a race, and we'd prefer not to be in a lock while
+  // doing this work.

[ramant (doing other things), 2012/02/15 18:33:46]

Wondered if "_heap_init" happens before ThreadData::Initialize. (I am guessing
it does).

[jar (doing other things), 2012/02/15 20:26:32]

heap_init is run super-duper-early, before *any* allocations are done.  As a
result, we can trust that IF it gets run at all, it is done by now.

On 2012/02/15 18:33:46, ramant wrote:

+  if (kAllowAlternateTimeSourceHandling)
+    OptionallyInitializeAlternateTimer();
+
   // 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);
@@ skipping 52 matching lines @@
   }
   return Now();
 }
 
 // static
 TrackedTime ThreadData::NowForEndOfRun() {
   return Now();
 }
 
 // static
+void ThreadData::SetAlternateTimeSource(NowFunction* now_function) {
+  if (kAllowAlternateTimeSourceHandling)
+    now_function_ = now_function;
+}
+
+// static
 TrackedTime ThreadData::Now() {
+  if (kAllowAlternateTimeSourceHandling && now_function_)
+    return TrackedTime::FromMilliseconds((*now_function_)());
   if (kTrackAllTaskObjects && TrackingStatus())
     return TrackedTime::Now();
   return TrackedTime();  // Super fast when disabled, or not compiled.
 }
 
 // static
 void ThreadData::EnsureCleanupWasCalled(int major_threads_shutdown_count) {
   base::AutoLock lock(*list_lock_.Pointer());
   if (worker_thread_data_creation_count_ == 0)
     return;  // We haven't really run much, and couldn't have leaked.
@@ skipping 150 matching lines @@
        ++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