Implemented threshold based trace events that only get added to the trace if the elapsed time between begin and end is greater than a specified time.

In order to reduce macro code duplication, created some additional internal helper macros.

Improved performance on the critical trace-disabled code path by deferring some member initialization. Removed the unused __LINE__/__FILE__ data.

Prefixed internal macros with "INTERNAL_" so that users ignore them. Moved all the internal macros below so that the user sees the relevant macros first.

BUG=81565
TEST=base_unittests

Review URL: http://codereview.chromium.org/7016012

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

3 files changed, 478 insertions, 167 deletions

diff --git a/base/debug/trace_event.cc b/base/debug/trace_event.cc
index 58ff82f..5a526f6 100644
--- a/base/debug/trace_event.cc
+++ b/base/debug/trace_event.cc
@@ -155,12 +155,34 @@ const char* GetPhaseStr(TraceEventPhase phase) {
 }  // namespace
 
 TraceEvent::TraceEvent()
-    : process_id(0),
-      thread_id(0),
-      phase(TRACE_EVENT_PHASE_BEGIN),
-      category(NULL),
-      name(NULL) {
-  memset(arg_names, 0, sizeof(arg_names));
+    : process_id_(0),
+      thread_id_(0),
+      phase_(TRACE_EVENT_PHASE_BEGIN),
+      category_(NULL),
+      name_(NULL) {
+  arg_names_[0] = NULL;
+  arg_names_[1] = NULL;
+}
+
+TraceEvent::TraceEvent(unsigned long process_id,
+                       unsigned long thread_id,
+                       TimeTicks timestamp,
+                       TraceEventPhase phase,
+                       const TraceCategory* category,
+                       const char* name,
+                       const char* arg1_name, const TraceValue& arg1_val,
+                       const char* arg2_name, const TraceValue& arg2_val)
+    : process_id_(process_id),
+      thread_id_(thread_id),
+      timestamp_(timestamp),
+      phase_(phase),
+      category_(category),
+      name_(name) {
+  COMPILE_ASSERT(kTraceMaxNumArgs == 2, TraceEvent_arg_count_out_of_sync);
+  arg_names_[0] = arg1_name;
+  arg_names_[1] = arg2_name;
+  arg_values_[0] = arg1_val;
+  arg_values_[1] = arg2_val;
 }
 
 TraceEvent::~TraceEvent() {
@@ -180,28 +202,28 @@ void TraceEvent::AppendEventsAsJSON(const std::vector<TraceEvent>& events,
 }
 
 void TraceEvent::AppendAsJSON(std::string* out) const {
-  const char* phase_str = GetPhaseStr(phase);
-  int64 time_int64 = timestamp.ToInternalValue();
+  const char* phase_str = GetPhaseStr(phase_);
+  int64 time_int64 = timestamp_.ToInternalValue();
   // Category name checked at category creation time.
-  DCHECK(!strchr(name, '"'));
+  DCHECK(!strchr(name_, '"'));
   StringAppendF(out,
       "{\"cat\":\"%s\",\"pid\":%i,\"tid\":%i,\"ts\":%lld,"
       "\"ph\":\"%s\",\"name\":\"%s\",\"args\":{",
-      category->name,
-      static_cast<int>(process_id),
-      static_cast<int>(thread_id),
+      category_->name,
+      static_cast<int>(process_id_),
+      static_cast<int>(thread_id_),
       static_cast<long long>(time_int64),
       phase_str,
-      name);
+      name_);
 
   // Output argument names and values, stop at first NULL argument name.
-  for (size_t i = 0; i < kTraceMaxNumArgs && arg_names[i]; ++i) {
+  for (size_t i = 0; i < kTraceMaxNumArgs && arg_names_[i]; ++i) {
     if (i > 0)
       *out += ",";
     *out += "\"";
-    *out += arg_names[i];
+    *out += arg_names_[i];
     *out += "\":";
-    arg_values[i].AppendAsJSON(out);
+    arg_values_[i].AppendAsJSON(out);
   }
   *out += "}}";
 }
@@ -314,38 +336,50 @@ void TraceLog::Flush() {
   }
 }
 
-void TraceLog::AddTraceEvent(TraceEventPhase phase,
-                             const char* file, int line,
-                             const TraceCategory* category,
-                             const char* name,
-                             const char* arg1_name, TraceValue arg1_val,
-                             const char* arg2_name, TraceValue arg2_val) {
-  DCHECK(file && name);
+int TraceLog::AddTraceEvent(TraceEventPhase phase,
+                            const TraceCategory* category,
+                            const char* name,
+                            const char* arg1_name, TraceValue arg1_val,
+                            const char* arg2_name, TraceValue arg2_val,
+                            int threshold_begin_id,
+                            int64 threshold) {
+  DCHECK(name);
 #ifdef USE_UNRELIABLE_NOW
   TimeTicks now = TimeTicks::HighResNow();
 #else
   TimeTicks now = TimeTicks::Now();
 #endif
   BufferFullCallback buffer_full_callback_copy;
+  int ret_begin_id = -1;
   {
     AutoLock lock(lock_);
     if (!enabled_ || !category->enabled)
-      return;
+      return -1;
     if (logged_events_.size() >= kTraceEventBufferSize)
-      return;
-    logged_events_.push_back(TraceEvent());
-    TraceEvent& event = logged_events_.back();
-    event.process_id = static_cast<unsigned long>(base::GetCurrentProcId());
-    event.thread_id = PlatformThread::CurrentId();
-    event.timestamp = now;
-    event.phase = phase;
-    event.category = category;
-    event.name = name;
-    event.arg_names[0] = arg1_name;
-    event.arg_values[0] = arg1_val;
-    event.arg_names[1] = arg2_name;
-    event.arg_values[1] = arg2_val;
-    COMPILE_ASSERT(kTraceMaxNumArgs == 2, TraceEvent_arg_count_out_of_sync);
+      return -1;
+    if (threshold_begin_id > -1) {
+      DCHECK(phase == base::debug::TRACE_EVENT_PHASE_END);
+      size_t begin_i = static_cast<size_t>(threshold_begin_id);
+      // Return now if there has been a flush since the begin event was posted.
+      if (begin_i >= logged_events_.size())
+        return -1;
+      // Determine whether to drop the begin/end pair.
+      TimeDelta elapsed = now - logged_events_[begin_i].timestamp();
+      if (elapsed < TimeDelta::FromMicroseconds(threshold)) {
+        // Remove begin event and do not add end event.
+        // This will be expensive if there have been other events in the
+        // mean time (should be rare).
+        logged_events_.erase(logged_events_.begin() + begin_i);
+        return -1;
+      }
+    }
+    ret_begin_id = static_cast<int>(logged_events_.size());
+    logged_events_.push_back(
+        TraceEvent(static_cast<unsigned long>(base::GetCurrentProcId()),
+                   PlatformThread::CurrentId(),
+                   now, phase, category, name,
+                   arg1_name, arg1_val,
+                   arg2_name, arg2_val));
 
     if (logged_events_.size() == kTraceEventBufferSize) {
       buffer_full_callback_copy = buffer_full_callback_;
@@ -354,10 +388,11 @@ void TraceLog::AddTraceEvent(TraceEventPhase phase,
 
   if (!buffer_full_callback_copy.is_null())
     buffer_full_callback_copy.Run();
+
+  return ret_begin_id;
 }
 
 void TraceLog::AddTraceEventEtw(TraceEventPhase phase,
-                                const char* file, int line,
                                 const char* name,
                                 const void* id,
                                 const char* extra) {
@@ -372,9 +407,10 @@ void TraceLog::AddTraceEventEtw(TraceEventPhase phase,
     TraceLog* tracelog = TraceLog::GetInstance();
     if (!tracelog)
       return;
-    tracelog->AddTraceEvent(phase, file, line, category, name,
+    tracelog->AddTraceEvent(phase, category, name,
                             "id", id,
-                            "extra", extra ? extra : "");
+                            "extra", extra ? extra : "",
+                            -1, 0);
   }
 }
 
@@ -382,5 +418,51 @@ void TraceLog::Resurrect() {
   StaticMemorySingletonTraits<TraceLog>::Resurrect();
 }
 
+namespace internal {
+
+void TraceEndOnScopeClose::Initialize(const TraceCategory* category,
+                                      const char* name) {
+  data_.category = category;
+  data_.name = name;
+  p_data_ = &data_;
+}
+
+void TraceEndOnScopeClose::AddEventIfEnabled() {
+  // Only called when p_data_ is non-null.
+  if (p_data_->category->enabled) {
+    base::debug::TraceLog::GetInstance()->AddTraceEvent(
+        base::debug::TRACE_EVENT_PHASE_END,
+        p_data_->category,
+        p_data_->name,
+        NULL, 0, NULL, 0,
+        -1, 0);
+  }
+}
+
+void TraceEndOnScopeCloseThreshold::Initialize(const TraceCategory* category,
+                                               const char* name,
+                                               int threshold_begin_id,
+                                               int64 threshold) {
+  data_.category = category;
+  data_.name = name;
+  data_.threshold_begin_id = threshold_begin_id;
+  data_.threshold = threshold;
+  p_data_ = &data_;
+}
+
+void TraceEndOnScopeCloseThreshold::AddEventIfEnabled() {
+  // Only called when p_data_ is non-null.
+  if (p_data_->category->enabled) {
+    base::debug::TraceLog::GetInstance()->AddTraceEvent(
+        base::debug::TRACE_EVENT_PHASE_END,
+        p_data_->category,
+        p_data_->name,
+        NULL, 0, NULL, 0,
+        p_data_->threshold_begin_id, p_data_->threshold);
+  }
+}
+
+} // namespace internal
+
 }  // namespace debug
 }  // namespace base
diff --git a/base/debug/trace_event.h b/base/debug/trace_event.h
index 7aed02e9..d88e901 100644
--- a/base/debug/trace_event.h
+++ b/base/debug/trace_event.h
@@ -29,8 +29,7 @@
 //   }
 //
 // The trace system will automatically add to this information the
-// current process id, thread id, a timestamp down to the
-// microsecond, as well as the file and line number of the calling location.
+// current process id, thread id, and a timestamp in microseconds.
 //
 // By default, trace collection is compiled in, but turned off at runtime.
 // Collecting trace data is the responsibility of the embedding
@@ -86,144 +85,158 @@
 #define TRACE_EVENT_BEGIN_ETW(name, id, extra) \
   base::debug::TraceLog::AddTraceEventEtw( \
       base::debug::TRACE_EVENT_PHASE_BEGIN, \
-      __FILE__, __LINE__, name, reinterpret_cast<const void*>(id), extra);
+      name, reinterpret_cast<const void*>(id), extra);
 
 #define TRACE_EVENT_END_ETW(name, id, extra) \
   base::debug::TraceLog::AddTraceEventEtw( \
       base::debug::TRACE_EVENT_PHASE_END, \
-      __FILE__, __LINE__, name, reinterpret_cast<const void*>(id), extra);
+      name, reinterpret_cast<const void*>(id), extra);
 
 #define TRACE_EVENT_INSTANT_ETW(name, id, extra) \
   base::debug::TraceLog::AddTraceEventEtw( \
       base::debug::TRACE_EVENT_PHASE_INSTANT, \
-      __FILE__, __LINE__, name, reinterpret_cast<const void*>(id), extra);
-
-
-// Implementation detail: trace event macros create temporary variables
-// to keep instrumentation overhead low. These macros give each temporary
-// variable a unique name based on the line number to prevent name collissions.
-#define TRACE_EVENT_UNIQUE_IDENTIFIER3(a,b) a##b
-#define TRACE_EVENT_UNIQUE_IDENTIFIER2(a,b) \
-  TRACE_EVENT_UNIQUE_IDENTIFIER3(a,b)
-#define TRACE_EVENT_UNIQUE_IDENTIFIER(name_prefix) \
-  TRACE_EVENT_UNIQUE_IDENTIFIER2(name_prefix, __LINE__)
+      name, reinterpret_cast<const void*>(id), extra);
 
 // Records a pair of begin and end events called "name" for the current
 // scope, with 0, 1 or 2 associated arguments. If the category is not
 // enabled, then this does nothing.
 // - category and name strings must have application lifetime (statics or
 //   literals). They may not include " chars.
-// - ANNOTATE_BENIGN_RACE, see Thread Safety above.
 #define TRACE_EVENT0(category, name) \
   TRACE_EVENT1(category, name, NULL, 0)
 #define TRACE_EVENT1(category, name, arg1_name, arg1_val) \
   TRACE_EVENT2(category, name, arg1_name, arg1_val, NULL, 0)
 #define TRACE_EVENT2(category, name, arg1_name, arg1_val, arg2_name, arg2_val) \
-  static const base::debug::TraceCategory* \
-      TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = NULL; \
-  ANNOTATE_BENIGN_RACE(&TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \
-                       "trace_event category"); \
-  if (!TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic)) \
-    TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \
-        base::debug::TraceLog::GetCategory(category); \
-  if (TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic)->enabled) { \
-    base::debug::TraceLog::GetInstance()->AddTraceEvent( \
-        base::debug::TRACE_EVENT_PHASE_BEGIN, \
-        __FILE__, __LINE__, \
-        TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \
-        name, \
-        arg1_name, arg1_val, \
-        arg2_name, arg2_val); \
-  } \
-  base::debug::internal::TraceEndOnScopeClose \
-      TRACE_EVENT_UNIQUE_IDENTIFIER(profileScope) ( \
-          __FILE__, __LINE__, \
-          TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), name);
+  INTERNAL_TRACE_EVENT_ADD_SCOPED( \
+      category, name, arg1_name, arg1_val, arg2_name, arg2_val)
 
 // Records a single event called "name" immediately, with 0, 1 or 2
 // associated arguments. If the category is not enabled, then this
 // does nothing.
 // - category and name strings must have application lifetime (statics or
 //   literals). They may not include " chars.
-// - ANNOTATE_BENIGN_RACE, see Thread Safety above.
 #define TRACE_EVENT_INSTANT0(category, name) \
   TRACE_EVENT_INSTANT1(category, name, NULL, 0)
 #define TRACE_EVENT_INSTANT1(category, name, arg1_name, arg1_val) \
   TRACE_EVENT_INSTANT2(category, name, arg1_name, arg1_val, NULL, 0)
 #define TRACE_EVENT_INSTANT2(category, name, arg1_name, arg1_val, \
     arg2_name, arg2_val) \
-  static const base::debug::TraceCategory* \
-      TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = NULL; \
-  ANNOTATE_BENIGN_RACE(&TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \
-                       "trace_event category"); \
-  if (!TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic)) \
-    TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \
-        base::debug::TraceLog::GetCategory(category); \
-  if (TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic)->enabled) { \
-    base::debug::TraceLog::GetInstance()->AddTraceEvent( \
-        base::debug::TRACE_EVENT_PHASE_INSTANT, \
-        __FILE__, __LINE__, \
-        TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \
-        name, \
-        arg1_name, arg1_val, \
-        arg2_name, arg2_val); \
-  }
+  INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_INSTANT, \
+      category, name, arg1_name, arg1_val, arg2_name, arg2_val)
 
 // Records a single BEGIN event called "name" immediately, with 0, 1 or 2
 // associated arguments. If the category is not enabled, then this
 // does nothing.
 // - category and name strings must have application lifetime (statics or
 //   literals). They may not include " chars.
-// - ANNOTATE_BENIGN_RACE, see Thread Safety above.
 #define TRACE_EVENT_BEGIN0(category, name) \
   TRACE_EVENT_BEGIN1(category, name, NULL, 0)
 #define TRACE_EVENT_BEGIN1(category, name, arg1_name, arg1_val) \
   TRACE_EVENT_BEGIN2(category, name, arg1_name, arg1_val, NULL, 0)
 #define TRACE_EVENT_BEGIN2(category, name, arg1_name, arg1_val, \
     arg2_name, arg2_val) \
-  static const base::debug::TraceCategory* \
-      TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = NULL; \
-  ANNOTATE_BENIGN_RACE(&TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \
-                       "trace_event category"); \
-  if (!TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic)) \
-    TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \
-        base::debug::TraceLog::GetCategory(category); \
-  if (TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic)->enabled) { \
-    base::debug::TraceLog::GetInstance()->AddTraceEvent( \
-        base::debug::TRACE_EVENT_PHASE_BEGIN, \
-        __FILE__, __LINE__, \
-        TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \
-        name, \
-        arg1_name, arg1_val, \
-        arg2_name, arg2_val); \
-  }
+  INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_BEGIN, \
+      category, name, arg1_name, arg1_val, arg2_name, arg2_val)
 
 // Records a single END event for "name" immediately. If the category
 // is not enabled, then this does nothing.
 // - category and name strings must have application lifetime (statics or
 //   literals). They may not include " chars.
-// - ANNOTATE_BENIGN_RACE, see Thread Safety above.
 #define TRACE_EVENT_END0(category, name) \
   TRACE_EVENT_END1(category, name, NULL, 0)
 #define TRACE_EVENT_END1(category, name, arg1_name, arg1_val) \
   TRACE_EVENT_END2(category, name, arg1_name, arg1_val, NULL, 0)
 #define TRACE_EVENT_END2(category, name, arg1_name, arg1_val, \
     arg2_name, arg2_val) \
+  INTERNAL_TRACE_EVENT_ADD(base::debug::TRACE_EVENT_PHASE_END, \
+      category, name, arg1_name, arg1_val, arg2_name, arg2_val)
+
+// Time threshold event:
+// Only record the event if the duration is greater than the specified
+// threshold_us (time in microseconds).
+// Records a pair of begin and end events called "name" for the current
+// scope, with 0, 1 or 2 associated arguments. If the category is not
+// enabled, then this does nothing.
+// - category and name strings must have application lifetime (statics or
+//   literals). They may not include " chars.
+#define TRACE_EVENT_IF_LONGER_THAN0(threshold_us, category, name) \
+  TRACE_EVENT_IF_LONGER_THAN1(threshold_us, category, name, NULL, 0)
+#define TRACE_EVENT_IF_LONGER_THAN1( \
+    threshold_us, category, name, arg1_name, arg1_val) \
+  TRACE_EVENT_IF_LONGER_THAN2(threshold_us, category, name, \
+                         arg1_name, arg1_val, NULL, 0)
+#define TRACE_EVENT_IF_LONGER_THAN2( \
+    threshold_us, category, name, arg1_name, arg1_val, arg2_name, arg2_val) \
+  INTERNAL_TRACE_EVENT_ADD_SCOPED_IF_LONGER_THAN(threshold_us, \
+      category, name, arg1_name, arg1_val, arg2_name, arg2_val)
+
+
+// Implementation detail: trace event macros create temporary variables
+// to keep instrumentation overhead low. These macros give each temporary
+// variable a unique name based on the line number to prevent name collissions.
+#define INTERNAL_TRACE_EVENT_UID3(a,b) \
+    trace_event_unique_##a##b
+#define INTERNAL_TRACE_EVENT_UID2(a,b) \
+  INTERNAL_TRACE_EVENT_UID3(a,b)
+#define INTERNAL_TRACE_EVENT_UID(name_prefix) \
+  INTERNAL_TRACE_EVENT_UID2(name_prefix, __LINE__)
+
+// Implementation detail: internal macro to create static category.
+// - ANNOTATE_BENIGN_RACE, see Thread Safety above.
+#define INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category) \
   static const base::debug::TraceCategory* \
-      TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = NULL; \
-  ANNOTATE_BENIGN_RACE(&TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \
+      INTERNAL_TRACE_EVENT_UID(catstatic) = NULL; \
+  ANNOTATE_BENIGN_RACE(&INTERNAL_TRACE_EVENT_UID(catstatic), \
                        "trace_event category"); \
-  if (!TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic)) \
-    TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \
-        base::debug::TraceLog::GetCategory(category); \
-  if (TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic)->enabled) { \
+  if (!INTERNAL_TRACE_EVENT_UID(catstatic)) \
+    INTERNAL_TRACE_EVENT_UID(catstatic) = \
+        base::debug::TraceLog::GetCategory(category);
+
+// Implementation detail: internal macro to create static category and add begin
+// event if the category is enabled.
+#define INTERNAL_TRACE_EVENT_ADD( \
+    phase, category, name, arg1_name, arg1_val, arg2_name, arg2_val) \
+  INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \
+  if (INTERNAL_TRACE_EVENT_UID(catstatic)->enabled) { \
     base::debug::TraceLog::GetInstance()->AddTraceEvent( \
-        base::debug::TRACE_EVENT_PHASE_END, \
-        __FILE__, __LINE__, \
-        TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \
-        name, \
-        arg1_name, arg1_val, \
-        arg2_name, arg2_val); \
+        phase, INTERNAL_TRACE_EVENT_UID(catstatic), \
+        name, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0); \
+  }
+
+// Implementation detail: internal macro to create static category and add begin
+// event if the category is enabled. Also adds the end event when the scope
+// ends.
+#define INTERNAL_TRACE_EVENT_ADD_SCOPED( \
+    category, name, arg1_name, arg1_val, arg2_name, arg2_val) \
+  INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \
+  base::debug::internal::TraceEndOnScopeClose \
+      INTERNAL_TRACE_EVENT_UID(profileScope); \
+  if (INTERNAL_TRACE_EVENT_UID(catstatic)->enabled) { \
+    base::debug::TraceLog::GetInstance()->AddTraceEvent( \
+        base::debug::TRACE_EVENT_PHASE_BEGIN, \
+        INTERNAL_TRACE_EVENT_UID(catstatic), \
+        name, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0); \
+    INTERNAL_TRACE_EVENT_UID(profileScope).Initialize( \
+        INTERNAL_TRACE_EVENT_UID(catstatic), name); \
+  }
+
+// Implementation detail: internal macro to create static category and add begin
+// event if the category is enabled. Also adds the end event when the scope
+// ends. If the elapsed time is < threshold time, the begin/end pair is erased.
+#define INTERNAL_TRACE_EVENT_ADD_SCOPED_IF_LONGER_THAN(threshold, \
+    category, name, arg1_name, arg1_val, arg2_name, arg2_val) \
+  INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \
+  base::debug::internal::TraceEndOnScopeCloseThreshold \
+      INTERNAL_TRACE_EVENT_UID(profileScope); \
+  if (INTERNAL_TRACE_EVENT_UID(catstatic)->enabled) { \
+    int INTERNAL_TRACE_EVENT_UID(begin_event_id) = \
+      base::debug::TraceLog::GetInstance()->AddTraceEvent( \
+          base::debug::TRACE_EVENT_PHASE_BEGIN, \
+          INTERNAL_TRACE_EVENT_UID(catstatic), \
+          name, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0); \
+    INTERNAL_TRACE_EVENT_UID(profileScope).Initialize( \
+        INTERNAL_TRACE_EVENT_UID(catstatic), name, \
+        INTERNAL_TRACE_EVENT_UID(begin_event_id), threshold); \
   }
 
 namespace base {
@@ -357,8 +370,17 @@ class BASE_API TraceValue {
 // OutputCallback whenever the tracing system decides to flush. This
 // can happen at any time, on any thread, or you can programatically
 // force it to happen.
-struct TraceEvent {
+class TraceEvent {
+ public:
   TraceEvent();
+  TraceEvent(unsigned long process_id,
+             unsigned long thread_id,
+             TimeTicks timestamp,
+             TraceEventPhase phase,
+             const TraceCategory* category,
+             const char* name,
+             const char* arg1_name, const TraceValue& arg1_val,
+             const char* arg2_name, const TraceValue& arg2_val);
   ~TraceEvent();
 
   // Serialize event data to JSON
@@ -368,15 +390,17 @@ struct TraceEvent {
                                  std::string* out);
   void AppendAsJSON(std::string* out) const;
 
+  TimeTicks timestamp() const { return timestamp_; }
 
-  unsigned long process_id;
-  unsigned long thread_id;
-  TimeTicks timestamp;
-  TraceEventPhase phase;
-  const TraceCategory* category;
-  const char* name;
-  const char* arg_names[kTraceMaxNumArgs];
-  TraceValue arg_values[kTraceMaxNumArgs];
+ private:
+  unsigned long process_id_;
+  unsigned long thread_id_;
+  TimeTicks timestamp_;
+  TraceEventPhase phase_;
+  const TraceCategory* category_;
+  const char* name_;
+  const char* arg_names_[kTraceMaxNumArgs];
+  TraceValue arg_values_[kTraceMaxNumArgs];
 };
 
 
@@ -412,23 +436,27 @@ class BASE_API TraceLog {
   static const TraceCategory* GetCategory(const char* name);
 
   // Called by TRACE_EVENT* macros, don't call this directly.
-  void AddTraceEvent(TraceEventPhase phase,
-      const char* file, int line,
-      const TraceCategory* category,
-      const char* name,
-      const char* arg1_name, TraceValue arg1_val,
-      const char* arg2_name, TraceValue arg2_val);
+  // Returns the index in the internal vector of the event if it was added, or
+  //         -1 if the event was not added.
+  // On end events, the return value of the begin event can be specified along
+  // with a threshold in microseconds. If the elapsed time between begin and end
+  // is less than the threshold, the begin/end event pair is dropped.
+  int AddTraceEvent(TraceEventPhase phase,
+                    const TraceCategory* category,
+                    const char* name,
+                    const char* arg1_name, TraceValue arg1_val,
+                    const char* arg2_name, TraceValue arg2_val,
+                    int threshold_begin_id,
+                    int64 threshold);
   static void AddTraceEventEtw(TraceEventPhase phase,
-      const char* file, int line,
-      const char* name,
-      const void* id,
-      const char* extra);
+                               const char* name,
+                               const void* id,
+                               const char* extra);
   static void AddTraceEventEtw(TraceEventPhase phase,
-      const char* file, int line,
-      const char* name,
-      const void* id,
-      const std::string& extra) {
-    AddTraceEventEtw(phase, file, line, name, id, extra.c_str());
+                               const char* name,
+                               const void* id,
+                               const std::string& extra) {
+    AddTraceEventEtw(phase, name, id, extra.c_str());
   }
 
   // Exposed for unittesting only, allows resurrecting our
@@ -460,29 +488,65 @@ namespace internal {
 // Used by TRACE_EVENTx macro. Do not use directly.
 class BASE_API TraceEndOnScopeClose {
  public:
-  TraceEndOnScopeClose(const char* file, int line,
-                       const TraceCategory* category,
-                       const char* name)
-      : file_(file)
-      , line_(line)
-      , category_(category)
-      , name_(name) { }
-
+  TraceEndOnScopeClose() : p_data_(NULL) {}
   ~TraceEndOnScopeClose() {
-    if (category_->enabled)
-      base::debug::TraceLog::GetInstance()->AddTraceEvent(
-          base::debug::TRACE_EVENT_PHASE_END,
-          file_, line_,
-          category_,
-          name_,
-          NULL, 0, NULL, 0);
+    if (p_data_)
+      AddEventIfEnabled();
   }
 
+  void Initialize(const TraceCategory* category,
+                  const char* name);
+
  private:
-  const char* file_;
-  int line_;
-  const TraceCategory* category_;
-  const char* name_;
+  // Add the end event if the category is still enabled.
+  void AddEventIfEnabled();
+
+  // This Data struct workaround is to avoid initializing all the members
+  // in Data during construction of this object, since this object is always
+  // constructed, even when tracing is disabled. If the members of Data were
+  // members of this class instead, compiler warnings occur about potential
+  // uninitialized accesses.
+  struct Data {
+    const TraceCategory* category;
+    const char* name;
+  };
+  Data* p_data_;
+  Data data_;
+};
+
+// Used by TRACE_EVENTx macro. Do not use directly.
+class BASE_API TraceEndOnScopeCloseThreshold {
+ public:
+  TraceEndOnScopeCloseThreshold() : p_data_(NULL) {}
+  ~TraceEndOnScopeCloseThreshold() {
+    if (p_data_)
+      AddEventIfEnabled();
+  }
+
+  // Called by macros only when tracing is enabled at the point when the begin
+  // event is added.
+  void Initialize(const TraceCategory* category,
+                  const char* name,
+                  int threshold_begin_id,
+                  int64 threshold);
+
+ private:
+  // Add the end event if the category is still enabled.
+  void AddEventIfEnabled();
+
+  // This Data struct workaround is to avoid initializing all the members
+  // in Data during construction of this object, since this object is always
+  // constructed, even when tracing is disabled. If the members of Data were
+  // members of this class instead, compiler warnings occur about potential
+  // uninitialized accesses.
+  struct Data {
+    int64 threshold;
+    const TraceCategory* category;
+    const char* name;
+    int threshold_begin_id;
+  };
+  Data* p_data_;
+  Data data_;
 };
 
 }  // namespace internal
diff --git a/base/debug/trace_event_unittest.cc b/base/debug/trace_event_unittest.cc
index 360468d..a4b846e 100644
--- a/base/debug/trace_event_unittest.cc
+++ b/base/debug/trace_event_unittest.cc
@@ -21,10 +21,17 @@ namespace debug {
 
 namespace {
 
+struct JsonKeyValue {
+  const char* key;
+  const char* value;
+};
+
 class TraceEventTestFixture : public testing::Test {
  public:
   void ManualTestSetUp();
   void OnTraceDataCollected(TraceLog::RefCountedString* json_events_str);
+  bool FindMatchingTraceEntry(const JsonKeyValue* key_values);
+  bool FindNamePhase(const char* name, const char* phase);
 
   std::string trace_string_;
   ListValue trace_parsed_;
@@ -63,6 +70,61 @@ void TraceEventTestFixture::OnTraceDataCollected(
   }
 }
 
+static bool IsKeyValueInDict(const JsonKeyValue* key_value,
+                             DictionaryValue* dict) {
+  Value* value = NULL;
+  std::string value_str;
+  if (dict->Get(key_value->key, &value) &&
+      value->GetAsString(&value_str) &&
+      value_str == key_value->value)
+    return true;
+
+  // Recurse to test arguments
+  DictionaryValue* args_dict = NULL;
+  dict->GetDictionary("args", &args_dict);
+  if (args_dict)
+    return IsKeyValueInDict(key_value, args_dict);
+
+  return false;
+}
+
+static bool IsAllKeyValueInDict(const JsonKeyValue* key_values,
+                                DictionaryValue* dict) {
+  // Scan all key_values, they must all be present and equal.
+  while (key_values && key_values->key) {
+    if (!IsKeyValueInDict(key_values, dict))
+      return false;
+    ++key_values;
+  }
+  return true;
+}
+
+bool TraceEventTestFixture::FindMatchingTraceEntry(
+    const JsonKeyValue* key_values) {
+  // Scan all items
+  size_t trace_parsed_count = trace_parsed_.GetSize();
+  for (size_t i = 0; i < trace_parsed_count; i++) {
+    Value* value = NULL;
+    trace_parsed_.Get(i, &value);
+    if (!value || value->GetType() != Value::TYPE_DICTIONARY)
+      continue;
+    DictionaryValue* dict = static_cast<DictionaryValue*>(value);
+
+    if (IsAllKeyValueInDict(key_values, dict))
+      return true;
+  }
+  return false;
+}
+
+bool TraceEventTestFixture::FindNamePhase(const char* name, const char* phase) {
+  JsonKeyValue key_values[] = {
+    {"name", name},
+    {"ph", phase},
+    {0, 0}
+  };
+  return FindMatchingTraceEntry(key_values);
+}
+
 bool IsStringInDict(const char* string_to_match, DictionaryValue* dict) {
   for (DictionaryValue::key_iterator ikey = dict->begin_keys();
        ikey != dict->end_keys(); ++ikey) {
@@ -224,6 +286,109 @@ TEST_F(TraceEventTestFixture, DataCaptured) {
   DataCapturedValidateTraces(trace_parsed_, trace_string_);
 }
 
+// Simple Test for time threshold events.
+TEST_F(TraceEventTestFixture, DataCapturedThreshold) {
+  ManualTestSetUp();
+  TraceLog::GetInstance()->SetEnabled(true);
+
+  // Test that events at the same level are properly filtered by threshold.
+  {
+    TRACE_EVENT_IF_LONGER_THAN0(100, "time", "threshold 100");
+    TRACE_EVENT_IF_LONGER_THAN0(1000, "time", "threshold 1000");
+    TRACE_EVENT_IF_LONGER_THAN0(10000, "time", "threshold 10000");
+    // 100+ seconds to avoid flakiness.
+    TRACE_EVENT_IF_LONGER_THAN0(100000000, "time", "threshold long1");
+    TRACE_EVENT_IF_LONGER_THAN0(200000000, "time", "threshold long2");
+    base::PlatformThread::Sleep(20); // 20000 us
+  }
+
+  // Test that a normal nested event remains after it's parent event is dropped.
+  {
+    TRACE_EVENT_IF_LONGER_THAN0(1000000, "time", "2threshold10000");
+    {
+      TRACE_EVENT0("time", "nonthreshold1");
+    }
+  }
+
+  // Test that parent thresholded events are dropped while some nested events
+  // remain.
+  {
+    TRACE_EVENT0("time", "nonthreshold3");
+    {
+      TRACE_EVENT_IF_LONGER_THAN0(200000000, "time", "3thresholdlong2");
+      {
+        TRACE_EVENT_IF_LONGER_THAN0(100000000, "time", "3thresholdlong1");
+        {
+          TRACE_EVENT_IF_LONGER_THAN0(10000, "time", "3threshold10000");
+          {
+            TRACE_EVENT_IF_LONGER_THAN0(1000, "time", "3threshold1000");
+            {
+              TRACE_EVENT_IF_LONGER_THAN0(100, "time", "3threshold100");
+              base::PlatformThread::Sleep(20);
+            }
+          }
+        }
+      }
+    }
+  }
+
+  // Test that child thresholded events are dropped while some parent events
+  // remain.
+  {
+    TRACE_EVENT0("time", "nonthreshold4");
+    {
+      TRACE_EVENT_IF_LONGER_THAN0(100, "time", "4threshold100");
+      {
+        TRACE_EVENT_IF_LONGER_THAN0(1000, "time", "4threshold1000");
+        {
+          TRACE_EVENT_IF_LONGER_THAN0(10000, "time", "4threshold10000");
+          {
+            TRACE_EVENT_IF_LONGER_THAN0(100000000, "time",
+                                        "4thresholdlong1");
+            {
+              TRACE_EVENT_IF_LONGER_THAN0(200000000, "time",
+                                          "4thresholdlong2");
+              base::PlatformThread::Sleep(20);
+            }
+          }
+        }
+      }
+    }
+  }
+
+  TraceLog::GetInstance()->SetEnabled(false);
+
+#define EXPECT_FIND_BE_(str) \
+  EXPECT_TRUE(FindNamePhase(str, "B")); \
+  EXPECT_TRUE(FindNamePhase(str, "E"))
+#define EXPECT_NOT_FIND_BE_(str) \
+  EXPECT_FALSE(FindNamePhase(str, "B")); \
+  EXPECT_FALSE(FindNamePhase(str, "E"))
+
+  EXPECT_FIND_BE_("threshold 100");
+  EXPECT_FIND_BE_("threshold 1000");
+  EXPECT_FIND_BE_("threshold 10000");
+  EXPECT_NOT_FIND_BE_("threshold long1");
+  EXPECT_NOT_FIND_BE_("threshold long2");
+
+  EXPECT_NOT_FIND_BE_("2threshold10000");
+  EXPECT_FIND_BE_("nonthreshold1");
+
+  EXPECT_FIND_BE_("nonthreshold3");
+  EXPECT_FIND_BE_("3threshold100");
+  EXPECT_FIND_BE_("3threshold1000");
+  EXPECT_FIND_BE_("3threshold10000");
+  EXPECT_NOT_FIND_BE_("3thresholdlong1");
+  EXPECT_NOT_FIND_BE_("3thresholdlong2");
+
+  EXPECT_FIND_BE_("nonthreshold4");
+  EXPECT_FIND_BE_("4threshold100");
+  EXPECT_FIND_BE_("4threshold1000");
+  EXPECT_FIND_BE_("4threshold10000");
+  EXPECT_NOT_FIND_BE_("4thresholdlong1");
+  EXPECT_NOT_FIND_BE_("4thresholdlong2");
+}
+
 // Test that data sent from other threads is gathered
 TEST_F(TraceEventTestFixture, DataCapturedOnThread) {
   ManualTestSetUp();