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

base/debug/trace_event_test_utils.h

+// Copyright (c) 2011 The Chromium Authors. All rights reserved.

[nduca, 2011/10/11 20:33:37]

trace_event_analyzer.h

move tests of the analyzer into trace_event_analyzer_test.cc

[jbates, 2011/10/12 22:35:20]

Done.

+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+// Use trace::Query with TraceAnalyzer to search for specific trace events.

[nduca, 2011/10/11 20:33:37]

Advertise the namespace that these are all in? I had to go down to code to
understand that this was in base::trace (a casual trace_event user never sees
the namespace stuff).

[jbates, 2011/10/12 22:35:20]

Done.

+// Queries can be combined using boolean and comparison operators.
+//
+// Construct TraceAnalyzer with the json trace string retrieved from TraceLog:
+// TraceAnalyzer analyzer(json_events);

[nduca, 2011/10/11 20:33:37]

What happens if it fails to parse? Maybe a TraceAnalyzer*
TraceAnalyzer::create(json_events) would be better?

[jbates, 2011/10/12 22:35:20]

This should be okay, because the parse would only fail if there's a bug in
trace_event or trace_controller, which will be extremely rare. In the event that
it does happen, the test will fail because there will be no trace events.

+// ConstEventPtrVector events;

[nduca, 2011/10/11 20:33:37]

A blurb explaining the basic idea of trace analysis would be pretty cool, and
might help shake out some rough edges here... "You analyze traces by parsing the
events, then issuing queries against it. Queries are a tree of blahblahblah.
Events come out as TestTraceEvent objects. Relationships are automatically
resolved and accessible via other_event."

[jbates, 2011/10/12 22:35:20]

Done.

+//
+// To find begin events called "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);
+//
+// By default, only begin/end events on the same thread will ever be associated.
+// If the test needs to analyze events that begin and end on different threads,

[nduca, 2011/10/11 20:33:37]

Recapping our verbal discussion, I think should take this opportunity to fix B/E
events and make very precise semantic rules about B-E pairing. THis may clean up
this code a bit.

[jbates, 2011/10/12 22:35:20]

Sounds good. On second look though, the trace_event change can be done
independently since it doesn't change this code. I fixed the example below to
make this compatible with the current assumptions about BEGIN/END events.

+// it can specify custom assocations. The typical procedure is to include a
+// unique ID as one of the TRACE_EVENT arguments that only matches a single
+// begin/end pair across all Chrome processes and threads.
+//
+// For example:
+//   [Thread 1]
+//   TRACE_EVENT_BEGIN1("test_latency", "timing1", "id", 3);
+//   [Later, on Thread 2]
+//   TRACE_EVENT_END1("test_latency", "timing1", "id", 3);

[nduca, 2011/10/11 20:33:37]

This trace wont' even parse in the trace_event_viewer? More reason to fix B/E
inconsistency.

[jbates, 2011/10/12 22:35:20]

Fixed the example to use TRACE_EVENT_INSTANT, which is compatible with both the
current about:tracing assumptions about BEGIN/END and the future support for
START/FINISH events.

+// Then, to associate these begin/end pairs:
+//   Query begin(Query(EVENT_PHASE) == TRACE_EVENT_PHASE_BEGIN);
+//   Query end(Query(EVENT_PHASE) == TRACE_EVENT_PHASE_END);
+//   Query match(Query(EVENT_NAME) == Query(OTHER_NAME) &&
+//               Query(EVENT_ARG, "id") == Query(OTHER_ARG, "id"));
+//   analyzer.AssociateEvents(begin, end, match);

[nduca, 2011/10/11 20:33:37]

Based on the first example, I was hoping we'd see call "FindEvents" again, but
maybe with some additional arguments. It wasn't clera to me that FindEvents
associated events, and that AssociateEvents did to but using a custom operator.

Maybe FindEvents(Query)
      FindEvents(begin, end, matcher)

When we fix B/E events (e.g. moving B/E on other threads to be S/F events) do we
have use cases for FindEvents with custom matchers?

[jbates, 2011/10/12 22:35:20]

You're right, it should have been there... Done.

but
Actually, it's TraceAnalyzer::SetEvents (called during construction) that sets
default associations. I updated the comments to make that more clear.
AssociateEvents can be called multiple times to setup multiple associations.
ClearAssociations resets them. This might not currently be useful, but it's
flexible to future possibilities such as having an event associated with more
than one other event.
Probably not, but I'm not sure. I need to implement the input latency test to
get a better idea of what is needed. Since inputs are coalesced, it's going to
be challenging to have a single begin/end pair that represents oldest input and
corresponding DoDeferredUpdate.

+// Then you can search for "timing1" events and evaluate their durations.
+
+
+#ifndef BASE_DEBUG_TRACE_EVENT_TEST_UTILS_H_
+#define BASE_DEBUG_TRACE_EVENT_TEST_UTILS_H_
+#pragma once
+
+#include <map>
+
+#include "base/debug/trace_event.h"
+
+namespace base {
+class Value;
+
+namespace debug {
+
+namespace trace {
+class QueryNode;
+}
+
+// TestTraceEvent is a more convenient form of the TraceEvent class to make
+// tracing-based tests easier to write.
+struct TestTraceEvent {

[nduca, 2011/10/11 20:33:37]

I'm confused about base::trace vs base::debug::trace vs base::trace. Can we
clean this up?

The name here is hard. I understand that you need an event that is part of the
analyzer...

Whatabout
base::trace::analysis::Query
base::trace::analysis::Event
base::trace::analysis::TraceAnalyzer

[jbates, 2011/10/12 22:35:20]

I've been thinking it would be great to move tracing stuff from base::debug to
base or base::trace since it's no longer debug-only. That would be a great place
for all of trace_event.h and trace_event_analysis.h. I think that's a separate
CL though. This header follows the trace_event.h namespace conventions except
for the Query class, which gets its own namespace for syntactic sugar. I'm open
to changing namespaces up, but I'd prefer to do it in conjunction with
trace_event.h. WDYT?

+  // 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;
+  };
+
+  TestTraceEvent();
+  TestTraceEvent(const base::Value* event_value);
+  ~TestTraceEvent();
+
+  // Convert JSON string to array of TestTraceEvent.
+  // |output| is appended with the parsed events.
+  static bool ParseEventsFromJson(const std::string& json,

[nduca, 2011/10/11 20:33:37]

Makes more sense on traceanalyzer?

[jbates, 2011/10/12 22:35:20]

This is only dependent on TestTraceEvent, so I think it's best to keep it here
to reduce coupling. It also matches the static TraceEvent::AppendEventsAsJSON.

+                                  std::vector<TestTraceEvent>* output);
+
+  bool operator< (const TestTraceEvent& rhs) const {
+    return timestamp < rhs.timestamp;
+  }
+
+  // Returns duration if it's available.

[nduca, 2011/10/11 20:33:37]

Add a bool has_other_event() const;

Modify comment to be Returns duration if has_other_event()

[jbates, 2011/10/12 22:35:20]

Done.

+  bool GetDuration(double* duration) const;
+
+  // Return the argument value if it exists.
+  bool IsArg(const std::string& name) const;

[nduca, 2011/10/11 20:33:37]

HasArg

[jbates, 2011/10/12 22:35:20]

Removed it - it wasn't used anywhere :)

+  // 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;
+
+  // Called by TraceAnalyzer to associate this event with another event.

[nduca, 2011/10/11 20:33:37]

Use friending so that this isn't visible?

[jbates, 2011/10/12 22:35:20]

Also removed, it was unnecessary.

+  void set_other_event(const TestTraceEvent* event) {
+    other_event = event;
+  }
+
+  // Process ID and Thread ID.

[nduca, 2011/10/11 20:33:37]

Are these really supposed to be public? Makes me anxious. :)

It'd be good to hide stuff that's needed for trace analyzer, and make any
accesses go through methods.

[jbates, 2011/10/12 22:35:20]

This is for tests, so I think it's best to keep it simple and public.

+  PidTid pid_tid;
+  // Time since epoch in microseconds.
+  // Stored as double to match its JSON representation.
+  double timestamp;
+  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 TestTraceEvent* other_event;
+};
+
+// By using the trace namespace, tests can use short terms like "Query".
+namespace trace {
+
+// Pass these values to Query to compare with the corresponding member of a
+// TestTraceEvent.
+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(OTHER_EXISTS).
+  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);
+  Query(float num);
+  Query(int num);
+  Query(uint32 num);
+
+  // Compare with the given bool.
+  Query(bool boolean);
+
+  // Compare with the given phase.
+  Query(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) == TRACE_EVENT_PHASE_BEGIN) &&
+           Query(EVENT_HAS_OTHER);
+  }
+
+  // Find END events that have a corresponding BEGIN event.
+  static Query MatchEndWithBegin() {
+    return (Query(EVENT_PHASE) == 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(base::debug::TestTraceEvent::PidTid pid_tid) {
+    return (Query(EVENT_PID) == pid_tid.pid) &&
+           (Query(EVENT_TID) == pid_tid.tid);
+  }
+
+  // Match BEGIN/END 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;
+  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:
+  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;
+
+  // Return true if the given event matches this query tree.
+  // This is a recursive method that walks the query tree.
+  bool Evaluate(const TestTraceEvent& 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 TestTraceEvent& 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 TestTraceEvent& 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 TestTraceEvent& 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 TestTraceEvent& event, std::string* str) const;
+
+  // Evaluate this Query as an arithmetic operator on left_ and right_.
+  bool EvaluateArithmeticOperator(const TestTraceEvent& 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.
+  TraceValue GetMemberValue(const TestTraceEvent& 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_;
+};
+
+// QueryNode allows Query to store a ref-counted query tree.
+class QueryNode : public RefCounted<QueryNode> {
+ public:
+  QueryNode(const Query& query);
+  const Query& query() const { return query_; }
+
+ private:
+  friend class RefCounted<QueryNode>;
+  ~QueryNode();
+
+  Query query_;
+};
+
+}  // namespace trace
+
+// TraceAnalyzer is designed to make tracing-based tests easier to write.
+class TraceAnalyzer {
+ public:
+  typedef std::vector<base::debug::TestTraceEvent> EventVector;
+  typedef std::vector<const base::debug::TestTraceEvent*> ConstEventPtrVector;
+
+  TraceAnalyzer();
+  TraceAnalyzer(const std::string& json_events);
+  TraceAnalyzer(const EventVector& events);
+  ~TraceAnalyzer();
+
+  // Replace all events with |json_events|.
+  void SetEvents(const std::string& json_events);

[nduca, 2011/10/11 20:33:37]

Why this rather than creating another analyzer?

[jbates, 2011/10/12 22:35:20]

The code is about the same either way - may as well allow it.

+  // Replace all events with |events|.
+  void SetEvents(const EventVector& events);
+
+  // SetEvents calls this internally to match up typical begin/end pairs of
+  // events. This allows Query(OTHER_*) to access the associated event and
+  // enables Query(EVENT_DURATION).
+  // By default, an end event will match the most recent begin event with the
+  // same name, category, process ID and thread ID.
+  void SetDefaultAssociations();

[nduca, 2011/10/11 20:33:37]

Confused what this does. Does an end-user writing tests need to see this?

[jbates, 2011/10/12 22:35:20]

For now I think it makes sense to keep it available, since it documents the
default association behavior. The new examples in the initial header comments
also help explain how associations work.

+
+  // Clear existing event associations.
+  void ClearAssociations();

[nduca, 2011/10/11 20:33:37]

Same here... what does this do? Is the idea here that we the TestTraceEvents
returned are const so when you do a query using AssociateEvents, it causes the
other_event fields to change? Can we avoid this complexity, maybe at a
fractional performance cost?

[jbates, 2011/10/12 22:35:20]

Correct -- AssociateEvents can be called multiple times to setup multiple
associations.
I went all the way down the functional programming style API that returns a new
copy of the event vector for each call that modifies it, and ran into two
issues:
- there's no use case for filtering multiple times, because Queries can already
be combined to accomplish that. Without this use case, there's little reason
left for the functional style API.
- the other_event pointer is invalidated and would need to be reset to point to
the new vector data for each vector copy. This would be complicated and
hazardous code, not worth the effort. Keeping copies for associations is equally
ugly: the copy's assocations could diverge from other instances in the same
results... no good.

+
+  // By default, matching begin and end events are associated with each other as
+  // described in SetDefaultAssociations.
+  // AssociateEvents can be used to customize begin/end event associations.
+  // The only assumption is that end events occur after begin events.
+  //
+  // |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. Non-matching events are left with
+  // their existing assocations, so you may also want to call ClearAssociations.
+  void AssociateEvents(const trace::Query& begin,
+                       const trace::Query& end,
+                       const trace::Query& match);
+

[nduca, 2011/10/11 20:33:37]

If we had B/E only work on threads, always using 

And, suppose we had S/F that work anywhere, and that matching is done via name,
and any argument that starts with id. Eg
  S A id_x=1 id_y=2
  F A id_x=2 id_y=2 // no match
  F A id_x=1 id_y=2 // match
Where multiple matches are found, break tie via timestamp, e.g.
Eg
  S A ts=1 id=1
  F A ts=2 id=1 // not matched
  F A ts=1.5 id=1 // matched to the S

Does this work?

[jbates, 2011/10/12 22:35:20]

It might, but as we discussed, I'd like to start simple and build up rules as we
discover the need by writing a few tests.

+  const EventVector& events() { return raw_events_; }
+
+  const std::string& GetThreadName(const base::debug::TestTraceEvent::PidTid&
+                                   pid_tid);
+
+  // Find all events that match query and replace output vector.
+  size_t FindEvents(const trace::Query& query,
+                    ConstEventPtrVector* output) const;
+
+  // Helper method: find first event that matches query
+  const base::debug::TestTraceEvent* FindEvent(
+      const trace::Query& query) const;
+
+ private:
+  // Read metadata (thread names, etc) from events.
+  void ParseMetadata();
+
+  std::map<base::debug::TestTraceEvent::PidTid, std::string> thread_names_;
+  EventVector raw_events_;
+};
+
+}  // namespace debug
+}  // namespace base
+
+#endif  // BASE_DEBUG_TRACE_EVENT_TEST_UTILS_H_