Support tracking of IPC messages as tasks in profiler

Also started to do more cleanup, including creating
a base/profiler directory, and moving parts of the
over-sized tracked_objects.* into that directory.

r=rtenneti
Review URL: http://codereview.chromium.org/8480014

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@108752 0039d316-1c4b-4281-b951-d872f2087c98

12 files changed, 422 insertions, 212 deletions

diff --git a/base/base.gyp b/base/base.gyp
index 4cabea5..058a9f6 100644
--- a/base/base.gyp
+++ b/base/base.gyp
@@ -180,6 +180,7 @@
         'process_util_unittest.cc',
         'process_util_unittest_mac.h',
         'process_util_unittest_mac.mm',
+        'profiler/tracked_time_unittest.cc',
         'rand_util_unittest.cc',
         'scoped_native_library_unittest.cc',
         'scoped_temp_dir_unittest.cc',
diff --git a/base/base.gypi b/base/base.gypi
index 3e08705..ac20ab4 100644
--- a/base/base.gypi
+++ b/base/base.gypi
@@ -222,6 +222,10 @@
           'process_util_posix.cc',
           'process_util_win.cc',
           'process_win.cc',
+          'profiler/scoped_profile.cc',
+          'profiler/scoped_profile.h',
+          'profiler/tracked_time.cc',
+          'profiler/tracked_time.h',
           'rand_util.cc',
           'rand_util.h',
           'rand_util_c.h',
@@ -336,8 +340,8 @@
           'timer.h',
           'tracked_objects.cc',
           'tracked_objects.h',
-	  'tracking_info.cc',
-	  'tracking_info.h',
+          'tracking_info.cc',
+          'tracking_info.h',
           'tuple.h',
           'utf_offset_string_conversions.cc',
           'utf_offset_string_conversions.h',
diff --git a/base/location.h b/base/location.h
index 523bfaf..2fbe62c 100644
--- a/base/location.h
+++ b/base/location.h
@@ -72,11 +72,13 @@ class BASE_EXPORT Location {
 BASE_EXPORT const void* GetProgramCounter();
 
 // Define a macro to record the current source location.
-#define FROM_HERE tracked_objects::Location(                                   \
-    __FUNCTION__,                                                              \
-    __FILE__,                                                                  \
-    __LINE__,                                                                  \
-    tracked_objects::GetProgramCounter())                                      \
+#define FROM_HERE FROM_HERE_WITH_EXPLICIT_FUNCTION(__FUNCTION__)
+
+#define FROM_HERE_WITH_EXPLICIT_FUNCTION(function_name)                        \
+    ::tracked_objects::Location(function_name,                                 \
+                                __FILE__,                                      \
+                                __LINE__,                                      \
+                                ::tracked_objects::GetProgramCounter())
 
 }  // namespace tracked_objects
 
diff --git a/base/profiler/scoped_profile.cc b/base/profiler/scoped_profile.cc
new file mode 100644
index 0000000..7bd31fe
--- /dev/null
+++ b/base/profiler/scoped_profile.cc
@@ -0,0 +1,31 @@
+// 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/profiler/scoped_profile.h"
+
+#include "base/location.h"
+#include "base/tracked_objects.h"
+
+
+namespace tracked_objects {
+
+
+ScopedProfile::ScopedProfile(const Location& location)
+    : birth_(ThreadData::TallyABirthIfActive(location)),
+      start_of_run_(ThreadData::Now()) {
+}
+
+ScopedProfile::~ScopedProfile() {
+  StopClockAndTally();
+}
+
+void ScopedProfile::StopClockAndTally() {
+  if (!birth_)
+    return;
+  ThreadData::TallyRunInAScopedRegionIfTracking(birth_, start_of_run_,
+                                                ThreadData::Now());
+  birth_ = NULL;
+}
+
+}  // namespace tracked_objects
diff --git a/base/profiler/scoped_profile.h b/base/profiler/scoped_profile.h
new file mode 100644
index 0000000..2754f5e
--- /dev/null
+++ b/base/profiler/scoped_profile.h
@@ -0,0 +1,47 @@
+// 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.
+
+
+#ifndef BASE_PROFILER_SCOPED_PROFILE_H_
+#define BASE_PROFILER_SCOPED_PROFILE_H_
+
+//------------------------------------------------------------------------------
+// ScopedProfile provides basic helper functions for profiling a short
+// region of code within a scope.  It is separate from the related ThreadData
+// class so that it can be included without much other cruft, and provide the
+// macros listed below.
+
+#include "base/base_export.h"
+#include "base/location.h"
+#include "base/profiler/tracked_time.h"
+
+#define TRACK_RUN_IN_THIS_SCOPED_REGION_FOR_OFFICIAL_BUILDS(variable_name) \
+    ::tracked_objects::ScopedProfile variable_name(FROM_HERE)
+
+#define TRACK_RUN_IN_IPC_HANDLER(dispatch_function_name) \
+    ::tracked_objects::ScopedProfile some_tracking_variable_name(  \
+        FROM_HERE_WITH_EXPLICIT_FUNCTION(#dispatch_function_name))
+
+
+namespace tracked_objects {
+class Births;
+
+class BASE_EXPORT ScopedProfile {
+ public:
+  explicit ScopedProfile(const Location& location);
+  ~ScopedProfile();
+
+  // Stop tracing prior to the end destruction of the instance.
+  void StopClockAndTally();
+
+ private:
+  Births* birth_;  // Place in code where tracking started.
+  const TrackedTime start_of_run_;
+
+  DISALLOW_COPY_AND_ASSIGN(ScopedProfile);
+};
+
+}  // namespace tracked_objects
+
+#endif   // BASE_PROFILER_SCOPED_PROFILE_H_
diff --git a/base/profiler/tracked_time.cc b/base/profiler/tracked_time.cc
new file mode 100644
index 0000000..0e227bd
--- /dev/null
+++ b/base/profiler/tracked_time.cc
@@ -0,0 +1,80 @@
+// 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/profiler/tracked_time.h"
+
+#include "build/build_config.h"
+
+#if defined(OS_WIN)
+#include <mmsystem.h>  // Declare timeGetTime()... after including build_config.
+#endif
+
+namespace tracked_objects {
+
+#if defined(USE_FAST_TIME_CLASS_FOR_DURATION_CALCULATIONS)
+
+Duration::Duration() : ms_(0) {}
+Duration::Duration(int32 duration) : ms_(duration) {}
+
+Duration& Duration::operator+=(const Duration& other) {
+  ms_ += other.ms_;
+  return *this;
+}
+
+Duration Duration::operator+(const Duration& other) const {
+  return Duration(ms_ + other.ms_);
+}
+
+bool Duration::operator==(const Duration& other) const {
+  return ms_ == other.ms_;
+}
+
+bool Duration::operator!=(const Duration& other) const {
+  return ms_ != other.ms_;
+}
+
+bool Duration::operator>(const Duration& other) const {
+  return ms_ > other.ms_;
+}
+
+// static
+Duration Duration::FromMilliseconds(int ms) { return Duration(ms); }
+
+int32 Duration::InMilliseconds() const { return ms_; }
+
+//------------------------------------------------------------------------------
+
+TrackedTime::TrackedTime() : ms_(0) {}
+TrackedTime::TrackedTime(int32 ms) : ms_(ms) {}
+TrackedTime::TrackedTime(const base::TimeTicks& time)
+    : ms_((time - base::TimeTicks()).InMilliseconds()) {
+}
+
+// static
+TrackedTime TrackedTime::Now() {
+#if defined(OS_WIN)
+  // Use lock-free accessor to 32 bit time.
+  // Note that TimeTicks::Now() is built on this, so we have "compatible"
+  // times when we down-convert a TimeTicks sample.
+  // TODO(jar): Surface this interface via something in base/time.h.
+  return TrackedTime(static_cast<int32>(timeGetTime()));
+#else
+  // Posix has nice cheap 64 bit times, so we just down-convert it.
+  return TrackedTime(base::TimeTicks::Now());
+#endif  // OS_WIN
+}
+
+Duration TrackedTime::operator-(const TrackedTime& other) const {
+  return Duration(ms_ - other.ms_);
+}
+
+TrackedTime TrackedTime::operator+(const Duration& other) const {
+  return TrackedTime(ms_ + other.ms_);
+}
+
+bool TrackedTime::is_null() const { return ms_ == 0; }
+
+#endif  // USE_FAST_TIME_CLASS_FOR_DURATION_CALCULATIONS
+
+}  // namespace tracked_objects
diff --git a/base/profiler/tracked_time.h b/base/profiler/tracked_time.h
new file mode 100644
index 0000000..e8e6d17
--- /dev/null
+++ b/base/profiler/tracked_time.h
@@ -0,0 +1,84 @@
+// 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.
+
+#ifndef BASE_PROFILER_TRACKED_TIME_H_
+#define BASE_PROFILER_TRACKED_TIME_H_
+
+
+#include "base/base_export.h"
+#include "base/basictypes.h"
+#include "base/time.h"
+
+namespace tracked_objects {
+
+//------------------------------------------------------------------------------
+
+#define USE_FAST_TIME_CLASS_FOR_DURATION_CALCULATIONS
+
+#if defined(USE_FAST_TIME_CLASS_FOR_DURATION_CALCULATIONS)
+
+// TimeTicks maintains a wasteful 64 bits of data (we need less than 32), and on
+// windows, a 64 bit timer is expensive to even obtain. We use a simple
+// millisecond counter for most of our time values, as well as millisecond units
+// of duration between those values.  This means we can only handle durations
+// up to 49 days (range), or 24 days (non-negative time durations).
+// We only define enough methods to service the needs of the tracking classes,
+// and our interfaces are modeled after what TimeTicks and TimeDelta use (so we
+// can swap them into place if we want to use the "real" classes).
+
+class BASE_EXPORT Duration {  // Similar to base::TimeDelta.
+ public:
+  Duration();
+
+  Duration& operator+=(const Duration& other);
+  Duration operator+(const Duration& other) const;
+
+  bool operator==(const Duration& other) const;
+  bool operator!=(const Duration& other) const;
+  bool operator>(const Duration& other) const;
+
+  static Duration FromMilliseconds(int ms);
+
+  int32 InMilliseconds() const;
+
+ private:
+  friend class TrackedTime;
+  explicit Duration(int32 duration);
+
+  // Internal time is stored directly in milliseconds.
+  int32 ms_;
+};
+
+class BASE_EXPORT TrackedTime {  // Similar to base::TimeTicks.
+ public:
+  TrackedTime();
+  explicit TrackedTime(const base::TimeTicks& time);
+
+  static TrackedTime Now();
+  Duration operator-(const TrackedTime& other) const;
+  TrackedTime operator+(const Duration& other) const;
+  bool is_null() const;
+
+ private:
+  friend class Duration;
+  explicit TrackedTime(int32 ms);
+
+  // Internal duration is stored directly in milliseconds.
+  uint32 ms_;
+};
+
+#else
+
+// Just use full 64 bit time calculations, and the slower TimeTicks::Now().
+// This allows us (as an alternative) to test with larger ranges of times, and
+// with a more thoroughly tested class.
+
+typedef base::TimeTicks TrackedTime;
+typedef base::TimeDelta Duration;
+
+#endif  // USE_FAST_TIME_CLASS_FOR_DURATION_CALCULATIONS
+
+}  // namespace tracked_objects
+
+#endif  // BASE_PROFILER_TRACKED_TIME_H_
diff --git a/base/profiler/tracked_time_unittest.cc b/base/profiler/tracked_time_unittest.cc
new file mode 100644
index 0000000..fee4ba6
--- /dev/null
+++ b/base/profiler/tracked_time_unittest.cc
@@ -0,0 +1,111 @@
+// 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.
+
+// Test of classes in tracked_time.cc
+
+#include "base/profiler/tracked_time.h"
+#include "base/time.h"
+#include "base/tracked_objects.h"
+#include "testing/gtest/include/gtest/gtest.h"
+
+namespace tracked_objects {
+
+TEST(TrackedTimeTest, TrackedTimerMilliseconds) {
+  // First make sure we basicallly transfer simple milliseconds values as
+  // expected.  Most critically, things should not become null.
+  int32 kSomeMilliseconds = 243;  // Some example times.
+  int64 kReallyBigMilliseconds = (1LL << 35) + kSomeMilliseconds;
+
+  TrackedTime some = TrackedTime() +
+      Duration::FromMilliseconds(kSomeMilliseconds);
+  EXPECT_EQ(kSomeMilliseconds, (some - TrackedTime()).InMilliseconds());
+  EXPECT_FALSE(some.is_null());
+
+  // Now create a big time, to check that it is wrapped modulo 2^32.
+  base::TimeTicks big = base::TimeTicks() +
+      base::TimeDelta::FromMilliseconds(kReallyBigMilliseconds);
+  EXPECT_EQ(kReallyBigMilliseconds, (big - base::TimeTicks()).InMilliseconds());
+
+  TrackedTime wrapped_big(big);
+#if defined(USE_FAST_TIME_CLASS_FOR_DURATION_CALCULATIONS)
+  // Expect wrapping at 32 bits.
+  EXPECT_EQ(kSomeMilliseconds, (wrapped_big - TrackedTime()).InMilliseconds());
+#else  // !USE_FAST_TIME_CLASS_FOR_DURATION_CALCULATIONS)
+  // Expect no wrapping at 32 bits.
+  EXPECT_EQ(kReallyBigMilliseconds,
+            (wrapped_big - TrackedTime()).InMilliseconds());
+#endif  // USE_FAST_TIME_CLASS_FOR_DURATION_CALCULATIONS)
+}
+
+TEST(TrackedTimeTest, TrackedTimerDuration) {
+  int kFirstMilliseconds = 793;
+  int kSecondMilliseconds = 14889;
+
+  Duration first = Duration::FromMilliseconds(kFirstMilliseconds);
+  Duration second = Duration::FromMilliseconds(kSecondMilliseconds);
+
+  EXPECT_EQ(kFirstMilliseconds, first.InMilliseconds());
+  EXPECT_EQ(kSecondMilliseconds, second.InMilliseconds());
+
+  Duration sum = first + second;
+  EXPECT_EQ(kFirstMilliseconds + kSecondMilliseconds, sum.InMilliseconds());
+}
+
+TEST(TrackedTimeTest, TrackedTimerVsTimeTicks) {
+  // Make sure that our 32 bit timer is aligned with the TimeTicks() timer.
+
+  // First get a 64 bit timer (which should not be null).
+  base::TimeTicks ticks_before = base::TimeTicks::Now();
+  EXPECT_FALSE(ticks_before.is_null());
+
+  // Then get a 32 bit timer that can be be null when it wraps.
+  TrackedTime now = TrackedTime::Now();
+
+  // Then get a bracketing time.
+  base::TimeTicks ticks_after = base::TimeTicks::Now();
+  EXPECT_FALSE(ticks_after.is_null());
+
+  // Now make sure that we bracketed our tracked time nicely.
+  Duration before = now - TrackedTime(ticks_before);
+  EXPECT_LE(0, before.InMilliseconds());
+  Duration after = now - TrackedTime(ticks_after);
+  EXPECT_GE(0, after.InMilliseconds());
+}
+
+TEST(TrackedTimeTest, TrackedTimerDisabled) {
+  // Check to be sure disabling the collection of data induces a null time
+  // (which we know will return much faster).
+  if (!ThreadData::InitializeAndSetTrackingStatus(false))
+    return;
+  // Since we disabled tracking, we should get a null response.
+  TrackedTime track_now = ThreadData::Now();
+  EXPECT_TRUE(track_now.is_null());
+}
+
+TEST(TrackedTimeTest, TrackedTimerEnabled) {
+  if (!ThreadData::InitializeAndSetTrackingStatus(true))
+    return;
+  // Make sure that when we enable tracking, we get a real timer result.
+
+  // First get a 64 bit timer (which should not be null).
+  base::TimeTicks ticks_before = base::TimeTicks::Now();
+  EXPECT_FALSE(ticks_before.is_null());
+
+  // Then get a 32 bit timer that can be null when it wraps.
+  // Crtical difference from  the TrackedTimerVsTimeTicks test, is that we use
+  // ThreadData::Now().  It can sometimes return the null time.
+  TrackedTime now = ThreadData::Now();
+
+  // Then get a bracketing time.
+  base::TimeTicks ticks_after = base::TimeTicks::Now();
+  EXPECT_FALSE(ticks_after.is_null());
+
+  // Now make sure that we bracketed our tracked time nicely.
+  Duration before = now - TrackedTime(ticks_before);
+  EXPECT_LE(0, before.InMilliseconds());
+  Duration after = now - TrackedTime(ticks_after);
+  EXPECT_GE(0, after.InMilliseconds());
+}
+
+}  // namespace tracked_objects
diff --git a/base/tracked_objects.cc b/base/tracked_objects.cc
index 2885eb0..5403af58 100644
--- a/base/tracked_objects.cc
+++ b/base/tracked_objects.cc
@@ -509,6 +509,31 @@ void ThreadData::TallyRunOnWorkerThreadIfTracking(
 }
 
 // static
+void ThreadData::TallyRunInAScopedRegionIfTracking(
+    const Births* birth,
+    const TrackedTime& start_of_run,
+    const TrackedTime& end_of_run) {
+  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 = Get();
+  if (!current_thread_data)
+    return;
+
+  Duration queue_duration = Duration();
+  Duration run_duration = end_of_run - start_of_run;
+  current_thread_data->TallyADeath(*birth, queue_duration, run_duration);
+}
+
+
+
+// static
 ThreadData* ThreadData::first() {
   base::AutoLock lock(*list_lock_);
   return all_thread_data_list_head_;
diff --git a/base/tracked_objects.h b/base/tracked_objects.h
index 46986e6..f66e761 100644
--- a/base/tracked_objects.h
+++ b/base/tracked_objects.h
@@ -13,16 +13,13 @@
 
 #include "base/base_export.h"
 #include "base/location.h"
+#include "base/profiler/tracked_time.h"
 #include "base/time.h"
 #include "base/synchronization/lock.h"
 #include "base/threading/thread_local_storage.h"
 #include "base/tracking_info.h"
 #include "base/values.h"
 
-#if defined(OS_WIN)
-#include <mmsystem.h>  // Declare timeGetTime();
-#endif
-
 // TrackedObjects provides a database of stats about objects (generally Tasks)
 // that are tracked.  Tracking means their birth, death, duration, birth thread,
 // death thread, and birth place are recorded.  This data is carefully spread
@@ -172,96 +169,6 @@ class MessageLoop;
 namespace tracked_objects {
 
 //------------------------------------------------------------------------------
-
-#define USE_FAST_TIME_CLASS_FOR_DURATION_CALCULATIONS
-
-#if defined(USE_FAST_TIME_CLASS_FOR_DURATION_CALCULATIONS)
-
-// TimeTicks maintains a wasteful 64 bits of data (we need less than 32), and on
-// windows, a 64 bit timer is expensive to even obtain. We use a simple
-// millisecond counter for most of our time values, as well as millisecond units
-// of duration between those values.  This means we can only handle durations
-// up to 49 days (range), or 24 days (non-negative time durations).
-// We only define enough methods to service the needs of the tracking classes,
-// and our interfaces are modeled after what TimeTicks and TimeDelta use (so we
-// can swap them into place if we want to use the "real" classes).
-
-class BASE_EXPORT Duration {  // Similar to base::TimeDelta.
- public:
-  Duration() : ms_(0) {}
-
-  Duration& operator+=(const Duration& other) {
-    ms_ += other.ms_;
-    return *this;
-  }
-
-  Duration operator+(const Duration& other) const {
-    return Duration(ms_ + other.ms_);
-  }
-
-  bool operator==(const Duration& other) const { return ms_ == other.ms_; }
-  bool operator!=(const Duration& other) const { return ms_ != other.ms_; }
-  bool operator>(const Duration& other) const { return ms_ > other.ms_; }
-
-  static Duration FromMilliseconds(int ms) { return Duration(ms); }
-
-  int32 InMilliseconds() const { return ms_; }
-
- private:
-  friend class TrackedTime;
-  explicit Duration(int32 duration) : ms_(duration) {}
-
-  // Internal time is stored directly in milliseconds.
-  int32 ms_;
-};
-
-class BASE_EXPORT TrackedTime {  // Similar to base::TimeTicks.
- public:
-  TrackedTime() : ms_(0) {}
-  explicit TrackedTime(const base::TimeTicks& time)
-      : ms_((time - base::TimeTicks()).InMilliseconds()) {
-  }
-
-  static TrackedTime Now() {
-#if defined(OS_WIN)
-    // Use lock-free accessor to 32 bit time.
-    // Note that TimeTicks::Now() is built on this, so we have "compatible"
-    // times when we down-convert a TimeTicks sample.
-    // TODO(jar): Surface this interface via something in base/time.h.
-    return TrackedTime(static_cast<int32>(::timeGetTime()));
-#else
-    // Posix has nice cheap 64 bit times, so we just down-convert it.
-    return TrackedTime(base::TimeTicks::Now());
-#endif  // OS_WIN
-  }
-
-  Duration operator-(const TrackedTime& other) const {
-    return Duration(ms_ - other.ms_);
-  }
-
-  TrackedTime operator+(const Duration& other) const {
-    return TrackedTime(ms_ + other.ms_);
-  }
-
-  bool is_null() const { return ms_ == 0; }
-
- private:
-  friend class Duration;
-  explicit TrackedTime(int32 ms) : ms_(ms) {}
-
-  // Internal duration is stored directly in milliseconds.
-  uint32 ms_;
-};
-
-#else
-
-// Just use full 64 bit time calculations, and the slower TimeTicks::Now().
-typedef base::TimeTicks TrackedTime;
-typedef base::TimeDelta Duration;
-
-#endif  // USE_FAST_TIME_CLASS_FOR_DURATION_CALCULATIONS
-
-//------------------------------------------------------------------------------
 // For a specific thread, and a specific birth place, the collection of all
 // death info (with tallies for each death thread, to prevent access conflicts).
 class ThreadData;
@@ -712,9 +619,17 @@ class BASE_EXPORT ThreadData {
       const TrackedTime& start_of_run,
       const TrackedTime& end_of_run);
 
+  // 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 std::string thread_name() const { return thread_name_; }
 
   // ---------------------
+  // TODO(jar):
   // The following functions should all be private, and are only public because
   // the collection is done externally.  We need to relocate that code from the
   // collection class into this class, and then all these methods can be made
diff --git a/base/tracked_objects_unittest.cc b/base/tracked_objects_unittest.cc
index 67302fc..482e318 100644
--- a/base/tracked_objects_unittest.cc
+++ b/base/tracked_objects_unittest.cc
@@ -629,102 +629,5 @@ TEST_F(TrackedObjectsTest, DifferentLives) {
   EXPECT_EQ(one_line_result, json);
 }
 
-TEST_F(TrackedObjectsTest, TrackedTimerMilliseconds) {
-  // First make sure we basicallly transfer simple milliseconds values as
-  // expected.  Most critically, things should not become null.
-  int32 kSomeMilliseconds = 243;  // Some example times.
-  int64 kReallyBigMilliseconds = (1LL << 35) + kSomeMilliseconds;
-
-  TrackedTime some = TrackedTime() +
-      Duration::FromMilliseconds(kSomeMilliseconds);
-  EXPECT_EQ(kSomeMilliseconds, (some - TrackedTime()).InMilliseconds());
-  EXPECT_FALSE(some.is_null());
-
-  // Now create a big time, to check that it is wrapped modulo 2^32.
-  base::TimeTicks big = base::TimeTicks() +
-      base::TimeDelta::FromMilliseconds(kReallyBigMilliseconds);
-  EXPECT_EQ(kReallyBigMilliseconds, (big - base::TimeTicks()).InMilliseconds());
-
-  TrackedTime wrapped_big(big);
-#if defined(USE_FAST_TIME_CLASS_FOR_DURATION_CALCULATIONS)
-  // Expect wrapping at 32 bits.
-  EXPECT_EQ(kSomeMilliseconds, (wrapped_big - TrackedTime()).InMilliseconds());
-#else  // !USE_FAST_TIME_CLASS_FOR_DURATION_CALCULATIONS)
-  // Expect no wrapping at 32 bits.
-  EXPECT_EQ(kReallyBigMilliseconds,
-            (wrapped_big - TrackedTime()).InMilliseconds());
-#endif  // USE_FAST_TIME_CLASS_FOR_DURATION_CALCULATIONS)
-}
-
-TEST_F(TrackedObjectsTest, TrackedTimerDuration) {
-  int kFirstMilliseconds = 793;
-  int kSecondMilliseconds = 14889;
-
-  Duration first = Duration::FromMilliseconds(kFirstMilliseconds);
-  Duration second = Duration::FromMilliseconds(kSecondMilliseconds);
-
-  EXPECT_EQ(kFirstMilliseconds, first.InMilliseconds());
-  EXPECT_EQ(kSecondMilliseconds, second.InMilliseconds());
-
-  Duration sum = first + second;
-  EXPECT_EQ(kFirstMilliseconds + kSecondMilliseconds, sum.InMilliseconds());
-}
-
-TEST_F(TrackedObjectsTest, TrackedTimerVsTimeTicks) {
-  // Make sure that our 32 bit timer is aligned with the TimeTicks() timer.
-
-  // First get a 64 bit timer (which should not be null).
-  base::TimeTicks ticks_before = base::TimeTicks::Now();
-  EXPECT_FALSE(ticks_before.is_null());
-
-  // Then get a 32 bit timer that can be be null when it wraps.
-  TrackedTime now = TrackedTime::Now();
-
-  // Then get a bracketing time.
-  base::TimeTicks ticks_after = base::TimeTicks::Now();
-  EXPECT_FALSE(ticks_after.is_null());
-
-  // Now make sure that we bracketed our tracked time nicely.
-  Duration before = now - TrackedTime(ticks_before);
-  EXPECT_LE(0, before.InMilliseconds());
-  Duration after = now - TrackedTime(ticks_after);
-  EXPECT_GE(0, after.InMilliseconds());
-}
-
-TEST_F(TrackedObjectsTest, TrackedTimerDisabled) {
-  // Check to be sure disabling the collection of data induces a null time
-  // (which we know will return much faster).
-  if (!ThreadData::InitializeAndSetTrackingStatus(false))
-    return;
-  // Since we disabled tracking, we should get a null response.
-  TrackedTime track_now = ThreadData::Now();
-  EXPECT_TRUE(track_now.is_null());
-}
-
-TEST_F(TrackedObjectsTest, TrackedTimerEnabled) {
-  if (!ThreadData::InitializeAndSetTrackingStatus(true))
-    return;
-  // Make sure that when we enable tracking, we get a real timer result.
-
-  // First get a 64 bit timer (which should not be null).
-  base::TimeTicks ticks_before = base::TimeTicks::Now();
-  EXPECT_FALSE(ticks_before.is_null());
-
-  // Then get a 32 bit timer that can be null when it wraps.
-  // Crtical difference from  the TrackedTimerVsTimeTicks test, is that we use
-  // ThreadData::Now().  It can sometimes return the null time.
-  TrackedTime now = ThreadData::Now();
-
-  // Then get a bracketing time.
-  base::TimeTicks ticks_after = base::TimeTicks::Now();
-  EXPECT_FALSE(ticks_after.is_null());
-
-  // Now make sure that we bracketed our tracked time nicely.
-  Duration before = now - TrackedTime(ticks_before);
-  EXPECT_LE(0, before.InMilliseconds());
-  Duration after = now - TrackedTime(ticks_after);
-  EXPECT_GE(0, after.InMilliseconds());
-}
-
 
 }  // namespace tracked_objects
diff --git a/ipc/ipc_message_macros.h b/ipc/ipc_message_macros.h
index 9b3f732..3c7f50f 100644
--- a/ipc/ipc_message_macros.h
+++ b/ipc/ipc_message_macros.h
@@ -20,7 +20,7 @@
 //
 // The XXXMsgStart value is an enumeration that ensures uniqueness for
 // each different message file.  Later, you will use this inside your
-// XXX_messages.h file before invoking message declatation macros:
+// XXX_messages.h file before invoking message declaration macros:
 //     #define IPC_MESSAGE_START XXXMsgStart
 //       ( ... your macro invocations go here ... )
 //
@@ -176,6 +176,7 @@
 #ifndef IPC_IPC_MESSAGE_MACROS_H_
 #define IPC_IPC_MESSAGE_MACROS_H_
 
+#include "base/profiler/scoped_profile.h"
 #include "ipc/ipc_message_utils.h"
 #include "ipc/param_traits_macros.h"
 
@@ -940,20 +941,24 @@ LogFunctionMap g_log_function_mapping;
     bool msg_is_ok__ = true; \
     switch (ipc_message__.type()) { \
 
-#define IPC_MESSAGE_FORWARD(msg_class, obj, member_func) \
-  case msg_class::ID: \
-    msg_is_ok__ = msg_class::Dispatch(&ipc_message__, obj, this, \
-                                      &member_func); \
-    break;
+#define IPC_MESSAGE_FORWARD(msg_class, obj, member_func)                       \
+    case msg_class::ID: {                                                      \
+        TRACK_RUN_IN_IPC_HANDLER(member_func);                                 \
+        msg_is_ok__ = msg_class::Dispatch(&ipc_message__, obj, this,           \
+                                      &member_func);                           \
+      }                                                                        \
+      break;
 
 #define IPC_MESSAGE_HANDLER(msg_class, member_func) \
   IPC_MESSAGE_FORWARD(msg_class, this, _IpcMessageHandlerClass::member_func)
 
-#define IPC_MESSAGE_FORWARD_DELAY_REPLY(msg_class, obj, member_func) \
-    case msg_class::ID: \
-    msg_is_ok__ = msg_class::DispatchDelayReply(&ipc_message__, obj, \
-                                                &member_func); \
-    break;
+#define IPC_MESSAGE_FORWARD_DELAY_REPLY(msg_class, obj, member_func)           \
+    case msg_class::ID: {                                                      \
+        TRACK_RUN_IN_IPC_HANDLER(member_func);                                 \
+        msg_is_ok__ = msg_class::DispatchDelayReply(&ipc_message__, obj,       \
+                                                  &member_func);               \
+      }                                                                        \
+      break;
 
 #define IPC_MESSAGE_HANDLER_DELAY_REPLY(msg_class, member_func) \
   IPC_MESSAGE_FORWARD_DELAY_REPLY(msg_class, this, \
@@ -964,9 +969,11 @@ LogFunctionMap g_log_function_mapping;
     code; \
     break;
 
-#define IPC_REPLY_HANDLER(func) \
-   case IPC_REPLY_ID: \
-     func(ipc_message__); \
+#define IPC_REPLY_HANDLER(func)                                                \
+   case IPC_REPLY_ID: {                                                        \
+         TRACK_RUN_IN_IPC_HANDLER(func);                                       \
+         func(ipc_message__);                                                  \
+     }                                                                         \
      break;