Adding raw tracing to trace framework.

With some types of tracing you do not want to use the system time as the recorded event time. In those cases, we want to provide a timestamp that will be used to display the event.

In a similar vein, the thread which is outputting the event may not be the thread where the event happened so we also allow an explicit thread_id to be provided.

BUG=111509

Review URL: https://chromiumcodereview.appspot.com/11366109

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

5 files changed, 295 insertions, 78 deletions

diff --git a/base/debug/trace_event.h b/base/debug/trace_event.h
index d173282..3459a94 100644
--- a/base/debug/trace_event.h
+++ b/base/debug/trace_event.h
@@ -44,6 +44,22 @@
 #define TRACE_EVENT_API_ADD_TRACE_EVENT \
     base::debug::TraceLog::GetInstance()->AddTraceEvent
 
+// Add a trace event to the platform tracing system.
+// void TRACE_EVENT_API_ADD_TRACE_EVENT_WITH_TIMESTAMP(
+//                    char phase,
+//                    const unsigned char* category_enabled,
+//                    const char* name,
+//                    unsigned long long id,
+//                    int thread_id,
+//                    const TimeTicks& timestamp,
+//                    int num_args,
+//                    const char** arg_names,
+//                    const unsigned char* arg_types,
+//                    const unsigned long long* arg_values,
+//                    unsigned char flags)
+#define TRACE_EVENT_API_ADD_TRACE_EVENT_WITH_THREAD_ID_AND_TIMESTAMP \
+    base::debug::TraceLog::GetInstance()->AddTraceEventWithThreadIdAndTimestamp
+
 // Defines atomic operations used internally by the tracing system.
 #define TRACE_EVENT_API_ATOMIC_WORD base::subtle::AtomicWord
 #define TRACE_EVENT_API_ATOMIC_LOAD(var) base::subtle::NoBarrier_Load(&(var))
diff --git a/base/debug/trace_event_impl.cc b/base/debug/trace_event_impl.cc
index 69e9c600..3c770c3 100644
--- a/base/debug/trace_event_impl.cc
+++ b/base/debug/trace_event_impl.cc
@@ -20,6 +20,7 @@
 #include "base/sys_info.h"
 #include "base/third_party/dynamic_annotations/dynamic_annotations.h"
 #include "base/threading/platform_thread.h"
+#include "base/threading/thread_id_name_manager.h"
 #include "base/threading/thread_local.h"
 #include "base/time.h"
 #include "base/utf_string_conversions.h"
@@ -623,14 +624,33 @@ void TraceLog::Flush(const TraceLog::OutputCallback& cb) {
 }
 
 void TraceLog::AddTraceEvent(char phase,
-                            const unsigned char* category_enabled,
-                            const char* name,
-                            unsigned long long id,
-                            int num_args,
-                            const char** arg_names,
-                            const unsigned char* arg_types,
-                            const unsigned long long* arg_values,
-                            unsigned char flags) {
+                             const unsigned char* category_enabled,
+                             const char* name,
+                             unsigned long long id,
+                             int num_args,
+                             const char** arg_names,
+                             const unsigned char* arg_types,
+                             const unsigned long long* arg_values,
+                             unsigned char flags) {
+  int thread_id = static_cast<int>(base::PlatformThread::CurrentId());
+  base::TimeTicks now = base::TimeTicks::NowFromSystemTraceTime();
+  AddTraceEventWithThreadIdAndTimestamp(phase, category_enabled, name, id,
+                                        thread_id, now, num_args, arg_names,
+                                        arg_types, arg_values, flags);
+}
+
+void TraceLog::AddTraceEventWithThreadIdAndTimestamp(
+    char phase,
+    const unsigned char* category_enabled,
+    const char* name,
+    unsigned long long id,
+    int thread_id,
+    const TimeTicks& timestamp,
+    int num_args,
+    const char** arg_names,
+    const unsigned char* arg_types,
+    const unsigned long long* arg_values,
+    unsigned char flags) {
   DCHECK(name);
 
 #if defined(OS_ANDROID)
@@ -638,8 +658,9 @@ void TraceLog::AddTraceEvent(char phase,
                num_args, arg_names, arg_types, arg_values);
 #endif
 
-  TimeTicks now = TimeTicks::NowFromSystemTraceTime() - time_offset_;
+  TimeTicks now = timestamp - time_offset_;
   NotificationHelper notifier(this);
+
   {
     AutoLock lock(lock_);
     if (*category_enabled != CATEGORY_ENABLED)
@@ -647,9 +668,8 @@ void TraceLog::AddTraceEvent(char phase,
     if (logged_events_.size() >= kTraceEventBufferSize)
       return;
 
-    int thread_id = static_cast<int>(PlatformThread::CurrentId());
-
-    const char* new_name = PlatformThread::GetName();
+    const char* new_name = ThreadIdNameManager::GetInstance()->
+        GetName(thread_id);
     // Check if the thread name has been set or changed since the previous
     // call (if any), but don't bother if the new name is empty. Note this will
     // not detect a thread name change within the same char* buffer address: we
@@ -657,6 +677,7 @@ void TraceLog::AddTraceEvent(char phase,
     if (new_name != g_current_thread_name.Get().Get() &&
         new_name && *new_name) {
       g_current_thread_name.Get().Set(new_name);
+
       hash_map<int, std::string>::iterator existing_name =
           thread_names_.find(thread_id);
       if (existing_name == thread_names_.end()) {
diff --git a/base/debug/trace_event_impl.h b/base/debug/trace_event_impl.h
index 7e306e2..f152b0a4 100644
--- a/base/debug/trace_event_impl.h
+++ b/base/debug/trace_event_impl.h
@@ -258,14 +258,26 @@ class BASE_EXPORT TraceLog {
   // If |copy| is set, |name|, |arg_name1| and |arg_name2| will be deep copied
   // into the event; see "Memory scoping note" and TRACE_EVENT_COPY_XXX above.
   void AddTraceEvent(char phase,
-                    const unsigned char* category_enabled,
-                    const char* name,
-                    unsigned long long id,
-                    int num_args,
-                    const char** arg_names,
-                    const unsigned char* arg_types,
-                    const unsigned long long* arg_values,
-                    unsigned char flags);
+                     const unsigned char* category_enabled,
+                     const char* name,
+                     unsigned long long id,
+                     int num_args,
+                     const char** arg_names,
+                     const unsigned char* arg_types,
+                     const unsigned long long* arg_values,
+                     unsigned char flags);
+  void AddTraceEventWithThreadIdAndTimestamp(
+      char phase,
+      const unsigned char* category_enabled,
+      const char* name,
+      unsigned long long id,
+      int thread_id,
+      const TimeTicks& timestamp,
+      int num_args,
+      const char** arg_names,
+      const unsigned char* arg_types,
+      const unsigned long long* arg_values,
+      unsigned char flags);
   static void AddTraceEventEtw(char phase,
                                const char* name,
                                const void* id,
diff --git a/base/debug/trace_event_internal.h b/base/debug/trace_event_internal.h
index 9622411..7cd56d0 100644
--- a/base/debug/trace_event_internal.h
+++ b/base/debug/trace_event_internal.h
@@ -261,6 +261,23 @@
         category, name, TRACE_EVENT_FLAG_COPY, arg1_name, arg1_val, \
         arg2_name, arg2_val)
 
+// Similar to TRACE_EVENT_BEGINx but with a custom |at| timestamp provided.
+// - |id| is used to match the _BEGIN event with the _END event.
+//   Events are considered to match if their category, name and id values all
+//   match. |id| must either be a pointer or an integer value up to 64 bits. If
+//   it's a pointer, the bits will be xored with a hash of the process ID so
+//   that the same pointer on two different processes will not collide.
+#define TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0(category, \
+        name, id, thread_id, timestamp) \
+    INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP( \
+        TRACE_EVENT_PHASE_ASYNC_BEGIN, category, name, id, thread_id, \
+        timestamp, TRACE_EVENT_FLAG_NONE)
+#define TRACE_EVENT_COPY_BEGIN_WITH_ID_TID_AND_TIMESTAMP0( \
+        category, name, id, thread_id, timestamp) \
+    INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP( \
+        TRACE_EVENT_PHASE_ASYNC_BEGIN, category, name, id, thread_id, \
+        timestamp, TRACE_EVENT_FLAG_COPY)
+
 // 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
@@ -288,6 +305,23 @@
         category, name, TRACE_EVENT_FLAG_COPY, arg1_name, arg1_val, \
         arg2_name, arg2_val)
 
+// Similar to TRACE_EVENT_ENDx but with a custom |at| timestamp provided.
+// - |id| is used to match the _BEGIN event with the _END event.
+//   Events are considered to match if their category, name and id values all
+//   match. |id| must either be a pointer or an integer value up to 64 bits. If
+//   it's a pointer, the bits will be xored with a hash of the process ID so
+//   that the same pointer on two different processes will not collide.
+#define TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0(category, \
+        name, id, thread_id, timestamp) \
+    INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP( \
+        TRACE_EVENT_PHASE_ASYNC_END, category, name, id, thread_id, timestamp, \
+        TRACE_EVENT_FLAG_NONE)
+#define TRACE_EVENT_COPY_END_WITH_ID_TID_AND_TIMESTAMP0( \
+        category, name, id, thread_id, timestamp) \
+    INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP( \
+        TRACE_EVENT_PHASE_ASYNC_END, category, name, id, thread_id, timestamp, \
+        TRACE_EVENT_FLAG_COPY)
+
 // Records the value of a counter called "name" immediately. Value
 // must be representable as a 32 bit integer.
 // - category and name strings must have application lifetime (statics or
@@ -540,7 +574,6 @@
         category, name, id, TRACE_EVENT_FLAG_COPY, \
         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.
@@ -614,6 +647,24 @@
       } \
     } while (0)
 
+// Implementation detail: internal macro to create static category and add
+// event if the category is enabled.
+#define INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP(phase, category, \
+        name, id, thread_id, timestamp, flags, ...) \
+    do { \
+      INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \
+      if (*INTERNAL_TRACE_EVENT_UID(catstatic)) { \
+        unsigned char trace_event_flags = flags | TRACE_EVENT_FLAG_HAS_ID; \
+        trace_event_internal::TraceID trace_event_trace_id( \
+            id, &trace_event_flags); \
+        trace_event_internal::AddTraceEventWithThreadIdAndTimestamp( \
+            phase, INTERNAL_TRACE_EVENT_UID(catstatic), \
+            name, trace_event_trace_id.data(), \
+            thread_id, TimeTicks::FromInternalValue(timestamp), \
+            trace_event_flags, ##__VA_ARGS__); \
+      } \
+    } while (0)
+
 // Notes regarding the following definitions:
 // New values can be added and propagated to third party libraries, but existing
 // definitions must never be changed, because third party libraries may use old
@@ -793,39 +844,92 @@ static inline void SetTraceValue(const std::string& arg,
   *value = type_value.as_uint;
 }
 
-// These AddTraceEvent template functions are defined here instead of in the
-// macro, because the arg_values could be temporary objects, such as
-// std::string. In order to store pointers to the internal c_str and pass
-// through to the tracing API, the arg_values must live throughout
-// these procedures.
+// These AddTraceEvent and AddTraceEventWithThreadIdAndTimestamp template
+// functions are defined here instead of in the macro, because the arg_values
+// could be temporary objects, such as std::string. In order to store
+// pointers to the internal c_str and pass through to the tracing API,
+// the arg_values must live throughout these procedures.
+
+static inline void AddTraceEventWithThreadIdAndTimestamp(char phase,
+    const unsigned char* category_enabled,
+    const char* name,
+    unsigned long long id,
+    int thread_id,
+    const base::TimeTicks& timestamp,
+    unsigned char flags) {
+  TRACE_EVENT_API_ADD_TRACE_EVENT_WITH_THREAD_ID_AND_TIMESTAMP(
+      phase, category_enabled, name, id, thread_id, timestamp,
+      kZeroNumArgs, NULL, NULL, NULL, flags);
+}
 
 static inline void AddTraceEvent(char phase,
-                                const unsigned char* category_enabled,
-                                const char* name,
-                                unsigned long long id,
-                                unsigned char flags) {
-  TRACE_EVENT_API_ADD_TRACE_EVENT(
-      phase, category_enabled, name, id,
-      kZeroNumArgs, NULL, NULL, NULL, flags);
+                                 const unsigned char* category_enabled,
+                                 const char* name,
+                                 unsigned long long id,
+                                 unsigned char flags) {
+  int thread_id = static_cast<int>(base::PlatformThread::CurrentId());
+  base::TimeTicks now = base::TimeTicks::NowFromSystemTraceTime();
+  AddTraceEventWithThreadIdAndTimestamp(phase, category_enabled, name, id,
+      thread_id, now, flags);
 }
 
 template<class ARG1_TYPE>
-static inline void AddTraceEvent(char phase,
-                                const unsigned char* category_enabled,
-                                const char* name,
-                                unsigned long long id,
-                                unsigned char flags,
-                                const char* arg1_name,
-                                const ARG1_TYPE& arg1_val) {
+static inline void AddTraceEventWithThreadIdAndTimestamp(char phase,
+    const unsigned char* category_enabled,
+    const char* name,
+    unsigned long long id,
+    int thread_id,
+    const base::TimeTicks& timestamp,
+    unsigned char flags,
+    const char* arg1_name,
+    const ARG1_TYPE& arg1_val) {
   const int num_args = 1;
   unsigned char arg_types[1];
   unsigned long long arg_values[1];
   SetTraceValue(arg1_val, &arg_types[0], &arg_values[0]);
-  TRACE_EVENT_API_ADD_TRACE_EVENT(
-      phase, category_enabled, name, id,
+  TRACE_EVENT_API_ADD_TRACE_EVENT_WITH_THREAD_ID_AND_TIMESTAMP(
+      phase, category_enabled, name, id, thread_id, timestamp,
       num_args, &arg1_name, arg_types, arg_values, flags);
 }
 
+template<class ARG1_TYPE>
+static inline void AddTraceEvent(char phase,
+                                 const unsigned char* category_enabled,
+                                 const char* name,
+                                 unsigned long long id,
+                                 unsigned char flags,
+                                 const char* arg1_name,
+                                 const ARG1_TYPE& arg1_val) {
+  int thread_id = static_cast<int>(base::PlatformThread::CurrentId());
+  base::TimeTicks now = base::TimeTicks::NowFromSystemTraceTime();
+  AddTraceEventWithThreadIdAndTimestamp(phase, category_enabled, name, id,
+                                        thread_id, now, flags, arg1_name,
+                                        arg1_val);
+}
+
+template<class ARG1_TYPE, class ARG2_TYPE>
+static inline void AddTraceEventWithThreadIdAndTimestamp(char phase,
+    const unsigned char* category_enabled,
+    const char* name,
+    unsigned long long id,
+    int thread_id,
+    const base::TimeTicks& timestamp,
+    unsigned char flags,
+    const char* arg1_name,
+    const ARG1_TYPE& arg1_val,
+    const char* arg2_name,
+    const ARG2_TYPE& arg2_val) {
+  const int num_args = 2;
+  const char* arg_names[2] = { arg1_name, arg2_name };
+  unsigned char arg_types[2];
+  unsigned long long arg_values[2];
+  SetTraceValue(arg1_val, &arg_types[0], &arg_values[0]);
+  SetTraceValue(arg2_val, &arg_types[1], &arg_values[1]);
+  TRACE_EVENT_API_ADD_TRACE_EVENT_WITH_THREAD_ID_AND_TIMESTAMP(
+      phase, category_enabled, name, id, thread_id, timestamp,
+      num_args, arg_names, arg_types, arg_values, flags);
+}
+
 template<class ARG1_TYPE, class ARG2_TYPE>
 static inline void AddTraceEvent(char phase,
                                 const unsigned char* category_enabled,
@@ -836,15 +940,11 @@ static inline void AddTraceEvent(char phase,
                                 const ARG1_TYPE& arg1_val,
                                 const char* arg2_name,
                                 const ARG2_TYPE& arg2_val) {
-  const int num_args = 2;
-  const char* arg_names[2] = { arg1_name, arg2_name };
-  unsigned char arg_types[2];
-  unsigned long long arg_values[2];
-  SetTraceValue(arg1_val, &arg_types[0], &arg_values[0]);
-  SetTraceValue(arg2_val, &arg_types[1], &arg_values[1]);
-  TRACE_EVENT_API_ADD_TRACE_EVENT(
-      phase, category_enabled, name, id,
-      num_args, arg_names, arg_types, arg_values, flags);
+  int thread_id = static_cast<int>(base::PlatformThread::CurrentId());
+  base::TimeTicks now = base::TimeTicks::NowFromSystemTraceTime();
+  AddTraceEventWithThreadIdAndTimestamp(phase, category_enabled, name, id,
+                                        thread_id, now, flags, arg1_name,
+                                        arg1_val, arg2_name, arg2_val);
 }
 
 // Used by TRACE_EVENTx macro. Do not use directly.
@@ -864,7 +964,6 @@ class TRACE_EVENT_API_CLASS_EXPORT TraceEndOnScopeClose {
     p_data_ = &data_;
   }
 
-
  private:
   // Add the end event if the category is still enabled.
   void AddEventIfEnabled() {
diff --git a/base/debug/trace_event_unittest.cc b/base/debug/trace_event_unittest.cc
index c42cc5d..15e11a7 100644
--- a/base/debug/trace_event_unittest.cc
+++ b/base/debug/trace_event_unittest.cc
@@ -4,6 +4,8 @@
 
 #include "base/debug/trace_event_unittest.h"
 
+#include <cstdlib>
+
 #include "base/bind.h"
 #include "base/command_line.h"
 #include "base/debug/trace_event.h"
@@ -39,6 +41,10 @@ struct JsonKeyValue {
   CompareOp op;
 };
 
+static int kThreadId = 42;
+static int kAsyncId = 5;
+static const char kAsyncIdStr[] = "5";
+
 class TraceEventTestFixture : public testing::Test {
  public:
   // This fixture does not use SetUp() because the fixture must be manually set
@@ -337,10 +343,10 @@ void TraceWithAllMacroVariants(WaitableEvent* task_complete_event) {
                      "name1", "value1",
                      "name2", "value2");
 
-    TRACE_EVENT_ASYNC_BEGIN0("all", "TRACE_EVENT_ASYNC_BEGIN0 call", 5);
-    TRACE_EVENT_ASYNC_BEGIN1("all", "TRACE_EVENT_ASYNC_BEGIN1 call", 5,
+    TRACE_EVENT_ASYNC_BEGIN0("all", "TRACE_EVENT_ASYNC_BEGIN0 call", kAsyncId);
+    TRACE_EVENT_ASYNC_BEGIN1("all", "TRACE_EVENT_ASYNC_BEGIN1 call", kAsyncId,
                              "name1", "value1");
-    TRACE_EVENT_ASYNC_BEGIN2("all", "TRACE_EVENT_ASYNC_BEGIN2 call", 5,
+    TRACE_EVENT_ASYNC_BEGIN2("all", "TRACE_EVENT_ASYNC_BEGIN2 call", kAsyncId,
                              "name1", "value1",
                              "name2", "value2");
 
@@ -349,19 +355,19 @@ void TraceWithAllMacroVariants(WaitableEvent* task_complete_event) {
     TRACE_EVENT_ASYNC_STEP1("all", "TRACE_EVENT_ASYNC_STEP1 call",
                                   5, "step2", "name1", "value1");
 
-    TRACE_EVENT_ASYNC_END0("all", "TRACE_EVENT_ASYNC_END0 call", 5);
-    TRACE_EVENT_ASYNC_END1("all", "TRACE_EVENT_ASYNC_END1 call", 5,
+    TRACE_EVENT_ASYNC_END0("all", "TRACE_EVENT_ASYNC_END0 call", kAsyncId);
+    TRACE_EVENT_ASYNC_END1("all", "TRACE_EVENT_ASYNC_END1 call", kAsyncId,
                            "name1", "value1");
-    TRACE_EVENT_ASYNC_END2("all", "TRACE_EVENT_ASYNC_END2 call", 5,
+    TRACE_EVENT_ASYNC_END2("all", "TRACE_EVENT_ASYNC_END2 call", kAsyncId,
                            "name1", "value1",
                            "name2", "value2");
 
-    TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW0 call", 5, NULL);
-    TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW1 call", 5, "value");
-    TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW0 call", 5, NULL);
-    TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW1 call", 5, "value");
-    TRACE_EVENT_INSTANT_ETW("TRACE_EVENT_INSTANT_ETW0 call", 5, NULL);
-    TRACE_EVENT_INSTANT_ETW("TRACE_EVENT_INSTANT_ETW1 call", 5, "value");
+    TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW0 call", kAsyncId, NULL);
+    TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW1 call", kAsyncId, "value");
+    TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW0 call", kAsyncId, NULL);
+    TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW1 call", kAsyncId, "value");
+    TRACE_EVENT_INSTANT_ETW("TRACE_EVENT_INSTANT_ETW0 call", kAsyncId, NULL);
+    TRACE_EVENT_INSTANT_ETW("TRACE_EVENT_INSTANT_ETW1 call", kAsyncId, "value");
 
     TRACE_COUNTER1("all", "TRACE_COUNTER1 call", 31415);
     TRACE_COUNTER2("all", "TRACE_COUNTER2 call",
@@ -371,6 +377,21 @@ void TraceWithAllMacroVariants(WaitableEvent* task_complete_event) {
     TRACE_COUNTER_ID1("all", "TRACE_COUNTER_ID1 call", 0x319009, 31415);
     TRACE_COUNTER_ID2("all", "TRACE_COUNTER_ID2 call", 0x319009,
                       "a", 30000, "b", 1415);
+
+    TRACE_EVENT_COPY_BEGIN_WITH_ID_TID_AND_TIMESTAMP0("all",
+        "TRACE_EVENT_COPY_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 call",
+        kAsyncId, kThreadId, 12345);
+    TRACE_EVENT_COPY_END_WITH_ID_TID_AND_TIMESTAMP0("all",
+        "TRACE_EVENT_COPY_END_WITH_ID_TID_AND_TIMESTAMP0 call",
+        kAsyncId, kThreadId, 23456);
+
+    TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0("all",
+        "TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 call",
+        kAsyncId + 1, kThreadId, 34567);
+    TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0("all",
+        "TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0 call",
+        kAsyncId + 1, kThreadId, 45678);
+
   } // Scope close causes TRACE_EVENT0 etc to send their END events.
 
   if (task_complete_event)
@@ -451,15 +472,15 @@ void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed) {
 
   EXPECT_FIND_("TRACE_EVENT_ASYNC_BEGIN0 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_FIND_("TRACE_EVENT_ASYNC_BEGIN1 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("name1");
   EXPECT_SUB_FIND_("value1");
   EXPECT_FIND_("TRACE_EVENT_ASYNC_BEGIN2 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("name1");
   EXPECT_SUB_FIND_("value1");
   EXPECT_SUB_FIND_("name2");
@@ -467,26 +488,26 @@ void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed) {
 
   EXPECT_FIND_("TRACE_EVENT_ASYNC_STEP0 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("step1");
   EXPECT_FIND_("TRACE_EVENT_ASYNC_STEP1 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("step2");
   EXPECT_SUB_FIND_("name1");
   EXPECT_SUB_FIND_("value1");
 
   EXPECT_FIND_("TRACE_EVENT_ASYNC_END0 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_FIND_("TRACE_EVENT_ASYNC_END1 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("name1");
   EXPECT_SUB_FIND_("value1");
   EXPECT_FIND_("TRACE_EVENT_ASYNC_END2 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("name1");
   EXPECT_SUB_FIND_("value1");
   EXPECT_SUB_FIND_("name2");
@@ -494,32 +515,32 @@ void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed) {
 
   EXPECT_FIND_("TRACE_EVENT_BEGIN_ETW0 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("extra");
   EXPECT_SUB_FIND_("NULL");
   EXPECT_FIND_("TRACE_EVENT_BEGIN_ETW1 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("extra");
   EXPECT_SUB_FIND_("value");
   EXPECT_FIND_("TRACE_EVENT_END_ETW0 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("extra");
   EXPECT_SUB_FIND_("NULL");
   EXPECT_FIND_("TRACE_EVENT_END_ETW1 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("extra");
   EXPECT_SUB_FIND_("value");
   EXPECT_FIND_("TRACE_EVENT_INSTANT_ETW0 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("extra");
   EXPECT_SUB_FIND_("NULL");
   EXPECT_FIND_("TRACE_EVENT_INSTANT_ETW1 call");
   EXPECT_SUB_FIND_("id");
-  EXPECT_SUB_FIND_("5");
+  EXPECT_SUB_FIND_(kAsyncIdStr);
   EXPECT_SUB_FIND_("extra");
   EXPECT_SUB_FIND_("value");
 
@@ -580,6 +601,54 @@ void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed) {
     EXPECT_TRUE((item && item->GetInteger("args.b", &value)));
     EXPECT_EQ(1415, value);
   }
+
+  EXPECT_FIND_("TRACE_EVENT_COPY_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 call");
+  {
+    int val;
+    EXPECT_TRUE((item && item->GetInteger("ts", &val)));
+    EXPECT_EQ(12345, val);
+    EXPECT_TRUE((item && item->GetInteger("tid", &val)));
+    EXPECT_EQ(kThreadId, val);
+    std::string id;
+    EXPECT_TRUE((item && item->GetString("id", &id)));
+    EXPECT_EQ(kAsyncId, atoi(id.c_str()));
+  }
+
+  EXPECT_FIND_("TRACE_EVENT_COPY_END_WITH_ID_TID_AND_TIMESTAMP0 call");
+  {
+    int val;
+    EXPECT_TRUE((item && item->GetInteger("ts", &val)));
+    EXPECT_EQ(23456, val);
+    EXPECT_TRUE((item && item->GetInteger("tid", &val)));
+    EXPECT_EQ(kThreadId, val);
+    std::string id;
+    EXPECT_TRUE((item && item->GetString("id", &id)));
+    EXPECT_EQ(kAsyncId, atoi(id.c_str()));
+  }
+
+  EXPECT_FIND_("TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 call");
+  {
+    int val;
+    EXPECT_TRUE((item && item->GetInteger("ts", &val)));
+    EXPECT_EQ(34567, val);
+    EXPECT_TRUE((item && item->GetInteger("tid", &val)));
+    EXPECT_EQ(kThreadId, val);
+    std::string id;
+    EXPECT_TRUE((item && item->GetString("id", &id)));
+    EXPECT_EQ(kAsyncId + 1, atoi(id.c_str()));
+  }
+
+  EXPECT_FIND_("TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0 call");
+  {
+    int val;
+    EXPECT_TRUE((item && item->GetInteger("ts", &val)));
+    EXPECT_EQ(45678, val);
+    EXPECT_TRUE((item && item->GetInteger("tid", &val)));
+    EXPECT_EQ(kThreadId, val);
+    std::string id;
+    EXPECT_TRUE((item && item->GetString("id", &id)));
+    EXPECT_EQ(kAsyncId + 1, atoi(id.c_str()));
+  }
 }
 
 void TraceManyInstantEvents(int thread_id, int num_events,