diff options
Diffstat (limited to 'base/debug')
-rw-r--r-- | base/debug/trace_event.h | 16 | ||||
-rw-r--r-- | base/debug/trace_event_impl.cc | 45 | ||||
-rw-r--r-- | base/debug/trace_event_impl.h | 28 | ||||
-rw-r--r-- | base/debug/trace_event_internal.h | 163 | ||||
-rw-r--r-- | base/debug/trace_event_unittest.cc | 121 |
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, |