Add ASYNC_STEP support to trace_event and change START to ASYNC_BEGIN.

BUG=116095


Review URL: http://codereview.chromium.org/9522010

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@124348 0039d316-1c4b-4281-b951-d872f2087c98

3 files changed, 116 insertions, 51 deletions

diff --git a/base/test/trace_event_analyzer.cc b/base/test/trace_event_analyzer.cc
index 7aba0be..db1de4c 100644
--- a/base/test/trace_event_analyzer.cc
+++ b/base/test/trace_event_analyzer.cc
@@ -6,6 +6,7 @@
 
 #include <algorithm>
 #include <math.h>
+#include <set>
 
 #include "base/json/json_reader.h"
 #include "base/memory/scoped_ptr.h"
@@ -44,8 +45,9 @@ bool TraceEvent::SetFromJSON(const base::Value* event_value) {
   phase = *phase_str.data();
 
   bool require_origin = (phase != TRACE_EVENT_PHASE_METADATA);
-  bool require_id = (phase == TRACE_EVENT_PHASE_START ||
-                     phase == TRACE_EVENT_PHASE_FINISH);
+  bool require_id = (phase == TRACE_EVENT_PHASE_ASYNC_BEGIN ||
+                     phase == TRACE_EVENT_PHASE_ASYNC_STEP ||
+                     phase == TRACE_EVENT_PHASE_ASYNC_END);
 
   if (require_origin && !dictionary->GetInteger("pid", &thread.process_id)) {
     LOG(ERROR) << "pid is missing from TraceEvent JSON";
@@ -72,7 +74,7 @@ bool TraceEvent::SetFromJSON(const base::Value* event_value) {
     return false;
   }
   if (require_id && !dictionary->GetString("id", &id)) {
-    LOG(ERROR) << "id is missing from START/FINISH TraceEvent JSON";
+    LOG(ERROR) << "id is missing from ASYNC_BEGIN/ASYNC_END TraceEvent JSON";
     return false;
   }
 
@@ -702,11 +704,14 @@ void TraceAnalyzer::AssociateBeginEndEvents() {
   AssociateEvents(begin, end, match);
 }
 
-void TraceAnalyzer::AssociateStartFinishEvents() {
+void TraceAnalyzer::AssociateAsyncBeginEndEvents() {
   using trace_analyzer::Query;
 
-  Query begin(Query::EventPhase() == Query::Phase(TRACE_EVENT_PHASE_START));
-  Query end(Query::EventPhase() == Query::Phase(TRACE_EVENT_PHASE_FINISH));
+  Query begin(
+      Query::EventPhase() == Query::Phase(TRACE_EVENT_PHASE_ASYNC_BEGIN) ||
+      Query::EventPhase() == Query::Phase(TRACE_EVENT_PHASE_ASYNC_STEP));
+  Query end(Query::EventPhase() == Query::Phase(TRACE_EVENT_PHASE_ASYNC_END) ||
+            Query::EventPhase() == Query::Phase(TRACE_EVENT_PHASE_ASYNC_STEP));
   Query match(Query::EventName() == Query::OtherName() &&
               Query::EventCategory() == Query::OtherCategory() &&
               Query::EventId() == Query::OtherId());
@@ -728,9 +733,7 @@ void TraceAnalyzer::AssociateEvents(const Query& first,
 
     TraceEvent& this_event = raw_events_[event_index];
 
-    if (first.Evaluate(this_event)) {
-      begin_stack.push_back(&this_event);
-    } else if (second.Evaluate(this_event)) {
+    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) {
@@ -741,8 +744,6 @@ void TraceAnalyzer::AssociateEvents(const Query& first,
         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;
@@ -752,18 +753,31 @@ void TraceAnalyzer::AssociateEvents(const Query& first,
         begin_event.other_event = other_backup;
       }
     }
+    // Even if this_event is a |second| event that has matched an earlier
+    // |first| event, it can still also be a |first| event and be associated
+    // with a later |second| event.
+    if (first.Evaluate(this_event)) {
+      begin_stack.push_back(&this_event);
+    }
   }
 }
 
 void TraceAnalyzer::MergeAssociatedEventArgs() {
   for (size_t i = 0; i < raw_events_.size(); ++i) {
-    if (raw_events_[i].other_event) {
+    // Merge all associated events with the first event.
+    const TraceEvent* other = raw_events_[i].other_event;
+    // Avoid looping by keeping set of encountered TraceEvents.
+    std::set<const TraceEvent*> encounters;
+    encounters.insert(&raw_events_[i]);
+    while (other && encounters.find(other) == encounters.end()) {
+      encounters.insert(other);
       raw_events_[i].arg_numbers.insert(
-          raw_events_[i].other_event->arg_numbers.begin(),
-          raw_events_[i].other_event->arg_numbers.end());
+          other->arg_numbers.begin(),
+          other->arg_numbers.end());
       raw_events_[i].arg_strings.insert(
-          raw_events_[i].other_event->arg_strings.begin(),
-          raw_events_[i].other_event->arg_strings.end());
+          other->arg_strings.begin(),
+          other->arg_strings.end());
+      other = other->other_event;
     }
   }
 }
diff --git a/base/test/trace_event_analyzer.h b/base/test/trace_event_analyzer.h
index 4817ec8..05a008e 100644
--- a/base/test/trace_event_analyzer.h
+++ b/base/test/trace_event_analyzer.h
@@ -29,10 +29,6 @@
 // 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);
@@ -277,9 +273,10 @@ class Query {
            Query(EVENT_HAS_OTHER);
   }
 
-  // Find START events that have a corresponding FINISH event.
-  static Query MatchStartWithFinish() {
-    return (Query(EVENT_PHASE) == Query::Phase(TRACE_EVENT_PHASE_START)) &&
+  // Find ASYNC_BEGIN events that have a corresponding ASYNC_END event.
+  static Query MatchAsyncBeginWithNext() {
+    return (Query(EVENT_PHASE) ==
+            Query::Phase(TRACE_EVENT_PHASE_ASYNC_BEGIN)) &&
            Query(EVENT_HAS_OTHER);
   }
 
@@ -482,13 +479,15 @@ class TraceAnalyzer {
   // 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.
+  // about:tracing. After association, the BEGIN event will point to the
+  // matching END event, but the END event will not point to the BEGIN event.
   void AssociateBeginEndEvents();
 
-  // Associate START and FINISH events with each other.
-  // A FINISH event will match the most recent START event with the same name,
-  // category, and ID.
-  void AssociateStartFinishEvents();
+  // Associate ASYNC_BEGIN, ASYNC_STEP and ASYNC_END events with each other.
+  // An ASYNC_END event will match the most recent ASYNC_BEGIN or ASYNC_STEP
+  // event with the same name, category, and ID. This creates a singly linked
+  // list of ASYNC_BEGIN->ASYNC_STEP...->ASYNC_END.
+  void AssociateAsyncBeginEndEvents();
 
   // AssociateEvents can be used to customize event associations by setting the
   // other_event member of TraceEvent. This should be used to associate two
@@ -504,10 +503,10 @@ class TraceAnalyzer {
   //            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.
+  // When a match is found, the pair will be associated by having the first
+  // event's other_event member point to the 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.
diff --git a/base/test/trace_event_analyzer_unittest.cc b/base/test/trace_event_analyzer_unittest.cc
index 8ff611f..e533c49 100644
--- a/base/test/trace_event_analyzer_unittest.cc
+++ b/base/test/trace_event_analyzer_unittest.cc
@@ -447,7 +447,8 @@ TEST_F(TraceEventAnalyzerTest, MergeAssociatedEventArgs) {
   const char* arg_string = "arg_string";
   BeginTracing();
   {
-    TRACE_EVENT1("cat1", "name1", "arg", arg_string);
+    TRACE_EVENT_BEGIN0("cat1", "name1");
+    TRACE_EVENT_END1("cat1", "name1", "arg", arg_string);
   }
   EndTracing();
 
@@ -457,8 +458,7 @@ TEST_F(TraceEventAnalyzerTest, MergeAssociatedEventArgs) {
   analyzer->AssociateBeginEndEvents();
 
   TraceEventVector found;
-  analyzer->FindEvents(Query::EventName() == Query::String("name1") &&
-      Query::EventPhase() == Query::Phase(TRACE_EVENT_PHASE_END), &found);
+  analyzer->FindEvents(Query::MatchBeginName("name1"), &found);
   ASSERT_EQ(1u, found.size());
   std::string arg_actual;
   EXPECT_FALSE(found[0]->GetArgAsString("arg", &arg_actual));
@@ -468,35 +468,87 @@ TEST_F(TraceEventAnalyzerTest, MergeAssociatedEventArgs) {
   EXPECT_STREQ(arg_string, arg_actual.c_str());
 }
 
-// Test AssociateStartFinishEvents
-TEST_F(TraceEventAnalyzerTest, StartFinishAssocations) {
+// Test AssociateAsyncBeginEndEvents
+TEST_F(TraceEventAnalyzerTest, AsyncBeginEndAssocations) {
   ManualSetUp();
 
   BeginTracing();
   {
-    TRACE_EVENT_FINISH0("cat1", "name1", 0xA); // does not match / out of order
-    TRACE_EVENT_START0("cat1", "name1", 0xB);
-    TRACE_EVENT_START0("cat1", "name1", 0xC);
+    TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xA); // no match / out of order
+    TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xB);
+    TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xC);
     TRACE_EVENT_INSTANT0("cat1", "name1"); // noise
     TRACE_EVENT0("cat1", "name1"); // noise
-    TRACE_EVENT_FINISH0("cat1", "name1", 0xB);
-    TRACE_EVENT_FINISH0("cat1", "name1", 0xC);
-    TRACE_EVENT_START0("cat1", "name1", 0xA); // does not match / out of order
+    TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xB);
+    TRACE_EVENT_ASYNC_END0("cat1", "name1", 0xC);
+    TRACE_EVENT_ASYNC_BEGIN0("cat1", "name1", 0xA); // no match / out of order
   }
   EndTracing();
 
   scoped_ptr<TraceAnalyzer>
       analyzer(TraceAnalyzer::Create(output_.json_output));
   ASSERT_TRUE(analyzer.get());
-  analyzer->AssociateStartFinishEvents();
+  analyzer->AssociateAsyncBeginEndEvents();
 
   TraceEventVector found;
-  analyzer->FindEvents(Query::MatchStartWithFinish(), &found);
+  analyzer->FindEvents(Query::MatchAsyncBeginWithNext(), &found);
   ASSERT_EQ(2u, found.size());
   EXPECT_STRCASEEQ("B", found[0]->id.c_str());
   EXPECT_STRCASEEQ("C", found[1]->id.c_str());
 }
 
+// Test AssociateAsyncBeginEndEvents
+TEST_F(TraceEventAnalyzerTest, AsyncBeginEndAssocationsWithSteps) {
+  ManualSetUp();
+
+  BeginTracing();
+  {
+    TRACE_EVENT_ASYNC_STEP0("c", "n", 0xA);
+    TRACE_EVENT_ASYNC_END0("c", "n", 0xA);
+    TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xB);
+    TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xC);
+    TRACE_EVENT_ASYNC_STEP0("c", "n", 0xB);
+    TRACE_EVENT_ASYNC_STEP0("c", "n", 0xC);
+    TRACE_EVENT_ASYNC_STEP1("c", "n", 0xC, "a", 1);
+    TRACE_EVENT_ASYNC_END0("c", "n", 0xB);
+    TRACE_EVENT_ASYNC_END0("c", "n", 0xC);
+    TRACE_EVENT_ASYNC_BEGIN0("c", "n", 0xA);
+    TRACE_EVENT_ASYNC_STEP0("c", "n", 0xA);
+  }
+  EndTracing();
+
+  scoped_ptr<TraceAnalyzer>
+      analyzer(TraceAnalyzer::Create(output_.json_output));
+  ASSERT_TRUE(analyzer.get());
+  analyzer->AssociateAsyncBeginEndEvents();
+
+  TraceEventVector found;
+  analyzer->FindEvents(Query::MatchAsyncBeginWithNext(), &found);
+  ASSERT_EQ(3u, found.size());
+
+  EXPECT_STRCASEEQ("B", found[0]->id.c_str());
+  EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP, found[0]->other_event->phase);
+  EXPECT_TRUE(found[0]->other_event->other_event);
+  EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_END,
+            found[0]->other_event->other_event->phase);
+
+  EXPECT_STRCASEEQ("C", found[1]->id.c_str());
+  EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP, found[1]->other_event->phase);
+  EXPECT_TRUE(found[1]->other_event->other_event);
+  EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP,
+            found[1]->other_event->other_event->phase);
+  double arg_actual = 0;
+  EXPECT_TRUE(found[1]->other_event->other_event->GetArgAsNumber(
+                  "a", &arg_actual));
+  EXPECT_EQ(1.0, arg_actual);
+  EXPECT_TRUE(found[1]->other_event->other_event->other_event);
+  EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_END,
+            found[1]->other_event->other_event->other_event->phase);
+
+  EXPECT_STRCASEEQ("A", found[2]->id.c_str());
+  EXPECT_EQ(TRACE_EVENT_PHASE_ASYNC_STEP, found[2]->other_event->phase);
+}
+
 // Test that the TraceAnalyzer custom associations work.
 TEST_F(TraceEventAnalyzerTest, CustomAssociations) {
   ManualSetUp();
@@ -541,25 +593,25 @@ TEST_F(TraceEventAnalyzerTest, CustomAssociations) {
                        !Query::EventHasOther(), &found);
   EXPECT_EQ(1u, found.size());
 
-  // cat2 and cat4 are a associated.
+  // cat2 and cat4 are associated.
   analyzer->FindEvents(Query::EventCategory() == Query::String("cat2") &&
                        Query::OtherCategory() == Query::String("cat4"), &found);
   EXPECT_EQ(1u, found.size());
 
-  // cat4 and cat2 are a associated.
+  // cat4 and cat2 are not associated.
   analyzer->FindEvents(Query::EventCategory() == Query::String("cat4") &&
                        Query::OtherCategory() == Query::String("cat2"), &found);
-  EXPECT_EQ(1u, found.size());
+  EXPECT_EQ(0u, found.size());
 
-  // cat3 and cat5 are a associated.
+  // cat3 and cat5 are associated.
   analyzer->FindEvents(Query::EventCategory() == Query::String("cat3") &&
                        Query::OtherCategory() == Query::String("cat5"), &found);
   EXPECT_EQ(1u, found.size());
 
-  // cat5 and cat3 are a associated.
+  // cat5 and cat3 are not associated.
   analyzer->FindEvents(Query::EventCategory() == Query::String("cat5") &&
                        Query::OtherCategory() == Query::String("cat3"), &found);
-  EXPECT_EQ(1u, found.size());
+  EXPECT_EQ(0u, found.size());
 }
 
 // Verify that Query literals and types are properly casted.