diff options
author | jbates@chromium.org <jbates@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98> | 2011-10-29 03:16:52 +0000 |
---|---|---|
committer | jbates@chromium.org <jbates@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98> | 2011-10-29 03:16:52 +0000 |
commit | 7a79dafb74683a2d9b6a3fc9de053b7c5eb4374d (patch) | |
tree | 37b3ecfddb4ab1936ff08965230bbb954719eb79 | |
parent | b69934e7860287a2569e4b0d76fbfa35a54ac4ec (diff) | |
download | chromium_src-7a79dafb74683a2d9b6a3fc9de053b7c5eb4374d.zip chromium_src-7a79dafb74683a2d9b6a3fc9de053b7c5eb4374d.tar.gz chromium_src-7a79dafb74683a2d9b6a3fc9de053b7c5eb4374d.tar.bz2 |
add classes trace_analyzer::Query and TraceAnalyzer to improve testing (retry)
http://codereview.chromium.org/7981004/
BUG=95714
TEST=base_unittests
Review URL: http://codereview.chromium.org/8418044
git-svn-id: svn://svn.chromium.org/chrome/trunk/src@107861 0039d316-1c4b-4281-b951-d872f2087c98
-rw-r--r-- | base/base.gyp | 3 | ||||
-rw-r--r-- | base/debug/trace_event.cc | 51 | ||||
-rw-r--r-- | base/debug/trace_event.h | 12 | ||||
-rw-r--r-- | base/test/trace_event_analyzer.cc | 697 | ||||
-rw-r--r-- | base/test/trace_event_analyzer.h | 448 | ||||
-rw-r--r-- | base/test/trace_event_analyzer_unittest.cc | 502 |
6 files changed, 1693 insertions, 20 deletions
diff --git a/base/base.gyp b/base/base.gyp index 3003ec8..b94a1f5 100644 --- a/base/base.gyp +++ b/base/base.gyp @@ -240,6 +240,7 @@ 'task_queue_unittest.cc', 'task_unittest.cc', 'template_util_unittest.cc', + 'test/trace_event_analyzer_unittest.cc', 'threading/non_thread_safe_unittest.cc', 'threading/platform_thread_unittest.cc', 'threading/simple_thread_unittest.cc', @@ -444,6 +445,8 @@ 'test/test_timeouts.h', 'test/thread_test_helper.cc', 'test/thread_test_helper.h', + 'test/trace_event_analyzer.cc', + 'test/trace_event_analyzer.h', ], }, { diff --git a/base/debug/trace_event.cc b/base/debug/trace_event.cc index 63f057f..d3bc293 100644 --- a/base/debug/trace_event.cc +++ b/base/debug/trace_event.cc @@ -11,7 +11,6 @@ #endif #include "base/bind.h" #include "base/format_macros.h" -#include "base/memory/ref_counted_memory.h" #include "base/process_util.h" #include "base/stringprintf.h" #include "base/threading/thread_local.h" @@ -119,22 +118,6 @@ void TraceValue::AppendAsJSON(std::string* out) const { namespace { -const char* GetPhaseStr(TraceEventPhase phase) { - switch(phase) { - case TRACE_EVENT_PHASE_BEGIN: - return "B"; - case TRACE_EVENT_PHASE_INSTANT: - return "I"; - case TRACE_EVENT_PHASE_END: - return "E"; - case TRACE_EVENT_PHASE_METADATA: - return "M"; - default: - NOTREACHED() << "Invalid phase argument"; - return "?"; - } -} - size_t GetAllocLength(const char* str) { return str ? strlen(str) + 1 : 0; } // Copies |*member| into |*buffer|, sets |*member| to point to this new @@ -221,6 +204,38 @@ TraceEvent::TraceEvent(unsigned long process_id, TraceEvent::~TraceEvent() { } +const char* TraceEvent::GetPhaseString(TraceEventPhase phase) { + switch(phase) { + case TRACE_EVENT_PHASE_BEGIN: + return "B"; + case TRACE_EVENT_PHASE_INSTANT: + return "I"; + case TRACE_EVENT_PHASE_END: + return "E"; + case TRACE_EVENT_PHASE_METADATA: + return "M"; + default: + NOTREACHED() << "Invalid phase argument"; + return "?"; + } +} + +TraceEventPhase TraceEvent::GetPhase(const char* phase) { + switch(*phase) { + case 'B': + return TRACE_EVENT_PHASE_BEGIN; + case 'I': + return TRACE_EVENT_PHASE_INSTANT; + case 'E': + return TRACE_EVENT_PHASE_END; + case 'M': + return TRACE_EVENT_PHASE_METADATA; + default: + NOTREACHED() << "Invalid phase name"; + return TRACE_EVENT_PHASE_METADATA; + } +} + void TraceEvent::AppendEventsAsJSON(const std::vector<TraceEvent>& events, size_t start, size_t count, @@ -233,7 +248,7 @@ void TraceEvent::AppendEventsAsJSON(const std::vector<TraceEvent>& events, } void TraceEvent::AppendAsJSON(std::string* out) const { - const char* phase_str = GetPhaseStr(phase_); + const char* phase_str = GetPhaseString(phase_); int64 time_int64 = timestamp_.ToInternalValue(); // Category name checked at category creation time. DCHECK(!strchr(name_, '"')); diff --git a/base/debug/trace_event.h b/base/debug/trace_event.h index b4f7d28..bfa4993 100644 --- a/base/debug/trace_event.h +++ b/base/debug/trace_event.h @@ -102,6 +102,7 @@ #include "base/callback.h" #include "base/hash_tables.h" +#include "base/memory/ref_counted_memory.h" #include "base/memory/singleton.h" #include "base/string_util.h" #include "base/third_party/dynamic_annotations/dynamic_annotations.h" @@ -419,6 +420,10 @@ class BASE_EXPORT TraceValue { 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 { @@ -445,7 +450,7 @@ class BASE_EXPORT TraceValue { return value_.as_pointer; } const char* as_string() const { - DCHECK(type_ == TRACE_TYPE_STRING || type_ == TRACE_TYPE_STATIC_STRING); + DCHECK(is_string()); return value_.as_string; } const char** as_assignable_string() { @@ -471,7 +476,7 @@ class BASE_EXPORT 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. -class TraceEvent { +class BASE_EXPORT TraceEvent { public: TraceEvent(); TraceEvent(unsigned long process_id, @@ -485,6 +490,9 @@ class TraceEvent { bool copy); ~TraceEvent(); + static const char* GetPhaseString(TraceEventPhase phase); + static TraceEventPhase GetPhase(const char* phase); + // Serialize event data to JSON static void AppendEventsAsJSON(const std::vector<TraceEvent>& events, size_t start, diff --git a/base/test/trace_event_analyzer.cc b/base/test/trace_event_analyzer.cc new file mode 100644 index 0000000..3e0f373 --- /dev/null +++ b/base/test/trace_event_analyzer.cc @@ -0,0 +1,697 @@ +// Copyright (c) 2011 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/test/trace_event_analyzer.h" + +#include <algorithm> +#include <math.h> + +#include "base/json/json_reader.h" +#include "base/memory/scoped_ptr.h" +#include "base/values.h" + +namespace trace_analyzer { + +// TraceEvent + +TraceEvent::TraceEvent() + : thread(0, 0), + timestamp(0), + phase(base::debug::TRACE_EVENT_PHASE_BEGIN), + other_event(NULL) { +} + +TraceEvent::~TraceEvent() { +} + +bool TraceEvent::SetFromJSON(const base::Value* event_value) { + if (event_value->GetType() != base::Value::TYPE_DICTIONARY) + return false; + const base::DictionaryValue* dictionary = + static_cast<const base::DictionaryValue*>(event_value); + + std::string phase_str; + base::DictionaryValue* args = NULL; + + if (dictionary->GetInteger("pid", &thread.process_id) && + dictionary->GetInteger("tid", &thread.thread_id) && + dictionary->GetDouble("ts", ×tamp) && + dictionary->GetString("cat", &category) && + dictionary->GetString("name", &name) && + dictionary->GetString("ph", &phase_str) && + dictionary->GetDictionary("args", &args)) { + + phase = base::debug::TraceEvent::GetPhase(phase_str.c_str()); + + // For each argument, copy the type and create a trace_analyzer::TraceValue. + base::DictionaryValue::key_iterator keyi = args->begin_keys(); + for (; keyi != args->end_keys(); ++keyi) { + std::string str; + bool boolean = false; + int int_num = 0; + double double_num = 0.0; + Value* value = NULL; + if (args->GetWithoutPathExpansion(*keyi, &value)) { + if (value->GetAsString(&str)) + arg_strings[*keyi] = str; + else if (value->GetAsInteger(&int_num)) + arg_numbers[*keyi] = static_cast<double>(int_num); + else if (value->GetAsBoolean(&boolean)) + arg_numbers[*keyi] = static_cast<double>(boolean ? 1 : 0); + else if (value->GetAsDouble(&double_num)) + arg_numbers[*keyi] = double_num; + else + return false; // Invalid trace event JSON format. + } + } + + return true; + } + + return false; +} + +bool TraceEvent::GetAbsTimeToOtherEvent(double* duration) const { + if (!other_event) + return false; + + *duration = fabs(other_event->timestamp - timestamp); + return true; +} + +bool TraceEvent::GetArgAsString(const std::string& name, + std::string* arg) const { + std::map<std::string, std::string>::const_iterator i = arg_strings.find(name); + if (i != arg_strings.end()) { + *arg = i->second; + return true; + } + return false; +} + +bool TraceEvent::GetArgAsNumber(const std::string& name, + double* arg) const { + std::map<std::string, double>::const_iterator i = arg_numbers.find(name); + if (i != arg_numbers.end()) { + *arg = i->second; + return true; + } + return false; +} + +// QueryNode + +QueryNode::QueryNode(const Query& query) : query_(query) { +} + +QueryNode::~QueryNode() { +} + +// Query + +Query::Query(TraceEventMember member) + : type_(QUERY_EVENT_MEMBER), + operator_(OP_INVALID), + member_(member), + number_(0), + is_pattern_(false) { +} + +Query::Query(TraceEventMember member, const std::string& arg_name) + : type_(QUERY_EVENT_MEMBER), + operator_(OP_INVALID), + member_(member), + number_(0), + string_(arg_name), + is_pattern_(false) { +} + +Query::Query(const Query& query) + : type_(query.type_), + operator_(query.operator_), + left_(query.left_), + right_(query.right_), + member_(query.member_), + number_(query.number_), + string_(query.string_), + is_pattern_(query.is_pattern_) { +} + +Query::~Query() { +} + +Query Query::String(const std::string& str) { + return Query(str); +} + +Query Query::Double(double num) { + return Query(num); +} + +Query Query::Int(int32 num) { + return Query(static_cast<double>(num)); +} + +Query Query::Uint(uint32 num) { + return Query(static_cast<double>(num)); +} + +Query Query::Bool(bool boolean) { + return Query(boolean ? 1.0 : 0.0); +} + +Query Query::Phase(base::debug::TraceEventPhase phase) { + return Query(static_cast<double>(phase)); +} + +Query Query::Pattern(const std::string& pattern) { + Query query(pattern); + query.is_pattern_ = true; + return query; +} + +bool Query::Evaluate(const TraceEvent& event) const { + // First check for values that can convert to bool. + + // double is true if != 0: + double bool_value = 0.0; + bool is_bool = GetAsDouble(event, &bool_value); + if (is_bool) + return (bool_value != 0.0); + + // string is true if it is non-empty: + std::string str_value; + bool is_str = GetAsString(event, &str_value); + if (is_str) + return !str_value.empty(); + + DCHECK(type_ == QUERY_BOOLEAN_OPERATOR) + << "Invalid query: missing boolean expression"; + DCHECK(left_.get() && (right_.get() || is_unary_operator())); + + if (is_comparison_operator()) { + DCHECK(left().is_value() && right().is_value()) + << "Invalid query: comparison operator used between event member and " + "value."; + bool compare_result = false; + if (CompareAsDouble(event, &compare_result)) + return compare_result; + 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(); + } + } + + NOTREACHED(); + return false; +} + +bool Query::CompareAsDouble(const TraceEvent& event, bool* result) const { + double lhs, rhs; + if (!left().GetAsDouble(event, &lhs) || !right().GetAsDouble(event, &rhs)) + return false; + switch (operator_) { + case OP_EQ: + *result = (lhs == rhs); + return true; + case OP_NE: + *result = (lhs != rhs); + return true; + case OP_LT: + *result = (lhs < rhs); + return true; + case OP_LE: + *result = (lhs <= rhs); + return true; + case OP_GT: + *result = (lhs > rhs); + return true; + case OP_GE: + *result = (lhs >= rhs); + return true; + default: + NOTREACHED(); + return false; + } + return true; +} + +bool Query::CompareAsString(const TraceEvent& event, bool* result) const { + std::string lhs, rhs; + if (!left().GetAsString(event, &lhs) || !right().GetAsString(event, &rhs)) + return false; + switch (operator_) { + case OP_EQ: + if (right().is_pattern_) + *result = MatchPattern(lhs, rhs); + else if (left().is_pattern_) + *result = MatchPattern(rhs, lhs); + else + *result = (lhs == rhs); + return true; + case OP_NE: + if (right().is_pattern_) + *result = !MatchPattern(lhs, rhs); + else if (left().is_pattern_) + *result = !MatchPattern(rhs, lhs); + else + *result = (lhs != rhs); + return true; + case OP_LT: + *result = (lhs < rhs); + return true; + case OP_LE: + *result = (lhs <= rhs); + return true; + case OP_GT: + *result = (lhs > rhs); + return true; + case OP_GE: + *result = (lhs >= rhs); + return true; + default: + NOTREACHED(); + return false; + } + return true; +} + +bool Query::EvaluateArithmeticOperator(const TraceEvent& event, + double* num) const { + DCHECK(type_ == QUERY_ARITHMETIC_OPERATOR); + DCHECK(left_.get() && (right_.get() || is_unary_operator())); + + double lhs = 0, rhs = 0; + if (!left().GetAsDouble(event, &lhs)) + return false; + if (!is_unary_operator() && !right().GetAsDouble(event, &rhs)) + return false; + + switch (operator_) { + case OP_ADD: + *num = lhs + rhs; + return true; + case OP_SUB: + *num = lhs - rhs; + return true; + case OP_MUL: + *num = lhs * rhs; + return true; + case OP_DIV: + *num = lhs / rhs; + return true; + case OP_MOD: + *num = static_cast<double>(static_cast<int64>(lhs) % + static_cast<int64>(rhs)); + return true; + case OP_NEGATE: + *num = -lhs; + return true; + default: + NOTREACHED(); + return false; + } +} + +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; + case QUERY_NUMBER: + *num = number_; + return true; + default: + return false; + } +} + +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; + case QUERY_STRING: + *str = string_; + return true; + default: + return false; + } +} + +base::debug::TraceValue Query::GetMemberValue(const TraceEvent& event) const { + DCHECK(type_ == QUERY_EVENT_MEMBER); + + // 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; + + // Request for member of associated event, but there is no associated event. + if (!the_event) + return base::debug::TraceValue(); + + switch (member_) { + case EVENT_PID: + case OTHER_PID: + return static_cast<double>(the_event->thread.process_id); + case EVENT_TID: + case OTHER_TID: + return static_cast<double>(the_event->thread.thread_id); + case EVENT_TIME: + case OTHER_TIME: + return the_event->timestamp; + case EVENT_DURATION: + { + double duration; + if (the_event->GetAbsTimeToOtherEvent(&duration)) + return duration; + else + return base::debug::TraceValue(); + } + 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_HAS_ARG: + case OTHER_HAS_ARG: + // Search for the argument name and return true if found. + return static_cast<double>((the_event->arg_strings.find(string_) != + the_event->arg_strings.end()) || + (the_event->arg_numbers.find(string_) != + the_event->arg_numbers.end()) ? 1 : 0); + 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 str_i->second; + + 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; + + 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; + } + default: + NOTREACHED(); + return base::debug::TraceValue(); + } +} + +Query::Query(const std::string& str) + : type_(QUERY_STRING), + operator_(OP_INVALID), + member_(EVENT_INVALID), + number_(0), + string_(str), + is_pattern_(false) { +} + +Query::Query(double num) + : type_(QUERY_NUMBER), + operator_(OP_INVALID), + member_(EVENT_INVALID), + number_(num), + is_pattern_(false) { +} +const Query& Query::left() const { + return left_->query(); +} + +const Query& Query::right() const { + return right_->query(); +} + +Query Query::operator==(const Query& rhs) const { + return Query(*this, rhs, OP_EQ); +} + +Query Query::operator!=(const Query& rhs) const { + return Query(*this, rhs, OP_NE); +} + +Query Query::operator<(const Query& rhs) const { + return Query(*this, rhs, OP_LT); +} + +Query Query::operator<=(const Query& rhs) const { + return Query(*this, rhs, OP_LE); +} + +Query Query::operator>(const Query& rhs) const { + return Query(*this, rhs, OP_GT); +} + +Query Query::operator>=(const Query& rhs) const { + return Query(*this, rhs, OP_GE); +} + +Query Query::operator&&(const Query& rhs) const { + return Query(*this, rhs, OP_AND); +} + +Query Query::operator||(const Query& rhs) const { + return Query(*this, rhs, OP_OR); +} + +Query Query::operator!() const { + return Query(*this, OP_NOT); +} + +Query Query::operator+(const Query& rhs) const { + return Query(*this, rhs, OP_ADD); +} + +Query Query::operator-(const Query& rhs) const { + return Query(*this, rhs, OP_SUB); +} + +Query Query::operator*(const Query& rhs) const { + return Query(*this, rhs, OP_MUL); +} + +Query Query::operator/(const Query& rhs) const { + return Query(*this, rhs, OP_DIV); +} + +Query Query::operator%(const Query& rhs) const { + return Query(*this, rhs, OP_MOD); +} + +Query Query::operator-() const { + return Query(*this, OP_NEGATE); +} + + +Query::Query(const Query& left, const Query& right, Operator binary_op) + : operator_(binary_op), + left_(new QueryNode(left)), + right_(new QueryNode(right)), + member_(EVENT_INVALID), + number_(0) { + type_ = (binary_op < OP_ADD ? + QUERY_BOOLEAN_OPERATOR : QUERY_ARITHMETIC_OPERATOR); +} + +Query::Query(const Query& left, Operator unary_op) + : operator_(unary_op), + left_(new QueryNode(left)), + member_(EVENT_INVALID), + number_(0) { + type_ = (unary_op < OP_ADD ? + QUERY_BOOLEAN_OPERATOR : QUERY_ARITHMETIC_OPERATOR); +} + +namespace { + +// Search |events| for |query| and add matches to |output|. +size_t FindMatchingEvents(const std::vector<TraceEvent>& events, + const Query& query, + TraceAnalyzer::TraceEventVector* output) { + for (size_t i = 0; i < events.size(); ++i) { + if (query.Evaluate(events[i])) + output->push_back(&events[i]); + } + return output->size(); +} + +bool ParseEventsFromJson(const std::string& json, + std::vector<TraceEvent>* output) { + scoped_ptr<base::Value> root; + root.reset(base::JSONReader::Read(json, false)); + + ListValue* root_list = NULL; + if (!root.get() || !root->GetAsList(&root_list)) + return false; + + for (size_t i = 0; i < root_list->GetSize(); ++i) { + Value* item = NULL; + if (root_list->Get(i, &item)) { + TraceEvent event; + if (event.SetFromJSON(item)) + output->push_back(event); + else + return false; + } + } + + return true; +} + +} // namespace + +// TraceAnalyzer + +TraceAnalyzer::TraceAnalyzer() : allow_assocation_changes_(true) { +} + +TraceAnalyzer::~TraceAnalyzer() { +} + +// static +TraceAnalyzer* TraceAnalyzer::Create(const std::string& json_events) { + scoped_ptr<TraceAnalyzer> analyzer(new TraceAnalyzer()); + if (analyzer->SetEvents(json_events)) + return analyzer.release(); + return NULL; +} + +bool TraceAnalyzer::SetEvents(const std::string& json_events) { + raw_events_.clear(); + if (!ParseEventsFromJson(json_events, &raw_events_)) + return false; + std::stable_sort(raw_events_.begin(), raw_events_.end()); + ParseMetadata(); + return true; +} + +void TraceAnalyzer::AssociateBeginEndEvents() { + using namespace trace_analyzer; + + Query begin(Query(EVENT_PHASE) == + Query::Phase(base::debug::TRACE_EVENT_PHASE_BEGIN)); + Query end(Query(EVENT_PHASE) == + Query::Phase(base::debug::TRACE_EVENT_PHASE_END)); + Query match(Query(EVENT_NAME) == Query(OTHER_NAME) && + Query(EVENT_CATEGORY) == Query(OTHER_CATEGORY) && + Query(EVENT_TID) == Query(OTHER_TID) && + Query(EVENT_PID) == Query(OTHER_PID)); + + AssociateEvents(begin, end, match); +} + +void TraceAnalyzer::AssociateEvents(const Query& first, + const Query& second, + const Query& match) { + DCHECK(allow_assocation_changes_) << "AssociateEvents not allowed after " + "FindEvents"; + + // Search for matching begin/end event pairs. When a matching end is found, + // it is associated with the begin event. + std::vector<TraceEvent*> begin_stack; + for (size_t event_index = 0; event_index < raw_events_.size(); + ++event_index) { + + TraceEvent& this_event = raw_events_[event_index]; + + if (first.Evaluate(this_event)) { + begin_stack.push_back(&this_event); + } else if (second.Evaluate(this_event)) { + // Search stack for matching begin, starting from end. + for (int stack_index = static_cast<int>(begin_stack.size()) - 1; + stack_index >= 0; --stack_index) { + TraceEvent& begin_event = *begin_stack[stack_index]; + + // Temporarily set other to test against the match query. + const TraceEvent* other_backup = begin_event.other_event; + begin_event.other_event = &this_event; + if (match.Evaluate(begin_event)) { + // Found a matching begin/end pair. + // Set event association: + this_event.other_event = &begin_event; + // Erase the matching begin event index from the stack. + begin_stack.erase(begin_stack.begin() + stack_index); + break; + } + + // Not a match, restore original other and continue. + begin_event.other_event = other_backup; + } + } + } +} + +size_t TraceAnalyzer::FindEvents(const Query& query, TraceEventVector* output) { + allow_assocation_changes_ = false; + output->clear(); + return FindMatchingEvents(raw_events_, query, output); +} + +const TraceEvent* TraceAnalyzer::FindOneEvent(const Query& query) { + TraceEventVector output; + if (FindEvents(query, &output) > 0) + return output.front(); + return NULL; +} + +const std::string& TraceAnalyzer::GetThreadName( + const TraceEvent::ProcessThreadID& thread) { + // If thread is not found, just add and return empty string. + return thread_names_[thread]; +} + +void TraceAnalyzer::ParseMetadata() { + for (size_t i = 0; i < raw_events_.size(); ++i) { + TraceEvent& this_event = raw_events_[i]; + // Check for thread name metadata. + if (this_event.phase != base::debug::TRACE_EVENT_PHASE_METADATA || + this_event.name != "thread_name") + continue; + std::map<std::string, std::string>::const_iterator string_it = + this_event.arg_strings.find("name"); + if (string_it != this_event.arg_strings.end()) + thread_names_[this_event.thread] = string_it->second; + } +} + +} // namespace trace_analyzer + diff --git a/base/test/trace_event_analyzer.h b/base/test/trace_event_analyzer.h new file mode 100644 index 0000000..4bf4884 --- /dev/null +++ b/base/test/trace_event_analyzer.h @@ -0,0 +1,448 @@ +// Copyright (c) 2011 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. + +// Use trace_analyzer::Query and trace_analyzer::TraceAnalyzer to search for +// specific trace events that were generated by the trace_event.h API. +// +// Basic procedure: +// - Get trace events JSON string from base::debug::TraceLog. +// - Create TraceAnalyzer with JSON string. +// - Call TraceAnalyzer::AssociateBeginEndEvents (optional). +// - Call TraceAnalyzer::AssociateEvents (zero or more times). +// - Call TraceAnalyzer::FindEvents with queries to find specific events. +// +// A Query is a boolean expression tree that evaluates to true or false for a +// given trace event. Queries can be combined into a tree using boolean, +// arithmetic and comparison operators that refer to data of an individual trace +// event. +// +// The events are returned as trace_analyzer::TraceEvent objects. +// TraceEvent contains a single trace event's data, as well as a pointer to +// a related trace event. The related trace event is typically the matching end +// of a begin event or the matching begin of an end event. +// +// The following examples use this basic setup code to construct TraceAnalyzer +// with the json trace string retrieved from TraceLog and construct an event +// vector for retrieving events: +// +// TraceAnalyzer analyzer(json_events); +// TraceEventVector events; +// +// During construction, TraceAnalyzer::SetDefaultAssociations is called to +// associate all matching begin/end pairs similar to how they are shown in +// about:tracing. +// +// EXAMPLE 1: Find events named "my_event". +// +// analyzer.FindEvents(Query(EVENT_NAME) == "my_event", &events); +// +// EXAMPLE 2: Find begin events named "my_event" with duration > 1 second. +// +// Query q = (Query(EVENT_NAME) == Query::String("my_event") && +// Query(EVENT_PHASE) == Query::Phase(TRACE_EVENT_PHASE_BEGIN) && +// Query(EVENT_DURATION) > Query::Double(1000000.0)); +// analyzer.FindEvents(q, &events); +// +// EXAMPLE 3: Associating event pairs across threads. +// +// If the test needs to analyze something that starts and ends on different +// threads, the test needs to use INSTANT events. The typical procedure is to +// specify the same unique ID as a TRACE_EVENT argument on both the start and +// finish INSTANT events. Then use the following procedure to associate those +// events. +// +// Step 1: instrument code with custom begin/end trace events. +// [Thread 1 tracing code] +// TRACE_EVENT_INSTANT1("test_latency", "timing1_begin", "id", 3); +// [Thread 2 tracing code] +// TRACE_EVENT_INSTANT1("test_latency", "timing1_end", "id", 3); +// +// Step 2: associate these custom begin/end pairs. +// Query begin(Query(EVENT_NAME) == Query::String("timing1_begin")); +// Query end(Query(EVENT_NAME) == Query::String("timing1_end")); +// Query match(Query(EVENT_ARG, "id") == Query(OTHER_ARG, "id")); +// analyzer.AssociateEvents(begin, end, match); +// +// Step 3: search for "timing1_begin" events with existing other event. +// Query q = (Query(EVENT_NAME) == Query::String("timing1_begin") && +// Query(EVENT_HAS_OTHER)); +// analyzer.FindEvents(q, &events); +// +// Step 4: analyze events, such as checking durations. +// for (size_t i = 0; i < events.size(); ++i) { +// double duration; +// EXPECT_TRUE(events[i].GetAbsTimeToOtherEvent(&duration)); +// EXPECT_LT(duration, 1000000.0/60.0); // expect less than 1/60 second. +// } + + +#ifndef BASE_TEST_TRACE_EVENT_ANALYZER_H_ +#define BASE_TEST_TRACE_EVENT_ANALYZER_H_ +#pragma once + +#include <map> + +#include "base/debug/trace_event.h" +#include "base/memory/ref_counted_memory.h" +#include "base/memory/scoped_ptr.h" + +namespace base { +class Value; +} + +namespace trace_analyzer { +class QueryNode; + +// trace_analyzer::TraceEvent is a more convenient form of the +// base::debug::TraceEvent class to make tracing-based tests easier to write. +struct TraceEvent { + // ProcessThreadID contains a Process ID and Thread ID. + struct ProcessThreadID { + ProcessThreadID() : process_id(0), thread_id(0) {} + ProcessThreadID(int process_id, int thread_id) + : process_id(process_id), thread_id(thread_id) {} + bool operator< (const ProcessThreadID& rhs) const { + if (process_id != rhs.process_id) + return process_id < rhs.process_id; + return thread_id < rhs.thread_id; + } + int process_id; + int thread_id; + }; + + TraceEvent(); + ~TraceEvent(); + + bool SetFromJSON(const base::Value* event_value) WARN_UNUSED_RESULT; + + bool operator< (const TraceEvent& rhs) const { + return timestamp < rhs.timestamp; + } + + bool has_other_event() const { return other_event; } + + // Returns absolute duration in microseconds between this event and other + // event. Returns false if has_other_event() is false. + bool GetAbsTimeToOtherEvent(double* duration) const; + + // Return the argument value if it exists and it is a string. + bool GetArgAsString(const std::string& name, std::string* arg) const; + // Return the argument value if it exists and it is a number. + bool GetArgAsNumber(const std::string& name, double* arg) const; + + // Process ID and Thread ID. + ProcessThreadID thread; + + // Time since epoch in microseconds. + // Stored as double to match its JSON representation. + double timestamp; + + base::debug::TraceEventPhase phase; + + std::string category; + + std::string name; + + // All numbers and bool values from TraceEvent args are cast to double. + // bool becomes 1.0 (true) or 0.0 (false). + std::map<std::string, double> arg_numbers; + + std::map<std::string, std::string> arg_strings; + + // The other event associated with this event (or NULL). + const TraceEvent* other_event; +}; + +// Pass these values to Query to compare with the corresponding member of a +// TraceEvent. +enum TraceEventMember { + EVENT_INVALID, + // Use these to access the event members: + EVENT_PID, + EVENT_TID, + // Return the timestamp of the event in microseconds since epoch. + EVENT_TIME, + // Return the absolute time between event and other event in microseconds. + // Only works for events with associated BEGIN/END: Query(EVENT_HAS_OTHER). + EVENT_DURATION, + EVENT_PHASE, + EVENT_CATEGORY, + EVENT_NAME, + EVENT_HAS_ARG, + EVENT_ARG, + // Return true if associated event exists. + // (Typically BEGIN for END or END for BEGIN). + EVENT_HAS_OTHER, + // Use these to access the associated event's members: + OTHER_PID, + OTHER_TID, + OTHER_TIME, + OTHER_PHASE, + OTHER_CATEGORY, + OTHER_NAME, + OTHER_HAS_ARG, + OTHER_ARG +}; + +class Query { + public: + // Compare with the given member. + Query(TraceEventMember member); + + // Compare with the given member argument value. + Query(TraceEventMember member, const std::string& arg_name); + + Query(const Query& query); + + ~Query(); + + // Compare with the given string. + static Query String(const std::string& str); + + // Compare with the given number. + static Query Double(double num); + static Query Int(int32 num); + static Query Uint(uint32 num); + + // Compare with the given bool. + static Query Bool(bool boolean); + + // Compare with the given phase. + static Query Phase(base::debug::TraceEventPhase phase); + + // Compare with the given string pattern. Only works with == and != operators. + // Example: Query(EVENT_NAME) == Query::Pattern("MyEvent*") + static Query Pattern(const std::string& pattern); + + // Common queries: + + // Find BEGIN events that have a corresponding END event. + static Query MatchBeginWithEnd() { + return (Query(EVENT_PHASE) == + Query::Phase(base::debug::TRACE_EVENT_PHASE_BEGIN)) && + Query(EVENT_HAS_OTHER); + } + + // Find BEGIN events of given |name| which also have associated END events. + static Query MatchBeginName(const std::string& name) { + return (Query(EVENT_NAME) == name) && MatchBeginWithEnd(); + } + + // Match given Process ID and Thread ID. + static Query MatchThread(const TraceEvent::ProcessThreadID& thread) { + return (Query(EVENT_PID) == Query::Int(thread.process_id)) && + (Query(EVENT_TID) == Query::Int(thread.thread_id)); + } + + // Match event pair that spans multiple threads. + static Query MatchCrossThread() { + return (Query(EVENT_PID) != Query(OTHER_PID)) || + (Query(EVENT_TID) != Query(OTHER_TID)); + } + + // Boolean operators: + Query operator==(const Query& rhs) const; + Query operator!=(const Query& rhs) const; + Query operator< (const Query& rhs) const; + Query operator<=(const Query& rhs) const; + Query operator> (const Query& rhs) const; + Query operator>=(const Query& rhs) const; + Query operator&&(const Query& rhs) const; + Query operator||(const Query& rhs) const; + Query operator!() const; + + // Arithmetic operators: + // Following operators are applied to double arguments: + Query operator+(const Query& rhs) const; + Query operator-(const Query& rhs) const; + Query operator*(const Query& rhs) const; + Query operator/(const Query& rhs) const; + Query operator-() const; + // Mod operates on int64 args (doubles are casted to int64 beforehand): + Query operator%(const Query& rhs) const; + + // Return true if the given event matches this query tree. + // This is a recursive method that walks the query tree. + bool Evaluate(const TraceEvent& event) const; + + private: + enum Operator { + OP_INVALID, + // Boolean operators: + OP_EQ, + OP_NE, + OP_LT, + OP_LE, + OP_GT, + OP_GE, + OP_AND, + OP_OR, + OP_NOT, + // Arithmetic operators: + OP_ADD, + OP_SUB, + OP_MUL, + OP_DIV, + OP_MOD, + OP_NEGATE + }; + + enum QueryType { + QUERY_BOOLEAN_OPERATOR, + QUERY_ARITHMETIC_OPERATOR, + QUERY_EVENT_MEMBER, + QUERY_NUMBER, + QUERY_STRING + }; + + // Compare with the given string. + Query(const std::string& str); + + // Compare with the given number. + Query(double num); + + // Construct a boolean Query that returns (left <binary_op> right). + Query(const Query& left, const Query& right, Operator binary_op); + + // Construct a boolean Query that returns (<binary_op> left). + Query(const Query& left, Operator unary_op); + + // Try to compare left_ against right_ based on operator_. + // If either left or right does not convert to double, false is returned. + // Otherwise, true is returned and |result| is set to the comparison result. + bool CompareAsDouble(const TraceEvent& event, bool* result) const; + + // Try to compare left_ against right_ based on operator_. + // If either left or right does not convert to string, false is returned. + // Otherwise, true is returned and |result| is set to the comparison result. + bool CompareAsString(const TraceEvent& event, bool* result) const; + + // Attempt to convert this Query to a double. On success, true is returned + // and the double value is stored in |num|. + bool GetAsDouble(const TraceEvent& event, double* num) const; + + // Attempt to convert this Query to a string. On success, true is returned + // and the string value is stored in |str|. + bool GetAsString(const TraceEvent& event, std::string* str) const; + + // Evaluate this Query as an arithmetic operator on left_ and right_. + 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; + + // Does this Query represent a value? + bool is_value() const { return type_ != QUERY_BOOLEAN_OPERATOR; } + + bool is_unary_operator() const { + return operator_ == OP_NOT || operator_ == OP_NEGATE; + } + + bool is_comparison_operator() const { + return operator_ != OP_INVALID && operator_ < OP_AND; + } + + const Query& left() const; + const Query& right() const; + + QueryType type_; + Operator operator_; + scoped_refptr<QueryNode> left_; + scoped_refptr<QueryNode> right_; + TraceEventMember member_; + double number_; + std::string string_; + bool is_pattern_; +}; + +// Implementation detail: +// QueryNode allows Query to store a ref-counted query tree. +class QueryNode : public base::RefCounted<QueryNode> { + public: + explicit QueryNode(const Query& query); + const Query& query() const { return query_; } + + private: + friend class base::RefCounted<QueryNode>; + ~QueryNode(); + + Query query_; +}; + +// TraceAnalyzer helps tests search for trace events. +class TraceAnalyzer { + public: + typedef std::vector<const TraceEvent*> TraceEventVector; + + ~TraceAnalyzer(); + + // Use trace events from JSON string generated by tracing API. + // Returns non-NULL if the JSON is successfully parsed. + static TraceAnalyzer* Create(const std::string& json_events) + WARN_UNUSED_RESULT; + + // Associate BEGIN and END events with each other. This allows Query(OTHER_*) + // to access the associated event and enables Query(EVENT_DURATION). + // An end event will match the most recent begin event with the same name, + // category, process ID and thread ID. This matches what is shown in + // about:tracing. + void AssociateBeginEndEvents(); + + // AssociateEvents can be used to customize event associations by setting the + // other_event member of TraceEvent. This should be used to associate two + // INSTANT events. + // + // The assumptions are: + // - |first| events occur before |second| events. + // - the closest matching |second| event is the correct match. + // + // |first| - Eligible |first| events match this query. + // |second| - Eligible |second| events match this query. + // |match| - This query is run on the |first| event. The OTHER_* EventMember + // queries will point to an eligible |second| event. The query + // should evaluate to true if the |first|/|second| pair is a match. + // + // When a match is found, the pair will be associated by having their + // other_event member point to each other. AssociateEvents does not clear + // previous associations, so it is possible to associate multiple pairs of + // events by calling AssociateEvents more than once with different queries. + // + // NOTE: AssociateEvents will overwrite existing other_event associations if + // the queries pass for events that already had a previous association. + // + // After calling FindEvents or FindOneEvent, it is not allowed to call + // AssociateEvents again. + void AssociateEvents(const Query& first, + const Query& second, + const Query& match); + + // Find all events that match query and replace output vector. + size_t FindEvents(const Query& query, TraceEventVector* output); + + // Helper method: find first event that matches query + const TraceEvent* FindOneEvent(const Query& query); + + const std::string& GetThreadName(const TraceEvent::ProcessThreadID& thread); + + private: + TraceAnalyzer(); + + bool SetEvents(const std::string& json_events) WARN_UNUSED_RESULT; + + // Read metadata (thread names, etc) from events. + void ParseMetadata(); + + std::map<TraceEvent::ProcessThreadID, std::string> thread_names_; + std::vector<TraceEvent> raw_events_; + bool allow_assocation_changes_; + + DISALLOW_COPY_AND_ASSIGN(TraceAnalyzer); +}; + +} // namespace trace_analyzer + +#endif // BASE_TEST_TRACE_EVENT_ANALYZER_H_ diff --git a/base/test/trace_event_analyzer_unittest.cc b/base/test/trace_event_analyzer_unittest.cc new file mode 100644 index 0000000..2047b12 --- /dev/null +++ b/base/test/trace_event_analyzer_unittest.cc @@ -0,0 +1,502 @@ +// Copyright (c) 2011 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/bind.h" +#include "base/test/trace_event_analyzer.h" +#include "testing/gmock/include/gmock/gmock.h" +#include "testing/gtest/include/gtest/gtest.h" + +namespace trace_analyzer { + +namespace { + +class TraceEventAnalyzerTest : public testing::Test { + public: + void ManualSetUp(); + void OnTraceDataCollected( + scoped_refptr<base::debug::TraceLog::RefCountedString> json_events_str); + void BeginTracing(); + void EndTracing(); + + base::debug::TraceResultBuffer::SimpleOutput output_; + base::debug::TraceResultBuffer buffer_; +}; + +void TraceEventAnalyzerTest::ManualSetUp() { + base::debug::TraceLog::Resurrect(); + base::debug::TraceLog* tracelog = base::debug::TraceLog::GetInstance(); + ASSERT_TRUE(tracelog); + tracelog->SetOutputCallback( + base::Bind(&TraceEventAnalyzerTest::OnTraceDataCollected, + base::Unretained(this))); + buffer_.SetOutputCallback(output_.GetCallback()); + output_.json_output.clear(); +} + +void TraceEventAnalyzerTest::OnTraceDataCollected( + scoped_refptr<base::debug::TraceLog::RefCountedString> json_events_str) { + buffer_.AddFragment(json_events_str->data); +} + +void TraceEventAnalyzerTest::BeginTracing() { + output_.json_output.clear(); + buffer_.Start(); + base::debug::TraceLog::GetInstance()->SetEnabled(true); +} + +void TraceEventAnalyzerTest::EndTracing() { + base::debug::TraceLog::GetInstance()->SetEnabled(false); + buffer_.Finish(); +} + +} // namespace + +TEST_F(TraceEventAnalyzerTest, NoEvents) { + using namespace trace_analyzer; + ManualSetUp(); + + // Create an empty JSON event string: + buffer_.Start(); + buffer_.Finish(); + + scoped_ptr<TraceAnalyzer> + analyzer(TraceAnalyzer::Create(output_.json_output)); + ASSERT_TRUE(analyzer.get()); + + // Search for all events and verify that nothing is returned. + TraceAnalyzer::TraceEventVector found; + analyzer->FindEvents(Query::Bool(true), &found); + EXPECT_EQ(0u, found.size()); +} + +TEST_F(TraceEventAnalyzerTest, QueryEventMember) { + using namespace trace_analyzer; + ManualSetUp(); + + TraceEvent event; + event.thread.process_id = 3; + event.thread.thread_id = 4; + event.timestamp = 1.5; + event.phase = base::debug::TRACE_EVENT_PHASE_BEGIN; + event.category = "category"; + event.name = "name"; + event.arg_numbers["num"] = 7.0; + event.arg_strings["str"] = "the string"; + + // Other event with all different members: + TraceEvent other; + other.thread.process_id = 5; + other.thread.thread_id = 6; + other.timestamp = 2.5; + other.phase = base::debug::TRACE_EVENT_PHASE_END; + other.category = "category2"; + other.name = "name2"; + other.arg_numbers["num2"] = 8.0; + other.arg_strings["str2"] = "the string 2"; + + event.other_event = &other; + double duration; + ASSERT_TRUE(event.GetAbsTimeToOtherEvent(&duration)); + + Query event_pid = (Query(EVENT_PID) == Query::Int(event.thread.process_id)); + Query event_tid = (Query(EVENT_TID) == Query::Int(event.thread.thread_id)); + Query event_time = (Query(EVENT_TIME) == Query::Double(event.timestamp)); + Query event_duration = (Query(EVENT_DURATION) == Query::Double(duration)); + Query event_phase = (Query(EVENT_PHASE) == Query::Phase(event.phase)); + Query event_category = + (Query(EVENT_CATEGORY) == Query::String(event.category)); + Query event_name = (Query(EVENT_NAME) == Query::String(event.name)); + Query event_has_arg1 = Query(EVENT_HAS_ARG, "num"); + Query event_has_arg2 = Query(EVENT_HAS_ARG, "str"); + Query event_arg1 = + (Query(EVENT_ARG, "num") == Query::Double(event.arg_numbers["num"])); + Query event_arg2 = + (Query(EVENT_ARG, "str") == Query::String(event.arg_strings["str"])); + Query event_has_other = Query(EVENT_HAS_OTHER); + Query other_pid = (Query(OTHER_PID) == Query::Int(other.thread.process_id)); + Query other_tid = (Query(OTHER_TID) == Query::Int(other.thread.thread_id)); + Query other_time = (Query(OTHER_TIME) == Query::Double(other.timestamp)); + Query other_phase = (Query(OTHER_PHASE) == Query::Phase(other.phase)); + Query other_category = + (Query(OTHER_CATEGORY) == Query::String(other.category)); + Query other_name = (Query(OTHER_NAME) == Query::String(other.name)); + Query other_has_arg1 = Query(OTHER_HAS_ARG, "num2"); + Query other_has_arg2 = Query(OTHER_HAS_ARG, "str2"); + Query other_arg1 = + (Query(OTHER_ARG, "num2") == Query::Double(other.arg_numbers["num2"])); + Query other_arg2 = + (Query(OTHER_ARG, "str2") == Query::String(other.arg_strings["str2"])); + + EXPECT_TRUE(event_pid.Evaluate(event)); + EXPECT_TRUE(event_tid.Evaluate(event)); + EXPECT_TRUE(event_time.Evaluate(event)); + EXPECT_TRUE(event_duration.Evaluate(event)); + EXPECT_TRUE(event_phase.Evaluate(event)); + EXPECT_TRUE(event_category.Evaluate(event)); + EXPECT_TRUE(event_name.Evaluate(event)); + EXPECT_TRUE(event_has_arg1.Evaluate(event)); + EXPECT_TRUE(event_has_arg2.Evaluate(event)); + EXPECT_TRUE(event_arg1.Evaluate(event)); + EXPECT_TRUE(event_arg2.Evaluate(event)); + EXPECT_TRUE(event_has_other.Evaluate(event)); + EXPECT_TRUE(other_pid.Evaluate(event)); + EXPECT_TRUE(other_tid.Evaluate(event)); + EXPECT_TRUE(other_time.Evaluate(event)); + EXPECT_TRUE(other_phase.Evaluate(event)); + EXPECT_TRUE(other_category.Evaluate(event)); + EXPECT_TRUE(other_name.Evaluate(event)); + EXPECT_TRUE(other_has_arg1.Evaluate(event)); + EXPECT_TRUE(other_has_arg2.Evaluate(event)); + EXPECT_TRUE(other_arg1.Evaluate(event)); + EXPECT_TRUE(other_arg2.Evaluate(event)); + + // Evaluate event queries against other to verify the queries fail when the + // event members are wrong. + EXPECT_FALSE(event_pid.Evaluate(other)); + EXPECT_FALSE(event_tid.Evaluate(other)); + EXPECT_FALSE(event_time.Evaluate(other)); + EXPECT_FALSE(event_duration.Evaluate(other)); + EXPECT_FALSE(event_phase.Evaluate(other)); + EXPECT_FALSE(event_category.Evaluate(other)); + EXPECT_FALSE(event_name.Evaluate(other)); + EXPECT_FALSE(event_has_arg1.Evaluate(other)); + EXPECT_FALSE(event_has_arg2.Evaluate(other)); + EXPECT_FALSE(event_arg1.Evaluate(other)); + EXPECT_FALSE(event_arg2.Evaluate(other)); + EXPECT_FALSE(event_has_other.Evaluate(other)); +} + +TEST_F(TraceEventAnalyzerTest, BooleanOperators) { + using namespace trace_analyzer; + ManualSetUp(); + + BeginTracing(); + { + TRACE_EVENT_INSTANT1("cat1", "name1", "num", 1); + TRACE_EVENT_INSTANT1("cat1", "name2", "num", 2); + TRACE_EVENT_INSTANT1("cat2", "name3", "num", 3); + TRACE_EVENT_INSTANT1("cat2", "name4", "num", 4); + } + EndTracing(); + + scoped_ptr<TraceAnalyzer> + analyzer(TraceAnalyzer::Create(output_.json_output)); + ASSERT_TRUE(!!analyzer.get()); + + TraceAnalyzer::TraceEventVector found; + + // == + + analyzer->FindEvents(Query(EVENT_CATEGORY) == Query::String("cat1"), &found); + ASSERT_EQ(2u, found.size()); + EXPECT_STREQ("name1", found[0]->name.c_str()); + EXPECT_STREQ("name2", found[1]->name.c_str()); + + analyzer->FindEvents(Query(EVENT_ARG, "num") == Query::Int(2), &found); + ASSERT_EQ(1u, found.size()); + EXPECT_STREQ("name2", found[0]->name.c_str()); + + // != + + analyzer->FindEvents(Query(EVENT_CATEGORY) != Query::String("cat1"), &found); + ASSERT_EQ(2u, found.size()); + EXPECT_STREQ("name3", found[0]->name.c_str()); + EXPECT_STREQ("name4", found[1]->name.c_str()); + + analyzer->FindEvents(Query(EVENT_ARG, "num") != Query::Int(2), &found); + ASSERT_EQ(3u, found.size()); + EXPECT_STREQ("name1", found[0]->name.c_str()); + EXPECT_STREQ("name3", found[1]->name.c_str()); + EXPECT_STREQ("name4", found[2]->name.c_str()); + + // < + analyzer->FindEvents(Query(EVENT_ARG, "num") < Query::Int(2), &found); + ASSERT_EQ(1u, found.size()); + EXPECT_STREQ("name1", found[0]->name.c_str()); + + // <= + analyzer->FindEvents(Query(EVENT_ARG, "num") <= Query::Int(2), &found); + ASSERT_EQ(2u, found.size()); + EXPECT_STREQ("name1", found[0]->name.c_str()); + EXPECT_STREQ("name2", found[1]->name.c_str()); + + // > + analyzer->FindEvents(Query(EVENT_ARG, "num") > Query::Int(3), &found); + ASSERT_EQ(1u, found.size()); + EXPECT_STREQ("name4", found[0]->name.c_str()); + + // >= + analyzer->FindEvents(Query(EVENT_ARG, "num") >= Query::Int(4), &found); + ASSERT_EQ(1u, found.size()); + EXPECT_STREQ("name4", found[0]->name.c_str()); + + // && + analyzer->FindEvents(Query(EVENT_NAME) != Query::String("name1") && + Query(EVENT_ARG, "num") < Query::Int(3), &found); + ASSERT_EQ(1u, found.size()); + EXPECT_STREQ("name2", found[0]->name.c_str()); + + // || + analyzer->FindEvents(Query(EVENT_NAME) == Query::String("name1") || + Query(EVENT_ARG, "num") == Query::Int(3), &found); + ASSERT_EQ(2u, found.size()); + EXPECT_STREQ("name1", found[0]->name.c_str()); + EXPECT_STREQ("name3", found[1]->name.c_str()); + + // ! + analyzer->FindEvents(!(Query(EVENT_NAME) == Query::String("name1") || + Query(EVENT_ARG, "num") == Query::Int(3)), &found); + ASSERT_EQ(2u, found.size()); + EXPECT_STREQ("name2", found[0]->name.c_str()); + EXPECT_STREQ("name4", found[1]->name.c_str()); +} + +TEST_F(TraceEventAnalyzerTest, ArithmeticOperators) { + using namespace trace_analyzer; + ManualSetUp(); + + BeginTracing(); + { + // These events are searched for: + TRACE_EVENT_INSTANT2("cat1", "math1", "a", 10, "b", 5); + TRACE_EVENT_INSTANT2("cat1", "math2", "a", 10, "b", 10); + // Extra events that never match, for noise: + TRACE_EVENT_INSTANT2("noise", "math3", "a", 1, "b", 3); + TRACE_EVENT_INSTANT2("noise", "math4", "c", 10, "d", 5); + } + EndTracing(); + + scoped_ptr<TraceAnalyzer> + analyzer(TraceAnalyzer::Create(output_.json_output)); + ASSERT_TRUE(analyzer.get()); + + TraceAnalyzer::TraceEventVector found; + + // Verify that arithmetic operators function: + + // + + analyzer->FindEvents(Query(EVENT_ARG, "a") + Query(EVENT_ARG, "b") == + Query::Int(20), &found); + EXPECT_EQ(1u, found.size()); + EXPECT_STREQ("math2", found.front()->name.c_str()); + + // - + analyzer->FindEvents(Query(EVENT_ARG, "a") - Query(EVENT_ARG, "b") == + Query::Int(5), &found); + EXPECT_EQ(1u, found.size()); + EXPECT_STREQ("math1", found.front()->name.c_str()); + + // * + analyzer->FindEvents(Query(EVENT_ARG, "a") * Query(EVENT_ARG, "b") == + Query::Int(50), &found); + EXPECT_EQ(1u, found.size()); + EXPECT_STREQ("math1", found.front()->name.c_str()); + + // / + analyzer->FindEvents(Query(EVENT_ARG, "a") / Query(EVENT_ARG, "b") == + Query::Int(2), &found); + EXPECT_EQ(1u, found.size()); + EXPECT_STREQ("math1", found.front()->name.c_str()); + + // % + analyzer->FindEvents(Query(EVENT_ARG, "a") % Query(EVENT_ARG, "b") == + Query::Int(0), &found); + EXPECT_EQ(2u, found.size()); + + // - (negate) + analyzer->FindEvents(-Query(EVENT_ARG, "b") == Query::Int(-10), &found); + EXPECT_EQ(1u, found.size()); + EXPECT_STREQ("math2", found.front()->name.c_str()); +} + +TEST_F(TraceEventAnalyzerTest, StringPattern) { + using namespace trace_analyzer; + ManualSetUp(); + + BeginTracing(); + { + TRACE_EVENT_INSTANT0("cat1", "name1"); + TRACE_EVENT_INSTANT0("cat1", "name2"); + TRACE_EVENT_INSTANT0("cat1", "no match"); + TRACE_EVENT_INSTANT0("cat1", "name3x"); + } + EndTracing(); + + scoped_ptr<TraceAnalyzer> + analyzer(TraceAnalyzer::Create(output_.json_output)); + ASSERT_TRUE(analyzer.get()); + + TraceAnalyzer::TraceEventVector found; + + analyzer->FindEvents(Query(EVENT_NAME) == Query::Pattern("name?"), &found); + ASSERT_EQ(2u, found.size()); + EXPECT_STREQ("name1", found[0]->name.c_str()); + EXPECT_STREQ("name2", found[1]->name.c_str()); + + analyzer->FindEvents(Query(EVENT_NAME) == Query::Pattern("name*"), &found); + ASSERT_EQ(3u, found.size()); + EXPECT_STREQ("name1", found[0]->name.c_str()); + EXPECT_STREQ("name2", found[1]->name.c_str()); + EXPECT_STREQ("name3x", found[2]->name.c_str()); + + analyzer->FindEvents(Query(EVENT_NAME) != Query::Pattern("name*"), &found); + ASSERT_EQ(1u, found.size()); + EXPECT_STREQ("no match", found[0]->name.c_str()); +} + +// Test that duration queries work. +TEST_F(TraceEventAnalyzerTest, Duration) { + using namespace trace_analyzer; + ManualSetUp(); + + int sleep_time_us = 200000; + // We will search for events that have a duration of greater than 90% of the + // sleep time, so that there is no flakiness. + int duration_cutoff_us = (sleep_time_us * 9) / 10; + + BeginTracing(); + { + TRACE_EVENT0("cat1", "name1"); // found by duration query + TRACE_EVENT0("noise", "name2"); // not searched for, just noise + { + TRACE_EVENT0("cat2", "name3"); // found by duration query + TRACE_EVENT_INSTANT0("noise", "name4"); // not searched for, just noise + base::PlatformThread::Sleep(sleep_time_us / 1000); + TRACE_EVENT0("cat2", "name5"); // not found (duration too short) + } + } + EndTracing(); + + scoped_ptr<TraceAnalyzer> + analyzer(TraceAnalyzer::Create(output_.json_output)); + ASSERT_TRUE(analyzer.get()); + analyzer->AssociateBeginEndEvents(); + + TraceAnalyzer::TraceEventVector found; + analyzer->FindEvents(Query::MatchBeginWithEnd() && + Query(EVENT_DURATION) > Query::Int(duration_cutoff_us) && + (Query(EVENT_CATEGORY) == Query::String("cat1") || + Query(EVENT_CATEGORY) == Query::String("cat2") || + Query(EVENT_CATEGORY) == Query::String("cat3")), &found); + ASSERT_EQ(2u, found.size()); + EXPECT_STREQ("name1", found[0]->name.c_str()); + EXPECT_STREQ("name3", found[1]->name.c_str()); +} + +// Test that arithmetic operators work. +TEST_F(TraceEventAnalyzerTest, BeginEndAssocations) { + using namespace trace_analyzer; + ManualSetUp(); + + BeginTracing(); + { + TRACE_EVENT_END0("cat1", "name1"); // does not match out of order begin + TRACE_EVENT0("cat1", "name2"); + TRACE_EVENT_INSTANT0("cat1", "name3"); + TRACE_EVENT_BEGIN0("cat1", "name1"); + } + EndTracing(); + + scoped_ptr<TraceAnalyzer> + analyzer(TraceAnalyzer::Create(output_.json_output)); + ASSERT_TRUE(analyzer.get()); + analyzer->AssociateBeginEndEvents(); + + TraceAnalyzer::TraceEventVector found; + analyzer->FindEvents(Query::MatchBeginWithEnd(), &found); + ASSERT_EQ(1u, found.size()); + EXPECT_STREQ("name2", found[0]->name.c_str()); +} + +// Test that the TraceAnalyzer custom associations work. +TEST_F(TraceEventAnalyzerTest, CustomAssociations) { + using namespace trace_analyzer; + ManualSetUp(); + + // Add events that begin/end in pipelined ordering with unique ID parameter + // to match up the begin/end pairs. + BeginTracing(); + { + TRACE_EVENT_INSTANT1("cat1", "end", "id", 1); // no begin match + TRACE_EVENT_INSTANT1("cat2", "begin", "id", 2); // end is cat4 + TRACE_EVENT_INSTANT1("cat3", "begin", "id", 3); // end is cat5 + TRACE_EVENT_INSTANT1("cat4", "end", "id", 2); + TRACE_EVENT_INSTANT1("cat5", "end", "id", 3); + TRACE_EVENT_INSTANT1("cat6", "begin", "id", 1); // no end match + } + EndTracing(); + + scoped_ptr<TraceAnalyzer> + analyzer(TraceAnalyzer::Create(output_.json_output)); + ASSERT_TRUE(analyzer.get()); + + // begin, end, and match queries to find proper begin/end pairs. + Query begin(Query(EVENT_NAME) == Query::String("begin")); + Query end(Query(EVENT_NAME) == Query::String("end")); + Query match(Query(EVENT_ARG, "id") == Query(OTHER_ARG, "id")); + analyzer->AssociateEvents(begin, end, match); + + TraceAnalyzer::TraceEventVector found; + + // cat1 has no other_event. + analyzer->FindEvents(Query(EVENT_CATEGORY) == Query::String("cat1") && + Query(EVENT_HAS_OTHER), &found); + EXPECT_EQ(0u, found.size()); + + // cat1 has no other_event. + analyzer->FindEvents(Query(EVENT_CATEGORY) == Query::String("cat1") && + !Query(EVENT_HAS_OTHER), &found); + EXPECT_EQ(1u, found.size()); + + // cat6 has no other_event. + analyzer->FindEvents(Query(EVENT_CATEGORY) == Query::String("cat6") && + !Query(EVENT_HAS_OTHER), &found); + EXPECT_EQ(1u, found.size()); + + // cat2 and cat4 are a associated. + analyzer->FindEvents(Query(EVENT_CATEGORY) == Query::String("cat2") && + Query(OTHER_CATEGORY) == Query::String("cat4"), &found); + EXPECT_EQ(1u, found.size()); + + // cat4 and cat2 are a associated. + analyzer->FindEvents(Query(EVENT_CATEGORY) == Query::String("cat4") && + Query(OTHER_CATEGORY) == Query::String("cat2"), &found); + EXPECT_EQ(1u, found.size()); + + // cat3 and cat5 are a associated. + analyzer->FindEvents(Query(EVENT_CATEGORY) == Query::String("cat3") && + Query(OTHER_CATEGORY) == Query::String("cat5"), &found); + EXPECT_EQ(1u, found.size()); + + // cat5 and cat3 are a associated. + analyzer->FindEvents(Query(EVENT_CATEGORY) == Query::String("cat5") && + Query(OTHER_CATEGORY) == Query::String("cat3"), &found); + EXPECT_EQ(1u, found.size()); +} + +// Verify that Query literals and types are properly casted. +TEST_F(TraceEventAnalyzerTest, Literals) { + using namespace trace_analyzer; + ManualSetUp(); + + // Since these queries don't refer to the event data, the dummy event below + // will never be accessed. + TraceEvent dummy; + char char_num = 5; + short short_num = -5; + EXPECT_TRUE((Query::Double(5.0) == Query::Int(char_num)).Evaluate(dummy)); + EXPECT_TRUE((Query::Double(-5.0) == Query::Int(short_num)).Evaluate(dummy)); + EXPECT_TRUE((Query::Double(1.0) == Query::Uint(1u)).Evaluate(dummy)); + EXPECT_TRUE((Query::Double(1.0) == Query::Int(1)).Evaluate(dummy)); + EXPECT_TRUE((Query::Double(-1.0) == Query::Int(-1)).Evaluate(dummy)); + EXPECT_TRUE((Query::Double(1.0) == Query::Double(1.0f)).Evaluate(dummy)); + EXPECT_TRUE((Query::Bool(true) == Query::Int(1)).Evaluate(dummy)); + EXPECT_TRUE((Query::Bool(false) == Query::Int(0)).Evaluate(dummy)); + EXPECT_TRUE((Query::Bool(true) == Query::Double(1.0f)).Evaluate(dummy)); + EXPECT_TRUE((Query::Bool(false) == Query::Double(0.0f)).Evaluate(dummy)); +} + + +} // namespace trace_analyzer + |