add classes trace_analyzer::Query and TraceAnalyzer to make it easy to search through trace data

base/test/trace_event_analyzer.h

+// 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) == "my_event" &&
+//            Query(EVENT_PHASE) == TRACE_EVENT_PHASE_BEGIN &&
+//            Query(EVENT_DURATION) > 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) == "timing1_begin");
+//   Query end(Query(EVENT_NAME) == "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) == "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].GetDuration(&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 {
+  // PidTid contains a Process ID and Thread ID.
+  struct PidTid {
+    PidTid() : pid(0), tid(0) {}
+    PidTid(int pid, int tid) : pid(pid), tid(tid) {}
+    bool operator< (PidTid rhs) const {
+      if (pid != rhs.pid)
+        return pid < rhs.pid;
+      return tid < rhs.tid;
+    }
+    int pid;
+    int tid;
+  };
+
+  TraceEvent();
+  explicit TraceEvent(const base::Value* event_value);
+  ~TraceEvent();
+
+  bool operator< (const TraceEvent& rhs) const {
+    return timestamp < rhs.timestamp;
+  }
+
+  bool has_other_event() const { return other_event; }
+
+  // Returns duration in microseconds if has_other_event() is true.
+  bool GetDuration(double* duration) const;

[nduca, 2011/10/14 23:14:16]

duration makes sense on begin events, but for two manually associated instant
events, its odd. Similarly, what is the duration of an end event?

TimeToOtherEvent might be more precise here. e.TimeToOtherEvent() for end event
"e" is -begin.TimeToOtherEvent(a)

[jbates, 2011/10/18 18:14:22]

Renamed to GetAbsTimeToOtherEvent and documented the behavior better.

+
+  // 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.
+  PidTid pid_tid;

[nduca, 2011/10/14 23:14:16]

Do we typically add spaces between fields? I forget... personally, this feels
dense.

[jbates, 2011/10/18 18:14:22]

Done.

+  // 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 duration of an event in seconds.
+  // 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);
+
+  // Compare with the given string.
+  Query(const std::string& str);
+  Query(const char* str);
+
+  // Compare with the given number.
+  Query(double num);

[Paweł Hajdan Jr., 2011/10/18 10:10:50]

Having an override for both double and float seems dangerous. This is an
invitation for trouble.

[jbates, 2011/10/18 18:14:22]

Done. FYI, this was safe because the float constructor passes through to the
double constructor. I removed the float constructor though because C++ is happy
to implicitly cast float to double.

+  Query(float num);
+  Query(int num);

[Paweł Hajdan Jr., 2011/10/18 10:10:50]

Same here for int and uint, and bool... when literals are used in the client
code I'm not so confident the expected ctor will be used. And if they're
essentially equivalent, they shouldn't be duplicated.

[jbates, 2011/10/18 18:14:22]

These three are all distinct types, so literals should go through to the
expected constructor. I added some tests to verify the expected behavior of
literals.

+  Query(uint32 num);
+
+  // Compare with the given bool.
+  Query(bool boolean);
+
+  // Compare with the given phase.
+  Query(base::debug::TraceEventPhase phase);
+
+  Query(const Query& query);
+
+  ~Query();
+
+  // Compare with the given string pattern. Only works with == and != operators.
+  // Example: Query(EVENT_NAME) == Query::Pattern("bla_*")
+  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) == base::debug::TRACE_EVENT_PHASE_BEGIN) &&
+           Query(EVENT_HAS_OTHER);
+  }
+
+  // Find END events that have a corresponding BEGIN event.
+  static Query MatchEndWithBegin() {
+    return (Query(EVENT_PHASE) == base::debug::TRACE_EVENT_PHASE_END) &&
+           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 MatchPidTid(TraceEvent::PidTid pid_tid) {
+    return (Query(EVENT_PID) == pid_tid.pid) &&
+           (Query(EVENT_TID) == pid_tid.tid);
+  }
+
+  // Match event pair that spans multiple threads.
+  static Query MatchCrossPidTid() {
+    return (Query(EVENT_PID) != Query(OTHER_PID)) ||
+           (Query(EVENT_TID) != Query(OTHER_TID));
+  }
+
+  // Boolean operators:
+  Query operator==(const Query& rhs) const;

[Paweł Hajdan Jr., 2011/10/18 10:07:15]

I think you get a response that there is no exception for those operators,
right?

[Paweł Hajdan Jr., 2011/10/18 10:10:50]

Ah, just realized you said Brett is OK with this. So am I.

+  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
+  };
+
+  // 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;
+  }
+
+  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();
+  ~TraceAnalyzer();
+
+  // Set trace events from JSON string generated by tracing API.
+  // Returns true if the JSON is successfully parsed.
+  bool SetEvents(const std::string& json_events) WARN_UNUSED_RESULT;

[nduca, 2011/10/14 23:14:16]

What happens if you call this twice?

[jbates, 2011/10/18 18:14:22]

Done.

+
+  // 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 begin/end event associations.

[nduca, 2011/10/14 23:14:16]

does this work on begin/end events? I thought you said we were going to only
allow custom association on immediate events?

[jbates, 2011/10/18 18:14:22]

Filed bug, improved comments. See related comment in .cc.

+  // The assumptions are:
+  // - end events occur after begin events.
+  // - the closest matching end event is the best match.
+  //
+  // |begin| - Eligible begin events match this query.
+  // |end|   - Eligible end events match this query.
+  // |match| - This query is run on the begin event. The OTHER event members
+  //           will point to an eligible end event. The query should evaluate to
+  //           true if the begin/end 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.
+  //
+  // After calling FindEvents or FindOneEvent, it is not allowed to call
+  // AssociateEvents again.
+  void AssociateEvents(const Query& begin,
+                       const Query& end,
+                       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::PidTid& pid_tid);
+
+ private:
+  // Read metadata (thread names, etc) from events.
+  void ParseMetadata();
+
+  std::map<TraceEvent::PidTid, 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_