Add TraceAnalyzer support for START/FINISH events and JSON error logging

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

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

base/test/trace_event_analyzer.cc

@@ -26,50 +26,82 @@ TraceEvent::~TraceEvent() {
 }
 
 bool TraceEvent::SetFromJSON(const base::Value* event_value) {
-  if (event_value->GetType() != base::Value::TYPE_DICTIONARY)
+  if (event_value->GetType() != base::Value::TYPE_DICTIONARY) {
+    LOG(ERROR) << "Value must be TYPE_DICTIONARY";
     return false;
+  }
   const base::DictionaryValue* dictionary =
       static_cast<const base::DictionaryValue*>(event_value);
 
   std::string phase_str;
   base::DictionaryValue* args = NULL;
 
-  if (dictionary->GetInteger("pid", &thread.process_id) &&
-      dictionary->GetInteger("tid", &thread.thread_id) &&
-      dictionary->GetDouble("ts", &timestamp) &&
-      dictionary->GetString("cat", &category) &&
-      dictionary->GetString("name", &name) &&
-      dictionary->GetString("ph", &phase_str) &&
-      dictionary->GetDictionary("args", &args)) {
-
-    phase = base::debug::TraceEvent::GetPhase(phase_str.c_str());
-
-    // For each argument, copy the type and create a trace_analyzer::TraceValue.
-    base::DictionaryValue::key_iterator keyi = args->begin_keys();
-    for (; keyi != args->end_keys(); ++keyi) {
-      std::string str;
-      bool boolean = false;
-      int int_num = 0;
-      double double_num = 0.0;
-      Value* value = NULL;
-      if (args->GetWithoutPathExpansion(*keyi, &value)) {
-        if (value->GetAsString(&str))
-          arg_strings[*keyi] = str;
-        else if (value->GetAsInteger(&int_num))
-          arg_numbers[*keyi] = static_cast<double>(int_num);
-        else if (value->GetAsBoolean(&boolean))
-          arg_numbers[*keyi] = static_cast<double>(boolean ? 1 : 0);
-        else if (value->GetAsDouble(&double_num))
-          arg_numbers[*keyi] = double_num;
-        else
-          return false;  // Invalid trace event JSON format.
+  if (!dictionary->GetString("ph", &phase_str)) {
+    LOG(ERROR) << "ph is missing from TraceEvent JSON";
+    return false;
+  }
+
+  phase = base::debug::TraceEvent::GetPhase(phase_str.c_str());
+
+  bool require_origin = (phase != TRACE_EVENT_PHASE_METADATA);
+  bool require_id = (phase == TRACE_EVENT_PHASE_START ||
+                     phase == TRACE_EVENT_PHASE_FINISH);
+
+  if (require_origin && !dictionary->GetInteger("pid", &thread.process_id)) {
+    LOG(ERROR) << "pid is missing from TraceEvent JSON";
+    return false;
+  }
+  if (require_origin && !dictionary->GetInteger("tid", &thread.thread_id)) {
+    LOG(ERROR) << "tid is missing from TraceEvent JSON";
+    return false;
+  }
+  if (require_origin && !dictionary->GetDouble("ts", &timestamp)) {
+    LOG(ERROR) << "ts is missing from TraceEvent JSON";
+    return false;
+  }
+  if (!dictionary->GetString("cat", &category)) {
+    LOG(ERROR) << "cat is missing from TraceEvent JSON";
+    return false;
+  }
+  if (!dictionary->GetString("name", &name)) {
+    LOG(ERROR) << "name is missing from TraceEvent JSON";
+    return false;
+  }
+  if (!dictionary->GetDictionary("args", &args)) {
+    LOG(ERROR) << "args is missing from TraceEvent JSON";
+    return false;
+  }
+  if (require_id && !dictionary->GetString("id", &id)) {
+    LOG(ERROR) << "id is missing from START/FINISH TraceEvent JSON";
+    return false;
+  }
+
+  // For each argument, copy the type and create a trace_analyzer::TraceValue.
+  base::DictionaryValue::key_iterator keyi = args->begin_keys();
+  for (; keyi != args->end_keys(); ++keyi) {
+    std::string str;
+    bool boolean = false;
+    int int_num = 0;
+    double double_num = 0.0;
+    Value* value = NULL;
+    if (args->GetWithoutPathExpansion(*keyi, &value)) {
+      if (value->GetAsString(&str))
+        arg_strings[*keyi] = str;
+      else if (value->GetAsInteger(&int_num))
+        arg_numbers[*keyi] = static_cast<double>(int_num);
+      else if (value->GetAsBoolean(&boolean))
+        arg_numbers[*keyi] = static_cast<double>(boolean ? 1 : 0);
+      else if (value->GetAsDouble(&double_num))
+        arg_numbers[*keyi] = double_num;
+      else {
+        LOG(ERROR) << "Value type of argument is not supported: " <<
+                      static_cast<int>(value->GetType());
+        return false;  // Invalid trace event JSON format.
       }
     }
-
-    return true;
   }
 
-  return false;
+  return true;
 }
 
 double TraceEvent::GetAbsTimeToOtherEvent() const {
@@ -436,6 +468,9 @@ base::debug::TraceValue Query::GetMemberValue(const TraceEvent& event) const {
     case EVENT_NAME:
     case OTHER_NAME:
       return the_event->name;
+    case EVENT_ID:
+    case OTHER_ID:
+      return the_event->id;
     case EVENT_HAS_STRING_ARG:
     case OTHER_HAS_STRING_ARG:
       return (the_event->HasStringArg(string_) ? 1.0 : 0.0);
@@ -641,10 +676,8 @@ bool TraceAnalyzer::SetEvents(const std::string& json_events) {
 void TraceAnalyzer::AssociateBeginEndEvents() {
   using namespace trace_analyzer;
 
-  Query begin(Query(EVENT_PHASE) ==
-      Query::Phase(TRACE_EVENT_PHASE_BEGIN));
-  Query end(Query(EVENT_PHASE) ==
-      Query::Phase(TRACE_EVENT_PHASE_END));
+  Query begin(Query(EVENT_PHASE) == Query::Phase(TRACE_EVENT_PHASE_BEGIN));
+  Query end(Query(EVENT_PHASE) == Query::Phase(TRACE_EVENT_PHASE_END));
   Query match(Query(EVENT_NAME) == Query(OTHER_NAME) &&
               Query(EVENT_CATEGORY) == Query(OTHER_CATEGORY) &&
               Query(EVENT_TID) == Query(OTHER_TID) &&
@@ -653,6 +686,18 @@ void TraceAnalyzer::AssociateBeginEndEvents() {
   AssociateEvents(begin, end, match);
 }
 
+void TraceAnalyzer::AssociateStartFinishEvents() {
+  using namespace trace_analyzer;
+
+  Query begin(Query(EVENT_PHASE) == Query::Phase(TRACE_EVENT_PHASE_START));
+  Query end(Query(EVENT_PHASE) == Query::Phase(TRACE_EVENT_PHASE_FINISH));
+  Query match(Query(EVENT_NAME) == Query(OTHER_NAME) &&
+              Query(EVENT_CATEGORY) == Query(OTHER_CATEGORY) &&
+              Query(EVENT_ID) == Query(OTHER_ID));
+
+  AssociateEvents(begin, end, match);
+}
+
 void TraceAnalyzer::AssociateEvents(const Query& first,
                                     const Query& second,
                                     const Query& match) {

base/test/trace_event_analyzer.h

@@ -158,6 +158,8 @@ struct TraceEvent {
 
   std::string name;
 
+  std::string id;
+
   // 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;
@@ -183,6 +185,7 @@ enum TraceEventMember {
   EVENT_PHASE,
   EVENT_CATEGORY,
   EVENT_NAME,
+  EVENT_ID,
 
   // Evaluates to true if arg exists and is a string.
   // Usage: Query(EVENT_HAS_STRING_ARG, "arg_name")
@@ -205,6 +208,7 @@ enum TraceEventMember {
   OTHER_PHASE,
   OTHER_CATEGORY,
   OTHER_NAME,
+  OTHER_ID,
 
   // Evaluates to true if arg exists and is a string.
   // Usage: Query(EVENT_HAS_STRING_ARG, "arg_name")
@@ -252,8 +256,13 @@ class Query {
 
   // Find BEGIN events that have a corresponding END event.
   static Query MatchBeginWithEnd() {
-    return (Query(EVENT_PHASE) ==
-            Query::Phase(TRACE_EVENT_PHASE_BEGIN)) &&
+    return (Query(EVENT_PHASE) == Query::Phase(TRACE_EVENT_PHASE_BEGIN)) &&
+           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)) &&
            Query(EVENT_HAS_OTHER);
   }
 
@@ -432,6 +441,11 @@ class TraceAnalyzer {
   // about:tracing.
   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();
+
   // AssociateEvents can be used to customize event associations by setting the
   // other_event member of TraceEvent. This should be used to associate two
   // INSTANT events.

base/test/trace_event_analyzer_unittest.cc

@@ -111,6 +111,7 @@ TEST_F(TraceEventAnalyzerTest, QueryEventMember) {
   event.phase = TRACE_EVENT_PHASE_BEGIN;
   event.category = "category";
   event.name = "name";
+  event.id = "1";
   event.arg_numbers["num"] = 7.0;
   event.arg_strings["str"] = "the string";
 
@@ -122,6 +123,7 @@ TEST_F(TraceEventAnalyzerTest, QueryEventMember) {
   other.phase = TRACE_EVENT_PHASE_END;
   other.category = "category2";
   other.name = "name2";
+  other.id = "2";
   other.arg_numbers["num2"] = 8.0;
   other.arg_strings["str2"] = "the string 2";
 
@@ -137,6 +139,7 @@ TEST_F(TraceEventAnalyzerTest, QueryEventMember) {
   Query event_category =
       (Query(EVENT_CATEGORY) == Query::String(event.category));
   Query event_name = (Query(EVENT_NAME) == Query::String(event.name));
+  Query event_id = (Query(EVENT_ID) == Query::String(event.id));
   Query event_has_arg1 = Query(EVENT_HAS_NUMBER_ARG, "num");
   Query event_has_arg2 = Query(EVENT_HAS_STRING_ARG, "str");
   Query event_arg1 =
@@ -151,6 +154,7 @@ TEST_F(TraceEventAnalyzerTest, QueryEventMember) {
   Query other_category =
       (Query(OTHER_CATEGORY) == Query::String(other.category));
   Query other_name = (Query(OTHER_NAME) == Query::String(other.name));
+  Query other_id = (Query(OTHER_ID) == Query::String(other.id));
   Query other_has_arg1 = Query(OTHER_HAS_NUMBER_ARG, "num2");
   Query other_has_arg2 = Query(OTHER_HAS_STRING_ARG, "str2");
   Query other_arg1 =
@@ -165,6 +169,7 @@ TEST_F(TraceEventAnalyzerTest, QueryEventMember) {
   EXPECT_TRUE(event_phase.Evaluate(event));
   EXPECT_TRUE(event_category.Evaluate(event));
   EXPECT_TRUE(event_name.Evaluate(event));
+  EXPECT_TRUE(event_id.Evaluate(event));
   EXPECT_TRUE(event_has_arg1.Evaluate(event));
   EXPECT_TRUE(event_has_arg2.Evaluate(event));
   EXPECT_TRUE(event_arg1.Evaluate(event));
@@ -176,6 +181,7 @@ TEST_F(TraceEventAnalyzerTest, QueryEventMember) {
   EXPECT_TRUE(other_phase.Evaluate(event));
   EXPECT_TRUE(other_category.Evaluate(event));
   EXPECT_TRUE(other_name.Evaluate(event));
+  EXPECT_TRUE(other_id.Evaluate(event));
   EXPECT_TRUE(other_has_arg1.Evaluate(event));
   EXPECT_TRUE(other_has_arg2.Evaluate(event));
   EXPECT_TRUE(other_arg1.Evaluate(event));
@@ -190,6 +196,7 @@ TEST_F(TraceEventAnalyzerTest, QueryEventMember) {
   EXPECT_FALSE(event_phase.Evaluate(other));
   EXPECT_FALSE(event_category.Evaluate(other));
   EXPECT_FALSE(event_name.Evaluate(other));
+  EXPECT_FALSE(event_id.Evaluate(other));
   EXPECT_FALSE(event_has_arg1.Evaluate(other));
   EXPECT_FALSE(event_has_arg2.Evaluate(other));
   EXPECT_FALSE(event_arg1.Evaluate(other));
@@ -414,7 +421,7 @@ TEST_F(TraceEventAnalyzerTest, Duration) {
   EXPECT_STREQ("name3", found[1]->name.c_str());
 }
 
-// Test that arithmetic operators work.
+// Test AssociateBeginEndEvents
 TEST_F(TraceEventAnalyzerTest, BeginEndAssocations) {
   using namespace trace_analyzer;
   ManualSetUp();
@@ -439,6 +446,36 @@ TEST_F(TraceEventAnalyzerTest, BeginEndAssocations) {
   EXPECT_STREQ("name2", found[0]->name.c_str());
 }
 
+// Test AssociateStartFinishEvents
+TEST_F(TraceEventAnalyzerTest, StartFinishAssocations) {
+  using namespace trace_analyzer;
+  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_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
+  }
+  EndTracing();
+
+  scoped_ptr<TraceAnalyzer>
+      analyzer(TraceAnalyzer::Create(output_.json_output));
+  ASSERT_TRUE(analyzer.get());
+  analyzer->AssociateStartFinishEvents();
+
+  TraceAnalyzer::TraceEventVector found;
+  analyzer->FindEvents(Query::MatchStartWithFinish(), &found);
+  ASSERT_EQ(2u, found.size());
+  EXPECT_STRCASEEQ("B", found[0]->id.c_str());
+  EXPECT_STRCASEEQ("C", found[1]->id.c_str());
+}
+
 // Test that the TraceAnalyzer custom associations work.
 TEST_F(TraceEventAnalyzerTest, CustomAssociations) {
   using namespace trace_analyzer;