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 if (GetArgAsString(name, &arg_string))
149 return std::string();
152 double TraceEvent::GetKnownArgAsDouble(const std::string& name) const {
154 if (GetArgAsNumber(name, &arg_double))
160 int TraceEvent::GetKnownArgAsInt(const std::string& name) const {
162 if (GetArgAsNumber(name, &arg_double))
163 return static_cast<int>(arg_double);
168 bool TraceEvent::GetKnownArgAsBool(const std::string& name) const {
170 if (GetArgAsNumber(name, &arg_double))
171 return (arg_double != 0.0);
178 QueryNode::QueryNode(const Query& query) : query_(query) {
181 QueryNode::~QueryNode() {
186 Query::Query(TraceEventMember member)
187 : type_(QUERY_EVENT_MEMBER),
188 operator_(OP_INVALID),
194 Query::Query(TraceEventMember member, const std::string& arg_name)
195 : type_(QUERY_EVENT_MEMBER),
196 operator_(OP_INVALID),
203 Query::Query(const Query& query)
204 : type_(query.type_),
205 operator_(query.operator_),
207 right_(query.right_),
208 member_(query.member_),
209 number_(query.number_),
210 string_(query.string_),
211 is_pattern_(query.is_pattern_) {
217 Query Query::String(const std::string& str) {
221 Query Query::Double(double num) {
225 Query Query::Int(int32 num) {
226 return Query(static_cast<double>(num));
229 Query Query::Uint(uint32 num) {
230 return Query(static_cast<double>(num));
233 Query Query::Bool(bool boolean) {
234 return Query(boolean ? 1.0 : 0.0);
237 Query Query::Phase(char phase) {
238 return Query(static_cast<double>(phase));
241 Query Query::Pattern(const std::string& pattern) {
242 Query query(pattern);
243 query.is_pattern_ = true;
247 bool Query::Evaluate(const TraceEvent& event) const {
248 // First check for values that can convert to bool.
250 // double is true if != 0:
251 double bool_value = 0.0;
252 bool is_bool = GetAsDouble(event, &bool_value);
254 return (bool_value != 0.0);
256 // string is true if it is non-empty:
257 std::string str_value;
258 bool is_str = GetAsString(event, &str_value);
260 return !str_value.empty();
262 DCHECK(type_ == QUERY_BOOLEAN_OPERATOR)
263 << "Invalid query: missing boolean expression";
264 DCHECK(left_.get() && (right_.get() || is_unary_operator()));
266 if (is_comparison_operator()) {
267 DCHECK(left().is_value() && right().is_value())
268 << "Invalid query: comparison operator used between event member and "
270 bool compare_result = false;
271 if (CompareAsDouble(event, &compare_result))
272 return compare_result;
273 else if (CompareAsString(event, &compare_result))
274 return compare_result;
277 // It's a logical operator.
280 return left().Evaluate(event) && right().Evaluate(event);
282 return left().Evaluate(event) || right().Evaluate(event);
284 return !left().Evaluate(event);
293 bool Query::CompareAsDouble(const TraceEvent& event, bool* result) const {
295 if (!left().GetAsDouble(event, &lhs) || !right().GetAsDouble(event, &rhs))
299 *result = (lhs == rhs);
302 *result = (lhs != rhs);
305 *result = (lhs < rhs);
308 *result = (lhs <= rhs);
311 *result = (lhs > rhs);
314 *result = (lhs >= rhs);
323 bool Query::CompareAsString(const TraceEvent& event, bool* result) const {
324 std::string lhs, rhs;
325 if (!left().GetAsString(event, &lhs) || !right().GetAsString(event, &rhs))
329 if (right().is_pattern_)
330 *result = MatchPattern(lhs, rhs);
331 else if (left().is_pattern_)
332 *result = MatchPattern(rhs, lhs);
334 *result = (lhs == rhs);
337 if (right().is_pattern_)
338 *result = !MatchPattern(lhs, rhs);
339 else if (left().is_pattern_)
340 *result = !MatchPattern(rhs, lhs);
342 *result = (lhs != rhs);
345 *result = (lhs < rhs);
348 *result = (lhs <= rhs);
351 *result = (lhs > rhs);
354 *result = (lhs >= rhs);
363 bool Query::EvaluateArithmeticOperator(const TraceEvent& event,
365 DCHECK(type_ == QUERY_ARITHMETIC_OPERATOR);
366 DCHECK(left_.get() && (right_.get() || is_unary_operator()));
368 double lhs = 0, rhs = 0;
369 if (!left().GetAsDouble(event, &lhs))
371 if (!is_unary_operator() && !right().GetAsDouble(event, &rhs))
388 *num = static_cast<double>(static_cast<int64>(lhs) %
389 static_cast<int64>(rhs));
400 bool Query::GetAsDouble(const TraceEvent& event, double* num) const {
402 case QUERY_ARITHMETIC_OPERATOR:
403 return EvaluateArithmeticOperator(event, num);
404 case QUERY_EVENT_MEMBER:
405 return GetMemberValueAsDouble(event, num);
414 bool Query::GetAsString(const TraceEvent& event, std::string* str) const {
416 case QUERY_EVENT_MEMBER:
417 return GetMemberValueAsString(event, str);
426 bool Query::GetMemberValueAsDouble(const TraceEvent& event,
428 DCHECK(type_ == QUERY_EVENT_MEMBER);
430 // This could be a request for a member of |event| or a member of |event|'s
431 // associated event. Store the target event in the_event:
432 const TraceEvent* the_event = (member_ < OTHER_PID) ?
433 &event : event.other_event;
435 // Request for member of associated event, but there is no associated event.
442 *num = static_cast<double>(the_event->thread.process_id);
446 *num = static_cast<double>(the_event->thread.thread_id);
450 *num = the_event->timestamp;
453 if (the_event->has_other_event()) {
454 *num = the_event->GetAbsTimeToOtherEvent();
458 case EVENT_COMPLETE_DURATION:
459 if (the_event->phase == TRACE_EVENT_PHASE_COMPLETE) {
460 *num = the_event->duration;
466 *num = static_cast<double>(the_event->phase);
468 case EVENT_HAS_STRING_ARG:
469 case OTHER_HAS_STRING_ARG:
470 *num = (the_event->HasStringArg(string_) ? 1.0 : 0.0);
472 case EVENT_HAS_NUMBER_ARG:
473 case OTHER_HAS_NUMBER_ARG:
474 *num = (the_event->HasNumberArg(string_) ? 1.0 : 0.0);
478 // Search for the argument name and return its value if found.
479 std::map<std::string, double>::const_iterator num_i =
480 the_event->arg_numbers.find(string_);
481 if (num_i == the_event->arg_numbers.end())
483 *num = num_i->second;
486 case EVENT_HAS_OTHER:
487 // return 1.0 (true) if the other event exists
488 *num = event.other_event ? 1.0 : 0.0;
495 bool Query::GetMemberValueAsString(const TraceEvent& event,
496 std::string* str) const {
497 DCHECK(type_ == QUERY_EVENT_MEMBER);
499 // This could be a request for a member of |event| or a member of |event|'s
500 // associated event. Store the target event in the_event:
501 const TraceEvent* the_event = (member_ < OTHER_PID) ?
502 &event : event.other_event;
504 // Request for member of associated event, but there is no associated event.
511 *str = the_event->category;
515 *str = the_event->name;
519 *str = the_event->id;
523 // Search for the argument name and return its value if found.
524 std::map<std::string, std::string>::const_iterator str_i =
525 the_event->arg_strings.find(string_);
526 if (str_i == the_event->arg_strings.end())
528 *str = str_i->second;
536 Query::Query(const std::string& str)
537 : type_(QUERY_STRING),
538 operator_(OP_INVALID),
539 member_(EVENT_INVALID),
545 Query::Query(double num)
546 : type_(QUERY_NUMBER),
547 operator_(OP_INVALID),
548 member_(EVENT_INVALID),
552 const Query& Query::left() const {
553 return left_->query();
556 const Query& Query::right() const {
557 return right_->query();
560 Query Query::operator==(const Query& rhs) const {
561 return Query(*this, rhs, OP_EQ);
564 Query Query::operator!=(const Query& rhs) const {
565 return Query(*this, rhs, OP_NE);
568 Query Query::operator<(const Query& rhs) const {
569 return Query(*this, rhs, OP_LT);
572 Query Query::operator<=(const Query& rhs) const {
573 return Query(*this, rhs, OP_LE);
576 Query Query::operator>(const Query& rhs) const {
577 return Query(*this, rhs, OP_GT);
580 Query Query::operator>=(const Query& rhs) const {
581 return Query(*this, rhs, OP_GE);
584 Query Query::operator&&(const Query& rhs) const {
585 return Query(*this, rhs, OP_AND);
588 Query Query::operator||(const Query& rhs) const {
589 return Query(*this, rhs, OP_OR);
592 Query Query::operator!() const {
593 return Query(*this, OP_NOT);
596 Query Query::operator+(const Query& rhs) const {
597 return Query(*this, rhs, OP_ADD);
600 Query Query::operator-(const Query& rhs) const {
601 return Query(*this, rhs, OP_SUB);
604 Query Query::operator*(const Query& rhs) const {
605 return Query(*this, rhs, OP_MUL);
608 Query Query::operator/(const Query& rhs) const {
609 return Query(*this, rhs, OP_DIV);
612 Query Query::operator%(const Query& rhs) const {
613 return Query(*this, rhs, OP_MOD);
616 Query Query::operator-() const {
617 return Query(*this, OP_NEGATE);
621 Query::Query(const Query& left, const Query& right, Operator binary_op)
622 : operator_(binary_op),
623 left_(new QueryNode(left)),
624 right_(new QueryNode(right)),
625 member_(EVENT_INVALID),
627 type_ = (binary_op < OP_ADD ?
628 QUERY_BOOLEAN_OPERATOR : QUERY_ARITHMETIC_OPERATOR);
631 Query::Query(const Query& left, Operator unary_op)
632 : operator_(unary_op),
633 left_(new QueryNode(left)),
634 member_(EVENT_INVALID),
636 type_ = (unary_op < OP_ADD ?
637 QUERY_BOOLEAN_OPERATOR : QUERY_ARITHMETIC_OPERATOR);
642 // Search |events| for |query| and add matches to |output|.
643 size_t FindMatchingEvents(const std::vector<TraceEvent>& events,
645 TraceEventVector* output) {
646 for (size_t i = 0; i < events.size(); ++i) {
647 if (query.Evaluate(events[i]))
648 output->push_back(&events[i]);
650 return output->size();
653 bool ParseEventsFromJson(const std::string& json,
654 std::vector<TraceEvent>* output) {
655 scoped_ptr<base::Value> root;
656 root.reset(base::JSONReader::Read(json));
658 base::ListValue* root_list = NULL;
659 if (!root.get() || !root->GetAsList(&root_list))
662 for (size_t i = 0; i < root_list->GetSize(); ++i) {
663 base::Value* item = NULL;
664 if (root_list->Get(i, &item)) {
666 if (event.SetFromJSON(item))
667 output->push_back(event);
680 TraceAnalyzer::TraceAnalyzer() : allow_assocation_changes_(true) {
683 TraceAnalyzer::~TraceAnalyzer() {
687 TraceAnalyzer* TraceAnalyzer::Create(const std::string& json_events) {
688 scoped_ptr<TraceAnalyzer> analyzer(new TraceAnalyzer());
689 if (analyzer->SetEvents(json_events))
690 return analyzer.release();
694 bool TraceAnalyzer::SetEvents(const std::string& json_events) {
696 if (!ParseEventsFromJson(json_events, &raw_events_))
698 std::stable_sort(raw_events_.begin(), raw_events_.end());
703 void TraceAnalyzer::AssociateBeginEndEvents() {
704 using trace_analyzer::Query;
706 Query begin(Query::EventPhaseIs(TRACE_EVENT_PHASE_BEGIN));
707 Query end(Query::EventPhaseIs(TRACE_EVENT_PHASE_END));
708 Query match(Query::EventName() == Query::OtherName() &&
709 Query::EventCategory() == Query::OtherCategory() &&
710 Query::EventTid() == Query::OtherTid() &&
711 Query::EventPid() == Query::OtherPid());
713 AssociateEvents(begin, end, match);
716 void TraceAnalyzer::AssociateAsyncBeginEndEvents() {
717 using trace_analyzer::Query;
720 Query::EventPhaseIs(TRACE_EVENT_PHASE_ASYNC_BEGIN) ||
721 Query::EventPhaseIs(TRACE_EVENT_PHASE_ASYNC_STEP_INTO) ||
722 Query::EventPhaseIs(TRACE_EVENT_PHASE_ASYNC_STEP_PAST));
723 Query end(Query::EventPhaseIs(TRACE_EVENT_PHASE_ASYNC_END) ||
724 Query::EventPhaseIs(TRACE_EVENT_PHASE_ASYNC_STEP_INTO) ||
725 Query::EventPhaseIs(TRACE_EVENT_PHASE_ASYNC_STEP_PAST));
726 Query match(Query::EventName() == Query::OtherName() &&
727 Query::EventCategory() == Query::OtherCategory() &&
728 Query::EventId() == Query::OtherId());
730 AssociateEvents(begin, end, match);
733 void TraceAnalyzer::AssociateEvents(const Query& first,
735 const Query& match) {
736 DCHECK(allow_assocation_changes_) << "AssociateEvents not allowed after "
739 // Search for matching begin/end event pairs. When a matching end is found,
740 // it is associated with the begin event.
741 std::vector<TraceEvent*> begin_stack;
742 for (size_t event_index = 0; event_index < raw_events_.size();
745 TraceEvent& this_event = raw_events_[event_index];
747 if (second.Evaluate(this_event)) {
748 // Search stack for matching begin, starting from end.
749 for (int stack_index = static_cast<int>(begin_stack.size()) - 1;
750 stack_index >= 0; --stack_index) {
751 TraceEvent& begin_event = *begin_stack[stack_index];
753 // Temporarily set other to test against the match query.
754 const TraceEvent* other_backup = begin_event.other_event;
755 begin_event.other_event = &this_event;
756 if (match.Evaluate(begin_event)) {
757 // Found a matching begin/end pair.
758 // Erase the matching begin event index from the stack.
759 begin_stack.erase(begin_stack.begin() + stack_index);
763 // Not a match, restore original other and continue.
764 begin_event.other_event = other_backup;
767 // Even if this_event is a |second| event that has matched an earlier
768 // |first| event, it can still also be a |first| event and be associated
769 // with a later |second| event.
770 if (first.Evaluate(this_event)) {
771 begin_stack.push_back(&this_event);
776 void TraceAnalyzer::MergeAssociatedEventArgs() {
777 for (size_t i = 0; i < raw_events_.size(); ++i) {
778 // Merge all associated events with the first event.
779 const TraceEvent* other = raw_events_[i].other_event;
780 // Avoid looping by keeping set of encountered TraceEvents.
781 std::set<const TraceEvent*> encounters;
782 encounters.insert(&raw_events_[i]);
783 while (other && encounters.find(other) == encounters.end()) {
784 encounters.insert(other);
785 raw_events_[i].arg_numbers.insert(
786 other->arg_numbers.begin(),
787 other->arg_numbers.end());
788 raw_events_[i].arg_strings.insert(
789 other->arg_strings.begin(),
790 other->arg_strings.end());
791 other = other->other_event;
796 size_t TraceAnalyzer::FindEvents(const Query& query, TraceEventVector* output) {
797 allow_assocation_changes_ = false;
799 return FindMatchingEvents(raw_events_, query, output);
802 const TraceEvent* TraceAnalyzer::FindFirstOf(const Query& query) {
803 TraceEventVector output;
804 if (FindEvents(query, &output) > 0)
805 return output.front();
809 const TraceEvent* TraceAnalyzer::FindLastOf(const Query& query) {
810 TraceEventVector output;
811 if (FindEvents(query, &output) > 0)
812 return output.back();
816 const std::string& TraceAnalyzer::GetThreadName(
817 const TraceEvent::ProcessThreadID& thread) {
818 // If thread is not found, just add and return empty string.
819 return thread_names_[thread];
822 void TraceAnalyzer::ParseMetadata() {
823 for (size_t i = 0; i < raw_events_.size(); ++i) {
824 TraceEvent& this_event = raw_events_[i];
825 // Check for thread name metadata.
826 if (this_event.phase != TRACE_EVENT_PHASE_METADATA ||
827 this_event.name != "thread_name")
829 std::map<std::string, std::string>::const_iterator string_it =
830 this_event.arg_strings.find("name");
831 if (string_it != this_event.arg_strings.end())
832 thread_names_[this_event.thread] = string_it->second;
836 // TraceEventVector utility functions.
838 bool GetRateStats(const TraceEventVector& events,
840 const RateStatsOptions* options) {
842 // Need at least 3 events to calculate rate stats.
843 const size_t kMinEvents = 3;
844 if (events.size() < kMinEvents) {
845 LOG(ERROR) << "Not enough events: " << events.size();
849 std::vector<double> deltas;
850 size_t num_deltas = events.size() - 1;
851 for (size_t i = 0; i < num_deltas; ++i) {
852 double delta = events.at(i + 1)->timestamp - events.at(i)->timestamp;
854 LOG(ERROR) << "Events are out of order";
857 deltas.push_back(delta);
860 std::sort(deltas.begin(), deltas.end());
863 if (options->trim_min + options->trim_max > events.size() - kMinEvents) {
864 LOG(ERROR) << "Attempt to trim too many events";
867 deltas.erase(deltas.begin(), deltas.begin() + options->trim_min);
868 deltas.erase(deltas.end() - options->trim_max, deltas.end());
871 num_deltas = deltas.size();
872 double delta_sum = 0.0;
873 for (size_t i = 0; i < num_deltas; ++i)
874 delta_sum += deltas[i];
876 stats->min_us = *std::min_element(deltas.begin(), deltas.end());
877 stats->max_us = *std::max_element(deltas.begin(), deltas.end());
878 stats->mean_us = delta_sum / static_cast<double>(num_deltas);
880 double sum_mean_offsets_squared = 0.0;
881 for (size_t i = 0; i < num_deltas; ++i) {
882 double offset = fabs(deltas[i] - stats->mean_us);
883 sum_mean_offsets_squared += offset * offset;
885 stats->standard_deviation_us =
886 sqrt(sum_mean_offsets_squared / static_cast<double>(num_deltas - 1));
891 bool FindFirstOf(const TraceEventVector& events,
894 size_t* return_index) {
896 for (size_t i = position; i < events.size(); ++i) {
897 if (query.Evaluate(*events.at(i))) {
905 bool FindLastOf(const TraceEventVector& events,
908 size_t* return_index) {
912 position = (position < events.size()) ? position : events.size() - 1;
914 if (query.Evaluate(*events.at(position))) {
915 *return_index = position;
925 bool FindClosest(const TraceEventVector& events,
928 size_t* return_closest,
929 size_t* return_second_closest) {
930 CHECK(return_closest);
931 if (events.empty() || position >= events.size())
933 size_t closest = events.size();
934 size_t second_closest = events.size();
935 for (size_t i = 0; i < events.size(); ++i) {
936 if (!query.Evaluate(*events.at(i)))
938 if (closest == events.size()) {
942 if (fabs(events.at(i)->timestamp - events.at(position)->timestamp) <
943 fabs(events.at(closest)->timestamp - events.at(position)->timestamp)) {
944 second_closest = closest;
946 } else if (second_closest == events.size()) {
951 if (closest < events.size() &&
952 (!return_second_closest || second_closest < events.size())) {
953 *return_closest = closest;
954 if (return_second_closest)
955 *return_second_closest = second_closest;
962 size_t CountMatches(const TraceEventVector& events,
964 size_t begin_position,
965 size_t end_position) {
966 if (begin_position >= events.size())
968 end_position = (end_position < events.size()) ? end_position : events.size();
970 for (size_t i = begin_position; i < end_position; ++i) {
971 if (query.Evaluate(*events.at(i)))
977 } // namespace trace_analyzer