trace_event: distinguish between scoped begin/end and global start/finish events

BUG=100131

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

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

base/debug/trace_event_unittest.cc

@@ -43,8 +43,12 @@ class TraceEventTestFixture : public testing::Test {
   void ManualTestSetUp();
   void OnTraceDataCollected(
       scoped_refptr<TraceLog::RefCountedString> events_str);
-  bool FindMatchingTraceEntry(const JsonKeyValue* key_values);
-  bool FindNamePhase(const char* name, const char* phase);
+  DictionaryValue* FindMatchingTraceEntry(const JsonKeyValue* key_values);
+  DictionaryValue* FindNamePhase(const char* name, const char* phase);
+  DictionaryValue* FindNamePhaseKeyValue(const char* name,
+                                         const char* phase,
+                                         const char* key,
+                                         const char* value);
   bool FindMatchingValue(const char* key,
                          const char* value);
   bool FindNonMatchingValue(const char* key,
@@ -150,7 +154,7 @@ static bool IsAllKeyValueInDict(const JsonKeyValue* key_values,
   return true;
 }
 
-bool TraceEventTestFixture::FindMatchingTraceEntry(
+DictionaryValue* TraceEventTestFixture::FindMatchingTraceEntry(
     const JsonKeyValue* key_values) {
   // Scan all items
   size_t trace_parsed_count = trace_parsed_.GetSize();
@@ -162,12 +166,13 @@ bool TraceEventTestFixture::FindMatchingTraceEntry(
     DictionaryValue* dict = static_cast<DictionaryValue*>(value);
 
     if (IsAllKeyValueInDict(key_values, dict))
-      return true;
+      return dict;
   }
-  return false;
+  return NULL;
 }
 
-bool TraceEventTestFixture::FindNamePhase(const char* name, const char* phase) {
+DictionaryValue* TraceEventTestFixture::FindNamePhase(const char* name,
+                                                      const char* phase) {
   JsonKeyValue key_values[] = {
     {"name", name, IS_EQUAL},
     {"ph", phase, IS_EQUAL},
@@ -176,6 +181,20 @@ bool TraceEventTestFixture::FindNamePhase(const char* name, const char* phase) {
   return FindMatchingTraceEntry(key_values);
 }
 
+DictionaryValue* TraceEventTestFixture::FindNamePhaseKeyValue(
+    const char* name,
+    const char* phase,
+    const char* key,
+    const char* value) {
+  JsonKeyValue key_values[] = {
+    {"name", name, IS_EQUAL},
+    {"ph", phase, IS_EQUAL},
+    {key, value, IS_EQUAL},
+    {0, 0, IS_EQUAL}
+  };
+  return FindMatchingTraceEntry(key_values);
+}
+
 bool TraceEventTestFixture::FindMatchingValue(const char* key,
                                               const char* value) {
   JsonKeyValue key_values[] = {
@@ -262,10 +281,10 @@ std::vector<DictionaryValue*> FindTraceEntries(
 
 void TraceWithAllMacroVariants(WaitableEvent* task_complete_event) {
   {
-    TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW call", 1122, "extrastring1");
-    TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW call", 3344, "extrastring2");
+    TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW call", 0x1122, "extrastring1");
+    TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW call", 0x3344, "extrastring2");
     TRACE_EVENT_INSTANT_ETW("TRACE_EVENT_INSTANT_ETW call",
-                            5566, "extrastring3");
+                            0x5566, "extrastring3");
 
     TRACE_EVENT0("all", "TRACE_EVENT0 call");
     TRACE_EVENT1("all", "TRACE_EVENT1 call", "name1", "value1");
@@ -315,9 +334,9 @@ void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed) {
   EXPECT_FIND_("all");
   EXPECT_FIND_("TRACE_EVENT_BEGIN_ETW call");
   {
-    int int_val = 0;
-    EXPECT_TRUE(item && item->GetInteger("args.id", &int_val));
-    EXPECT_EQ(1122, int_val);
+    std::string str_val;
+    EXPECT_TRUE(item && item->GetString("args.id", &str_val));
+    EXPECT_STREQ("1122", str_val.c_str());
   }
   EXPECT_SUB_FIND_("extrastring1");
   EXPECT_FIND_("TRACE_EVENT_END_ETW call");
@@ -664,6 +683,72 @@ TEST_F(TraceEventTestFixture, DataCapturedThreshold) {
   EXPECT_NOT_FIND_BE_("4thresholdlong2");
 }
 
+// Test Start/Finish events
+TEST_F(TraceEventTestFixture, StartFinishEvents) {
+  ManualTestSetUp();
+  TraceLog::GetInstance()->SetEnabled(true);
+
+  unsigned long long id = 0xfeedbeeffeedbeefull;
+  TRACE_EVENT_START0( "cat", "name1", id);
+  TRACE_EVENT_FINISH0("cat", "name1", id);
+  TRACE_EVENT_BEGIN0( "cat", "name2");
+  TRACE_EVENT_START0( "cat", "name3", 0);
+
+  TraceLog::GetInstance()->SetEnabled(false);
+
+  EXPECT_TRUE(FindNamePhase("name1", "S"));
+  EXPECT_TRUE(FindNamePhase("name1", "F"));
+
+  std::string id_str;
+  StringAppendF(&id_str, "%llx", id);
+
+  EXPECT_TRUE(FindNamePhaseKeyValue("name1", "S", "id", id_str.c_str()));
+  EXPECT_TRUE(FindNamePhaseKeyValue("name1", "F", "id", id_str.c_str()));
+  EXPECT_TRUE(FindNamePhaseKeyValue("name3", "S", "id", "0"));
+
+  // BEGIN events should not have id
+  EXPECT_FALSE(FindNamePhaseKeyValue("name2", "B", "id", "0"));
+}
+
+// Test Start/Finish events
+TEST_F(TraceEventTestFixture, StartFinishPointerMangling) {
+  ManualTestSetUp();
+
+  void* ptr = this;
+
+  TraceLog::GetInstance()->SetProcessID(100);
+  TraceLog::GetInstance()->SetEnabled(true);
+  TRACE_EVENT_START0( "cat", "name1", ptr);
+  TRACE_EVENT_START0( "cat", "name2", ptr);
+  TraceLog::GetInstance()->SetEnabled(false);
+
+  TraceLog::GetInstance()->SetProcessID(200);
+  TraceLog::GetInstance()->SetEnabled(true);
+  TRACE_EVENT_FINISH0( "cat", "name1", ptr);
+  TraceLog::GetInstance()->SetEnabled(false);
+
+  DictionaryValue* start = FindNamePhase("name1", "S");
+  DictionaryValue* start2 = FindNamePhase("name2", "S");
+  DictionaryValue* finish = FindNamePhase("name1", "F");
+  EXPECT_TRUE(start);
+  EXPECT_TRUE(start2);
+  EXPECT_TRUE(finish);
+
+  Value* value = NULL;
+  std::string start_id_str;
+  std::string start2_id_str;
+  std::string finish_id_str;
+  ASSERT_TRUE(start->Get("id", &value));
+  ASSERT_TRUE(value->GetAsString(&start_id_str));
+  ASSERT_TRUE(start2->Get("id", &value));
+  ASSERT_TRUE(value->GetAsString(&start2_id_str));
+  ASSERT_TRUE(finish->Get("id", &value));
+  ASSERT_TRUE(value->GetAsString(&finish_id_str));
+
+  EXPECT_STREQ(start_id_str.c_str(), start2_id_str.c_str());
+  EXPECT_STRNE(start_id_str.c_str(), finish_id_str.c_str());
+}
+
 // Test that static strings are not copied.
 TEST_F(TraceEventTestFixture, StaticStringVsString) {
   ManualTestSetUp();

base/debug/trace_event_win.h

@@ -107,7 +107,7 @@ const base::win::EtwEventType kTraceEventTypeEnd = 0x11;
 const base::win::EtwEventType kTraceEventTypeInstant = 0x12;
 
 // If this flag is set in enable flags
-enum TraceEventFlags {
+enum TraceEventETWFlags {
   CAPTURE_STACK_TRACE = 0x0001,
 };
 

base/debug/trace_event_win_unittest.cc

@@ -216,7 +216,7 @@ TEST_F(TraceEventWinTest, TraceLog) {
   // Full argument version, passing lengths explicitly.
   TraceEventETWProvider::Trace(kName,
                         strlen(kName),
-                        base::debug::TRACE_EVENT_PHASE_BEGIN,
+                        TRACE_EVENT_PHASE_BEGIN,
                         kId,
                         kExtra,
                         strlen(kExtra));
@@ -229,7 +229,7 @@ TEST_F(TraceEventWinTest, TraceLog) {
 
   // Const char* version.
   TraceEventETWProvider::Trace(static_cast<const char*>(kName),
-                        base::debug::TRACE_EVENT_PHASE_END,
+                        TRACE_EVENT_PHASE_END,
                         kId,
                         static_cast<const char*>(kExtra));
 
@@ -241,7 +241,7 @@ TEST_F(TraceEventWinTest, TraceLog) {
 
   // std::string extra version.
   TraceEventETWProvider::Trace(static_cast<const char*>(kName),
-                        base::debug::TRACE_EVENT_PHASE_INSTANT,
+                        TRACE_EVENT_PHASE_INSTANT,
                         kId,
                         std::string(kExtra));
 
@@ -255,7 +255,7 @@ TEST_F(TraceEventWinTest, TraceLog) {
   // Test for sanity on NULL inputs.
   TraceEventETWProvider::Trace(NULL,
                         0,
-                        base::debug::TRACE_EVENT_PHASE_BEGIN,
+                        TRACE_EVENT_PHASE_BEGIN,
                         kId,
                         NULL,
                         0);
@@ -268,7 +268,7 @@ TEST_F(TraceEventWinTest, TraceLog) {
 
   TraceEventETWProvider::Trace(NULL,
                         -1,
-                        base::debug::TRACE_EVENT_PHASE_END,
+                        TRACE_EVENT_PHASE_END,
                         kId,
                         NULL,
                         -1);

base/test/trace_event_analyzer.cc

@@ -18,7 +18,7 @@ namespace trace_analyzer {
 TraceEvent::TraceEvent()
     : thread(0, 0),
       timestamp(0),
-      phase(base::debug::TRACE_EVENT_PHASE_BEGIN),
+      phase(TRACE_EVENT_PHASE_BEGIN),
       other_event(NULL) {
 }
 
@@ -642,9 +642,9 @@ void TraceAnalyzer::AssociateBeginEndEvents() {
   using namespace trace_analyzer;
 
   Query begin(Query(EVENT_PHASE) ==
-      Query::Phase(base::debug::TRACE_EVENT_PHASE_BEGIN));
+      Query::Phase(TRACE_EVENT_PHASE_BEGIN));
   Query end(Query(EVENT_PHASE) ==
-      Query::Phase(base::debug::TRACE_EVENT_PHASE_END));
+      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) &&
@@ -752,7 +752,7 @@ void TraceAnalyzer::ParseMetadata() {
   for (size_t i = 0; i < raw_events_.size(); ++i) {
     TraceEvent& this_event = raw_events_[i];
     // Check for thread name metadata.
-    if (this_event.phase != base::debug::TRACE_EVENT_PHASE_METADATA ||
+    if (this_event.phase != TRACE_EVENT_PHASE_METADATA ||
         this_event.name != "thread_name")
       continue;
     std::map<std::string, std::string>::const_iterator string_it =

base/test/trace_event_analyzer.h

@@ -253,7 +253,7 @@ class Query {
   // Find BEGIN events that have a corresponding END event.
   static Query MatchBeginWithEnd() {
     return (Query(EVENT_PHASE) ==
-            Query::Phase(base::debug::TRACE_EVENT_PHASE_BEGIN)) &&
+            Query::Phase(TRACE_EVENT_PHASE_BEGIN)) &&
            Query(EVENT_HAS_OTHER);
   }
 

base/test/trace_event_analyzer_unittest.cc

@@ -108,7 +108,7 @@ TEST_F(TraceEventAnalyzerTest, QueryEventMember) {
   event.thread.process_id = 3;
   event.thread.thread_id = 4;
   event.timestamp = 1.5;
-  event.phase = base::debug::TRACE_EVENT_PHASE_BEGIN;
+  event.phase = TRACE_EVENT_PHASE_BEGIN;
   event.category = "category";
   event.name = "name";
   event.arg_numbers["num"] = 7.0;
@@ -119,7 +119,7 @@ TEST_F(TraceEventAnalyzerTest, QueryEventMember) {
   other.thread.process_id = 5;
   other.thread.thread_id = 6;
   other.timestamp = 2.5;
-  other.phase = base::debug::TRACE_EVENT_PHASE_END;
+  other.phase = TRACE_EVENT_PHASE_END;
   other.category = "category2";
   other.name = "name2";
   other.arg_numbers["num2"] = 8.0;

chrome/browser/resources/tracing/tests/start_finish.json

+[
+{"cat":"r","pid":1,"tid":1,"ts":50,"ph":"S","name":"A","args":{},"id":"1a"},
+{"cat":"r","pid":1,"tid":1,"ts":100,"ph":"S","name":"B","args":{},"id":"1"},
+{"cat":"r","pid":1,"tid":1,"ts":120,"ph":"B","name":"BE1","args":{}},
+{"cat":"r","pid":1,"tid":1,"ts":150,"ph":"F","name":"D","args":{},"id":"bf1"},
+{"cat":"r","pid":1,"tid":1,"ts":170,"ph":"E","name":"BE1","args":{}},
+{"cat":"r","pid":1,"tid":1,"ts":200,"ph":"S","name":"B","args":{},"id":"2"},
+{"cat":"r","pid":1,"tid":1,"ts":220,"ph":"B","name":"BE1","args":{}},
+{"cat":"r","pid":1,"tid":1,"ts":230,"ph":"B","name":"BE2","args":{}},
+{"cat":"r","pid":1,"tid":1,"ts":250,"ph":"S","name":"A","args":{},"id":"2a"},
+{"cat":"r","pid":1,"tid":1,"ts":270,"ph":"E","name":"BE2","args":{}},
+{"cat":"r","pid":1,"tid":1,"ts":300,"ph":"F","name":"B","args":{},"id":"1"},
+{"cat":"r","pid":1,"tid":1,"ts":350,"ph":"E","name":"BE1","args":{}},
+{"cat":"r","pid":1,"tid":1,"ts":400,"ph":"F","name":"B","args":{},"id":"2"},
+{"cat":"r","pid":2,"tid":2,"ts":500,"ph":"S","name":"E","args":{},"id":"1"},
+{"cat":"r","pid":2,"tid":3,"ts":600,"ph":"S","name":"E","args":{},"id":"2"},
+{"cat":"r","pid":3,"tid":4,"ts":700,"ph":"F","name":"E","args":{},"id":"1"},
+{"cat":"r","pid":1,"tid":1,"ts":725,"ph":"S","name":"D","args":{},"id":"bf2"},
+{"cat":"r","pid":1,"tid":1,"ts":750,"ph":"F","name":"A","args":{},"id":"2a"},
+{"cat":"r","pid":3,"tid":5,"ts":800,"ph":"F","name":"E","args":{},"id":"2"},
+{"cat":"r","pid":1,"tid":1,"ts":900,"ph":"F","name":"A","args":{},"id":"1a"}
+]