diff options
Diffstat (limited to 'base')
| -rw-r--r-- | base/debug/trace_event.cc | 373 | ||||
| -rw-r--r-- | base/debug/trace_event.h | 715 | ||||
| -rw-r--r-- | base/debug/trace_event_unittest.cc | 118 | ||||
| -rw-r--r-- | base/debug/trace_event_win.cc | 6 | ||||
| -rw-r--r-- | base/debug/trace_event_win.h | 10 | ||||
| -rw-r--r-- | base/test/trace_event_analyzer.cc | 156 | ||||
| -rw-r--r-- | base/test/trace_event_analyzer.h | 13 |
7 files changed, 819 insertions, 572 deletions
diff --git a/base/debug/trace_event.cc b/base/debug/trace_event.cc index 969af1c..c554769 100644 --- a/base/debug/trace_event.cc +++ b/base/debug/trace_event.cc @@ -1,4 +1,4 @@ -// Copyright (c) 2011 The Chromium Authors. All rights reserved. +// Copyright (c) 2012 The Chromium Authors. All rights reserved. // Use of this source code is governed by a BSD-style license that can be // found in the LICENSE file. @@ -45,27 +45,21 @@ const size_t kTraceEventBatchSize = 1000; namespace { -// Specify these values when the corresponding argument of AddTraceEvent is not -// used. -static const char* kNoArgName = NULL; -static const int kNoArgValue = 0; -static const int kNoThreshholdBeginId = -1; -static const int64 kNoThresholdValue = 0; -static const int kNoEventId = 0; - -TraceCategory g_categories[TRACE_EVENT_MAX_CATEGORIES] = { - { "tracing already shutdown", false }, - { "tracing categories exhausted; must increase TRACE_EVENT_MAX_CATEGORIES", - false }, - { "__metadata", - false } +// Parallel arrays g_categories and g_category_enabled are separate so that +// a pointer to a member of g_category_enabled can be easily converted to an +// index into g_categories. This allows macros to deal only with char enabled +// pointers from g_category_enabled, and we can convert internally to determine +// the category name from the char enabled pointer. +const char* g_categories[TRACE_EVENT_MAX_CATEGORIES] = { + "tracing already shutdown", + "tracing categories exhausted; must increase TRACE_EVENT_MAX_CATEGORIES", + "__metadata", }; -const TraceCategory* const g_category_already_shutdown = - &g_categories[0]; -const TraceCategory* const g_category_categories_exhausted = - &g_categories[1]; -const TraceCategory* const g_category_metadata = - &g_categories[2]; +// The enabled flag is char instead of bool so that the API can be used from C. +unsigned char g_category_enabled[TRACE_EVENT_MAX_CATEGORIES] = { 0 }; +const int g_category_already_shutdown = 0; +const int g_category_categories_exhausted = 1; +const int g_category_metadata = 2; int g_category_index = 3; // skip initial 3 categories // The most-recently captured name of the current thread @@ -73,41 +67,35 @@ LazyInstance<ThreadLocalPointer<const char>, LeakyLazyInstanceTraits<ThreadLocalPointer<const char> > > g_current_thread_name = LAZY_INSTANCE_INITIALIZER; -} // namespace - -//////////////////////////////////////////////////////////////////////////////// -// -// TraceValue -// -//////////////////////////////////////////////////////////////////////////////// - -void TraceValue::AppendAsJSON(std::string* out) const { +void AppendValueAsJSON(unsigned char type, + TraceEvent::TraceValue value, + std::string* out) { std::string::size_type start_pos; - switch (type_) { - case TRACE_TYPE_BOOL: - *out += as_bool() ? "true" : "false"; + switch (type) { + case TRACE_VALUE_TYPE_BOOL: + *out += value.as_bool ? "true" : "false"; break; - case TRACE_TYPE_UINT: - StringAppendF(out, "%" PRIu64, as_uint()); + case TRACE_VALUE_TYPE_UINT: + StringAppendF(out, "%" PRIu64, static_cast<uint64>(value.as_uint)); break; - case TRACE_TYPE_INT: - StringAppendF(out, "%" PRId64, as_int()); + case TRACE_VALUE_TYPE_INT: + StringAppendF(out, "%" PRId64, static_cast<int64>(value.as_int)); break; - case TRACE_TYPE_DOUBLE: - StringAppendF(out, "%f", as_double()); + case TRACE_VALUE_TYPE_DOUBLE: + StringAppendF(out, "%f", value.as_double); break; - case TRACE_TYPE_POINTER: + case TRACE_VALUE_TYPE_POINTER: // JSON only supports double and int numbers. // So as not to lose bits from a 64-bit pointer, output as a hex string. StringAppendF(out, "\"%" PRIx64 "\"", static_cast<uint64>( reinterpret_cast<intptr_t>( - as_pointer()))); + value.as_pointer))); break; - case TRACE_TYPE_STRING: - case TRACE_TYPE_STATIC_STRING: + case TRACE_VALUE_TYPE_STRING: + case TRACE_VALUE_TYPE_COPY_STRING: *out += "\""; start_pos = out->size(); - *out += as_string() ? as_string() : "NULL"; + *out += value.as_string ? value.as_string : "NULL"; // insert backslash before special characters for proper json format. while ((start_pos = out->find_first_of("\\\"", start_pos)) != std::string::npos) { @@ -123,16 +111,7 @@ void TraceValue::AppendAsJSON(std::string* out) const { } } -//////////////////////////////////////////////////////////////////////////////// -// -// TraceID -// -//////////////////////////////////////////////////////////////////////////////// - -TraceID::TraceID(void* rhs) { - data_ = base::debug::TraceLog::GetInstance()->GetIntraProcessID( - static_cast<uint64>(reinterpret_cast<uintptr_t>(rhs))); -} +} // namespace //////////////////////////////////////////////////////////////////////////////// // @@ -161,7 +140,7 @@ void CopyTraceEventParameter(char** buffer, TraceEvent::TraceEvent() : id_(0u), - category_(NULL), + category_enabled_(NULL), name_(NULL), thread_id_(0), phase_(TRACE_EVENT_PHASE_BEGIN), @@ -172,43 +151,54 @@ TraceEvent::TraceEvent() TraceEvent::TraceEvent(int thread_id, TimeTicks timestamp, - TraceEventPhase phase, - const TraceCategory* category, + char phase, + const unsigned char* category_enabled, const char* name, - TraceID id, - const char* arg1_name, const TraceValue& arg1_val, - const char* arg2_name, const TraceValue& arg2_val, - TraceEventFlags flags) + 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) : timestamp_(timestamp), id_(id), - category_(category), + category_enabled_(category_enabled), name_(name), thread_id_(thread_id), phase_(phase), flags_(flags) { - 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; + // Clamp num_args since it may have been set by a third_party library. + num_args = (num_args > kTraceMaxNumArgs) ? kTraceMaxNumArgs : num_args; + int i = 0; + for (; i < num_args; ++i) { + arg_names_[i] = arg_names[i]; + arg_values_[i].as_uint = arg_values[i]; + arg_types_[i] = arg_types[i]; + } + for (; i < kTraceMaxNumArgs; ++i) { + arg_names_[i] = NULL; + arg_values_[i].as_uint = 0u; + arg_types_[i] = TRACE_VALUE_TYPE_UINT; + } bool copy = !!(flags & TRACE_EVENT_FLAG_COPY); size_t alloc_size = 0; if (copy) { alloc_size += GetAllocLength(name); - alloc_size += GetAllocLength(arg1_name); - alloc_size += GetAllocLength(arg2_name); + for (i = 0; i < num_args; ++i) { + alloc_size += GetAllocLength(arg_names_[i]); + if (arg_types_[i] == TRACE_VALUE_TYPE_STRING) + arg_types_[i] = TRACE_VALUE_TYPE_COPY_STRING; + } } - bool arg1_is_copy = (arg1_val.type() == TraceValue::TRACE_TYPE_STRING); - bool arg2_is_copy = (arg2_val.type() == TraceValue::TRACE_TYPE_STRING); - - // We only take a copy of arg_vals if they are of type string (not static - // string), regardless of the |copy| flag. - if (arg1_is_copy) - alloc_size += GetAllocLength(arg1_val.as_string()); - if (arg2_is_copy) - alloc_size += GetAllocLength(arg2_val.as_string()); + bool arg_is_copy[kTraceMaxNumArgs]; + for (i = 0; i < num_args; ++i) { + // We only take a copy of arg_vals if they are of type COPY_STRING. + arg_is_copy[i] = (arg_types_[i] == TRACE_VALUE_TYPE_COPY_STRING); + if (arg_is_copy[i]) + alloc_size += GetAllocLength(arg_values_[i].as_string); + } if (alloc_size) { parameter_copy_storage_ = new base::RefCountedString; @@ -217,13 +207,13 @@ TraceEvent::TraceEvent(int thread_id, const char* end = ptr + alloc_size; if (copy) { CopyTraceEventParameter(&ptr, &name_, end); - CopyTraceEventParameter(&ptr, &arg_names_[0], end); - CopyTraceEventParameter(&ptr, &arg_names_[1], end); + for (i = 0; i < num_args; ++i) + CopyTraceEventParameter(&ptr, &arg_names_[i], end); + } + for (i = 0; i < num_args; ++i) { + if (arg_is_copy[i]) + CopyTraceEventParameter(&ptr, &arg_values_[i].as_string, end); } - if (arg1_is_copy) - CopyTraceEventParameter(&ptr, arg_values_[0].as_assignable_string(), end); - if (arg2_is_copy) - CopyTraceEventParameter(&ptr, arg_values_[1].as_assignable_string(), end); DCHECK_EQ(end, ptr) << "Overrun by " << ptr - end; } } @@ -243,7 +233,6 @@ void TraceEvent::AppendEventsAsJSON(const std::vector<TraceEvent>& events, } void TraceEvent::AppendAsJSON(std::string* out) const { - const char phase_char = GetPhaseChar(phase_); int64 time_int64 = timestamp_.ToInternalValue(); int process_id = TraceLog::GetInstance()->process_id(); // Category name checked at category creation time. @@ -251,28 +240,28 @@ void TraceEvent::AppendAsJSON(std::string* out) const { StringAppendF(out, "{\"cat\":\"%s\",\"pid\":%i,\"tid\":%i,\"ts\":%" PRId64 "," "\"ph\":\"%c\",\"name\":\"%s\",\"args\":{", - category_->name, + TraceLog::GetCategoryName(category_enabled_), process_id, thread_id_, time_int64, - phase_char, + phase_, name_); // Output argument names and values, stop at first NULL argument name. - for (size_t i = 0; i < kTraceMaxNumArgs && arg_names_[i]; ++i) { + for (int i = 0; i < kTraceMaxNumArgs && arg_names_[i]; ++i) { if (i > 0) *out += ","; *out += "\""; *out += arg_names_[i]; *out += "\":"; - arg_values_[i].AppendAsJSON(out); + AppendValueAsJSON(arg_types_[i], arg_values_[i], out); } *out += "}"; // If id_ is set, print it out as a hex string so we don't loose any // bits (it might be a 64-bit pointer). if (flags_ & TRACE_EVENT_FLAG_HAS_ID) - StringAppendF(out, ",\"id\":\"%" PRIx64 "\"", id_.data()); + StringAppendF(out, ",\"id\":\"%" PRIx64 "\"", static_cast<uint64>(id_)); *out += "}"; } @@ -338,47 +327,62 @@ TraceLog::TraceLog() TraceLog::~TraceLog() { } -const TraceCategory* TraceLog::GetCategory(const char* name) { +const unsigned char* TraceLog::GetCategoryEnabled(const char* name) { TraceLog* tracelog = GetInstance(); - if (!tracelog){ - DCHECK(!g_category_already_shutdown->enabled); - return g_category_already_shutdown; + if (!tracelog) { + DCHECK(!g_category_enabled[g_category_already_shutdown]); + return &g_category_enabled[g_category_already_shutdown]; } - return tracelog->GetCategoryInternal(name); + return tracelog->GetCategoryEnabledInternal(name); +} + +const char* TraceLog::GetCategoryName(const unsigned char* category_enabled) { + // Calculate the index of the category by finding category_enabled in + // g_category_enabled array. + uintptr_t category_begin = reinterpret_cast<uintptr_t>(g_category_enabled); + uintptr_t category_ptr = reinterpret_cast<uintptr_t>(category_enabled); + DCHECK(category_ptr >= category_begin && + category_ptr < reinterpret_cast<uintptr_t>(g_category_enabled + + TRACE_EVENT_MAX_CATEGORIES)) << + "out of bounds category pointer"; + uintptr_t category_index = + (category_ptr - category_begin) / sizeof(g_category_enabled[0]); + return g_categories[category_index]; } static void EnableMatchingCategory(int category_index, const std::vector<std::string>& patterns, - bool is_included) { + unsigned char is_included) { std::vector<std::string>::const_iterator ci = patterns.begin(); bool is_match = false; for (; ci != patterns.end(); ++ci) { - is_match = MatchPattern(g_categories[category_index].name, ci->c_str()); + is_match = MatchPattern(g_categories[category_index], ci->c_str()); if (is_match) break; } - ANNOTATE_BENIGN_RACE(&g_categories[category_index].enabled, + ANNOTATE_BENIGN_RACE(&g_category_enabled[category_index], "trace_event category enabled"); - g_categories[category_index].enabled = is_match ? is_included : !is_included; + g_category_enabled[category_index] = is_match ? + is_included : (is_included ^ 1); } // Enable/disable each category based on the category filters in |patterns|. // If the category name matches one of the patterns, its enabled status is set // to |is_included|. Otherwise its enabled status is set to !|is_included|. static void EnableMatchingCategories(const std::vector<std::string>& patterns, - bool is_included) { + unsigned char is_included) { for (int i = 0; i < g_category_index; i++) EnableMatchingCategory(i, patterns, is_included); } -const TraceCategory* TraceLog::GetCategoryInternal(const char* name) { +const unsigned char* TraceLog::GetCategoryEnabledInternal(const char* name) { AutoLock lock(lock_); DCHECK(!strchr(name, '"')) << "Category names may not contain double quote"; // Search for pre-existing category matching this name for (int i = 0; i < g_category_index; i++) { - if (strcmp(g_categories[i].name, name) == 0) - return &g_categories[i]; + if (strcmp(g_categories[i], name) == 0) + return &g_category_enabled[i]; } // Create a new category @@ -386,30 +390,30 @@ const TraceCategory* TraceLog::GetCategoryInternal(const char* name) { "must increase TRACE_EVENT_MAX_CATEGORIES"; if (g_category_index < TRACE_EVENT_MAX_CATEGORIES) { int new_index = g_category_index++; - g_categories[new_index].name = name; - DCHECK(!g_categories[new_index].enabled); + g_categories[new_index] = name; + DCHECK(!g_category_enabled[new_index]); if (enabled_) { // Note that if both included and excluded_categories are empty, the else // clause below excludes nothing, thereby enabling this category. if (!included_categories_.empty()) - EnableMatchingCategory(new_index, included_categories_, true); + EnableMatchingCategory(new_index, included_categories_, 1); else - EnableMatchingCategory(new_index, excluded_categories_, false); + EnableMatchingCategory(new_index, excluded_categories_, 0); } else { - ANNOTATE_BENIGN_RACE(&g_categories[new_index].enabled, + ANNOTATE_BENIGN_RACE(&g_category_enabled[new_index], "trace_event category enabled"); - g_categories[new_index].enabled = false; + g_category_enabled[new_index] = 0; } - return &g_categories[new_index]; + return &g_category_enabled[new_index]; } else { - return g_category_categories_exhausted; + return &g_category_enabled[g_category_categories_exhausted]; } } void TraceLog::GetKnownCategories(std::vector<std::string>* categories) { AutoLock lock(lock_); for (int i = 0; i < g_category_index; i++) - categories->push_back(g_categories[i].name); + categories->push_back(g_categories[i]); } void TraceLog::SetEnabled(const std::vector<std::string>& included_categories, @@ -424,9 +428,9 @@ void TraceLog::SetEnabled(const std::vector<std::string>& included_categories, // Note that if both included and excluded_categories are empty, the else // clause below excludes nothing, thereby enabling all categories. if (!included_categories_.empty()) - EnableMatchingCategories(included_categories_, true); + EnableMatchingCategories(included_categories_, 1); else - EnableMatchingCategories(excluded_categories_, false); + EnableMatchingCategories(excluded_categories_, 0); } void TraceLog::SetEnabled(const std::string& categories) { @@ -470,7 +474,7 @@ void TraceLog::SetDisabled() { included_categories_.clear(); excluded_categories_.clear(); for (int i = 0; i < g_category_index; i++) - g_categories[i].enabled = false; + g_category_enabled[i] = 0; AddThreadNameMetadataEvents(); AddClockSyncMetadataEvents(); } // release lock @@ -523,22 +527,24 @@ void TraceLog::Flush() { } } -int TraceLog::AddTraceEvent(TraceEventPhase phase, - const TraceCategory* category, +int TraceLog::AddTraceEvent(char phase, + const unsigned char* category_enabled, const char* name, - TraceID id, - const char* arg1_name, TraceValue arg1_val, - const char* arg2_name, TraceValue arg2_val, + unsigned long long id, + int num_args, + const char** arg_names, + const unsigned char* arg_types, + const unsigned long long* arg_values, int threshold_begin_id, - int64 threshold, - TraceEventFlags flags) { + long long threshold, + unsigned char flags) { DCHECK(name); TimeTicks now = TimeTicks::HighResNow(); BufferFullCallback buffer_full_callback_copy; int ret_begin_id = -1; { AutoLock lock(lock_); - if (!category->enabled) + if (!*category_enabled) return -1; if (logged_events_.size() >= kTraceEventBufferSize) return -1; @@ -592,9 +598,8 @@ int TraceLog::AddTraceEvent(TraceEventPhase phase, ret_begin_id = static_cast<int>(logged_events_.size()); logged_events_.push_back( TraceEvent(thread_id, - now, phase, category, name, id, - arg1_name, arg1_val, - arg2_name, arg2_val, + now, phase, category_enabled, name, id, + num_args, arg_names, arg_types, arg_values, flags)); if (logged_events_.size() == kTraceEventBufferSize) { @@ -608,19 +613,18 @@ int TraceLog::AddTraceEvent(TraceEventPhase phase, return ret_begin_id; } -void TraceLog::AddTraceEventEtw(TraceEventPhase phase, +void TraceLog::AddTraceEventEtw(char phase, const char* name, const void* id, const char* extra) { #if defined(OS_WIN) TraceEventETWProvider::Trace(name, phase, id, extra); #endif - INTERNAL_TRACE_EVENT_ADD(phase, - "ETW Trace Event", name, "id", id, "extra", TRACE_STR_COPY(extra), - TRACE_EVENT_FLAG_COPY); + INTERNAL_TRACE_EVENT_ADD(phase, "ETW Trace Event", name, + TRACE_EVENT_FLAG_COPY, "id", id, "extra", extra); } -void TraceLog::AddTraceEventEtw(TraceEventPhase phase, +void TraceLog::AddTraceEventEtw(char phase, const char* name, const void* id, const std::string& extra) @@ -628,25 +632,35 @@ void TraceLog::AddTraceEventEtw(TraceEventPhase phase, #if defined(OS_WIN) TraceEventETWProvider::Trace(name, phase, id, extra); #endif - INTERNAL_TRACE_EVENT_ADD(phase, - "ETW Trace Event", name, "id", id, "extra", extra, - TRACE_EVENT_FLAG_COPY); -} - -int TraceLog::AddCounterEvent(const TraceCategory* category, - const char* name, - TraceID id, - const char* value1_name, int32 value1_val, - const char* value2_name, int32 value2_val, - TraceEventFlags flags) { - return AddTraceEvent(TRACE_EVENT_PHASE_COUNTER, - category, - name, - id, - value1_name, value1_val, - value2_name, value2_val, - -1, 0, - flags); + INTERNAL_TRACE_EVENT_ADD(phase, "ETW Trace Event", name, + TRACE_EVENT_FLAG_COPY, "id", id, "extra", extra); +} + +void TraceLog::AddCounterEvent(const unsigned char* category_enabled, + const char* name, + unsigned long long id, + const char* value1_name, int value1_val, + const char* value2_name, int value2_val, + unsigned char flags) { + int num_args = value2_name ? 2 : 1; + const char* arg_names[2] = {value1_name, value2_name}; + unsigned char arg_types[2]; + unsigned long long arg_values[2]; + trace_event_internal::SetTraceValue(value1_val, &arg_types[0], + &arg_values[0]); + trace_event_internal::SetTraceValue(value2_val, &arg_types[1], + &arg_values[1]); + AddTraceEvent(TRACE_EVENT_PHASE_COUNTER, + category_enabled, + name, + id, + num_args, + arg_names, + arg_types, + arg_values, + trace_event_internal::kNoThreshholdBeginId, + trace_event_internal::kNoThresholdValue, + flags); } void TraceLog::AddClockSyncMetadataEvents() { @@ -693,14 +707,20 @@ void TraceLog::AddThreadNameMetadataEvents() { for(base::hash_map<int, std::string>::iterator it = thread_names_.begin(); it != thread_names_.end(); it++) { - if (!it->second.empty()) + if (!it->second.empty()) { + int num_args = 1; + const char* arg_name = "name"; + unsigned char arg_type; + unsigned long long arg_value; + trace_event_internal::SetTraceValue(it->second, &arg_type, &arg_value); logged_events_.push_back( TraceEvent(it->first, TimeTicks(), TRACE_EVENT_PHASE_METADATA, - g_category_metadata, "thread_name", 0, - "name", it->second, - NULL, 0, + &g_category_enabled[g_category_metadata], + "thread_name", trace_event_internal::kNoEventId, + num_args, &arg_name, &arg_type, &arg_value, TRACE_EVENT_FLAG_NONE)); + } } } @@ -716,38 +736,42 @@ void TraceLog::SetProcessID(int process_id) { process_id_ = process_id; // Create a FNV hash from the process ID for XORing. // See http://isthe.com/chongo/tech/comp/fnv/ for algorithm details. - uint64 offset_basis = 14695981039346656037ull; - uint64 fnv_prime = 1099511628211ull; + unsigned long long offset_basis = 14695981039346656037ull; + unsigned long long fnv_prime = 1099511628211ull; unsigned long long pid = static_cast<unsigned long long>(process_id_); process_id_hash_ = (offset_basis ^ pid) * fnv_prime; } -namespace internal { +} // namespace debug +} // namespace base + +namespace trace_event_internal { -void TraceEndOnScopeClose::Initialize(const TraceCategory* category, +void TraceEndOnScopeClose::Initialize(const unsigned char* category_enabled, const char* name) { - data_.category = category; + data_.category_enabled = category_enabled; 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( + if (*p_data_->category_enabled) { + TRACE_EVENT_API_ADD_TRACE_EVENT( TRACE_EVENT_PHASE_END, - p_data_->category, + p_data_->category_enabled, p_data_->name, kNoEventId, - kNoArgName, kNoArgValue, kNoArgName, kNoArgValue, + kZeroNumArgs, NULL, NULL, NULL, kNoThreshholdBeginId, kNoThresholdValue, TRACE_EVENT_FLAG_NONE); } } -void TraceEndOnScopeCloseThreshold::Initialize(const TraceCategory* category, - const char* name, - int threshold_begin_id, - int64 threshold) { - data_.category = category; +void TraceEndOnScopeCloseThreshold::Initialize( + const unsigned char* category_enabled, + const char* name, + int threshold_begin_id, + long long threshold) { + data_.category_enabled = category_enabled; data_.name = name; data_.threshold_begin_id = threshold_begin_id; data_.threshold = threshold; @@ -756,18 +780,15 @@ void TraceEndOnScopeCloseThreshold::Initialize(const TraceCategory* category, void TraceEndOnScopeCloseThreshold::AddEventIfEnabled() { // Only called when p_data_ is non-null. - if (p_data_->category->enabled) { - base::debug::TraceLog::GetInstance()->AddTraceEvent( + if (*p_data_->category_enabled) { + TRACE_EVENT_API_ADD_TRACE_EVENT( TRACE_EVENT_PHASE_END, - p_data_->category, + p_data_->category_enabled, p_data_->name, kNoEventId, - kNoArgName, kNoArgValue, kNoArgName, kNoArgValue, + kZeroNumArgs, NULL, NULL, NULL, p_data_->threshold_begin_id, p_data_->threshold, TRACE_EVENT_FLAG_NONE); } } -} // namespace internal - -} // namespace debug -} // namespace base +} // namespace trace_event_internal diff --git a/base/debug/trace_event.h b/base/debug/trace_event.h index 444c975..a1fff3e 100644 --- a/base/debug/trace_event.h +++ b/base/debug/trace_event.h @@ -1,4 +1,4 @@ -// Copyright (c) 2011 The Chromium Authors. All rights reserved. +// Copyright (c) 2012 The Chromium Authors. All rights reserved. // Use of this source code is governed by a BSD-style license that can be // found in the LICENSE file. @@ -126,7 +126,7 @@ // the static variable is safe, as they will be serialized by the lock and // multiple calls will return the same pointer to the category. // -// Then the category.enabled flag is checked. This is a volatile bool, and +// Then the category_enabled flag is checked. This is a unsigned char, and // not intended to be multithread safe. It optimizes access to AddTraceEvent // which is threadsafe internally via TraceLog::lock_. The enabled flag may // cause some threads to incorrectly call or skip calling AddTraceEvent near @@ -160,9 +160,56 @@ #include "base/third_party/dynamic_annotations/dynamic_annotations.h" #include "base/timer.h" +//////////////////////////////////////////////////////////////////////////////// +// TODO(jbates): split this into a separate header. +// This header is designed to be give you trace_event macros without specifying +// how the events actually get collected and stored. If you need to expose trace +// event to some other universe, you can copy-and-paste this file and just +// implement these API macros. + +// unsigned char* +// TRACE_EVENT_API_GET_CATEGORY_ENABLED(const char* category_name) +#define TRACE_EVENT_API_GET_CATEGORY_ENABLED \ + base::debug::TraceLog::GetCategoryEnabled + +// Returns the threshold_begin_id used by TRACE_IF_LONGER_THAN macros. +// int TRACE_EVENT_API_ADD_TRACE_EVENT( +// 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, +// int threshold_begin_id, +// long long threshold, +// unsigned char flags) +#define TRACE_EVENT_API_ADD_TRACE_EVENT \ + base::debug::TraceLog::GetInstance()->AddTraceEvent + +// void TRACE_EVENT_API_ADD_COUNTER_EVENT( +// const unsigned char* category_enabled, +// const char* name, +// unsigned long long id, +// const char* arg1_name, int arg1_val, +// const char* arg2_name, int arg2_val, +// unsigned char flags) +#define TRACE_EVENT_API_ADD_COUNTER_EVENT \ + base::debug::TraceLog::GetInstance()->AddCounterEvent + +// Mangle |pointer| with a process ID hash so that if |pointer| occurs on more +// than one process, it will not collide in the trace data. +// unsigned long long TRACE_EVENT_API_GET_ID_FROM_POINTER(void* pointer) +#define TRACE_EVENT_API_GET_ID_FROM_POINTER \ + base::debug::TraceLog::GetInstance()->GetInterProcessID + +//////////////////////////////////////////////////////////////////////////////// + // By default, const char* argument values are assumed to have long-lived scope // and will not be copied. Use this macro to force a const char* to be copied. -#define TRACE_STR_COPY(str) base::debug::TraceValue::StringWithCopy(str) +#define TRACE_STR_COPY(str) \ + trace_event_internal::TraceStringWithCopy(str) // Older style trace macros with explicit id and extra data // Only these macros result in publishing data to ETW as currently implemented. @@ -187,12 +234,12 @@ // - category and name strings must have application lifetime (statics or // literals). They may not include " chars. #define TRACE_EVENT0(category, name) \ - TRACE_EVENT1(category, name, NULL, 0) + INTERNAL_TRACE_EVENT_ADD_SCOPED(category, name) #define TRACE_EVENT1(category, name, arg1_name, arg1_val) \ - TRACE_EVENT2(category, name, arg1_name, arg1_val, NULL, 0) + INTERNAL_TRACE_EVENT_ADD_SCOPED(category, name, arg1_name, arg1_val) #define TRACE_EVENT2(category, name, arg1_name, arg1_val, arg2_name, arg2_val) \ - INTERNAL_TRACE_EVENT_ADD_SCOPED( \ - category, name, arg1_name, arg1_val, arg2_name, arg2_val) + INTERNAL_TRACE_EVENT_ADD_SCOPED(category, name, arg1_name, arg1_val, \ + arg2_name, arg2_val) // Same as TRACE_EVENT except that they are not included in official builds. #ifdef OFFICIAL_BUILD @@ -229,25 +276,27 @@ // - category and name strings must have application lifetime (statics or // literals). They may not include " chars. #define TRACE_EVENT_INSTANT0(category, name) \ - TRACE_EVENT_INSTANT1(category, name, NULL, 0) + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_INSTANT, \ + category, name, TRACE_EVENT_FLAG_NONE) #define TRACE_EVENT_INSTANT1(category, name, arg1_name, arg1_val) \ - TRACE_EVENT_INSTANT2(category, name, arg1_name, arg1_val, NULL, 0) + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_INSTANT, \ + category, name, TRACE_EVENT_FLAG_NONE, arg1_name, arg1_val) #define TRACE_EVENT_INSTANT2(category, name, arg1_name, arg1_val, \ arg2_name, arg2_val) \ INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_INSTANT, \ - category, name, arg1_name, arg1_val, arg2_name, arg2_val, \ - TRACE_EVENT_FLAG_NONE) + category, name, TRACE_EVENT_FLAG_NONE, arg1_name, arg1_val, \ + arg2_name, arg2_val) #define TRACE_EVENT_COPY_INSTANT0(category, name) \ - TRACE_EVENT_COPY_INSTANT1(category, name, NULL, 0) + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_INSTANT, \ + category, name, TRACE_EVENT_FLAG_COPY) #define TRACE_EVENT_COPY_INSTANT1(category, name, arg1_name, arg1_val) \ - TRACE_EVENT_COPY_INSTANT2(category, name, arg1_name, arg1_val, NULL, 0) + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_INSTANT, \ + category, name, TRACE_EVENT_FLAG_COPY, arg1_name, arg1_val) #define TRACE_EVENT_COPY_INSTANT2(category, name, arg1_name, arg1_val, \ arg2_name, arg2_val) \ INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_INSTANT, \ - category, name, \ - arg1_name, base::debug::TraceValue::ForceCopy(arg1_val), \ - arg2_name, base::debug::TraceValue::ForceCopy(arg2_val), \ - TRACE_EVENT_FLAG_COPY) + category, name, TRACE_EVENT_FLAG_COPY, 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 @@ -255,50 +304,54 @@ // - category and name strings must have application lifetime (statics or // literals). They may not include " chars. #define TRACE_EVENT_BEGIN0(category, name) \ - TRACE_EVENT_BEGIN1(category, name, NULL, 0) + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_BEGIN, \ + category, name, TRACE_EVENT_FLAG_NONE) #define TRACE_EVENT_BEGIN1(category, name, arg1_name, arg1_val) \ - TRACE_EVENT_BEGIN2(category, name, arg1_name, arg1_val, NULL, 0) + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_BEGIN, \ + category, name, TRACE_EVENT_FLAG_NONE, arg1_name, arg1_val) #define TRACE_EVENT_BEGIN2(category, name, arg1_name, arg1_val, \ arg2_name, arg2_val) \ INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_BEGIN, \ - category, name, arg1_name, arg1_val, arg2_name, arg2_val, \ - TRACE_EVENT_FLAG_NONE) + category, name, TRACE_EVENT_FLAG_NONE, arg1_name, arg1_val, \ + arg2_name, arg2_val) #define TRACE_EVENT_COPY_BEGIN0(category, name) \ - TRACE_EVENT_COPY_BEGIN1(category, name, NULL, 0) + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_BEGIN, \ + category, name, TRACE_EVENT_FLAG_COPY) #define TRACE_EVENT_COPY_BEGIN1(category, name, arg1_name, arg1_val) \ - TRACE_EVENT_COPY_BEGIN2(category, name, arg1_name, arg1_val, NULL, 0) + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_BEGIN, \ + category, name, TRACE_EVENT_FLAG_COPY, arg1_name, arg1_val) #define TRACE_EVENT_COPY_BEGIN2(category, name, arg1_name, arg1_val, \ arg2_name, arg2_val) \ INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_BEGIN, \ - category, name, \ - arg1_name, base::debug::TraceValue::ForceCopy(arg1_val), \ - arg2_name, base::debug::TraceValue::ForceCopy(arg2_val), \ - TRACE_EVENT_FLAG_COPY) + category, name, TRACE_EVENT_FLAG_COPY, 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. #define TRACE_EVENT_END0(category, name) \ - TRACE_EVENT_END1(category, name, NULL, 0) + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, \ + category, name, TRACE_EVENT_FLAG_NONE) #define TRACE_EVENT_END1(category, name, arg1_name, arg1_val) \ - TRACE_EVENT_END2(category, name, arg1_name, arg1_val, NULL, 0) + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, \ + category, name, TRACE_EVENT_FLAG_NONE, arg1_name, arg1_val) #define TRACE_EVENT_END2(category, name, arg1_name, arg1_val, \ arg2_name, arg2_val) \ INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, \ - category, name, arg1_name, arg1_val, arg2_name, arg2_val, \ - TRACE_EVENT_FLAG_NONE) + category, name, TRACE_EVENT_FLAG_NONE, arg1_name, arg1_val, \ + arg2_name, arg2_val) #define TRACE_EVENT_COPY_END0(category, name) \ - TRACE_EVENT_COPY_END1(category, name, NULL, 0) + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, \ + category, name, TRACE_EVENT_FLAG_COPY) #define TRACE_EVENT_COPY_END1(category, name, arg1_name, arg1_val) \ - TRACE_EVENT_COPY_END2(category, name, arg1_name, arg1_val, NULL, 0) + INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, \ + category, name, TRACE_EVENT_FLAG_COPY, arg1_name, arg1_val) #define TRACE_EVENT_COPY_END2(category, name, arg1_name, arg1_val, \ arg2_name, arg2_val) \ INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, \ - category, name, \ - arg1_name, base::debug::TraceValue::ForceCopy(arg1_val), \ - arg2_name, base::debug::TraceValue::ForceCopy(arg2_val), \ - TRACE_EVENT_FLAG_COPY) + category, name, TRACE_EVENT_FLAG_COPY, arg1_name, arg1_val, \ + arg2_name, arg2_val) // Time threshold event: // Only record the event if the duration is greater than the specified @@ -309,15 +362,15 @@ // - 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) + INTERNAL_TRACE_EVENT_ADD_SCOPED_IF_LONGER_THAN(threshold_us, category, name) #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) + threshold_us, category, name, arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD_SCOPED_IF_LONGER_THAN( \ + threshold_us, category, name, arg1_name, arg1_val) #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) + INTERNAL_TRACE_EVENT_ADD_SCOPED_IF_LONGER_THAN( \ + threshold_us, category, name, arg1_name, arg1_val, arg2_name, arg2_val) // Records the value of a counter called "name" immediately. Value // must be representable as a 32 bit integer. @@ -336,14 +389,14 @@ #define TRACE_COUNTER2(category, name, value1_name, value1_val, \ value2_name, value2_val) \ INTERNAL_TRACE_EVENT_ADD_COUNTER( \ - category, name, 0, value1_name, value1_val, value2_name, value2_val, \ + category, name, trace_event_internal::kNoEventId, \ + value1_name, value1_val, value2_name, value2_val, \ TRACE_EVENT_FLAG_NONE) #define TRACE_COPY_COUNTER2(category, name, value1_name, value1_val, \ value2_name, value2_val) \ INTERNAL_TRACE_EVENT_ADD_COUNTER( \ - category, name, 0, \ - value1_name, value1_val, \ - value2_name, value2_val, \ + category, name, trace_event_internal::kNoEventId, \ + value1_name, value1_val, value2_name, value2_val, \ TRACE_EVENT_FLAG_COPY) // Records the value of a counter called "name" immediately. Value @@ -392,48 +445,54 @@ // 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_START0(category, name, id) \ - TRACE_EVENT_START1(category, name, id, NULL, 0) + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_START, \ + category, name, id, TRACE_EVENT_FLAG_HAS_ID) #define TRACE_EVENT_START1(category, name, id, arg1_name, arg1_val) \ - TRACE_EVENT_START2(category, name, id, arg1_name, arg1_val, NULL, 0) + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_START, \ + category, name, id, TRACE_EVENT_FLAG_HAS_ID, arg1_name, arg1_val) #define TRACE_EVENT_START2(category, name, id, arg1_name, arg1_val, \ arg2_name, arg2_val) \ INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_START, \ - category, name, id, arg1_name, arg1_val, arg2_name, arg2_val, \ - TRACE_EVENT_FLAG_HAS_ID) + category, name, id, TRACE_EVENT_FLAG_HAS_ID, \ + arg1_name, arg1_val, arg2_name, arg2_val) #define TRACE_EVENT_COPY_START0(category, name, id) \ - TRACE_EVENT_COPY_START1(category, name, id, NULL, 0) + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_START, \ + category, name, id, TRACE_EVENT_FLAG_HAS_ID | TRACE_EVENT_FLAG_COPY) #define TRACE_EVENT_COPY_START1(category, name, id, arg1_name, arg1_val) \ - TRACE_EVENT_COPY_START2(category, name, id, arg1_name, arg1_val, NULL, 0) + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_START, \ + category, name, id, TRACE_EVENT_FLAG_HAS_ID | TRACE_EVENT_FLAG_COPY, \ + arg1_name, arg1_val) #define TRACE_EVENT_COPY_START2(category, name, id, arg1_name, arg1_val, \ arg2_name, arg2_val) \ INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_START, \ - category, name, id, \ - arg1_name, base::debug::TraceValue::ForceCopy(arg1_val), \ - arg2_name, base::debug::TraceValue::ForceCopy(arg2_val), \ - TRACE_EVENT_FLAG_HAS_ID | TRACE_EVENT_FLAG_COPY) + category, name, id, TRACE_EVENT_FLAG_HAS_ID | TRACE_EVENT_FLAG_COPY, \ + arg1_name, arg1_val, arg2_name, arg2_val) // Records a single FINISH event for "name" immediately. If the category // is not enabled, then this does nothing. #define TRACE_EVENT_FINISH0(category, name, id) \ - TRACE_EVENT_FINISH1(category, name, id, NULL, 0) + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FINISH, \ + category, name, id, TRACE_EVENT_FLAG_HAS_ID) #define TRACE_EVENT_FINISH1(category, name, id, arg1_name, arg1_val) \ - TRACE_EVENT_FINISH2(category, name, id, arg1_name, arg1_val, NULL, 0) + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FINISH, \ + category, name, id, TRACE_EVENT_FLAG_HAS_ID, arg1_name, arg1_val) #define TRACE_EVENT_FINISH2(category, name, id, arg1_name, arg1_val, \ arg2_name, arg2_val) \ INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FINISH, \ - category, name, id, arg1_name, arg1_val, arg2_name, arg2_val, \ - TRACE_EVENT_FLAG_HAS_ID) + category, name, id, TRACE_EVENT_FLAG_HAS_ID, \ + arg1_name, arg1_val, arg2_name, arg2_val) #define TRACE_EVENT_COPY_FINISH0(category, name, id) \ - TRACE_EVENT_COPY_FINISH1(category, name, id, NULL, 0) + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FINISH, \ + category, name, id, TRACE_EVENT_FLAG_HAS_ID | TRACE_EVENT_FLAG_COPY) #define TRACE_EVENT_COPY_FINISH1(category, name, id, arg1_name, arg1_val) \ - TRACE_EVENT_COPY_FINISH2(category, name, id, arg1_name, arg1_val, NULL, 0) + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FINISH, \ + category, name, id, TRACE_EVENT_FLAG_HAS_ID | TRACE_EVENT_FLAG_COPY, \ + arg1_name, arg1_val) #define TRACE_EVENT_COPY_FINISH2(category, name, id, arg1_name, arg1_val, \ arg2_name, arg2_val) \ INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FINISH, \ - category, name, id, \ - arg1_name, base::debug::TraceValue::ForceCopy(arg1_val), \ - arg2_name, base::debug::TraceValue::ForceCopy(arg2_val), \ - TRACE_EVENT_FLAG_HAS_ID | TRACE_EVENT_FLAG_COPY) + category, name, id, TRACE_EVENT_FLAG_HAS_ID | TRACE_EVENT_FLAG_COPY, \ + arg1_name, arg1_val, arg2_name, arg2_val) // Implementation detail: trace event macros create temporary variables @@ -449,23 +508,21 @@ // 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* \ - INTERNAL_TRACE_EVENT_UID(catstatic) = NULL; \ + static const unsigned char* INTERNAL_TRACE_EVENT_UID(catstatic) = NULL; \ ANNOTATE_BENIGN_RACE(&INTERNAL_TRACE_EVENT_UID(catstatic), \ "trace_event category"); \ if (!INTERNAL_TRACE_EVENT_UID(catstatic)) \ INTERNAL_TRACE_EVENT_UID(catstatic) = \ - base::debug::TraceLog::GetCategory(category); + TRACE_EVENT_API_GET_CATEGORY_ENABLED(category); // Implementation detail: internal macro to create static category and add // event if the category is enabled. -#define INTERNAL_TRACE_EVENT_ADD( \ - phase, category, name, arg1_name, arg1_val, arg2_name, arg2_val, flags) \ +#define INTERNAL_TRACE_EVENT_ADD(phase, category, name, flags, ...) \ INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \ - if (INTERNAL_TRACE_EVENT_UID(catstatic)->enabled) { \ - base::debug::TraceLog::GetInstance()->AddTraceEvent( \ - phase, INTERNAL_TRACE_EVENT_UID(catstatic), \ - name, 0, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, flags); \ + if (*INTERNAL_TRACE_EVENT_UID(catstatic)) { \ + trace_event_internal::AddTraceEvent( \ + phase, INTERNAL_TRACE_EVENT_UID(catstatic), name, \ + trace_event_internal::kNoEventId, flags, ##__VA_ARGS__); \ } // Implementation detail: internal macro to create static category and @@ -473,26 +530,26 @@ #define INTERNAL_TRACE_EVENT_ADD_COUNTER( \ category, name, id, arg1_name, arg1_val, arg2_name, arg2_val, flags) \ INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \ - if (INTERNAL_TRACE_EVENT_UID(catstatic)->enabled) { \ - base::debug::TraceLog::GetInstance()->AddCounterEvent( \ + if (*INTERNAL_TRACE_EVENT_UID(catstatic)) { \ + TRACE_EVENT_API_ADD_COUNTER_EVENT( \ INTERNAL_TRACE_EVENT_UID(catstatic), \ - name, id, arg1_name, arg1_val, arg2_name, arg2_val, flags); \ + name, trace_event_internal::TraceID(id).data(), \ + arg1_name, arg1_val, arg2_name, arg2_val, flags); \ } // 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) \ +#define INTERNAL_TRACE_EVENT_ADD_SCOPED(category, name, ...) \ INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \ - base::debug::internal::TraceEndOnScopeClose \ + trace_event_internal::TraceEndOnScopeClose \ INTERNAL_TRACE_EVENT_UID(profileScope); \ - if (INTERNAL_TRACE_EVENT_UID(catstatic)->enabled) { \ - base::debug::TraceLog::GetInstance()->AddTraceEvent( \ + if (*INTERNAL_TRACE_EVENT_UID(catstatic)) { \ + trace_event_internal::AddTraceEvent( \ TRACE_EVENT_PHASE_BEGIN, \ INTERNAL_TRACE_EVENT_UID(catstatic), \ - name, 0, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, \ - TRACE_EVENT_FLAG_NONE); \ + name, trace_event_internal::kNoEventId, \ + TRACE_EVENT_FLAG_NONE, ##__VA_ARGS__); \ INTERNAL_TRACE_EVENT_UID(profileScope).Initialize( \ INTERNAL_TRACE_EVENT_UID(catstatic), name); \ } @@ -501,17 +558,17 @@ // 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) \ + category, name, ...) \ INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \ - base::debug::internal::TraceEndOnScopeCloseThreshold \ + trace_event_internal::TraceEndOnScopeCloseThreshold \ INTERNAL_TRACE_EVENT_UID(profileScope); \ - if (INTERNAL_TRACE_EVENT_UID(catstatic)->enabled) { \ + if (*INTERNAL_TRACE_EVENT_UID(catstatic)) { \ int INTERNAL_TRACE_EVENT_UID(begin_event_id) = \ - base::debug::TraceLog::GetInstance()->AddTraceEvent( \ + trace_event_internal::AddTraceEvent( \ TRACE_EVENT_PHASE_BEGIN, \ INTERNAL_TRACE_EVENT_UID(catstatic), \ - name, 0, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, \ - TRACE_EVENT_FLAG_NONE); \ + name, trace_event_internal::kNoEventId, \ + TRACE_EVENT_FLAG_NONE, ##__VA_ARGS__); \ INTERNAL_TRACE_EVENT_UID(profileScope).Initialize( \ INTERNAL_TRACE_EVENT_UID(catstatic), name, \ INTERNAL_TRACE_EVENT_UID(begin_event_id), threshold); \ @@ -519,13 +576,14 @@ // Implementation detail: internal macro to create static category and add // event if the category is enabled. -#define INTERNAL_TRACE_EVENT_ADD_WITH_ID(phase, category, name, id, \ - arg1_name, arg1_val, arg2_name, arg2_val, flags) \ +#define INTERNAL_TRACE_EVENT_ADD_WITH_ID(phase, category, name, id, flags, \ + ...) \ INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category); \ - if (INTERNAL_TRACE_EVENT_UID(catstatic)->enabled) { \ - base::debug::TraceLog::GetInstance()->AddTraceEvent( \ + if (*INTERNAL_TRACE_EVENT_UID(catstatic)) { \ + trace_event_internal::AddTraceEvent( \ phase, INTERNAL_TRACE_EVENT_UID(catstatic), \ - name, id, arg1_name, arg1_val, arg2_name, arg2_val, -1, 0, flags); \ + name, trace_event_internal::TraceID(id).data(), flags, \ + ##__VA_ARGS__); \ } template <typename Type> @@ -537,173 +595,35 @@ class RefCountedString; namespace debug { -// Categories allow enabling/disabling of streams of trace events -struct TraceCategory { - const char* name; - volatile bool enabled; -}; +const int kTraceMaxNumArgs = 2; -const size_t kTraceMaxNumArgs = 2; +// 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 +// definitions. // Phase indicates the nature of an event entry. E.g. part of a begin/end pair. -typedef char TraceEventPhase; -#define TRACE_EVENT_PHASE_BEGIN (base::debug::TraceEventPhase('B')) -#define TRACE_EVENT_PHASE_END (base::debug::TraceEventPhase('E')) -#define TRACE_EVENT_PHASE_INSTANT (base::debug::TraceEventPhase('I')) -#define TRACE_EVENT_PHASE_START (base::debug::TraceEventPhase('S')) -#define TRACE_EVENT_PHASE_FINISH (base::debug::TraceEventPhase('F')) -#define TRACE_EVENT_PHASE_METADATA (base::debug::TraceEventPhase('M')) -#define TRACE_EVENT_PHASE_COUNTER (base::debug::TraceEventPhase('C')) - -typedef uint8 TraceEventFlags; -#define TRACE_EVENT_FLAG_NONE (base::debug::TraceEventFlags(0)) -#define TRACE_EVENT_FLAG_COPY (base::debug::TraceEventFlags(1<<0)) -#define TRACE_EVENT_FLAG_HAS_ID (base::debug::TraceEventFlags(1<<1)) - -// Simple union of values. This is much lighter weight than base::Value, which -// requires dynamic allocation and a vtable. To keep the trace runtime overhead -// low, we want constant size storage here. -class BASE_EXPORT TraceValue { - public: - enum Type { - TRACE_TYPE_UNDEFINED, - TRACE_TYPE_BOOL, - TRACE_TYPE_UINT, - TRACE_TYPE_INT, - TRACE_TYPE_DOUBLE, - TRACE_TYPE_POINTER, - TRACE_TYPE_STRING, - TRACE_TYPE_STATIC_STRING - }; - - TraceValue() : type_(TRACE_TYPE_UNDEFINED) { - value_.as_uint = 0ull; - } - TraceValue(bool rhs) : type_(TRACE_TYPE_BOOL) { - value_.as_bool = rhs; - } - TraceValue(uint64 rhs) : type_(TRACE_TYPE_UINT) { - value_.as_uint = rhs; - } - TraceValue(uint32 rhs) : type_(TRACE_TYPE_UINT) { - value_.as_uint = rhs; - } - TraceValue(uint16 rhs) : type_(TRACE_TYPE_UINT) { - value_.as_uint = rhs; - } - TraceValue(uint8 rhs) : type_(TRACE_TYPE_UINT) { - value_.as_uint = rhs; - } - TraceValue(int64 rhs) : type_(TRACE_TYPE_INT) { - value_.as_int = rhs; - } - TraceValue(int32 rhs) : type_(TRACE_TYPE_INT) { - value_.as_int = rhs; - } - TraceValue(int16 rhs) : type_(TRACE_TYPE_INT) { - value_.as_int = rhs; - } - TraceValue(int8 rhs) : type_(TRACE_TYPE_INT) { - value_.as_int = rhs; - } - TraceValue(double rhs) : type_(TRACE_TYPE_DOUBLE) { - value_.as_double = rhs; - } - TraceValue(const void* rhs) : type_(TRACE_TYPE_POINTER) { - value_.as_pointer = rhs; - } - TraceValue(const std::string& rhs) : type_(TRACE_TYPE_STRING) { - value_.as_string = rhs.c_str(); - } - TraceValue(const char* rhs) : type_(TRACE_TYPE_STATIC_STRING) { - value_.as_string = rhs; - } - - static TraceValue StringWithCopy(const char* rhs) { - TraceValue value(rhs); - if (rhs) - value.type_ = TRACE_TYPE_STRING; - return value; - } - - static TraceValue ForceCopy(const TraceValue& rhs) { - TraceValue value(rhs); - if (value.type_ == TRACE_TYPE_STATIC_STRING && value.as_string()) - value.type_ = TRACE_TYPE_STRING; - return value; - } - - bool is_string() const { - return type_ == TRACE_TYPE_STRING || type_ == TRACE_TYPE_STATIC_STRING; - } - - void AppendAsJSON(std::string* out) const; - - Type type() const { - return type_; - } - uint64 as_uint() const { - DCHECK_EQ(TRACE_TYPE_UINT, type_); - return value_.as_uint; - } - bool as_bool() const { - DCHECK_EQ(TRACE_TYPE_BOOL, type_); - return value_.as_bool; - } - int64 as_int() const { - DCHECK_EQ(TRACE_TYPE_INT, type_); - return value_.as_int; - } - double as_double() const { - DCHECK_EQ(TRACE_TYPE_DOUBLE, type_); - return value_.as_double; - } - const void* as_pointer() const { - DCHECK_EQ(TRACE_TYPE_POINTER, type_); - return value_.as_pointer; - } - const char* as_string() const { - DCHECK(is_string()); - return value_.as_string; - } - const char** as_assignable_string() { - DCHECK_EQ(TRACE_TYPE_STRING, type_); - return &value_.as_string; - } - - private: - union Value { - bool as_bool; - uint64 as_uint; - int64 as_int; - double as_double; - const void* as_pointer; - const char* as_string; - }; - - Type type_; - Value value_; -}; - -// TraceID encapsulates an ID that can either be an integer or pointer. Pointers -// are mangled with the Process ID so that they are unlikely to collide when the -// same pointer is used on different processes. -class BASE_EXPORT TraceID { - public: - TraceID() : data_(0u) {} - TraceID(void* rhs); - TraceID(unsigned long long rhs) : data_(static_cast<uint64>(rhs)) {} - TraceID(unsigned long rhs) : data_(static_cast<uint64>(rhs)) {} - TraceID(unsigned int rhs) : data_(static_cast<uint64>(rhs)) {} - TraceID(long long rhs) : data_(static_cast<uint64>(rhs)) {} - TraceID(long rhs) : data_(static_cast<uint64>(rhs)) {} - TraceID(int rhs) : data_(static_cast<uint64>(rhs)) {} - - uint64 data() const { return data_; } - - private: - uint64 data_; -}; +#define TRACE_EVENT_PHASE_BEGIN ('B') +#define TRACE_EVENT_PHASE_END ('E') +#define TRACE_EVENT_PHASE_INSTANT ('I') +#define TRACE_EVENT_PHASE_START ('S') +#define TRACE_EVENT_PHASE_FINISH ('F') +#define TRACE_EVENT_PHASE_METADATA ('M') +#define TRACE_EVENT_PHASE_COUNTER ('C') + +// Flags for changing the behavior of TRACE_EVENT_API_ADD_TRACE_EVENT. +#define TRACE_EVENT_FLAG_NONE (static_cast<unsigned char>(0)) +#define TRACE_EVENT_FLAG_COPY (static_cast<unsigned char>(1<<0)) +#define TRACE_EVENT_FLAG_HAS_ID (static_cast<unsigned char>(1<<1)) + +// Type values for identifying types in the TraceValue union. +#define TRACE_VALUE_TYPE_BOOL (static_cast<unsigned char>(1)) +#define TRACE_VALUE_TYPE_UINT (static_cast<unsigned char>(2)) +#define TRACE_VALUE_TYPE_INT (static_cast<unsigned char>(3)) +#define TRACE_VALUE_TYPE_DOUBLE (static_cast<unsigned char>(4)) +#define TRACE_VALUE_TYPE_POINTER (static_cast<unsigned char>(5)) +#define TRACE_VALUE_TYPE_STRING (static_cast<unsigned char>(6)) +#define TRACE_VALUE_TYPE_COPY_STRING (static_cast<unsigned char>(7)) // Output records are "Events" and can be obtained via the // OutputCallback whenever the tracing system decides to flush. This @@ -711,26 +631,29 @@ class BASE_EXPORT TraceID { // force it to happen. class BASE_EXPORT TraceEvent { public: + union TraceValue { + bool as_bool; + unsigned long long as_uint; + long long as_int; + double as_double; + const void* as_pointer; + const char* as_string; + }; + TraceEvent(); TraceEvent(int thread_id, TimeTicks timestamp, - TraceEventPhase phase, - const TraceCategory* category, + char phase, + const unsigned char* category_enabled, const char* name, - TraceID id, - const char* arg1_name, const TraceValue& arg1_val, - const char* arg2_name, const TraceValue& arg2_val, - TraceEventFlags flags); + 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); ~TraceEvent(); - static char GetPhaseChar(TraceEventPhase phase) { - return static_cast<char>(phase); - } - - static TraceEventPhase GetPhase(const char* phase) { - return static_cast<TraceEventPhase>(*phase); - } - // Serialize event data to JSON static void AppendEventsAsJSON(const std::vector<TraceEvent>& events, size_t start, @@ -752,15 +675,16 @@ class BASE_EXPORT TraceEvent { // Note: these are ordered by size (largest first) for optimal packing. TimeTicks timestamp_; // id_ can be used to store phase-specific data. - TraceID id_; + unsigned long long id_; TraceValue arg_values_[kTraceMaxNumArgs]; const char* arg_names_[kTraceMaxNumArgs]; - const TraceCategory* category_; + const unsigned char* category_enabled_; const char* name_; scoped_refptr<base::RefCountedString> parameter_copy_storage_; int thread_id_; - TraceEventPhase phase_; - TraceEventFlags flags_; + char phase_; + unsigned char flags_; + unsigned char arg_types_[kTraceMaxNumArgs]; }; @@ -870,7 +794,8 @@ class BASE_EXPORT TraceLog { void Flush(); // Called by TRACE_EVENT* macros, don't call this directly. - static const TraceCategory* GetCategory(const char* name); + static const unsigned char* GetCategoryEnabled(const char* name); + static const char* GetCategoryName(const unsigned char* category_enabled); // Called by TRACE_EVENT* macros, don't call this directly. // Returns the index in the internal vector of the event if it was added, or @@ -880,36 +805,41 @@ class BASE_EXPORT TraceLog { // is less than the threshold, the begin/end event pair is dropped. // 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. - int AddTraceEvent(TraceEventPhase phase, - const TraceCategory* category, + int AddTraceEvent(char phase, + const unsigned char* category_enabled, const char* name, - TraceID id, - const char* arg1_name, TraceValue arg1_val, - const char* arg2_name, TraceValue arg2_val, + unsigned long long id, + int num_args, + const char** arg_names, + const unsigned char* arg_types, + const unsigned long long* arg_values, int threshold_begin_id, - int64 threshold, - TraceEventFlags flags); - static void AddTraceEventEtw(TraceEventPhase phase, + long long threshold, + unsigned char flags); + static void AddTraceEventEtw(char phase, const char* name, const void* id, const char* extra); - static void AddTraceEventEtw(TraceEventPhase phase, + static void AddTraceEventEtw(char phase, const char* name, const void* id, const std::string& extra); // A wrapper around AddTraceEvent used by TRACE_COUNTERx macros // that allows only integer values for the counters. - int AddCounterEvent(const TraceCategory* category, - const char* name, - TraceID id, - const char* arg1_name, int32 arg1_val, - const char* arg2_name, int32 arg2_val, - TraceEventFlags flags); - - // Mangle |id| with a hash based on the process ID so that if |id| occurs on + void AddCounterEvent(const unsigned char* category_enabled, + const char* name, + unsigned long long id, + const char* arg1_name, int arg1_val, + const char* arg2_name, int arg2_val, + unsigned char flags); + + // Mangle |ptr| with a hash based on the process ID so that if |ptr| occurs on // more than one process, it will not collide. - uint64 GetIntraProcessID(uint64 id) const { return id ^ process_id_hash_; } + unsigned long long GetInterProcessID(void* ptr) const { + return static_cast<unsigned long long>(reinterpret_cast<uintptr_t>(ptr)) ^ + process_id_hash_; + } int process_id() const { return process_id_; } @@ -937,7 +867,7 @@ class BASE_EXPORT TraceLog { TraceLog(); ~TraceLog(); - const TraceCategory* GetCategoryInternal(const char* name); + const unsigned char* GetCategoryEnabledInternal(const char* name); void AddThreadNameMetadataEvents(); void AddClockSyncMetadataEvents(); @@ -954,14 +884,180 @@ class BASE_EXPORT TraceLog { base::hash_map<int, std::string> thread_names_; // XORed with TraceID to make it unlikely to collide with other processes. - uint64 process_id_hash_; + unsigned long long process_id_hash_; int process_id_; DISALLOW_COPY_AND_ASSIGN(TraceLog); }; -namespace internal { +} // namespace debug +} // namespace base + +namespace trace_event_internal { + +// Specify these values when the corresponding argument of AddTraceEvent is not +// used. +const int kZeroNumArgs = 0; +const int kNoThreshholdBeginId = -1; +const long long kNoThresholdValue = 0; +const unsigned long long kNoEventId = 0; + +// TraceID encapsulates an ID that can either be an integer or pointer. Pointers +// are mangled with the Process ID so that they are unlikely to collide when the +// same pointer is used on different processes. +class BASE_EXPORT TraceID { + public: + explicit TraceID(void* rhs) : + data_(TRACE_EVENT_API_GET_ID_FROM_POINTER(rhs)) {} + explicit TraceID(unsigned long long rhs) : data_(rhs) {} + explicit TraceID(unsigned long rhs) : data_(rhs) {} + explicit TraceID(unsigned int rhs) : data_(rhs) {} + explicit TraceID(unsigned short rhs) : data_(rhs) {} + explicit TraceID(unsigned char rhs) : data_(rhs) {} + explicit TraceID(long long rhs) : + data_(static_cast<unsigned long long>(rhs)) {} + explicit TraceID(long rhs) : data_(static_cast<unsigned long long>(rhs)) {} + explicit TraceID(int rhs) : data_(static_cast<unsigned long long>(rhs)) {} + explicit TraceID(short rhs) : data_(static_cast<unsigned long long>(rhs)) {} + explicit TraceID(signed char rhs) : + data_(static_cast<unsigned long long>(rhs)) {} + + unsigned long long data() const { return data_; } + + private: + unsigned long long data_; +}; + +// Simple union to store various types as unsigned long long. +union TraceValueUnion { + bool as_bool; + unsigned long long as_uint; + long long as_int; + double as_double; + const void* as_pointer; + const char* as_string; +}; + +// Simple container for const char* that should be copied instead of retained. +class TraceStringWithCopy { + public: + explicit TraceStringWithCopy(const char* str) : str_(str) {} + operator const char* () const { return str_; } + private: + const char* str_; +}; + +// Define SetTraceValue for each allowed type. It stores the type and +// value in the return arguments. This allows this API to avoid declaring any +// structures so that it is portable to third_party libraries. +#define INTERNAL_DECLARE_SET_TRACE_VALUE(actual_type, \ + union_member, \ + value_type_id) \ + static inline void SetTraceValue(actual_type arg, \ + unsigned char* type, \ + unsigned long long* value) { \ + TraceValueUnion type_value; \ + type_value.union_member = arg; \ + *type = value_type_id; \ + *value = type_value.as_uint; \ + } +// Simpler form for int types that can be safely casted. +#define INTERNAL_DECLARE_SET_TRACE_VALUE_INT(actual_type, \ + value_type_id) \ + static inline void SetTraceValue(actual_type arg, \ + unsigned char* type, \ + unsigned long long* value) { \ + *type = value_type_id; \ + *value = static_cast<unsigned long long>(arg); \ + } + +INTERNAL_DECLARE_SET_TRACE_VALUE_INT(unsigned long long, TRACE_VALUE_TYPE_UINT) +INTERNAL_DECLARE_SET_TRACE_VALUE_INT(unsigned int, TRACE_VALUE_TYPE_UINT) +INTERNAL_DECLARE_SET_TRACE_VALUE_INT(unsigned short, TRACE_VALUE_TYPE_UINT) +INTERNAL_DECLARE_SET_TRACE_VALUE_INT(unsigned char, TRACE_VALUE_TYPE_UINT) +INTERNAL_DECLARE_SET_TRACE_VALUE_INT(long long, TRACE_VALUE_TYPE_INT) +INTERNAL_DECLARE_SET_TRACE_VALUE_INT(int, TRACE_VALUE_TYPE_INT) +INTERNAL_DECLARE_SET_TRACE_VALUE_INT(short, TRACE_VALUE_TYPE_INT) +INTERNAL_DECLARE_SET_TRACE_VALUE_INT(signed char, TRACE_VALUE_TYPE_INT) +INTERNAL_DECLARE_SET_TRACE_VALUE(bool, as_bool, TRACE_VALUE_TYPE_BOOL) +INTERNAL_DECLARE_SET_TRACE_VALUE(double, as_double, TRACE_VALUE_TYPE_DOUBLE) +INTERNAL_DECLARE_SET_TRACE_VALUE(const void*, as_pointer, + TRACE_VALUE_TYPE_POINTER) +INTERNAL_DECLARE_SET_TRACE_VALUE(const char*, as_string, + TRACE_VALUE_TYPE_STRING) +INTERNAL_DECLARE_SET_TRACE_VALUE(const TraceStringWithCopy&, as_string, + TRACE_VALUE_TYPE_COPY_STRING) + +#undef INTERNAL_DECLARE_SET_TRACE_VALUE +#undef INTERNAL_DECLARE_SET_TRACE_VALUE_INT + +// std::string version of SetTraceValue so that trace arguments can be strings. +static inline void SetTraceValue(const std::string& arg, + unsigned char* type, + unsigned long long* value) { + TraceValueUnion type_value; + type_value.as_string = arg.c_str(); + *type = TRACE_VALUE_TYPE_COPY_STRING; + *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. + +static inline int AddTraceEvent(char phase, + const unsigned char* category_enabled, + const char* name, + unsigned long long id, + unsigned char flags) { + return TRACE_EVENT_API_ADD_TRACE_EVENT( + phase, category_enabled, name, id, + kZeroNumArgs, NULL, NULL, NULL, + kNoThreshholdBeginId, kNoThresholdValue, flags); +} + +template<class ARG1_TYPE> +static inline int 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) { + 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]); + return TRACE_EVENT_API_ADD_TRACE_EVENT( + phase, category_enabled, name, id, + num_args, &arg1_name, arg_types, arg_values, + kNoThreshholdBeginId, kNoThresholdValue, flags); +} + +template<class ARG1_TYPE, class ARG2_TYPE> +static inline int 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, + 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]); + return TRACE_EVENT_API_ADD_TRACE_EVENT( + phase, category_enabled, name, id, + num_args, arg_names, arg_types, arg_values, + kNoThreshholdBeginId, kNoThresholdValue, flags); +} // Used by TRACE_EVENTx macro. Do not use directly. class BASE_EXPORT TraceEndOnScopeClose { @@ -973,7 +1069,7 @@ class BASE_EXPORT TraceEndOnScopeClose { AddEventIfEnabled(); } - void Initialize(const TraceCategory* category, + void Initialize(const unsigned char* category_enabled, const char* name); private: @@ -986,7 +1082,7 @@ class BASE_EXPORT TraceEndOnScopeClose { // members of this class instead, compiler warnings occur about potential // uninitialized accesses. struct Data { - const TraceCategory* category; + const unsigned char* category_enabled; const char* name; }; Data* p_data_; @@ -1005,10 +1101,10 @@ class BASE_EXPORT TraceEndOnScopeCloseThreshold { // Called by macros only when tracing is enabled at the point when the begin // event is added. - void Initialize(const TraceCategory* category, + void Initialize(const unsigned char* category_enabled, const char* name, int threshold_begin_id, - int64 threshold); + long long threshold); private: // Add the end event if the category is still enabled. @@ -1020,8 +1116,8 @@ class BASE_EXPORT TraceEndOnScopeCloseThreshold { // members of this class instead, compiler warnings occur about potential // uninitialized accesses. struct Data { - int64 threshold; - const TraceCategory* category; + long long threshold; + const unsigned char* category_enabled; const char* name; int threshold_begin_id; }; @@ -1029,9 +1125,6 @@ class BASE_EXPORT TraceEndOnScopeCloseThreshold { Data data_; }; -} // namespace internal - -} // namespace debug -} // namespace base +} // namespace trace_event_internal #endif // BASE_DEBUG_TRACE_EVENT_H_ diff --git a/base/debug/trace_event_unittest.cc b/base/debug/trace_event_unittest.cc index cb77fee..8486f90 100644 --- a/base/debug/trace_event_unittest.cc +++ b/base/debug/trace_event_unittest.cc @@ -1,4 +1,4 @@ -// Copyright (c) 2011 The Chromium Authors. All rights reserved. +// Copyright (c) 2012 The Chromium Authors. All rights reserved. // Use of this source code is governed by a BSD-style license that can be // found in the LICENSE file. @@ -99,6 +99,10 @@ void TraceEventTestFixture::OnTraceDataCollected( scoped_ptr<Value> root; root.reset(base::JSONReader::Read(json_output_.json_output, false)); + if (!root.get()) { + LOG(ERROR) << json_output_.json_output; + } + ListValue* root_list = NULL; ASSERT_TRUE(root.get()); ASSERT_TRUE(root->GetAsList(&root_list)); @@ -310,6 +314,34 @@ void TraceWithAllMacroVariants(WaitableEvent* task_complete_event) { "name1", "value1", "name2", "value2"); + TRACE_EVENT_IF_LONGER_THAN0(0, "all", "TRACE_EVENT_IF_LONGER_THAN0 call"); + TRACE_EVENT_IF_LONGER_THAN1(0, "all", "TRACE_EVENT_IF_LONGER_THAN1 call", + "name1", "value1"); + TRACE_EVENT_IF_LONGER_THAN2(0, "all", "TRACE_EVENT_IF_LONGER_THAN2 call", + "name1", "value1", + "name2", "value2"); + + TRACE_EVENT_START0("all", "TRACE_EVENT_START0 call", 5); + TRACE_EVENT_START1("all", "TRACE_EVENT_START1 call", 5, + "name1", "value1"); + TRACE_EVENT_START2("all", "TRACE_EVENT_START2 call", 5, + "name1", "value1", + "name2", "value2"); + + TRACE_EVENT_FINISH0("all", "TRACE_EVENT_FINISH0 call", 5); + TRACE_EVENT_FINISH1("all", "TRACE_EVENT_FINISH1 call", 5, + "name1", "value1"); + TRACE_EVENT_FINISH2("all", "TRACE_EVENT_FINISH2 call", 5, + "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_COUNTER1("all", "TRACE_COUNTER1 call", 31415); TRACE_COUNTER2("all", "TRACE_COUNTER2 call", "a", 30000, @@ -358,33 +390,117 @@ void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed) { EXPECT_EQ("E", ph_end); } EXPECT_FIND_("TRACE_EVENT1 call"); + EXPECT_SUB_FIND_("name1"); + EXPECT_SUB_FIND_("value1"); EXPECT_FIND_("TRACE_EVENT2 call"); EXPECT_SUB_FIND_("name1"); EXPECT_SUB_FIND_("\"value1\""); EXPECT_SUB_FIND_("name2"); EXPECT_SUB_FIND_("value\\2"); + EXPECT_FIND_("TRACE_EVENT_INSTANT0 call"); EXPECT_FIND_("TRACE_EVENT_INSTANT1 call"); + EXPECT_SUB_FIND_("name1"); + EXPECT_SUB_FIND_("value1"); EXPECT_FIND_("TRACE_EVENT_INSTANT2 call"); EXPECT_SUB_FIND_("name1"); EXPECT_SUB_FIND_("value1"); EXPECT_SUB_FIND_("name2"); EXPECT_SUB_FIND_("value2"); + EXPECT_FIND_("TRACE_EVENT_BEGIN0 call"); EXPECT_FIND_("TRACE_EVENT_BEGIN1 call"); + EXPECT_SUB_FIND_("name1"); + EXPECT_SUB_FIND_("value1"); EXPECT_FIND_("TRACE_EVENT_BEGIN2 call"); EXPECT_SUB_FIND_("name1"); EXPECT_SUB_FIND_("value1"); EXPECT_SUB_FIND_("name2"); EXPECT_SUB_FIND_("value2"); + EXPECT_FIND_("TRACE_EVENT_END0 call"); EXPECT_FIND_("TRACE_EVENT_END1 call"); + EXPECT_SUB_FIND_("name1"); + EXPECT_SUB_FIND_("value1"); EXPECT_FIND_("TRACE_EVENT_END2 call"); EXPECT_SUB_FIND_("name1"); EXPECT_SUB_FIND_("value1"); EXPECT_SUB_FIND_("name2"); EXPECT_SUB_FIND_("value2"); + EXPECT_FIND_("TRACE_EVENT_IF_LONGER_THAN0 call"); + EXPECT_FIND_("TRACE_EVENT_IF_LONGER_THAN1 call"); + EXPECT_SUB_FIND_("name1"); + EXPECT_SUB_FIND_("value1"); + EXPECT_FIND_("TRACE_EVENT_IF_LONGER_THAN2 call"); + EXPECT_SUB_FIND_("name1"); + EXPECT_SUB_FIND_("value1"); + EXPECT_SUB_FIND_("name2"); + EXPECT_SUB_FIND_("value2"); + + EXPECT_FIND_("TRACE_EVENT_START0 call"); + EXPECT_SUB_FIND_("id"); + EXPECT_SUB_FIND_("5"); + EXPECT_FIND_("TRACE_EVENT_START1 call"); + EXPECT_SUB_FIND_("id"); + EXPECT_SUB_FIND_("5"); + EXPECT_SUB_FIND_("name1"); + EXPECT_SUB_FIND_("value1"); + EXPECT_FIND_("TRACE_EVENT_START2 call"); + EXPECT_SUB_FIND_("id"); + EXPECT_SUB_FIND_("5"); + EXPECT_SUB_FIND_("name1"); + EXPECT_SUB_FIND_("value1"); + EXPECT_SUB_FIND_("name2"); + EXPECT_SUB_FIND_("value2"); + + EXPECT_FIND_("TRACE_EVENT_FINISH0 call"); + EXPECT_SUB_FIND_("id"); + EXPECT_SUB_FIND_("5"); + EXPECT_FIND_("TRACE_EVENT_FINISH1 call"); + EXPECT_SUB_FIND_("id"); + EXPECT_SUB_FIND_("5"); + EXPECT_SUB_FIND_("name1"); + EXPECT_SUB_FIND_("value1"); + EXPECT_FIND_("TRACE_EVENT_FINISH2 call"); + EXPECT_SUB_FIND_("id"); + EXPECT_SUB_FIND_("5"); + EXPECT_SUB_FIND_("name1"); + EXPECT_SUB_FIND_("value1"); + EXPECT_SUB_FIND_("name2"); + EXPECT_SUB_FIND_("value2"); + + EXPECT_FIND_("TRACE_EVENT_BEGIN_ETW0 call"); + EXPECT_SUB_FIND_("id"); + EXPECT_SUB_FIND_("5"); + 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_("extra"); + EXPECT_SUB_FIND_("value"); + EXPECT_FIND_("TRACE_EVENT_END_ETW0 call"); + EXPECT_SUB_FIND_("id"); + EXPECT_SUB_FIND_("5"); + 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_("extra"); + EXPECT_SUB_FIND_("value"); + EXPECT_FIND_("TRACE_EVENT_INSTANT_ETW0 call"); + EXPECT_SUB_FIND_("id"); + EXPECT_SUB_FIND_("5"); + 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_("extra"); + EXPECT_SUB_FIND_("value"); + EXPECT_FIND_("TRACE_COUNTER1 call"); { std::string ph; diff --git a/base/debug/trace_event_win.cc b/base/debug/trace_event_win.cc index bba4713..d5a21f4 100644 --- a/base/debug/trace_event_win.cc +++ b/base/debug/trace_event_win.cc @@ -1,4 +1,4 @@ -// Copyright (c) 2011 The Chromium Authors. All rights reserved. +// Copyright (c) 2012 The Chromium Authors. All rights reserved. // Use of this source code is governed by a BSD-style license that can be // found in the LICENSE file. #include "base/debug/trace_event_win.h" @@ -42,7 +42,7 @@ bool TraceEventETWProvider::StartTracing() { void TraceEventETWProvider::TraceEvent(const char* name, size_t name_len, - TraceEventPhase type, + char type, const void* id, const char* extra, size_t extra_len) { @@ -96,7 +96,7 @@ void TraceEventETWProvider::TraceEvent(const char* name, void TraceEventETWProvider::Trace(const char* name, size_t name_len, - TraceEventPhase type, + char type, const void* id, const char* extra, size_t extra_len) { diff --git a/base/debug/trace_event_win.h b/base/debug/trace_event_win.h index 7d66393..3da95ea 100644 --- a/base/debug/trace_event_win.h +++ b/base/debug/trace_event_win.h @@ -1,4 +1,4 @@ -// Copyright (c) 2011 The Chromium Authors. All rights reserved. +// Copyright (c) 2012 The Chromium Authors. All rights reserved. // Use of this source code is governed by a BSD-style license that can be // found in the LICENSE file. @@ -37,14 +37,14 @@ class BASE_EXPORT TraceEventETWProvider : public base::win::EtwTraceProvider { // be used for length. static void Trace(const char* name, size_t name_len, - TraceEventPhase type, + char type, const void* id, const char* extra, size_t extra_len); // Allows passing extra as a std::string for convenience. static void Trace(const char* name, - TraceEventPhase type, + char type, const void* id, const std::string& extra) { return Trace(name, -1, type, id, extra.c_str(), extra.length()); @@ -53,7 +53,7 @@ class BASE_EXPORT TraceEventETWProvider : public base::win::EtwTraceProvider { // Allows passing extra as a const char* to avoid constructing temporary // std::string instances where not needed. static void Trace(const char* name, - TraceEventPhase type, + char type, const void* id, const char* extra) { return Trace(name, -1, type, id, extra, -1); @@ -75,7 +75,7 @@ class BASE_EXPORT TraceEventETWProvider : public base::win::EtwTraceProvider { // string will be used. void TraceEvent(const char* name, size_t name_len, - TraceEventPhase type, + char type, const void* id, const char* extra, size_t extra_len); diff --git a/base/test/trace_event_analyzer.cc b/base/test/trace_event_analyzer.cc index 1341cc0..7aba0be 100644 --- a/base/test/trace_event_analyzer.cc +++ b/base/test/trace_event_analyzer.cc @@ -41,7 +41,7 @@ bool TraceEvent::SetFromJSON(const base::Value* event_value) { return false; } - phase = base::debug::TraceEvent::GetPhase(phase_str.c_str()); + phase = *phase_str.data(); bool require_origin = (phase != TRACE_EVENT_PHASE_METADATA); bool require_id = (phase == TRACE_EVENT_PHASE_START || @@ -229,7 +229,7 @@ Query Query::Bool(bool boolean) { return Query(boolean ? 1.0 : 0.0); } -Query Query::Phase(base::debug::TraceEventPhase phase) { +Query Query::Phase(char phase) { return Query(static_cast<double>(phase)); } @@ -268,17 +268,17 @@ bool Query::Evaluate(const TraceEvent& event) const { else if (CompareAsString(event, &compare_result)) return compare_result; return false; - } else { - switch (operator_) { - case OP_AND: - return left().Evaluate(event) && right().Evaluate(event); - case OP_OR: - return left().Evaluate(event) || right().Evaluate(event); - case OP_NOT: - return !left().Evaluate(event); - default: - NOTREACHED(); - } + } + // It's a logical operator. + switch (operator_) { + case OP_AND: + return left().Evaluate(event) && right().Evaluate(event); + case OP_OR: + return left().Evaluate(event) || right().Evaluate(event); + case OP_NOT: + return !left().Evaluate(event); + default: + NOTREACHED(); } NOTREACHED(); @@ -393,17 +393,11 @@ bool Query::EvaluateArithmeticOperator(const TraceEvent& event, } bool Query::GetAsDouble(const TraceEvent& event, double* num) const { - base::debug::TraceValue value; switch (type_) { case QUERY_ARITHMETIC_OPERATOR: return EvaluateArithmeticOperator(event, num); case QUERY_EVENT_MEMBER: - value = GetMemberValue(event); - if (value.type() == base::debug::TraceValue::TRACE_TYPE_DOUBLE) { - *num = value.as_double(); - return true; - } - return false; + return GetMemberValueAsDouble(event, num); case QUERY_NUMBER: *num = number_; return true; @@ -413,15 +407,9 @@ bool Query::GetAsDouble(const TraceEvent& event, double* num) const { } bool Query::GetAsString(const TraceEvent& event, std::string* str) const { - base::debug::TraceValue value; switch (type_) { case QUERY_EVENT_MEMBER: - value = GetMemberValue(event); - if (value.is_string()) { - *str = value.as_string(); - return true; - } - return false; + return GetMemberValueAsString(event, str); case QUERY_STRING: *str = string_; return true; @@ -430,7 +418,8 @@ bool Query::GetAsString(const TraceEvent& event, std::string* str) const { } } -base::debug::TraceValue Query::GetMemberValue(const TraceEvent& event) const { +bool Query::GetMemberValueAsDouble(const TraceEvent& event, + double* num) const { DCHECK(type_ == QUERY_EVENT_MEMBER); // This could be a request for a member of |event| or a member of |event|'s @@ -440,69 +429,96 @@ base::debug::TraceValue Query::GetMemberValue(const TraceEvent& event) const { // Request for member of associated event, but there is no associated event. if (!the_event) - return base::debug::TraceValue(); + return false; switch (member_) { case EVENT_PID: case OTHER_PID: - return static_cast<double>(the_event->thread.process_id); + *num = static_cast<double>(the_event->thread.process_id); + return true; case EVENT_TID: case OTHER_TID: - return static_cast<double>(the_event->thread.thread_id); + *num = static_cast<double>(the_event->thread.thread_id); + return true; case EVENT_TIME: case OTHER_TIME: - return the_event->timestamp; + *num = the_event->timestamp; + return true; case EVENT_DURATION: - { - if (the_event->has_other_event()) - return the_event->GetAbsTimeToOtherEvent(); - else - return base::debug::TraceValue(); + if (the_event->has_other_event()) { + *num = the_event->GetAbsTimeToOtherEvent(); + return true; } + return false; case EVENT_PHASE: case OTHER_PHASE: - return static_cast<double>(the_event->phase); - case EVENT_CATEGORY: - case OTHER_CATEGORY: - return the_event->category; - case EVENT_NAME: - case OTHER_NAME: - return the_event->name; - case EVENT_ID: - case OTHER_ID: - return the_event->id; + *num = static_cast<double>(the_event->phase); + return true; case EVENT_HAS_STRING_ARG: case OTHER_HAS_STRING_ARG: - return (the_event->HasStringArg(string_) ? 1.0 : 0.0); + *num = (the_event->HasStringArg(string_) ? 1.0 : 0.0); + return true; case EVENT_HAS_NUMBER_ARG: case OTHER_HAS_NUMBER_ARG: - return (the_event->HasNumberArg(string_) ? 1.0 : 0.0); + *num = (the_event->HasNumberArg(string_) ? 1.0 : 0.0); + return true; case EVENT_ARG: - case OTHER_ARG: - { - // Search for the argument name and return its value if found. + case OTHER_ARG: { + // Search for the argument name and return its value if found. + std::map<std::string, double>::const_iterator num_i = + the_event->arg_numbers.find(string_); + if (num_i == the_event->arg_numbers.end()) + return false; + *num = num_i->second; + return true; + } + case EVENT_HAS_OTHER: + // return 1.0 (true) if the other event exists + *num = event.other_event ? 1.0 : 0.0; + return true; + default: + return false; + } +} + +bool Query::GetMemberValueAsString(const TraceEvent& event, + std::string* str) const { + DCHECK(type_ == QUERY_EVENT_MEMBER); - std::map<std::string, std::string>::const_iterator str_i = - the_event->arg_strings.find(string_); - if (str_i != the_event->arg_strings.end()) - return str_i->second; + // This could be a request for a member of |event| or a member of |event|'s + // associated event. Store the target event in the_event: + const TraceEvent* the_event = (member_ < OTHER_PID) ? + &event : event.other_event; - std::map<std::string, double>::const_iterator num_i = - the_event->arg_numbers.find(string_); - if (num_i != the_event->arg_numbers.end()) - return num_i->second; + // Request for member of associated event, but there is no associated event. + if (!the_event) + return false; - return base::debug::TraceValue(); - } - case EVENT_HAS_OTHER: - { - // return 1.0 (true) if the other event exists - double result = event.other_event ? 1.0 : 0.0; - return result; - } + switch (member_) { + case EVENT_CATEGORY: + case OTHER_CATEGORY: + *str = the_event->category; + return true; + case EVENT_NAME: + case OTHER_NAME: + *str = the_event->name; + return true; + case EVENT_ID: + case OTHER_ID: + *str = the_event->id; + return true; + case EVENT_ARG: + case OTHER_ARG: { + // Search for the argument name and return its value if found. + std::map<std::string, std::string>::const_iterator str_i = + the_event->arg_strings.find(string_); + if (str_i == the_event->arg_strings.end()) + return false; + *str = str_i->second; + return true; + } default: - NOTREACHED(); - return base::debug::TraceValue(); + return false; } } diff --git a/base/test/trace_event_analyzer.h b/base/test/trace_event_analyzer.h index 949721b..4817ec8 100644 --- a/base/test/trace_event_analyzer.h +++ b/base/test/trace_event_analyzer.h @@ -152,7 +152,7 @@ struct TraceEvent { // Stored as double to match its JSON representation. double timestamp; - base::debug::TraceEventPhase phase; + char phase; std::string category; @@ -193,7 +193,7 @@ class Query { static Query Bool(bool boolean); // Compare with the given phase. - static Query Phase(base::debug::TraceEventPhase phase); + static Query Phase(char phase); // Compare with the given string pattern. Only works with == and != operators. // Example: Query(EVENT_NAME) == Query::Pattern("MyEvent*") @@ -424,10 +424,11 @@ class Query { bool EvaluateArithmeticOperator(const TraceEvent& event, double* num) const; - // For QUERY_EVENT_MEMBER Query: attempt to get the value of the Query. - // The TraceValue will either be TRACE_TYPE_DOUBLE, TRACE_TYPE_STRING, - // or if requested member does not exist, it will be TRACE_TYPE_UNDEFINED. - base::debug::TraceValue GetMemberValue(const TraceEvent& event) const; + // For QUERY_EVENT_MEMBER Query: attempt to get the double value of the Query. + bool GetMemberValueAsDouble(const TraceEvent& event, double* num) const; + + // For QUERY_EVENT_MEMBER Query: attempt to get the string value of the Query. + bool GetMemberValueAsString(const TraceEvent& event, std::string* num) const; // Does this Query represent a value? bool is_value() const { return type_ != QUERY_BOOLEAN_OPERATOR; } |