1 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
2 // Use of this source code is governed by a BSD-style license that can be
3 // found in the LICENSE file.
5 #include "base/test/trace_event_analyzer.h"
11 #include "base/json/json_reader.h"
12 #include "base/memory/scoped_ptr.h"
13 #include "base/values.h"
15 namespace trace_analyzer {
19 TraceEvent::TraceEvent()
23 phase(TRACE_EVENT_PHASE_BEGIN),
27 TraceEvent::~TraceEvent() {
30 bool TraceEvent::SetFromJSON(const base::Value* event_value) {
31 if (event_value->GetType() != base::Value::TYPE_DICTIONARY) {
32 LOG(ERROR) << "Value must be TYPE_DICTIONARY";
35 const base::DictionaryValue* dictionary =
36 static_cast<const base::DictionaryValue*>(event_value);
38 std::string phase_str;
39 const base::DictionaryValue* args = NULL;
41 if (!dictionary->GetString("ph", &phase_str)) {
42 LOG(ERROR) << "ph is missing from TraceEvent JSON";
46 phase = *phase_str.data();
48 bool may_have_duration = (phase == TRACE_EVENT_PHASE_COMPLETE);
49 bool require_origin = (phase != TRACE_EVENT_PHASE_METADATA);
50 bool require_id = (phase == TRACE_EVENT_PHASE_ASYNC_BEGIN ||
51 phase == TRACE_EVENT_PHASE_ASYNC_STEP_INTO ||
52 phase == TRACE_EVENT_PHASE_ASYNC_STEP_PAST ||
53 phase == TRACE_EVENT_PHASE_ASYNC_END);
55 if (require_origin && !dictionary->GetInteger("pid", &thread.process_id)) {
56 LOG(ERROR) << "pid is missing from TraceEvent JSON";
59 if (require_origin && !dictionary->GetInteger("tid", &thread.thread_id)) {
60 LOG(ERROR) << "tid is missing from TraceEvent JSON";
63 if (require_origin && !dictionary->GetDouble("ts", ×tamp)) {
64 LOG(ERROR) << "ts is missing from TraceEvent JSON";
67 if (may_have_duration) {
68 dictionary->GetDouble("dur", &duration);
70 if (!dictionary->GetString("cat", &category)) {
71 LOG(ERROR) << "cat is missing from TraceEvent JSON";
74 if (!dictionary->GetString("name", &name)) {
75 LOG(ERROR) << "name is missing from TraceEvent JSON";
78 if (!dictionary->GetDictionary("args", &args)) {
79 LOG(ERROR) << "args is missing from TraceEvent JSON";
82 if (require_id && !dictionary->GetString("id", &id)) {
83 LOG(ERROR) << "id is missing from ASYNC_BEGIN/ASYNC_END TraceEvent JSON";
87 // For each argument, copy the type and create a trace_analyzer::TraceValue.
88 for (base::DictionaryValue::Iterator it(*args); !it.IsAtEnd();
93 double double_num = 0.0;
94 if (it.value().GetAsString(&str)) {
95 arg_strings[it.key()] = str;
96 } else if (it.value().GetAsInteger(&int_num)) {
97 arg_numbers[it.key()] = static_cast<double>(int_num);
98 } else if (it.value().GetAsBoolean(&boolean)) {
99 arg_numbers[it.key()] = static_cast<double>(boolean ? 1 : 0);
100 } else if (it.value().GetAsDouble(&double_num)) {
101 arg_numbers[it.key()] = double_num;
103 LOG(WARNING) << "Value type of argument is not supported: " <<
104 static_cast<int>(it.value().GetType());
105 continue; // Skip non-supported arguments.
112 double TraceEvent::GetAbsTimeToOtherEvent() const {
113 return fabs(other_event->timestamp - timestamp);
116 bool TraceEvent::GetArgAsString(const std::string& name,
117 std::string* arg) const {
118 std::map<std::string, std::string>::const_iterator i = arg_strings.find(name);
119 if (i != arg_strings.end()) {
126 bool TraceEvent::GetArgAsNumber(const std::string& name,
128 std::map<std::string, double>::const_iterator i = arg_numbers.find(name);
129 if (i != arg_numbers.end()) {
136 bool TraceEvent::HasStringArg(const std::string& name) const {
137 return (arg_strings.find(name) != arg_strings.end());
140 bool TraceEvent::HasNumberArg(const std::string& name) const {
141 return (arg_numbers.find(name) != arg_numbers.end());
144 std::string TraceEvent::GetKnownArgAsString(const std::string& name) const {
145 std::string arg_string;
146 bool result = GetArgAsString(name, &arg_string);
151 double TraceEvent::GetKnownArgAsDouble(const std::string& name) const {
152 double arg_double = 0;
153 bool result = GetArgAsNumber(name, &arg_double);
158 int TraceEvent::GetKnownArgAsInt(const std::string& name) const {
159 double arg_double = 0;
160 bool result = GetArgAsNumber(name, &arg_double);
162 return static_cast<int>(arg_double);
165 bool TraceEvent::GetKnownArgAsBool(const std::string& name) const {
166 double arg_double = 0;
167 bool result = GetArgAsNumber(name, &arg_double);
169 return (arg_double != 0.0);
174 QueryNode::QueryNode(const Query& query) : query_(query) {
177 QueryNode::~QueryNode() {
182 Query::Query(TraceEventMember member)
183 : type_(QUERY_EVENT_MEMBER),
184 operator_(OP_INVALID),
190 Query::Query(TraceEventMember member, const std::string& arg_name)
191 : type_(QUERY_EVENT_MEMBER),
192 operator_(OP_INVALID),
199 Query::Query(const Query& query)
200 : type_(query.type_),
201 operator_(query.operator_),
203 right_(query.right_),
204 member_(query.member_),
205 number_(query.number_),
206 string_(query.string_),
207 is_pattern_(query.is_pattern_) {
213 Query Query::String(const std::string& str) {
217 Query Query::Double(double num) {
221 Query Query::Int(int32 num) {
222 return Query(static_cast<double>(num));
225 Query Query::Uint(uint32 num) {
226 return Query(static_cast<double>(num));
229 Query Query::Bool(bool boolean) {
230 return Query(boolean ? 1.0 : 0.0);
233 Query Query::Phase(char phase) {
234 return Query(static_cast<double>(phase));
237 Query Query::Pattern(const std::string& pattern) {
238 Query query(pattern);
239 query.is_pattern_ = true;
243 bool Query::Evaluate(const TraceEvent& event) const {
244 // First check for values that can convert to bool.
246 // double is true if != 0:
247 double bool_value = 0.0;
248 bool is_bool = GetAsDouble(event, &bool_value);
250 return (bool_value != 0.0);
252 // string is true if it is non-empty:
253 std::string str_value;
254 bool is_str = GetAsString(event, &str_value);
256 return !str_value.empty();
258 DCHECK_EQ(QUERY_BOOLEAN_OPERATOR, type_)
259 << "Invalid query: missing boolean expression";
261 DCHECK(right_.get() || is_unary_operator());
263 if (is_comparison_operator()) {
264 DCHECK(left().is_value() && right().is_value())
265 << "Invalid query: comparison operator used between event member and "
267 bool compare_result = false;
268 if (CompareAsDouble(event, &compare_result))
269 return compare_result;
270 if (CompareAsString(event, &compare_result))
271 return compare_result;
274 // It's a logical operator.
277 return left().Evaluate(event) && right().Evaluate(event);
279 return left().Evaluate(event) || right().Evaluate(event);
281 return !left().Evaluate(event);
288 bool Query::CompareAsDouble(const TraceEvent& event, bool* result) const {
290 if (!left().GetAsDouble(event, &lhs) || !right().GetAsDouble(event, &rhs))
294 *result = (lhs == rhs);
297 *result = (lhs != rhs);
300 *result = (lhs < rhs);
303 *result = (lhs <= rhs);
306 *result = (lhs > rhs);
309 *result = (lhs >= rhs);
317 bool Query::CompareAsString(const TraceEvent& event, bool* result) const {
318 std::string lhs, rhs;
319 if (!left().GetAsString(event, &lhs) || !right().GetAsString(event, &rhs))
323 if (right().is_pattern_)
324 *result = MatchPattern(lhs, rhs);
325 else if (left().is_pattern_)
326 *result = MatchPattern(rhs, lhs);
328 *result = (lhs == rhs);
331 if (right().is_pattern_)
332 *result = !MatchPattern(lhs, rhs);
333 else if (left().is_pattern_)
334 *result = !MatchPattern(rhs, lhs);
336 *result = (lhs != rhs);
339 *result = (lhs < rhs);
342 *result = (lhs <= rhs);
345 *result = (lhs > rhs);
348 *result = (lhs >= rhs);
356 bool Query::EvaluateArithmeticOperator(const TraceEvent& event,
358 DCHECK_EQ(QUERY_ARITHMETIC_OPERATOR, type_);
360 DCHECK(right_.get() || is_unary_operator());
362 double lhs = 0, rhs = 0;
363 if (!left().GetAsDouble(event, &lhs))
365 if (!is_unary_operator() && !right().GetAsDouble(event, &rhs))
382 *num = static_cast<double>(static_cast<int64>(lhs) %
383 static_cast<int64>(rhs));
394 bool Query::GetAsDouble(const TraceEvent& event, double* num) const {
396 case QUERY_ARITHMETIC_OPERATOR:
397 return EvaluateArithmeticOperator(event, num);
398 case QUERY_EVENT_MEMBER:
399 return GetMemberValueAsDouble(event, num);
408 bool Query::GetAsString(const TraceEvent& event, std::string* str) const {
410 case QUERY_EVENT_MEMBER:
411 return GetMemberValueAsString(event, str);
420 bool Query::GetMemberValueAsDouble(const TraceEvent& event,
422 DCHECK_EQ(QUERY_EVENT_MEMBER, type_);
424 // This could be a request for a member of |event| or a member of |event|'s
425 // associated event. Store the target event in the_event:
426 const TraceEvent* the_event = (member_ < OTHER_PID) ?
427 &event : event.other_event;
429 // Request for member of associated event, but there is no associated event.
436 *num = static_cast<double>(the_event->thread.process_id);
440 *num = static_cast<double>(the_event->thread.thread_id);
444 *num = the_event->timestamp;
447 if (!the_event->has_other_event())
449 *num = the_event->GetAbsTimeToOtherEvent();
451 case EVENT_COMPLETE_DURATION:
452 if (the_event->phase != TRACE_EVENT_PHASE_COMPLETE)
454 *num = the_event->duration;
458 *num = static_cast<double>(the_event->phase);
460 case EVENT_HAS_STRING_ARG:
461 case OTHER_HAS_STRING_ARG:
462 *num = (the_event->HasStringArg(string_) ? 1.0 : 0.0);
464 case EVENT_HAS_NUMBER_ARG:
465 case OTHER_HAS_NUMBER_ARG:
466 *num = (the_event->HasNumberArg(string_) ? 1.0 : 0.0);
470 // Search for the argument name and return its value if found.
471 std::map<std::string, double>::const_iterator num_i =
472 the_event->arg_numbers.find(string_);
473 if (num_i == the_event->arg_numbers.end())
475 *num = num_i->second;
478 case EVENT_HAS_OTHER:
479 // return 1.0 (true) if the other event exists
480 *num = event.other_event ? 1.0 : 0.0;
487 bool Query::GetMemberValueAsString(const TraceEvent& event,
488 std::string* str) const {
489 DCHECK_EQ(QUERY_EVENT_MEMBER, type_);
491 // This could be a request for a member of |event| or a member of |event|'s
492 // associated event. Store the target event in the_event:
493 const TraceEvent* the_event = (member_ < OTHER_PID) ?
494 &event : event.other_event;
496 // Request for member of associated event, but there is no associated event.
503 *str = the_event->category;
507 *str = the_event->name;
511 *str = the_event->id;
515 // Search for the argument name and return its value if found.
516 std::map<std::string, std::string>::const_iterator str_i =
517 the_event->arg_strings.find(string_);
518 if (str_i == the_event->arg_strings.end())
520 *str = str_i->second;
528 Query::Query(const std::string& str)
529 : type_(QUERY_STRING),
530 operator_(OP_INVALID),
531 member_(EVENT_INVALID),
537 Query::Query(double num)
538 : type_(QUERY_NUMBER),
539 operator_(OP_INVALID),
540 member_(EVENT_INVALID),
544 const Query& Query::left() const {
545 return left_->query();
548 const Query& Query::right() const {
549 return right_->query();
552 Query Query::operator==(const Query& rhs) const {
553 return Query(*this, rhs, OP_EQ);
556 Query Query::operator!=(const Query& rhs) const {
557 return Query(*this, rhs, OP_NE);
560 Query Query::operator<(const Query& rhs) const {
561 return Query(*this, rhs, OP_LT);
564 Query Query::operator<=(const Query& rhs) const {
565 return Query(*this, rhs, OP_LE);
568 Query Query::operator>(const Query& rhs) const {
569 return Query(*this, rhs, OP_GT);
572 Query Query::operator>=(const Query& rhs) const {
573 return Query(*this, rhs, OP_GE);
576 Query Query::operator&&(const Query& rhs) const {
577 return Query(*this, rhs, OP_AND);
580 Query Query::operator||(const Query& rhs) const {
581 return Query(*this, rhs, OP_OR);
584 Query Query::operator!() const {
585 return Query(*this, OP_NOT);
588 Query Query::operator+(const Query& rhs) const {
589 return Query(*this, rhs, OP_ADD);
592 Query Query::operator-(const Query& rhs) const {
593 return Query(*this, rhs, OP_SUB);
596 Query Query::operator*(const Query& rhs) const {
597 return Query(*this, rhs, OP_MUL);
600 Query Query::operator/(const Query& rhs) const {
601 return Query(*this, rhs, OP_DIV);
604 Query Query::operator%(const Query& rhs) const {
605 return Query(*this, rhs, OP_MOD);
608 Query Query::operator-() const {
609 return Query(*this, OP_NEGATE);
613 Query::Query(const Query& left, const Query& right, Operator binary_op)
614 : operator_(binary_op),
615 left_(new QueryNode(left)),
616 right_(new QueryNode(right)),
617 member_(EVENT_INVALID),
619 type_ = (binary_op < OP_ADD ?
620 QUERY_BOOLEAN_OPERATOR : QUERY_ARITHMETIC_OPERATOR);
623 Query::Query(const Query& left, Operator unary_op)
624 : operator_(unary_op),
625 left_(new QueryNode(left)),
626 member_(EVENT_INVALID),
628 type_ = (unary_op < OP_ADD ?
629 QUERY_BOOLEAN_OPERATOR : QUERY_ARITHMETIC_OPERATOR);
634 // Search |events| for |query| and add matches to |output|.
635 size_t FindMatchingEvents(const std::vector<TraceEvent>& events,
637 TraceEventVector* output,
638 bool ignore_metadata_events) {
639 for (size_t i = 0; i < events.size(); ++i) {
640 if (ignore_metadata_events && events[i].phase == TRACE_EVENT_PHASE_METADATA)
642 if (query.Evaluate(events[i]))
643 output->push_back(&events[i]);
645 return output->size();
648 bool ParseEventsFromJson(const std::string& json,
649 std::vector<TraceEvent>* output) {
650 scoped_ptr<base::Value> root;
651 root.reset(base::JSONReader::Read(json));
653 base::ListValue* root_list = NULL;
654 if (!root.get() || !root->GetAsList(&root_list))
657 for (size_t i = 0; i < root_list->GetSize(); ++i) {
658 base::Value* item = NULL;
659 if (root_list->Get(i, &item)) {
661 if (event.SetFromJSON(item))
662 output->push_back(event);
675 TraceAnalyzer::TraceAnalyzer()
676 : ignore_metadata_events_(false),
677 allow_assocation_changes_(true) {}
679 TraceAnalyzer::~TraceAnalyzer() {
683 TraceAnalyzer* TraceAnalyzer::Create(const std::string& json_events) {
684 scoped_ptr<TraceAnalyzer> analyzer(new TraceAnalyzer());
685 if (analyzer->SetEvents(json_events))
686 return analyzer.release();
690 bool TraceAnalyzer::SetEvents(const std::string& json_events) {
692 if (!ParseEventsFromJson(json_events, &raw_events_))
694 std::stable_sort(raw_events_.begin(), raw_events_.end());
699 void TraceAnalyzer::AssociateBeginEndEvents() {
700 using trace_analyzer::Query;
702 Query begin(Query::EventPhaseIs(TRACE_EVENT_PHASE_BEGIN));
703 Query end(Query::EventPhaseIs(TRACE_EVENT_PHASE_END));
704 Query match(Query::EventName() == Query::OtherName() &&
705 Query::EventCategory() == Query::OtherCategory() &&
706 Query::EventTid() == Query::OtherTid() &&
707 Query::EventPid() == Query::OtherPid());
709 AssociateEvents(begin, end, match);
712 void TraceAnalyzer::AssociateAsyncBeginEndEvents() {
713 using trace_analyzer::Query;
716 Query::EventPhaseIs(TRACE_EVENT_PHASE_ASYNC_BEGIN) ||
717 Query::EventPhaseIs(TRACE_EVENT_PHASE_ASYNC_STEP_INTO) ||
718 Query::EventPhaseIs(TRACE_EVENT_PHASE_ASYNC_STEP_PAST));
719 Query end(Query::EventPhaseIs(TRACE_EVENT_PHASE_ASYNC_END) ||
720 Query::EventPhaseIs(TRACE_EVENT_PHASE_ASYNC_STEP_INTO) ||
721 Query::EventPhaseIs(TRACE_EVENT_PHASE_ASYNC_STEP_PAST));
722 Query match(Query::EventName() == Query::OtherName() &&
723 Query::EventCategory() == Query::OtherCategory() &&
724 Query::EventId() == Query::OtherId());
726 AssociateEvents(begin, end, match);
729 void TraceAnalyzer::AssociateEvents(const Query& first,
731 const Query& match) {
732 DCHECK(allow_assocation_changes_)
733 << "AssociateEvents not allowed after FindEvents";
735 // Search for matching begin/end event pairs. When a matching end is found,
736 // it is associated with the begin event.
737 std::vector<TraceEvent*> begin_stack;
738 for (size_t event_index = 0; event_index < raw_events_.size();
741 TraceEvent& this_event = raw_events_[event_index];
743 if (second.Evaluate(this_event)) {
744 // Search stack for matching begin, starting from end.
745 for (int stack_index = static_cast<int>(begin_stack.size()) - 1;
746 stack_index >= 0; --stack_index) {
747 TraceEvent& begin_event = *begin_stack[stack_index];
749 // Temporarily set other to test against the match query.
750 const TraceEvent* other_backup = begin_event.other_event;
751 begin_event.other_event = &this_event;
752 if (match.Evaluate(begin_event)) {
753 // Found a matching begin/end pair.
754 // Erase the matching begin event index from the stack.
755 begin_stack.erase(begin_stack.begin() + stack_index);
759 // Not a match, restore original other and continue.
760 begin_event.other_event = other_backup;
763 // Even if this_event is a |second| event that has matched an earlier
764 // |first| event, it can still also be a |first| event and be associated
765 // with a later |second| event.
766 if (first.Evaluate(this_event)) {
767 begin_stack.push_back(&this_event);
772 void TraceAnalyzer::MergeAssociatedEventArgs() {
773 for (size_t i = 0; i < raw_events_.size(); ++i) {
774 // Merge all associated events with the first event.
775 const TraceEvent* other = raw_events_[i].other_event;
776 // Avoid looping by keeping set of encountered TraceEvents.
777 std::set<const TraceEvent*> encounters;
778 encounters.insert(&raw_events_[i]);
779 while (other && encounters.find(other) == encounters.end()) {
780 encounters.insert(other);
781 raw_events_[i].arg_numbers.insert(
782 other->arg_numbers.begin(),
783 other->arg_numbers.end());
784 raw_events_[i].arg_strings.insert(
785 other->arg_strings.begin(),
786 other->arg_strings.end());
787 other = other->other_event;
792 size_t TraceAnalyzer::FindEvents(const Query& query, TraceEventVector* output) {
793 allow_assocation_changes_ = false;
795 return FindMatchingEvents(
796 raw_events_, query, output, ignore_metadata_events_);
799 const TraceEvent* TraceAnalyzer::FindFirstOf(const Query& query) {
800 TraceEventVector output;
801 if (FindEvents(query, &output) > 0)
802 return output.front();
806 const TraceEvent* TraceAnalyzer::FindLastOf(const Query& query) {
807 TraceEventVector output;
808 if (FindEvents(query, &output) > 0)
809 return output.back();
813 const std::string& TraceAnalyzer::GetThreadName(
814 const TraceEvent::ProcessThreadID& thread) {
815 // If thread is not found, just add and return empty string.
816 return thread_names_[thread];
819 void TraceAnalyzer::ParseMetadata() {
820 for (size_t i = 0; i < raw_events_.size(); ++i) {
821 TraceEvent& this_event = raw_events_[i];
822 // Check for thread name metadata.
823 if (this_event.phase != TRACE_EVENT_PHASE_METADATA ||
824 this_event.name != "thread_name")
826 std::map<std::string, std::string>::const_iterator string_it =
827 this_event.arg_strings.find("name");
828 if (string_it != this_event.arg_strings.end())
829 thread_names_[this_event.thread] = string_it->second;
833 // TraceEventVector utility functions.
835 bool GetRateStats(const TraceEventVector& events,
837 const RateStatsOptions* options) {
839 // Need at least 3 events to calculate rate stats.
840 const size_t kMinEvents = 3;
841 if (events.size() < kMinEvents) {
842 LOG(ERROR) << "Not enough events: " << events.size();
846 std::vector<double> deltas;
847 size_t num_deltas = events.size() - 1;
848 for (size_t i = 0; i < num_deltas; ++i) {
849 double delta = events.at(i + 1)->timestamp - events.at(i)->timestamp;
851 LOG(ERROR) << "Events are out of order";
854 deltas.push_back(delta);
857 std::sort(deltas.begin(), deltas.end());
860 if (options->trim_min + options->trim_max > events.size() - kMinEvents) {
861 LOG(ERROR) << "Attempt to trim too many events";
864 deltas.erase(deltas.begin(), deltas.begin() + options->trim_min);
865 deltas.erase(deltas.end() - options->trim_max, deltas.end());
868 num_deltas = deltas.size();
869 double delta_sum = 0.0;
870 for (size_t i = 0; i < num_deltas; ++i)
871 delta_sum += deltas[i];
873 stats->min_us = *std::min_element(deltas.begin(), deltas.end());
874 stats->max_us = *std::max_element(deltas.begin(), deltas.end());
875 stats->mean_us = delta_sum / static_cast<double>(num_deltas);
877 double sum_mean_offsets_squared = 0.0;
878 for (size_t i = 0; i < num_deltas; ++i) {
879 double offset = fabs(deltas[i] - stats->mean_us);
880 sum_mean_offsets_squared += offset * offset;
882 stats->standard_deviation_us =
883 sqrt(sum_mean_offsets_squared / static_cast<double>(num_deltas - 1));
888 bool FindFirstOf(const TraceEventVector& events,
891 size_t* return_index) {
892 DCHECK(return_index);
893 for (size_t i = position; i < events.size(); ++i) {
894 if (query.Evaluate(*events[i])) {
902 bool FindLastOf(const TraceEventVector& events,
905 size_t* return_index) {
906 DCHECK(return_index);
907 for (size_t i = std::min(position + 1, events.size()); i != 0; --i) {
908 if (query.Evaluate(*events[i - 1])) {
909 *return_index = i - 1;
916 bool FindClosest(const TraceEventVector& events,
919 size_t* return_closest,
920 size_t* return_second_closest) {
921 DCHECK(return_closest);
922 if (events.empty() || position >= events.size())
924 size_t closest = events.size();
925 size_t second_closest = events.size();
926 for (size_t i = 0; i < events.size(); ++i) {
927 if (!query.Evaluate(*events.at(i)))
929 if (closest == events.size()) {
933 if (fabs(events.at(i)->timestamp - events.at(position)->timestamp) <
934 fabs(events.at(closest)->timestamp - events.at(position)->timestamp)) {
935 second_closest = closest;
937 } else if (second_closest == events.size()) {
942 if (closest < events.size() &&
943 (!return_second_closest || second_closest < events.size())) {
944 *return_closest = closest;
945 if (return_second_closest)
946 *return_second_closest = second_closest;
953 size_t CountMatches(const TraceEventVector& events,
955 size_t begin_position,
956 size_t end_position) {
957 if (begin_position >= events.size())
959 end_position = (end_position < events.size()) ? end_position : events.size();
961 for (size_t i = begin_position; i < end_position; ++i) {
962 if (query.Evaluate(*events.at(i)))
968 } // namespace trace_analyzer