summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
-rw-r--r--base/debug/trace_event.cc164
-rw-r--r--base/debug/trace_event.h316
-rw-r--r--base/debug/trace_event_unittest.cc165
-rw-r--r--gpu/command_buffer/client/cmd_buffer_helper.cc2
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;