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