base/debug/trace_event_unittest.cc

   1 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "base/debug/trace_event_unittest.h"
   6
   7 #include "base/bind.h"
   8 #include "base/command_line.h"
   9 #include "base/debug/trace_event.h"
  10 #include "base/json/json_reader.h"
  11 #include "base/json/json_writer.h"
  12 #include "base/memory/ref_counted_memory.h"
  13 #include "base/memory/scoped_ptr.h"
  14 #include "base/memory/singleton.h"
  15 #include "base/process_util.h"
  16 #include "base/stringprintf.h"
  17 #include "base/synchronization/waitable_event.h"
  18 #include "base/threading/platform_thread.h"
  19 #include "base/threading/thread.h"
  20 #include "base/values.h"
  21 #include "testing/gmock/include/gmock/gmock.h"
  22 #include "testing/gtest/include/gtest/gtest.h"
  23
  24 using base::debug::HighResSleepForTraceTest;
  25
  26 namespace base {
  27 namespace debug {
  28
  29 namespace {
  30
  31 enum CompareOp {
  32   IS_EQUAL,
  33   IS_NOT_EQUAL,
  34 };
  35
  36 struct JsonKeyValue {
  37   const char* key;
  38   const char* value;
  39   CompareOp op;
  40 };
  41
  42 class TraceEventTestFixture : public testing::Test {
  43  public:
  44   // This fixture does not use SetUp() because the fixture must be manually set
  45   // up multiple times when testing AtExit. Use ManualTestSetUp for this.
  46   void ManualTestSetUp();
  47   void OnTraceDataCollected(
  48       const scoped_refptr<base::RefCountedString>& events_str);
  49   void OnTraceNotification(int notification) {
  50     if (notification & TraceLog::EVENT_WATCH_NOTIFICATION)
  51       ++event_watch_notification_;
  52   }
  53   DictionaryValue* FindMatchingTraceEntry(const JsonKeyValue* key_values);
  54   DictionaryValue* FindNamePhase(const char* name, const char* phase);
  55   DictionaryValue* FindNamePhaseKeyValue(const char* name,
  56                                          const char* phase,
  57                                          const char* key,
  58                                          const char* value);
  59   bool FindMatchingValue(const char* key,
  60                          const char* value);
  61   bool FindNonMatchingValue(const char* key,
  62                             const char* value);
  63   void Clear() {
  64     trace_parsed_.Clear();
  65     json_output_.json_output.clear();
  66   }
  67
  68   void BeginTrace() {
  69     event_watch_notification_ = 0;
  70     TraceLog::GetInstance()->SetEnabled("*");
  71   }
  72
  73   void EndTraceAndFlush() {
  74     TraceLog::GetInstance()->SetDisabled();
  75     TraceLog::GetInstance()->Flush(
  76         base::Bind(&TraceEventTestFixture::OnTraceDataCollected,
  77                    base::Unretained(this)));
  78   }
  79
  80   virtual void SetUp() OVERRIDE {
  81     old_thread_name_ = PlatformThread::GetName();
  82   }
  83   virtual void TearDown() OVERRIDE {
  84     if (TraceLog::GetInstance())
  85       EXPECT_FALSE(TraceLog::GetInstance()->IsEnabled());
  86     PlatformThread::SetName(old_thread_name_ ? old_thread_name_  : "");
  87   }
  88
  89   const char* old_thread_name_;
  90   ListValue trace_parsed_;
  91   base::debug::TraceResultBuffer trace_buffer_;
  92   base::debug::TraceResultBuffer::SimpleOutput json_output_;
  93   int event_watch_notification_;
  94
  95  private:
  96   // We want our singleton torn down after each test.
  97   ShadowingAtExitManager at_exit_manager_;
  98   Lock lock_;
  99 };
 100
 101 void TraceEventTestFixture::ManualTestSetUp() {
 102   TraceLog::DeleteForTesting();
 103   TraceLog::Resurrect();
 104   TraceLog* tracelog = TraceLog::GetInstance();
 105   ASSERT_TRUE(tracelog);
 106   ASSERT_FALSE(tracelog->IsEnabled());
 107   tracelog->SetNotificationCallback(
 108       base::Bind(&TraceEventTestFixture::OnTraceNotification,
 109                  base::Unretained(this)));
 110   trace_buffer_.SetOutputCallback(json_output_.GetCallback());
 111 }
 112
 113 void TraceEventTestFixture::OnTraceDataCollected(
 114     const scoped_refptr<base::RefCountedString>& events_str) {
 115   AutoLock lock(lock_);
 116   json_output_.json_output.clear();
 117   trace_buffer_.Start();
 118   trace_buffer_.AddFragment(events_str->data());
 119   trace_buffer_.Finish();
 120
 121   scoped_ptr<Value> root;
 122   root.reset(base::JSONReader::Read(json_output_.json_output,
 123                                     JSON_PARSE_RFC | JSON_DETACHABLE_CHILDREN));
 124
 125   if (!root.get()) {
 126     LOG(ERROR) << json_output_.json_output;
 127   }
 128
 129   ListValue* root_list = NULL;
 130   ASSERT_TRUE(root.get());
 131   ASSERT_TRUE(root->GetAsList(&root_list));
 132
 133   // Move items into our aggregate collection
 134   while (root_list->GetSize()) {
 135     Value* item = NULL;
 136     root_list->Remove(0, &item);
 137     trace_parsed_.Append(item);
 138   }
 139 }
 140
 141 static bool CompareJsonValues(const std::string& lhs,
 142                               const std::string& rhs,
 143                               CompareOp op) {
 144   switch (op) {
 145     case IS_EQUAL:
 146       return lhs == rhs;
 147     case IS_NOT_EQUAL:
 148       return lhs != rhs;
 149     default:
 150       CHECK(0);
 151   }
 152   return false;
 153 }
 154
 155 static bool IsKeyValueInDict(const JsonKeyValue* key_value,
 156                              DictionaryValue* dict) {
 157   Value* value = NULL;
 158   std::string value_str;
 159   if (dict->Get(key_value->key, &value) &&
 160       value->GetAsString(&value_str) &&
 161       CompareJsonValues(value_str, key_value->value, key_value->op))
 162     return true;
 163
 164   // Recurse to test arguments
 165   DictionaryValue* args_dict = NULL;
 166   dict->GetDictionary("args", &args_dict);
 167   if (args_dict)
 168     return IsKeyValueInDict(key_value, args_dict);
 169
 170   return false;
 171 }
 172
 173 static bool IsAllKeyValueInDict(const JsonKeyValue* key_values,
 174                                 DictionaryValue* dict) {
 175   // Scan all key_values, they must all be present and equal.
 176   while (key_values && key_values->key) {
 177     if (!IsKeyValueInDict(key_values, dict))
 178       return false;
 179     ++key_values;
 180   }
 181   return true;
 182 }
 183
 184 DictionaryValue* TraceEventTestFixture::FindMatchingTraceEntry(
 185     const JsonKeyValue* key_values) {
 186   // Scan all items
 187   size_t trace_parsed_count = trace_parsed_.GetSize();
 188   for (size_t i = 0; i < trace_parsed_count; i++) {
 189     Value* value = NULL;
 190     trace_parsed_.Get(i, &value);
 191     if (!value || value->GetType() != Value::TYPE_DICTIONARY)
 192       continue;
 193     DictionaryValue* dict = static_cast<DictionaryValue*>(value);
 194
 195     if (IsAllKeyValueInDict(key_values, dict))
 196       return dict;
 197   }
 198   return NULL;
 199 }
 200
 201 DictionaryValue* TraceEventTestFixture::FindNamePhase(const char* name,
 202                                                       const char* phase) {
 203   JsonKeyValue key_values[] = {
 204     {"name", name, IS_EQUAL},
 205     {"ph", phase, IS_EQUAL},
 206     {0, 0, IS_EQUAL}
 207   };
 208   return FindMatchingTraceEntry(key_values);
 209 }
 210
 211 DictionaryValue* TraceEventTestFixture::FindNamePhaseKeyValue(
 212     const char* name,
 213     const char* phase,
 214     const char* key,
 215     const char* value) {
 216   JsonKeyValue key_values[] = {
 217     {"name", name, IS_EQUAL},
 218     {"ph", phase, IS_EQUAL},
 219     {key, value, IS_EQUAL},
 220     {0, 0, IS_EQUAL}
 221   };
 222   return FindMatchingTraceEntry(key_values);
 223 }
 224
 225 bool TraceEventTestFixture::FindMatchingValue(const char* key,
 226                                               const char* value) {
 227   JsonKeyValue key_values[] = {
 228     {key, value, IS_EQUAL},
 229     {0, 0, IS_EQUAL}
 230   };
 231   return FindMatchingTraceEntry(key_values);
 232 }
 233
 234 bool TraceEventTestFixture::FindNonMatchingValue(const char* key,
 235                                                  const char* value) {
 236   JsonKeyValue key_values[] = {
 237     {key, value, IS_NOT_EQUAL},
 238     {0, 0, IS_EQUAL}
 239   };
 240   return FindMatchingTraceEntry(key_values);
 241 }
 242
 243 bool IsStringInDict(const char* string_to_match, const DictionaryValue* dict) {
 244   for (DictionaryValue::key_iterator ikey = dict->begin_keys();
 245        ikey != dict->end_keys(); ++ikey) {
 246     const Value* child = NULL;
 247     if (!dict->GetWithoutPathExpansion(*ikey, &child))
 248       continue;
 249
 250     if ((*ikey).find(string_to_match) != std::string::npos)
 251       return true;
 252
 253     std::string value_str;
 254     child->GetAsString(&value_str);
 255     if (value_str.find(string_to_match) != std::string::npos)
 256       return true;
 257   }
 258
 259   // Recurse to test arguments
 260   const DictionaryValue* args_dict = NULL;
 261   dict->GetDictionary("args", &args_dict);
 262   if (args_dict)
 263     return IsStringInDict(string_to_match, args_dict);
 264
 265   return false;
 266 }
 267
 268 const DictionaryValue* FindTraceEntry(
 269     const ListValue& trace_parsed,
 270     const char* string_to_match,
 271     const DictionaryValue* match_after_this_item = NULL) {
 272   // Scan all items
 273   size_t trace_parsed_count = trace_parsed.GetSize();
 274   for (size_t i = 0; i < trace_parsed_count; i++) {
 275     const Value* value = NULL;
 276     trace_parsed.Get(i, &value);
 277     if (match_after_this_item) {
 278       if (value == match_after_this_item)
 279          match_after_this_item = NULL;
 280       continue;
 281     }
 282     if (!value || value->GetType() != Value::TYPE_DICTIONARY)
 283       continue;
 284     const DictionaryValue* dict = static_cast<const DictionaryValue*>(value);
 285
 286     if (IsStringInDict(string_to_match, dict))
 287       return dict;
 288   }
 289   return NULL;
 290 }
 291
 292 std::vector<const DictionaryValue*> FindTraceEntries(
 293     const ListValue& trace_parsed,
 294     const char* string_to_match) {
 295   std::vector<const DictionaryValue*> hits;
 296   size_t trace_parsed_count = trace_parsed.GetSize();
 297   for (size_t i = 0; i < trace_parsed_count; i++) {
 298     const Value* value = NULL;
 299     trace_parsed.Get(i, &value);
 300     if (!value || value->GetType() != Value::TYPE_DICTIONARY)
 301       continue;
 302     const DictionaryValue* dict = static_cast<const DictionaryValue*>(value);
 303
 304     if (IsStringInDict(string_to_match, dict))
 305       hits.push_back(dict);
 306   }
 307   return hits;
 308 }
 309
 310 void TraceWithAllMacroVariants(WaitableEvent* task_complete_event) {
 311   {
 312     TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW call", 0x1122, "extrastring1");
 313     TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW call", 0x3344, "extrastring2");
 314     TRACE_EVENT_INSTANT_ETW("TRACE_EVENT_INSTANT_ETW call",
 315                             0x5566, "extrastring3");
 316
 317     TRACE_EVENT0("all", "TRACE_EVENT0 call");
 318     TRACE_EVENT1("all", "TRACE_EVENT1 call", "name1", "value1");
 319     TRACE_EVENT2("all", "TRACE_EVENT2 call",
 320                  "name1", "\"value1\"",
 321                  "name2", "value\\2");
 322
 323     TRACE_EVENT_INSTANT0("all", "TRACE_EVENT_INSTANT0 call");
 324     TRACE_EVENT_INSTANT1("all", "TRACE_EVENT_INSTANT1 call", "name1", "value1");
 325     TRACE_EVENT_INSTANT2("all", "TRACE_EVENT_INSTANT2 call",
 326                          "name1", "value1",
 327                          "name2", "value2");
 328
 329     TRACE_EVENT_BEGIN0("all", "TRACE_EVENT_BEGIN0 call");
 330     TRACE_EVENT_BEGIN1("all", "TRACE_EVENT_BEGIN1 call", "name1", "value1");
 331     TRACE_EVENT_BEGIN2("all", "TRACE_EVENT_BEGIN2 call",
 332                        "name1", "value1",
 333                        "name2", "value2");
 334
 335     TRACE_EVENT_END0("all", "TRACE_EVENT_END0 call");
 336     TRACE_EVENT_END1("all", "TRACE_EVENT_END1 call", "name1", "value1");
 337     TRACE_EVENT_END2("all", "TRACE_EVENT_END2 call",
 338                      "name1", "value1",
 339                      "name2", "value2");
 340
 341     TRACE_EVENT_ASYNC_BEGIN0("all", "TRACE_EVENT_ASYNC_BEGIN0 call", 5);
 342     TRACE_EVENT_ASYNC_BEGIN1("all", "TRACE_EVENT_ASYNC_BEGIN1 call", 5,
 343                              "name1", "value1");
 344     TRACE_EVENT_ASYNC_BEGIN2("all", "TRACE_EVENT_ASYNC_BEGIN2 call", 5,
 345                              "name1", "value1",
 346                              "name2", "value2");
 347
 348     TRACE_EVENT_ASYNC_STEP0("all", "TRACE_EVENT_ASYNC_STEP0 call",
 349                                   5, "step1");
 350     TRACE_EVENT_ASYNC_STEP1("all", "TRACE_EVENT_ASYNC_STEP1 call",
 351                                   5, "step2", "name1", "value1");
 352
 353     TRACE_EVENT_ASYNC_END0("all", "TRACE_EVENT_ASYNC_END0 call", 5);
 354     TRACE_EVENT_ASYNC_END1("all", "TRACE_EVENT_ASYNC_END1 call", 5,
 355                            "name1", "value1");
 356     TRACE_EVENT_ASYNC_END2("all", "TRACE_EVENT_ASYNC_END2 call", 5,
 357                            "name1", "value1",
 358                            "name2", "value2");
 359
 360     TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW0 call", 5, NULL);
 361     TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW1 call", 5, "value");
 362     TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW0 call", 5, NULL);
 363     TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW1 call", 5, "value");
 364     TRACE_EVENT_INSTANT_ETW("TRACE_EVENT_INSTANT_ETW0 call", 5, NULL);
 365     TRACE_EVENT_INSTANT_ETW("TRACE_EVENT_INSTANT_ETW1 call", 5, "value");
 366
 367     TRACE_COUNTER1("all", "TRACE_COUNTER1 call", 31415);
 368     TRACE_COUNTER2("all", "TRACE_COUNTER2 call",
 369                    "a", 30000,
 370                    "b", 1415);
 371
 372     TRACE_COUNTER_ID1("all", "TRACE_COUNTER_ID1 call", 0x319009, 31415);
 373     TRACE_COUNTER_ID2("all", "TRACE_COUNTER_ID2 call", 0x319009,
 374                       "a", 30000, "b", 1415);
 375   } // Scope close causes TRACE_EVENT0 etc to send their END events.
 376
 377   if (task_complete_event)
 378     task_complete_event->Signal();
 379 }
 380
 381 void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed) {
 382   const DictionaryValue* item = NULL;
 383
 384 #define EXPECT_FIND_(string) \
 385     EXPECT_TRUE((item = FindTraceEntry(trace_parsed, string)));
 386 #define EXPECT_NOT_FIND_(string) \
 387     EXPECT_FALSE((item = FindTraceEntry(trace_parsed, string)));
 388 #define EXPECT_SUB_FIND_(string) \
 389     if (item) EXPECT_TRUE((IsStringInDict(string, item)));
 390
 391   EXPECT_FIND_("ETW Trace Event");
 392   EXPECT_FIND_("all");
 393   EXPECT_FIND_("TRACE_EVENT_BEGIN_ETW call");
 394   {
 395     std::string str_val;
 396     EXPECT_TRUE(item && item->GetString("args.id", &str_val));
 397     EXPECT_STREQ("1122", str_val.c_str());
 398   }
 399   EXPECT_SUB_FIND_("extrastring1");
 400   EXPECT_FIND_("TRACE_EVENT_END_ETW call");
 401   EXPECT_FIND_("TRACE_EVENT_INSTANT_ETW call");
 402   EXPECT_FIND_("TRACE_EVENT0 call");
 403   {
 404     std::string ph_begin;
 405     std::string ph_end;
 406     EXPECT_TRUE((item = FindTraceEntry(trace_parsed, "TRACE_EVENT0 call")));
 407     EXPECT_TRUE((item && item->GetString("ph", &ph_begin)));
 408     EXPECT_TRUE((item = FindTraceEntry(trace_parsed, "TRACE_EVENT0 call",
 409                                        item)));
 410     EXPECT_TRUE((item && item->GetString("ph", &ph_end)));
 411     EXPECT_EQ("B", ph_begin);
 412     EXPECT_EQ("E", ph_end);
 413   }
 414   EXPECT_FIND_("TRACE_EVENT1 call");
 415   EXPECT_SUB_FIND_("name1");
 416   EXPECT_SUB_FIND_("value1");
 417   EXPECT_FIND_("TRACE_EVENT2 call");
 418   EXPECT_SUB_FIND_("name1");
 419   EXPECT_SUB_FIND_("\"value1\"");
 420   EXPECT_SUB_FIND_("name2");
 421   EXPECT_SUB_FIND_("value\\2");
 422
 423   EXPECT_FIND_("TRACE_EVENT_INSTANT0 call");
 424   EXPECT_FIND_("TRACE_EVENT_INSTANT1 call");
 425   EXPECT_SUB_FIND_("name1");
 426   EXPECT_SUB_FIND_("value1");
 427   EXPECT_FIND_("TRACE_EVENT_INSTANT2 call");
 428   EXPECT_SUB_FIND_("name1");
 429   EXPECT_SUB_FIND_("value1");
 430   EXPECT_SUB_FIND_("name2");
 431   EXPECT_SUB_FIND_("value2");
 432
 433   EXPECT_FIND_("TRACE_EVENT_BEGIN0 call");
 434   EXPECT_FIND_("TRACE_EVENT_BEGIN1 call");
 435   EXPECT_SUB_FIND_("name1");
 436   EXPECT_SUB_FIND_("value1");
 437   EXPECT_FIND_("TRACE_EVENT_BEGIN2 call");
 438   EXPECT_SUB_FIND_("name1");
 439   EXPECT_SUB_FIND_("value1");
 440   EXPECT_SUB_FIND_("name2");
 441   EXPECT_SUB_FIND_("value2");
 442
 443   EXPECT_FIND_("TRACE_EVENT_END0 call");
 444   EXPECT_FIND_("TRACE_EVENT_END1 call");
 445   EXPECT_SUB_FIND_("name1");
 446   EXPECT_SUB_FIND_("value1");
 447   EXPECT_FIND_("TRACE_EVENT_END2 call");
 448   EXPECT_SUB_FIND_("name1");
 449   EXPECT_SUB_FIND_("value1");
 450   EXPECT_SUB_FIND_("name2");
 451   EXPECT_SUB_FIND_("value2");
 452
 453   EXPECT_FIND_("TRACE_EVENT_ASYNC_BEGIN0 call");
 454   EXPECT_SUB_FIND_("id");
 455   EXPECT_SUB_FIND_("5");
 456   EXPECT_FIND_("TRACE_EVENT_ASYNC_BEGIN1 call");
 457   EXPECT_SUB_FIND_("id");
 458   EXPECT_SUB_FIND_("5");
 459   EXPECT_SUB_FIND_("name1");
 460   EXPECT_SUB_FIND_("value1");
 461   EXPECT_FIND_("TRACE_EVENT_ASYNC_BEGIN2 call");
 462   EXPECT_SUB_FIND_("id");
 463   EXPECT_SUB_FIND_("5");
 464   EXPECT_SUB_FIND_("name1");
 465   EXPECT_SUB_FIND_("value1");
 466   EXPECT_SUB_FIND_("name2");
 467   EXPECT_SUB_FIND_("value2");
 468
 469   EXPECT_FIND_("TRACE_EVENT_ASYNC_STEP0 call");
 470   EXPECT_SUB_FIND_("id");
 471   EXPECT_SUB_FIND_("5");
 472   EXPECT_SUB_FIND_("step1");
 473   EXPECT_FIND_("TRACE_EVENT_ASYNC_STEP1 call");
 474   EXPECT_SUB_FIND_("id");
 475   EXPECT_SUB_FIND_("5");
 476   EXPECT_SUB_FIND_("step2");
 477   EXPECT_SUB_FIND_("name1");
 478   EXPECT_SUB_FIND_("value1");
 479
 480   EXPECT_FIND_("TRACE_EVENT_ASYNC_END0 call");
 481   EXPECT_SUB_FIND_("id");
 482   EXPECT_SUB_FIND_("5");
 483   EXPECT_FIND_("TRACE_EVENT_ASYNC_END1 call");
 484   EXPECT_SUB_FIND_("id");
 485   EXPECT_SUB_FIND_("5");
 486   EXPECT_SUB_FIND_("name1");
 487   EXPECT_SUB_FIND_("value1");
 488   EXPECT_FIND_("TRACE_EVENT_ASYNC_END2 call");
 489   EXPECT_SUB_FIND_("id");
 490   EXPECT_SUB_FIND_("5");
 491   EXPECT_SUB_FIND_("name1");
 492   EXPECT_SUB_FIND_("value1");
 493   EXPECT_SUB_FIND_("name2");
 494   EXPECT_SUB_FIND_("value2");
 495
 496   EXPECT_FIND_("TRACE_EVENT_BEGIN_ETW0 call");
 497   EXPECT_SUB_FIND_("id");
 498   EXPECT_SUB_FIND_("5");
 499   EXPECT_SUB_FIND_("extra");
 500   EXPECT_SUB_FIND_("NULL");
 501   EXPECT_FIND_("TRACE_EVENT_BEGIN_ETW1 call");
 502   EXPECT_SUB_FIND_("id");
 503   EXPECT_SUB_FIND_("5");
 504   EXPECT_SUB_FIND_("extra");
 505   EXPECT_SUB_FIND_("value");
 506   EXPECT_FIND_("TRACE_EVENT_END_ETW0 call");
 507   EXPECT_SUB_FIND_("id");
 508   EXPECT_SUB_FIND_("5");
 509   EXPECT_SUB_FIND_("extra");
 510   EXPECT_SUB_FIND_("NULL");
 511   EXPECT_FIND_("TRACE_EVENT_END_ETW1 call");
 512   EXPECT_SUB_FIND_("id");
 513   EXPECT_SUB_FIND_("5");
 514   EXPECT_SUB_FIND_("extra");
 515   EXPECT_SUB_FIND_("value");
 516   EXPECT_FIND_("TRACE_EVENT_INSTANT_ETW0 call");
 517   EXPECT_SUB_FIND_("id");
 518   EXPECT_SUB_FIND_("5");
 519   EXPECT_SUB_FIND_("extra");
 520   EXPECT_SUB_FIND_("NULL");
 521   EXPECT_FIND_("TRACE_EVENT_INSTANT_ETW1 call");
 522   EXPECT_SUB_FIND_("id");
 523   EXPECT_SUB_FIND_("5");
 524   EXPECT_SUB_FIND_("extra");
 525   EXPECT_SUB_FIND_("value");
 526
 527   EXPECT_FIND_("TRACE_COUNTER1 call");
 528   {
 529     std::string ph;
 530     EXPECT_TRUE((item && item->GetString("ph", &ph)));
 531     EXPECT_EQ("C", ph);
 532
 533     int value;
 534     EXPECT_TRUE((item && item->GetInteger("args.value", &value)));
 535     EXPECT_EQ(31415, value);
 536   }
 537
 538   EXPECT_FIND_("TRACE_COUNTER2 call");
 539   {
 540     std::string ph;
 541     EXPECT_TRUE((item && item->GetString("ph", &ph)));
 542     EXPECT_EQ("C", ph);
 543
 544     int value;
 545     EXPECT_TRUE((item && item->GetInteger("args.a", &value)));
 546     EXPECT_EQ(30000, value);
 547
 548     EXPECT_TRUE((item && item->GetInteger("args.b", &value)));
 549     EXPECT_EQ(1415, value);
 550   }
 551
 552   EXPECT_FIND_("TRACE_COUNTER_ID1 call");
 553   {
 554     std::string id;
 555     EXPECT_TRUE((item && item->GetString("id", &id)));
 556     EXPECT_EQ("319009", id);
 557
 558     std::string ph;
 559     EXPECT_TRUE((item && item->GetString("ph", &ph)));
 560     EXPECT_EQ("C", ph);
 561
 562     int value;
 563     EXPECT_TRUE((item && item->GetInteger("args.value", &value)));
 564     EXPECT_EQ(31415, value);
 565   }
 566
 567   EXPECT_FIND_("TRACE_COUNTER_ID2 call");
 568   {
 569     std::string id;
 570     EXPECT_TRUE((item && item->GetString("id", &id)));
 571     EXPECT_EQ("319009", id);
 572
 573     std::string ph;
 574     EXPECT_TRUE((item && item->GetString("ph", &ph)));
 575     EXPECT_EQ("C", ph);
 576
 577     int value;
 578     EXPECT_TRUE((item && item->GetInteger("args.a", &value)));
 579     EXPECT_EQ(30000, value);
 580
 581     EXPECT_TRUE((item && item->GetInteger("args.b", &value)));
 582     EXPECT_EQ(1415, value);
 583   }
 584 }
 585
 586 void TraceManyInstantEvents(int thread_id, int num_events,
 587                             WaitableEvent* task_complete_event) {
 588   for (int i = 0; i < num_events; i++) {
 589     TRACE_EVENT_INSTANT2("all", "multi thread event",
 590                          "thread", thread_id,
 591                          "event", i);
 592   }
 593
 594   if (task_complete_event)
 595     task_complete_event->Signal();
 596 }
 597
 598 void ValidateInstantEventPresentOnEveryThread(const ListValue& trace_parsed,
 599                                               int num_threads,
 600                                               int num_events) {
 601   std::map<int, std::map<int, bool> > results;
 602
 603   size_t trace_parsed_count = trace_parsed.GetSize();
 604   for (size_t i = 0; i < trace_parsed_count; i++) {
 605     const Value* value = NULL;
 606     trace_parsed.Get(i, &value);
 607     if (!value || value->GetType() != Value::TYPE_DICTIONARY)
 608       continue;
 609     const DictionaryValue* dict = static_cast<const DictionaryValue*>(value);
 610     std::string name;
 611     dict->GetString("name", &name);
 612     if (name != "multi thread event")
 613       continue;
 614
 615     int thread = 0;
 616     int event = 0;
 617     EXPECT_TRUE(dict->GetInteger("args.thread", &thread));
 618     EXPECT_TRUE(dict->GetInteger("args.event", &event));
 619     results[thread][event] = true;
 620   }
 621
 622   EXPECT_FALSE(results[-1][-1]);
 623   for (int thread = 0; thread < num_threads; thread++) {
 624     for (int event = 0; event < num_events; event++) {
 625       EXPECT_TRUE(results[thread][event]);
 626     }
 627   }
 628 }
 629
 630 void TraceCallsWithCachedCategoryPointersPointers(const char* name_str) {
 631   TRACE_EVENT0("category name1", name_str);
 632   TRACE_EVENT_INSTANT0("category name2", name_str);
 633   TRACE_EVENT_BEGIN0("category name3", name_str);
 634   TRACE_EVENT_END0("category name4", name_str);
 635 }
 636
 637 }  // namespace
 638
 639 void HighResSleepForTraceTest(base::TimeDelta elapsed) {
 640   base::TimeTicks end_time = base::TimeTicks::HighResNow() + elapsed;
 641   do {
 642     base::PlatformThread::Sleep(base::TimeDelta::FromMilliseconds(1));
 643   } while (base::TimeTicks::HighResNow() < end_time);
 644 }
 645
 646 // Simple Test for emitting data and validating it was received.
 647 TEST_F(TraceEventTestFixture, DataCaptured) {
 648   ManualTestSetUp();
 649   TraceLog::GetInstance()->SetEnabled(true);
 650
 651   TraceWithAllMacroVariants(NULL);
 652
 653   EndTraceAndFlush();
 654
 655   ValidateAllTraceMacrosCreatedData(trace_parsed_);
 656 }
 657
 658 class MockEnabledStateChangedObserver :
 659       public base::debug::TraceLog::EnabledStateChangedObserver {
 660  public:
 661   MOCK_METHOD0(OnTraceLogWillEnable, void());
 662   MOCK_METHOD0(OnTraceLogWillDisable, void());
 663 };
 664
 665 TEST_F(TraceEventTestFixture, EnabledObserverFiresOnEnable) {
 666   ManualTestSetUp();
 667
 668   MockEnabledStateChangedObserver observer;
 669   TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
 670
 671   EXPECT_CALL(observer, OnTraceLogWillEnable())
 672       .Times(1);
 673   TraceLog::GetInstance()->SetEnabled(true);
 674   testing::Mock::VerifyAndClear(&observer);
 675
 676   // Cleanup.
 677   TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
 678   TraceLog::GetInstance()->SetEnabled(false);
 679 }
 680
 681 TEST_F(TraceEventTestFixture, EnabledObserverDoesntFireOnSecondEnable) {
 682   ManualTestSetUp();
 683
 684   TraceLog::GetInstance()->SetEnabled(true);
 685
 686   testing::StrictMock<MockEnabledStateChangedObserver> observer;
 687   TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
 688
 689   EXPECT_CALL(observer, OnTraceLogWillEnable())
 690       .Times(0);
 691   EXPECT_CALL(observer, OnTraceLogWillDisable())
 692       .Times(0);
 693   TraceLog::GetInstance()->SetEnabled(true);
 694   testing::Mock::VerifyAndClear(&observer);
 695
 696   // Cleanup.
 697   TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
 698   TraceLog::GetInstance()->SetEnabled(false);
 699 }
 700
 701 TEST_F(TraceEventTestFixture, EnabledObserverDoesntFireOnUselessDisable) {
 702   ManualTestSetUp();
 703
 704
 705   testing::StrictMock<MockEnabledStateChangedObserver> observer;
 706   TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
 707
 708   EXPECT_CALL(observer, OnTraceLogWillEnable())
 709       .Times(0);
 710   EXPECT_CALL(observer, OnTraceLogWillDisable())
 711       .Times(0);
 712   TraceLog::GetInstance()->SetEnabled(false);
 713   testing::Mock::VerifyAndClear(&observer);
 714
 715   // Cleanup.
 716   TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
 717 }
 718
 719 TEST_F(TraceEventTestFixture, EnabledObserverFiresOnDisable) {
 720   ManualTestSetUp();
 721
 722   TraceLog::GetInstance()->SetEnabled(true);
 723
 724   MockEnabledStateChangedObserver observer;
 725   TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
 726
 727   EXPECT_CALL(observer, OnTraceLogWillDisable())
 728       .Times(1);
 729   TraceLog::GetInstance()->SetEnabled(false);
 730   testing::Mock::VerifyAndClear(&observer);
 731
 732   // Cleanup.
 733   TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
 734 }
 735
 736 // Test that categories work.
 737 TEST_F(TraceEventTestFixture, Categories) {
 738   ManualTestSetUp();
 739
 740   // Test that categories that are used can be retrieved whether trace was
 741   // enabled or disabled when the trace event was encountered.
 742   TRACE_EVENT_INSTANT0("c1", "name");
 743   TRACE_EVENT_INSTANT0("c2", "name");
 744   BeginTrace();
 745   TRACE_EVENT_INSTANT0("c3", "name");
 746   TRACE_EVENT_INSTANT0("c4", "name");
 747   EndTraceAndFlush();
 748   std::vector<std::string> cats;
 749   TraceLog::GetInstance()->GetKnownCategories(&cats);
 750   EXPECT_TRUE(std::find(cats.begin(), cats.end(), "c1") != cats.end());
 751   EXPECT_TRUE(std::find(cats.begin(), cats.end(), "c2") != cats.end());
 752   EXPECT_TRUE(std::find(cats.begin(), cats.end(), "c3") != cats.end());
 753   EXPECT_TRUE(std::find(cats.begin(), cats.end(), "c4") != cats.end());
 754
 755   const std::vector<std::string> empty_categories;
 756   std::vector<std::string> included_categories;
 757   std::vector<std::string> excluded_categories;
 758
 759   // Test that category filtering works.
 760
 761   // Include nonexistent category -> no events
 762   Clear();
 763   included_categories.clear();
 764   included_categories.push_back("not_found823564786");
 765   TraceLog::GetInstance()->SetEnabled(included_categories, empty_categories);
 766   TRACE_EVENT_INSTANT0("cat1", "name");
 767   TRACE_EVENT_INSTANT0("cat2", "name");
 768   EndTraceAndFlush();
 769   EXPECT_TRUE(trace_parsed_.empty());
 770
 771   // Include existent category -> only events of that category
 772   Clear();
 773   included_categories.clear();
 774   included_categories.push_back("inc");
 775   TraceLog::GetInstance()->SetEnabled(included_categories, empty_categories);
 776   TRACE_EVENT_INSTANT0("inc", "name");
 777   TRACE_EVENT_INSTANT0("inc2", "name");
 778   EndTraceAndFlush();
 779   EXPECT_TRUE(FindMatchingValue("cat", "inc"));
 780   EXPECT_FALSE(FindNonMatchingValue("cat", "inc"));
 781
 782   // Include existent wildcard -> all categories matching wildcard
 783   Clear();
 784   included_categories.clear();
 785   included_categories.push_back("inc_wildcard_*");
 786   included_categories.push_back("inc_wildchar_?_end");
 787   TraceLog::GetInstance()->SetEnabled(included_categories, empty_categories);
 788   TRACE_EVENT_INSTANT0("inc_wildcard_abc", "included");
 789   TRACE_EVENT_INSTANT0("inc_wildcard_", "included");
 790   TRACE_EVENT_INSTANT0("inc_wildchar_x_end", "included");
 791   TRACE_EVENT_INSTANT0("inc_wildchar_bla_end", "not_inc");
 792   TRACE_EVENT_INSTANT0("cat1", "not_inc");
 793   TRACE_EVENT_INSTANT0("cat2", "not_inc");
 794   EndTraceAndFlush();
 795   EXPECT_TRUE(FindMatchingValue("cat", "inc_wildcard_abc"));
 796   EXPECT_TRUE(FindMatchingValue("cat", "inc_wildcard_"));
 797   EXPECT_TRUE(FindMatchingValue("cat", "inc_wildchar_x_end"));
 798   EXPECT_FALSE(FindMatchingValue("name", "not_inc"));
 799
 800   included_categories.clear();
 801
 802   // Exclude nonexistent category -> all events
 803   Clear();
 804   excluded_categories.clear();
 805   excluded_categories.push_back("not_found823564786");
 806   TraceLog::GetInstance()->SetEnabled(empty_categories, excluded_categories);
 807   TRACE_EVENT_INSTANT0("cat1", "name");
 808   TRACE_EVENT_INSTANT0("cat2", "name");
 809   EndTraceAndFlush();
 810   EXPECT_TRUE(FindMatchingValue("cat", "cat1"));
 811   EXPECT_TRUE(FindMatchingValue("cat", "cat2"));
 812
 813   // Exclude existent category -> only events of other categories
 814   Clear();
 815   excluded_categories.clear();
 816   excluded_categories.push_back("inc");
 817   TraceLog::GetInstance()->SetEnabled(empty_categories, excluded_categories);
 818   TRACE_EVENT_INSTANT0("inc", "name");
 819   TRACE_EVENT_INSTANT0("inc2", "name");
 820   EndTraceAndFlush();
 821   EXPECT_TRUE(FindMatchingValue("cat", "inc2"));
 822   EXPECT_FALSE(FindMatchingValue("cat", "inc"));
 823
 824   // Exclude existent wildcard -> all categories not matching wildcard
 825   Clear();
 826   excluded_categories.clear();
 827   excluded_categories.push_back("inc_wildcard_*");
 828   excluded_categories.push_back("inc_wildchar_?_end");
 829   TraceLog::GetInstance()->SetEnabled(empty_categories, excluded_categories);
 830   TRACE_EVENT_INSTANT0("inc_wildcard_abc", "not_inc");
 831   TRACE_EVENT_INSTANT0("inc_wildcard_", "not_inc");
 832   TRACE_EVENT_INSTANT0("inc_wildchar_x_end", "not_inc");
 833   TRACE_EVENT_INSTANT0("inc_wildchar_bla_end", "included");
 834   TRACE_EVENT_INSTANT0("cat1", "included");
 835   TRACE_EVENT_INSTANT0("cat2", "included");
 836   EndTraceAndFlush();
 837   EXPECT_TRUE(FindMatchingValue("cat", "inc_wildchar_bla_end"));
 838   EXPECT_TRUE(FindMatchingValue("cat", "cat1"));
 839   EXPECT_TRUE(FindMatchingValue("cat", "cat2"));
 840   EXPECT_FALSE(FindMatchingValue("name", "not_inc"));
 841 }
 842
 843
 844 // Test EVENT_WATCH_NOTIFICATION
 845 TEST_F(TraceEventTestFixture, EventWatchNotification) {
 846   ManualTestSetUp();
 847
 848   // Basic one occurrence.
 849   BeginTrace();
 850   TraceLog::GetInstance()->SetWatchEvent("cat", "event");
 851   TRACE_EVENT_INSTANT0("cat", "event");
 852   EndTraceAndFlush();
 853   EXPECT_EQ(event_watch_notification_, 1);
 854
 855   // Basic one occurrence before Set.
 856   BeginTrace();
 857   TRACE_EVENT_INSTANT0("cat", "event");
 858   TraceLog::GetInstance()->SetWatchEvent("cat", "event");
 859   EndTraceAndFlush();
 860   EXPECT_EQ(event_watch_notification_, 1);
 861
 862   // Auto-reset after end trace.
 863   BeginTrace();
 864   TraceLog::GetInstance()->SetWatchEvent("cat", "event");
 865   EndTraceAndFlush();
 866   BeginTrace();
 867   TRACE_EVENT_INSTANT0("cat", "event");
 868   EndTraceAndFlush();
 869   EXPECT_EQ(event_watch_notification_, 0);
 870
 871   // Multiple occurrence.
 872   BeginTrace();
 873   int num_occurrences = 5;
 874   TraceLog::GetInstance()->SetWatchEvent("cat", "event");
 875   for (int i = 0; i < num_occurrences; ++i)
 876     TRACE_EVENT_INSTANT0("cat", "event");
 877   EndTraceAndFlush();
 878   EXPECT_EQ(event_watch_notification_, num_occurrences);
 879
 880   // Wrong category.
 881   BeginTrace();
 882   TraceLog::GetInstance()->SetWatchEvent("cat", "event");
 883   TRACE_EVENT_INSTANT0("wrong_cat", "event");
 884   EndTraceAndFlush();
 885   EXPECT_EQ(event_watch_notification_, 0);
 886
 887   // Wrong name.
 888   BeginTrace();
 889   TraceLog::GetInstance()->SetWatchEvent("cat", "event");
 890   TRACE_EVENT_INSTANT0("cat", "wrong_event");
 891   EndTraceAndFlush();
 892   EXPECT_EQ(event_watch_notification_, 0);
 893
 894   // Canceled.
 895   BeginTrace();
 896   TraceLog::GetInstance()->SetWatchEvent("cat", "event");
 897   TraceLog::GetInstance()->CancelWatchEvent();
 898   TRACE_EVENT_INSTANT0("cat", "event");
 899   EndTraceAndFlush();
 900   EXPECT_EQ(event_watch_notification_, 0);
 901 }
 902
 903 // Test ASYNC_BEGIN/END events
 904 TEST_F(TraceEventTestFixture, AsyncBeginEndEvents) {
 905   ManualTestSetUp();
 906   BeginTrace();
 907
 908   unsigned long long id = 0xfeedbeeffeedbeefull;
 909   TRACE_EVENT_ASYNC_BEGIN0( "cat", "name1", id);
 910   TRACE_EVENT_ASYNC_STEP0( "cat", "name1", id, "step1");
 911   TRACE_EVENT_ASYNC_END0("cat", "name1", id);
 912   TRACE_EVENT_BEGIN0( "cat", "name2");
 913   TRACE_EVENT_ASYNC_BEGIN0( "cat", "name3", 0);
 914
 915   EndTraceAndFlush();
 916
 917   EXPECT_TRUE(FindNamePhase("name1", "S"));
 918   EXPECT_TRUE(FindNamePhase("name1", "T"));
 919   EXPECT_TRUE(FindNamePhase("name1", "F"));
 920
 921   std::string id_str;
 922   StringAppendF(&id_str, "%llx", id);
 923
 924   EXPECT_TRUE(FindNamePhaseKeyValue("name1", "S", "id", id_str.c_str()));
 925   EXPECT_TRUE(FindNamePhaseKeyValue("name1", "T", "id", id_str.c_str()));
 926   EXPECT_TRUE(FindNamePhaseKeyValue("name1", "F", "id", id_str.c_str()));
 927   EXPECT_TRUE(FindNamePhaseKeyValue("name3", "S", "id", "0"));
 928
 929   // BEGIN events should not have id
 930   EXPECT_FALSE(FindNamePhaseKeyValue("name2", "B", "id", "0"));
 931 }
 932
 933 // Test ASYNC_BEGIN/END events
 934 TEST_F(TraceEventTestFixture, AsyncBeginEndPointerMangling) {
 935   ManualTestSetUp();
 936
 937   void* ptr = this;
 938
 939   TraceLog::GetInstance()->SetProcessID(100);
 940   BeginTrace();
 941   TRACE_EVENT_ASYNC_BEGIN0( "cat", "name1", ptr);
 942   TRACE_EVENT_ASYNC_BEGIN0( "cat", "name2", ptr);
 943   EndTraceAndFlush();
 944
 945   TraceLog::GetInstance()->SetProcessID(200);
 946   BeginTrace();
 947   TRACE_EVENT_ASYNC_END0( "cat", "name1", ptr);
 948   EndTraceAndFlush();
 949
 950   DictionaryValue* async_begin = FindNamePhase("name1", "S");
 951   DictionaryValue* async_begin2 = FindNamePhase("name2", "S");
 952   DictionaryValue* async_end = FindNamePhase("name1", "F");
 953   EXPECT_TRUE(async_begin);
 954   EXPECT_TRUE(async_begin2);
 955   EXPECT_TRUE(async_end);
 956
 957   Value* value = NULL;
 958   std::string async_begin_id_str;
 959   std::string async_begin2_id_str;
 960   std::string async_end_id_str;
 961   ASSERT_TRUE(async_begin->Get("id", &value));
 962   ASSERT_TRUE(value->GetAsString(&async_begin_id_str));
 963   ASSERT_TRUE(async_begin2->Get("id", &value));
 964   ASSERT_TRUE(value->GetAsString(&async_begin2_id_str));
 965   ASSERT_TRUE(async_end->Get("id", &value));
 966   ASSERT_TRUE(value->GetAsString(&async_end_id_str));
 967
 968   EXPECT_STREQ(async_begin_id_str.c_str(), async_begin2_id_str.c_str());
 969   EXPECT_STRNE(async_begin_id_str.c_str(), async_end_id_str.c_str());
 970 }
 971
 972 // Test that static strings are not copied.
 973 TEST_F(TraceEventTestFixture, StaticStringVsString) {
 974   ManualTestSetUp();
 975   TraceLog* tracer = TraceLog::GetInstance();
 976   // Make sure old events are flushed:
 977   EndTraceAndFlush();
 978   EXPECT_EQ(0u, tracer->GetEventsSize());
 979
 980   {
 981     BeginTrace();
 982     // Test that string arguments are copied.
 983     TRACE_EVENT2("cat", "name1",
 984                  "arg1", std::string("argval"), "arg2", std::string("argval"));
 985     // Test that static TRACE_STR_COPY string arguments are copied.
 986     TRACE_EVENT2("cat", "name2",
 987                  "arg1", TRACE_STR_COPY("argval"),
 988                  "arg2", TRACE_STR_COPY("argval"));
 989     size_t num_events = tracer->GetEventsSize();
 990     EXPECT_GT(num_events, 1u);
 991     const TraceEvent& event1 = tracer->GetEventAt(num_events - 2);
 992     const TraceEvent& event2 = tracer->GetEventAt(num_events - 1);
 993     EXPECT_STREQ("name1", event1.name());
 994     EXPECT_STREQ("name2", event2.name());
 995     EXPECT_TRUE(event1.parameter_copy_storage() != NULL);
 996     EXPECT_TRUE(event2.parameter_copy_storage() != NULL);
 997     EXPECT_GT(event1.parameter_copy_storage()->size(), 0u);
 998     EXPECT_GT(event2.parameter_copy_storage()->size(), 0u);
 999     EndTraceAndFlush();
1000   }
1001
1002   {
1003     BeginTrace();
1004     // Test that static literal string arguments are not copied.
1005     TRACE_EVENT2("cat", "name1",
1006                  "arg1", "argval", "arg2", "argval");
1007     // Test that static TRACE_STR_COPY NULL string arguments are not copied.
1008     const char* str1 = NULL;
1009     const char* str2 = NULL;
1010     TRACE_EVENT2("cat", "name2",
1011                  "arg1", TRACE_STR_COPY(str1),
1012                  "arg2", TRACE_STR_COPY(str2));
1013     size_t num_events = tracer->GetEventsSize();
1014     EXPECT_GT(num_events, 1u);
1015     const TraceEvent& event1 = tracer->GetEventAt(num_events - 2);
1016     const TraceEvent& event2 = tracer->GetEventAt(num_events - 1);
1017     EXPECT_STREQ("name1", event1.name());
1018     EXPECT_STREQ("name2", event2.name());
1019     EXPECT_TRUE(event1.parameter_copy_storage() == NULL);
1020     EXPECT_TRUE(event2.parameter_copy_storage() == NULL);
1021     EndTraceAndFlush();
1022   }
1023 }
1024
1025 // Test that data sent from other threads is gathered
1026 TEST_F(TraceEventTestFixture, DataCapturedOnThread) {
1027   ManualTestSetUp();
1028   BeginTrace();
1029
1030   Thread thread("1");
1031   WaitableEvent task_complete_event(false, false);
1032   thread.Start();
1033
1034   thread.message_loop()->PostTask(
1035       FROM_HERE, base::Bind(&TraceWithAllMacroVariants, &task_complete_event));
1036   task_complete_event.Wait();
1037   thread.Stop();
1038
1039   EndTraceAndFlush();
1040   ValidateAllTraceMacrosCreatedData(trace_parsed_);
1041 }
1042
1043 // Test that data sent from multiple threads is gathered
1044 TEST_F(TraceEventTestFixture, DataCapturedManyThreads) {
1045   ManualTestSetUp();
1046   BeginTrace();
1047
1048   const int num_threads = 4;
1049   const int num_events = 4000;
1050   Thread* threads[num_threads];
1051   WaitableEvent* task_complete_events[num_threads];
1052   for (int i = 0; i < num_threads; i++) {
1053     threads[i] = new Thread(StringPrintf("Thread %d", i).c_str());
1054     task_complete_events[i] = new WaitableEvent(false, false);
1055     threads[i]->Start();
1056     threads[i]->message_loop()->PostTask(
1057         FROM_HERE, base::Bind(&TraceManyInstantEvents,
1058                               i, num_events, task_complete_events[i]));
1059   }
1060
1061   for (int i = 0; i < num_threads; i++) {
1062     task_complete_events[i]->Wait();
1063   }
1064
1065   for (int i = 0; i < num_threads; i++) {
1066     threads[i]->Stop();
1067     delete threads[i];
1068     delete task_complete_events[i];
1069   }
1070
1071   EndTraceAndFlush();
1072
1073   ValidateInstantEventPresentOnEveryThread(trace_parsed_,
1074                                            num_threads, num_events);
1075 }
1076
1077 // Test that thread and process names show up in the trace
1078 TEST_F(TraceEventTestFixture, ThreadNames) {
1079   ManualTestSetUp();
1080
1081   // Create threads before we enable tracing to make sure
1082   // that tracelog still captures them.
1083   const int num_threads = 4;
1084   const int num_events = 10;
1085   Thread* threads[num_threads];
1086   PlatformThreadId thread_ids[num_threads];
1087   for (int i = 0; i < num_threads; i++)
1088     threads[i] = new Thread(StringPrintf("Thread %d", i).c_str());
1089
1090   // Enable tracing.
1091   BeginTrace();
1092
1093   // Now run some trace code on these threads.
1094   WaitableEvent* task_complete_events[num_threads];
1095   for (int i = 0; i < num_threads; i++) {
1096     task_complete_events[i] = new WaitableEvent(false, false);
1097     threads[i]->Start();
1098     thread_ids[i] = threads[i]->thread_id();
1099     threads[i]->message_loop()->PostTask(
1100         FROM_HERE, base::Bind(&TraceManyInstantEvents,
1101                               i, num_events, task_complete_events[i]));
1102   }
1103   for (int i = 0; i < num_threads; i++) {
1104     task_complete_events[i]->Wait();
1105   }
1106
1107   // Shut things down.
1108   for (int i = 0; i < num_threads; i++) {
1109     threads[i]->Stop();
1110     delete threads[i];
1111     delete task_complete_events[i];
1112   }
1113
1114   EndTraceAndFlush();
1115
1116   std::string tmp;
1117   int tmp_int;
1118   const DictionaryValue* item;
1119
1120   // Make sure we get thread name metadata.
1121   // Note, the test suite may have created a ton of threads.
1122   // So, we'll have thread names for threads we didn't create.
1123   std::vector<const DictionaryValue*> items =
1124       FindTraceEntries(trace_parsed_, "thread_name");
1125   for (int i = 0; i < static_cast<int>(items.size()); i++) {
1126     item = items[i];
1127     ASSERT_TRUE(item);
1128     EXPECT_TRUE(item->GetInteger("tid", &tmp_int));
1129
1130     // See if this thread name is one of the threads we just created
1131     for (int j = 0; j < num_threads; j++) {
1132       if(static_cast<int>(thread_ids[j]) != tmp_int)
1133         continue;
1134
1135       std::string expected_name = StringPrintf("Thread %d", j);
1136       EXPECT_TRUE(item->GetString("ph", &tmp) && tmp == "M");
1137       EXPECT_TRUE(item->GetInteger("pid", &tmp_int) &&
1138                   tmp_int == static_cast<int>(base::GetCurrentProcId()));
1139       // If the thread name changes or the tid gets reused, the name will be
1140       // a comma-separated list of thread names, so look for a substring.
1141       EXPECT_TRUE(item->GetString("args.name", &tmp) &&
1142                   tmp.find(expected_name) != std::string::npos);
1143     }
1144   }
1145 }
1146
1147 TEST_F(TraceEventTestFixture, ThreadNameChanges) {
1148   ManualTestSetUp();
1149
1150   BeginTrace();
1151
1152   PlatformThread::SetName("");
1153   TRACE_EVENT_INSTANT0("drink", "water");
1154
1155   PlatformThread::SetName("cafe");
1156   TRACE_EVENT_INSTANT0("drink", "coffee");
1157
1158   PlatformThread::SetName("shop");
1159   // No event here, so won't appear in combined name.
1160
1161   PlatformThread::SetName("pub");
1162   TRACE_EVENT_INSTANT0("drink", "beer");
1163   TRACE_EVENT_INSTANT0("drink", "wine");
1164
1165   PlatformThread::SetName(" bar");
1166   TRACE_EVENT_INSTANT0("drink", "whisky");
1167
1168   EndTraceAndFlush();
1169
1170   std::vector<const DictionaryValue*> items =
1171       FindTraceEntries(trace_parsed_, "thread_name");
1172   EXPECT_EQ(1u, items.size());
1173   ASSERT_GT(items.size(), 0u);
1174   const DictionaryValue* item = items[0];
1175   ASSERT_TRUE(item);
1176   int tid;
1177   EXPECT_TRUE(item->GetInteger("tid", &tid));
1178   EXPECT_EQ(PlatformThread::CurrentId(), static_cast<PlatformThreadId>(tid));
1179
1180   std::string expected_name = "cafe,pub, bar";
1181   std::string tmp;
1182   EXPECT_TRUE(item->GetString("args.name", &tmp));
1183   EXPECT_EQ(expected_name, tmp);
1184 }
1185
1186 // Test trace calls made after tracing singleton shut down.
1187 //
1188 // The singleton is destroyed by our base::AtExitManager, but there can be
1189 // code still executing as the C++ static objects are destroyed. This test
1190 // forces the singleton to destroy early, and intentinally makes trace calls
1191 // afterwards.
1192 TEST_F(TraceEventTestFixture, AtExit) {
1193   // Repeat this test a few times. Besides just showing robustness, it also
1194   // allows us to test that events at shutdown do not appear with valid events
1195   // recorded after the system is started again.
1196   for (int i = 0; i < 4; i++) {
1197     // Scope to contain the then destroy the TraceLog singleton.
1198     {
1199       base::ShadowingAtExitManager exit_manager_will_destroy_singletons;
1200
1201       // Setup TraceLog singleton inside this test's exit manager scope
1202       // so that it will be destroyed when this scope closes.
1203       ManualTestSetUp();
1204
1205       TRACE_EVENT_INSTANT0("all", "not recorded; system not enabled");
1206
1207       BeginTrace();
1208
1209       TRACE_EVENT_INSTANT0("all", "is recorded 1; system has been enabled");
1210       // Trace calls that will cache pointers to categories; they're valid here
1211       TraceCallsWithCachedCategoryPointersPointers(
1212           "is recorded 2; system has been enabled");
1213
1214       EndTraceAndFlush();
1215     } // scope to destroy singleton
1216     ASSERT_FALSE(TraceLog::GetInstance());
1217
1218     // Now that singleton is destroyed, check what trace events were recorded
1219     const DictionaryValue* item = NULL;
1220     ListValue& trace_parsed = trace_parsed_;
1221     EXPECT_FIND_("is recorded 1");
1222     EXPECT_FIND_("is recorded 2");
1223     EXPECT_NOT_FIND_("not recorded");
1224
1225     // Make additional trace event calls on the shutdown system. They should
1226     // all pass cleanly, but the data not be recorded. We'll verify that next
1227     // time around the loop (the only way to flush the trace buffers).
1228     TRACE_EVENT_BEGIN_ETW("not recorded; system shutdown", 0, NULL);
1229     TRACE_EVENT_END_ETW("not recorded; system shutdown", 0, NULL);
1230     TRACE_EVENT_INSTANT_ETW("not recorded; system shutdown", 0, NULL);
1231     TRACE_EVENT0("all", "not recorded; system shutdown");
1232     TRACE_EVENT_INSTANT0("all", "not recorded; system shutdown");
1233     TRACE_EVENT_BEGIN0("all", "not recorded; system shutdown");
1234     TRACE_EVENT_END0("all", "not recorded; system shutdown");
1235
1236     TRACE_EVENT0("new category 0!", "not recorded; system shutdown");
1237     TRACE_EVENT_INSTANT0("new category 1!", "not recorded; system shutdown");
1238     TRACE_EVENT_BEGIN0("new category 2!", "not recorded; system shutdown");
1239     TRACE_EVENT_END0("new category 3!", "not recorded; system shutdown");
1240
1241     // Cached categories should be safe to check, and still disable traces
1242     TraceCallsWithCachedCategoryPointersPointers(
1243         "not recorded; system shutdown");
1244   }
1245 }
1246
1247 TEST_F(TraceEventTestFixture, NormallyNoDeepCopy) {
1248   // Test that the TRACE_EVENT macros do not deep-copy their string. If they
1249   // do so it may indicate a performance regression, but more-over it would
1250   // make the DEEP_COPY overloads redundant.
1251   ManualTestSetUp();
1252
1253   std::string name_string("event name");
1254
1255   BeginTrace();
1256   TRACE_EVENT_INSTANT0("category", name_string.c_str());
1257
1258   // Modify the string in place (a wholesale reassignment may leave the old
1259   // string intact on the heap).
1260   name_string[0] = '@';
1261
1262   EndTraceAndFlush();
1263
1264   EXPECT_FALSE(FindTraceEntry(trace_parsed_, "event name"));
1265   EXPECT_TRUE(FindTraceEntry(trace_parsed_, name_string.c_str()));
1266 }
1267
1268 TEST_F(TraceEventTestFixture, DeepCopy) {
1269   ManualTestSetUp();
1270
1271   static const char kOriginalName1[] = "name1";
1272   static const char kOriginalName2[] = "name2";
1273   static const char kOriginalName3[] = "name3";
1274   std::string name1(kOriginalName1);
1275   std::string name2(kOriginalName2);
1276   std::string name3(kOriginalName3);
1277   std::string arg1("arg1");
1278   std::string arg2("arg2");
1279   std::string val1("val1");
1280   std::string val2("val2");
1281
1282   BeginTrace();
1283   TRACE_EVENT_COPY_INSTANT0("category", name1.c_str());
1284   TRACE_EVENT_COPY_BEGIN1("category", name2.c_str(),
1285                           arg1.c_str(), 5);
1286   TRACE_EVENT_COPY_END2("category", name3.c_str(),
1287                         arg1.c_str(), val1,
1288                         arg2.c_str(), val2);
1289
1290   // As per NormallyNoDeepCopy, modify the strings in place.
1291   name1[0] = name2[0] = name3[0] = arg1[0] = arg2[0] = val1[0] = val2[0] = '@';
1292
1293   EndTraceAndFlush();
1294
1295   EXPECT_FALSE(FindTraceEntry(trace_parsed_, name1.c_str()));
1296   EXPECT_FALSE(FindTraceEntry(trace_parsed_, name2.c_str()));
1297   EXPECT_FALSE(FindTraceEntry(trace_parsed_, name3.c_str()));
1298
1299   const DictionaryValue* entry1 = FindTraceEntry(trace_parsed_, kOriginalName1);
1300   const DictionaryValue* entry2 = FindTraceEntry(trace_parsed_, kOriginalName2);
1301   const DictionaryValue* entry3 = FindTraceEntry(trace_parsed_, kOriginalName3);
1302   ASSERT_TRUE(entry1);
1303   ASSERT_TRUE(entry2);
1304   ASSERT_TRUE(entry3);
1305
1306   int i;
1307   EXPECT_FALSE(entry2->GetInteger("args.@rg1", &i));
1308   EXPECT_TRUE(entry2->GetInteger("args.arg1", &i));
1309   EXPECT_EQ(5, i);
1310
1311   std::string s;
1312   EXPECT_TRUE(entry3->GetString("args.arg1", &s));
1313   EXPECT_EQ("val1", s);
1314   EXPECT_TRUE(entry3->GetString("args.arg2", &s));
1315   EXPECT_EQ("val2", s);
1316 }
1317
1318 // Test that TraceResultBuffer outputs the correct result whether it is added
1319 // in chunks or added all at once.
1320 TEST_F(TraceEventTestFixture, TraceResultBuffer) {
1321   ManualTestSetUp();
1322
1323   Clear();
1324
1325   trace_buffer_.Start();
1326   trace_buffer_.AddFragment("bla1");
1327   trace_buffer_.AddFragment("bla2");
1328   trace_buffer_.AddFragment("bla3,bla4");
1329   trace_buffer_.Finish();
1330   EXPECT_STREQ(json_output_.json_output.c_str(), "[bla1,bla2,bla3,bla4]");
1331
1332   Clear();
1333
1334   trace_buffer_.Start();
1335   trace_buffer_.AddFragment("bla1,bla2,bla3,bla4");
1336   trace_buffer_.Finish();
1337   EXPECT_STREQ(json_output_.json_output.c_str(), "[bla1,bla2,bla3,bla4]");
1338 }
1339
1340 }  // namespace debug
1341 }  // namespace base