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

base/debug/trace_event_unittest.cc

 // 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.
 
 #include "base/debug/trace_event.h"
 
 #include "base/bind.h"
 #include "base/command_line.h"
 #include "base/json/json_reader.h"
 #include "base/json/json_writer.h"
@@ skipping 25 matching lines @@
   CompareOp op;
 };
 
 class TraceEventTestFixture : public testing::Test {
  public:
   // This fixture does not use SetUp() because the fixture must be manually set
   // up multiple times when testing AtExit. Use ManualTestSetUp for this.
   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,
                             const char* value);
   void Clear() {
     trace_parsed_.Clear();
     json_output_.json_output.clear();
   }
 
   virtual void SetUp() {
@@ skipping 85 matching lines @@
                                 DictionaryValue* dict) {
   // Scan all key_values, they must all be present and equal.
   while (key_values && key_values->key) {
     if (!IsKeyValueInDict(key_values, dict))
       return false;
     ++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();
   for (size_t i = 0; i < trace_parsed_count; i++) {
     Value* value = NULL;
     trace_parsed_.Get(i, &value);
     if (!value || value->GetType() != Value::TYPE_DICTIONARY)
       continue;
     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},
     {0, 0, IS_EQUAL}
   };
   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[] = {
     {key, value, IS_EQUAL},
     {0, 0, IS_EQUAL}
   };
   return FindMatchingTraceEntry(key_values);
 }
 
 bool TraceEventTestFixture::FindNonMatchingValue(const char* key,
@@ skipping 66 matching lines @@
     DictionaryValue* dict = static_cast<DictionaryValue*>(value);
 
     if (IsStringInDict(string_to_match, dict))
       hits.push_back(dict);
   }
   return hits;
 }
 
 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");
     TRACE_EVENT2("all", "TRACE_EVENT2 call",
                  "name1", "\"value1\"",
                  "name2", "value\\2");
 
     TRACE_EVENT_INSTANT0("all", "TRACE_EVENT_INSTANT0 call");
     TRACE_EVENT_INSTANT1("all", "TRACE_EVENT_INSTANT1 call", "name1", "value1");
     TRACE_EVENT_INSTANT2("all", "TRACE_EVENT_INSTANT2 call",
@@ skipping 29 matching lines @@
     EXPECT_TRUE((item = FindTraceEntry(trace_parsed, string)));
 #define EXPECT_NOT_FIND_(string) \
     EXPECT_FALSE((item = FindTraceEntry(trace_parsed, string)));
 #define EXPECT_SUB_FIND_(string) \
     if (item) EXPECT_TRUE((IsStringInDict(string, item)));
 
   EXPECT_FIND_("ETW Trace Event");
   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");
   EXPECT_FIND_("TRACE_EVENT_INSTANT_ETW call");
   EXPECT_FIND_("TRACE_EVENT0 call");
   {
     std::string ph_begin;
     std::string ph_end;
     EXPECT_TRUE((item = FindTraceEntry(trace_parsed, "TRACE_EVENT0 call")));
     EXPECT_TRUE((item && item->GetString("ph", &ph_begin)));
@@ skipping 326 matching lines @@
   EXPECT_NOT_FIND_BE_("3thresholdlong2");
 
   EXPECT_FIND_BE_("nonthreshold4");
   EXPECT_FIND_BE_("4threshold100");
   EXPECT_FIND_BE_("4threshold1000");
   EXPECT_FIND_BE_("4threshold10000");
   EXPECT_NOT_FIND_BE_("4thresholdlong1");
   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();
   TraceLog* tracer = TraceLog::GetInstance();
   // Make sure old events are flushed:
   tracer->SetEnabled(false);
   EXPECT_EQ(0u, tracer->GetEventsSize());
 
   {
     tracer->SetEnabled(true);
@@ skipping 348 matching lines @@
   Clear();
 
   trace_buffer_.Start();
   trace_buffer_.AddFragment("bla1,bla2,bla3,bla4");
   trace_buffer_.Finish();
   EXPECT_STREQ(json_output_.json_output.c_str(), "[bla1,bla2,bla3,bla4]");
 }
 
 }  // namespace debug
 }  // namespace base