src/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 <math.h>
   8 #include <cstdlib>
   9
  10 #include "base/bind.h"
  11 #include "base/command_line.h"
  12 #include "base/debug/trace_event.h"
  13 #include "base/debug/trace_event_synthetic_delay.h"
  14 #include "base/json/json_reader.h"
  15 #include "base/json/json_writer.h"
  16 #include "base/memory/ref_counted_memory.h"
  17 #include "base/memory/scoped_ptr.h"
  18 #include "base/memory/singleton.h"
  19 #include "base/process/process_handle.h"
  20 #include "base/strings/stringprintf.h"
  21 #include "base/synchronization/waitable_event.h"
  22 #include "base/threading/platform_thread.h"
  23 #include "base/threading/thread.h"
  24 #include "base/time/time.h"
  25 #include "base/values.h"
  26 #include "testing/gmock/include/gmock/gmock.h"
  27 #include "testing/gtest/include/gtest/gtest.h"
  28
  29 namespace base {
  30 namespace debug {
  31
  32 namespace {
  33
  34 enum CompareOp {
  35   IS_EQUAL,
  36   IS_NOT_EQUAL,
  37 };
  38
  39 struct JsonKeyValue {
  40   const char* key;
  41   const char* value;
  42   CompareOp op;
  43 };
  44
  45 const int kThreadId = 42;
  46 const int kAsyncId = 5;
  47 const char kAsyncIdStr[] = "0x5";
  48 const int kAsyncId2 = 6;
  49 const char kAsyncId2Str[] = "0x6";
  50
  51 class TraceEventTestFixture : public testing::Test {
  52  public:
  53   void OnTraceDataCollected(
  54       WaitableEvent* flush_complete_event,
  55       const scoped_refptr<base::RefCountedString>& events_str,
  56       bool has_more_events);
  57   void OnWatchEventMatched() {
  58     ++event_watch_notification_;
  59   }
  60   DictionaryValue* FindMatchingTraceEntry(const JsonKeyValue* key_values);
  61   DictionaryValue* FindNamePhase(const char* name, const char* phase);
  62   DictionaryValue* FindNamePhaseKeyValue(const char* name,
  63                                          const char* phase,
  64                                          const char* key,
  65                                          const char* value);
  66   void DropTracedMetadataRecords();
  67   bool FindMatchingValue(const char* key,
  68                          const char* value);
  69   bool FindNonMatchingValue(const char* key,
  70                             const char* value);
  71   void Clear() {
  72     trace_parsed_.Clear();
  73     json_output_.json_output.clear();
  74   }
  75
  76   void BeginTrace() {
  77     BeginSpecificTrace("*");
  78   }
  79
  80   void BeginSpecificTrace(const std::string& filter) {
  81     event_watch_notification_ = 0;
  82     TraceLog::GetInstance()->SetEnabled(
  83         CategoryFilter(filter),
  84         TraceLog::RECORDING_MODE,
  85         TraceOptions());
  86   }
  87
  88   void EndTraceAndFlush() {
  89     WaitableEvent flush_complete_event(false, false);
  90     EndTraceAndFlushAsync(&flush_complete_event);
  91     flush_complete_event.Wait();
  92   }
  93
  94   // Used when testing thread-local buffers which requires the thread initiating
  95   // flush to have a message loop.
  96   void EndTraceAndFlushInThreadWithMessageLoop() {
  97     WaitableEvent flush_complete_event(false, false);
  98     Thread flush_thread("flush");
  99     flush_thread.Start();
 100     flush_thread.message_loop()->PostTask(FROM_HERE,
 101       base::Bind(&TraceEventTestFixture::EndTraceAndFlushAsync,
 102                  base::Unretained(this),
 103                  &flush_complete_event));
 104     flush_complete_event.Wait();
 105   }
 106
 107   void EndTraceAndFlushAsync(WaitableEvent* flush_complete_event) {
 108     TraceLog::GetInstance()->SetDisabled();
 109     TraceLog::GetInstance()->Flush(
 110         base::Bind(&TraceEventTestFixture::OnTraceDataCollected,
 111                    base::Unretained(static_cast<TraceEventTestFixture*>(this)),
 112                    base::Unretained(flush_complete_event)));
 113   }
 114
 115   void FlushMonitoring() {
 116     WaitableEvent flush_complete_event(false, false);
 117     FlushMonitoring(&flush_complete_event);
 118     flush_complete_event.Wait();
 119   }
 120
 121   void FlushMonitoring(WaitableEvent* flush_complete_event) {
 122     TraceLog::GetInstance()->FlushButLeaveBufferIntact(
 123         base::Bind(&TraceEventTestFixture::OnTraceDataCollected,
 124                    base::Unretained(static_cast<TraceEventTestFixture*>(this)),
 125                    base::Unretained(flush_complete_event)));
 126   }
 127
 128   virtual void SetUp() override {
 129     const char* name = PlatformThread::GetName();
 130     old_thread_name_ = name ? strdup(name) : NULL;
 131
 132     TraceLog::DeleteForTesting();
 133     TraceLog* tracelog = TraceLog::GetInstance();
 134     ASSERT_TRUE(tracelog);
 135     ASSERT_FALSE(tracelog->IsEnabled());
 136     trace_buffer_.SetOutputCallback(json_output_.GetCallback());
 137     event_watch_notification_ = 0;
 138   }
 139   virtual void TearDown() override {
 140     if (TraceLog::GetInstance())
 141       EXPECT_FALSE(TraceLog::GetInstance()->IsEnabled());
 142     PlatformThread::SetName(old_thread_name_ ? old_thread_name_ : "");
 143     free(old_thread_name_);
 144     old_thread_name_ = NULL;
 145     // We want our singleton torn down after each test.
 146     TraceLog::DeleteForTesting();
 147   }
 148
 149   char* old_thread_name_;
 150   ListValue trace_parsed_;
 151   TraceResultBuffer trace_buffer_;
 152   TraceResultBuffer::SimpleOutput json_output_;
 153   int event_watch_notification_;
 154
 155  private:
 156   // We want our singleton torn down after each test.
 157   ShadowingAtExitManager at_exit_manager_;
 158   Lock lock_;
 159 };
 160
 161 void TraceEventTestFixture::OnTraceDataCollected(
 162     WaitableEvent* flush_complete_event,
 163     const scoped_refptr<base::RefCountedString>& events_str,
 164     bool has_more_events) {
 165   AutoLock lock(lock_);
 166   json_output_.json_output.clear();
 167   trace_buffer_.Start();
 168   trace_buffer_.AddFragment(events_str->data());
 169   trace_buffer_.Finish();
 170
 171   scoped_ptr<Value> root;
 172   root.reset(base::JSONReader::Read(json_output_.json_output,
 173                                     JSON_PARSE_RFC | JSON_DETACHABLE_CHILDREN));
 174
 175   if (!root.get()) {
 176     LOG(ERROR) << json_output_.json_output;
 177   }
 178
 179   ListValue* root_list = NULL;
 180   ASSERT_TRUE(root.get());
 181   ASSERT_TRUE(root->GetAsList(&root_list));
 182
 183   // Move items into our aggregate collection
 184   while (root_list->GetSize()) {
 185     scoped_ptr<Value> item;
 186     root_list->Remove(0, &item);
 187     trace_parsed_.Append(item.release());
 188   }
 189
 190   if (!has_more_events)
 191     flush_complete_event->Signal();
 192 }
 193
 194 static bool CompareJsonValues(const std::string& lhs,
 195                               const std::string& rhs,
 196                               CompareOp op) {
 197   switch (op) {
 198     case IS_EQUAL:
 199       return lhs == rhs;
 200     case IS_NOT_EQUAL:
 201       return lhs != rhs;
 202     default:
 203       CHECK(0);
 204   }
 205   return false;
 206 }
 207
 208 static bool IsKeyValueInDict(const JsonKeyValue* key_value,
 209                              DictionaryValue* dict) {
 210   Value* value = NULL;
 211   std::string value_str;
 212   if (dict->Get(key_value->key, &value) &&
 213       value->GetAsString(&value_str) &&
 214       CompareJsonValues(value_str, key_value->value, key_value->op))
 215     return true;
 216
 217   // Recurse to test arguments
 218   DictionaryValue* args_dict = NULL;
 219   dict->GetDictionary("args", &args_dict);
 220   if (args_dict)
 221     return IsKeyValueInDict(key_value, args_dict);
 222
 223   return false;
 224 }
 225
 226 static bool IsAllKeyValueInDict(const JsonKeyValue* key_values,
 227                                 DictionaryValue* dict) {
 228   // Scan all key_values, they must all be present and equal.
 229   while (key_values && key_values->key) {
 230     if (!IsKeyValueInDict(key_values, dict))
 231       return false;
 232     ++key_values;
 233   }
 234   return true;
 235 }
 236
 237 DictionaryValue* TraceEventTestFixture::FindMatchingTraceEntry(
 238     const JsonKeyValue* key_values) {
 239   // Scan all items
 240   size_t trace_parsed_count = trace_parsed_.GetSize();
 241   for (size_t i = 0; i < trace_parsed_count; i++) {
 242     Value* value = NULL;
 243     trace_parsed_.Get(i, &value);
 244     if (!value || value->GetType() != Value::TYPE_DICTIONARY)
 245       continue;
 246     DictionaryValue* dict = static_cast<DictionaryValue*>(value);
 247
 248     if (IsAllKeyValueInDict(key_values, dict))
 249       return dict;
 250   }
 251   return NULL;
 252 }
 253
 254 void TraceEventTestFixture::DropTracedMetadataRecords() {
 255   scoped_ptr<ListValue> old_trace_parsed(trace_parsed_.DeepCopy());
 256   size_t old_trace_parsed_size = old_trace_parsed->GetSize();
 257   trace_parsed_.Clear();
 258
 259   for (size_t i = 0; i < old_trace_parsed_size; i++) {
 260     Value* value = NULL;
 261     old_trace_parsed->Get(i, &value);
 262     if (!value || value->GetType() != Value::TYPE_DICTIONARY) {
 263       trace_parsed_.Append(value->DeepCopy());
 264       continue;
 265     }
 266     DictionaryValue* dict = static_cast<DictionaryValue*>(value);
 267     std::string tmp;
 268     if (dict->GetString("ph", &tmp) && tmp == "M")
 269       continue;
 270
 271     trace_parsed_.Append(value->DeepCopy());
 272   }
 273 }
 274
 275 DictionaryValue* TraceEventTestFixture::FindNamePhase(const char* name,
 276                                                       const char* phase) {
 277   JsonKeyValue key_values[] = {
 278     {"name", name, IS_EQUAL},
 279     {"ph", phase, IS_EQUAL},
 280     {0, 0, IS_EQUAL}
 281   };
 282   return FindMatchingTraceEntry(key_values);
 283 }
 284
 285 DictionaryValue* TraceEventTestFixture::FindNamePhaseKeyValue(
 286     const char* name,
 287     const char* phase,
 288     const char* key,
 289     const char* value) {
 290   JsonKeyValue key_values[] = {
 291     {"name", name, IS_EQUAL},
 292     {"ph", phase, IS_EQUAL},
 293     {key, value, IS_EQUAL},
 294     {0, 0, IS_EQUAL}
 295   };
 296   return FindMatchingTraceEntry(key_values);
 297 }
 298
 299 bool TraceEventTestFixture::FindMatchingValue(const char* key,
 300                                               const char* value) {
 301   JsonKeyValue key_values[] = {
 302     {key, value, IS_EQUAL},
 303     {0, 0, IS_EQUAL}
 304   };
 305   return FindMatchingTraceEntry(key_values);
 306 }
 307
 308 bool TraceEventTestFixture::FindNonMatchingValue(const char* key,
 309                                                  const char* value) {
 310   JsonKeyValue key_values[] = {
 311     {key, value, IS_NOT_EQUAL},
 312     {0, 0, IS_EQUAL}
 313   };
 314   return FindMatchingTraceEntry(key_values);
 315 }
 316
 317 bool IsStringInDict(const char* string_to_match, const DictionaryValue* dict) {
 318   for (DictionaryValue::Iterator it(*dict); !it.IsAtEnd(); it.Advance()) {
 319     if (it.key().find(string_to_match) != std::string::npos)
 320       return true;
 321
 322     std::string value_str;
 323     it.value().GetAsString(&value_str);
 324     if (value_str.find(string_to_match) != std::string::npos)
 325       return true;
 326   }
 327
 328   // Recurse to test arguments
 329   const DictionaryValue* args_dict = NULL;
 330   dict->GetDictionary("args", &args_dict);
 331   if (args_dict)
 332     return IsStringInDict(string_to_match, args_dict);
 333
 334   return false;
 335 }
 336
 337 const DictionaryValue* FindTraceEntry(
 338     const ListValue& trace_parsed,
 339     const char* string_to_match,
 340     const DictionaryValue* match_after_this_item = NULL) {
 341   // Scan all items
 342   size_t trace_parsed_count = trace_parsed.GetSize();
 343   for (size_t i = 0; i < trace_parsed_count; i++) {
 344     const Value* value = NULL;
 345     trace_parsed.Get(i, &value);
 346     if (match_after_this_item) {
 347       if (value == match_after_this_item)
 348          match_after_this_item = NULL;
 349       continue;
 350     }
 351     if (!value || value->GetType() != Value::TYPE_DICTIONARY)
 352       continue;
 353     const DictionaryValue* dict = static_cast<const DictionaryValue*>(value);
 354
 355     if (IsStringInDict(string_to_match, dict))
 356       return dict;
 357   }
 358   return NULL;
 359 }
 360
 361 std::vector<const DictionaryValue*> FindTraceEntries(
 362     const ListValue& trace_parsed,
 363     const char* string_to_match) {
 364   std::vector<const DictionaryValue*> hits;
 365   size_t trace_parsed_count = trace_parsed.GetSize();
 366   for (size_t i = 0; i < trace_parsed_count; i++) {
 367     const Value* value = NULL;
 368     trace_parsed.Get(i, &value);
 369     if (!value || value->GetType() != Value::TYPE_DICTIONARY)
 370       continue;
 371     const DictionaryValue* dict = static_cast<const DictionaryValue*>(value);
 372
 373     if (IsStringInDict(string_to_match, dict))
 374       hits.push_back(dict);
 375   }
 376   return hits;
 377 }
 378
 379 const char kControlCharacters[] = "\001\002\003\n\r";
 380
 381 void TraceWithAllMacroVariants(WaitableEvent* task_complete_event) {
 382   {
 383     TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW call", 0x1122, "extrastring1");
 384     TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW call", 0x3344, "extrastring2");
 385     TRACE_EVENT_INSTANT_ETW("TRACE_EVENT_INSTANT_ETW call",
 386                             0x5566, "extrastring3");
 387
 388     TRACE_EVENT0("all", "TRACE_EVENT0 call");
 389     TRACE_EVENT1("all", "TRACE_EVENT1 call", "name1", "value1");
 390     TRACE_EVENT2("all", "TRACE_EVENT2 call",
 391                  "name1", "\"value1\"",
 392                  "name2", "value\\2");
 393
 394     TRACE_EVENT_INSTANT0("all", "TRACE_EVENT_INSTANT0 call",
 395                          TRACE_EVENT_SCOPE_GLOBAL);
 396     TRACE_EVENT_INSTANT1("all", "TRACE_EVENT_INSTANT1 call",
 397                          TRACE_EVENT_SCOPE_PROCESS, "name1", "value1");
 398     TRACE_EVENT_INSTANT2("all", "TRACE_EVENT_INSTANT2 call",
 399                          TRACE_EVENT_SCOPE_THREAD,
 400                          "name1", "value1",
 401                          "name2", "value2");
 402
 403     TRACE_EVENT_BEGIN0("all", "TRACE_EVENT_BEGIN0 call");
 404     TRACE_EVENT_BEGIN1("all", "TRACE_EVENT_BEGIN1 call", "name1", "value1");
 405     TRACE_EVENT_BEGIN2("all", "TRACE_EVENT_BEGIN2 call",
 406                        "name1", "value1",
 407                        "name2", "value2");
 408
 409     TRACE_EVENT_END0("all", "TRACE_EVENT_END0 call");
 410     TRACE_EVENT_END1("all", "TRACE_EVENT_END1 call", "name1", "value1");
 411     TRACE_EVENT_END2("all", "TRACE_EVENT_END2 call",
 412                      "name1", "value1",
 413                      "name2", "value2");
 414
 415     TRACE_EVENT_ASYNC_BEGIN0("all", "TRACE_EVENT_ASYNC_BEGIN0 call", kAsyncId);
 416     TRACE_EVENT_ASYNC_BEGIN1("all", "TRACE_EVENT_ASYNC_BEGIN1 call", kAsyncId,
 417                              "name1", "value1");
 418     TRACE_EVENT_ASYNC_BEGIN2("all", "TRACE_EVENT_ASYNC_BEGIN2 call", kAsyncId,
 419                              "name1", "value1",
 420                              "name2", "value2");
 421
 422     TRACE_EVENT_ASYNC_STEP_INTO0("all", "TRACE_EVENT_ASYNC_STEP_INTO0 call",
 423                                  kAsyncId, "step_begin1");
 424     TRACE_EVENT_ASYNC_STEP_INTO1("all", "TRACE_EVENT_ASYNC_STEP_INTO1 call",
 425                                  kAsyncId, "step_begin2", "name1", "value1");
 426
 427     TRACE_EVENT_ASYNC_END0("all", "TRACE_EVENT_ASYNC_END0 call", kAsyncId);
 428     TRACE_EVENT_ASYNC_END1("all", "TRACE_EVENT_ASYNC_END1 call", kAsyncId,
 429                            "name1", "value1");
 430     TRACE_EVENT_ASYNC_END2("all", "TRACE_EVENT_ASYNC_END2 call", kAsyncId,
 431                            "name1", "value1",
 432                            "name2", "value2");
 433
 434     TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW0 call", kAsyncId, NULL);
 435     TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW1 call", kAsyncId, "value");
 436     TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW0 call", kAsyncId, NULL);
 437     TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW1 call", kAsyncId, "value");
 438     TRACE_EVENT_INSTANT_ETW("TRACE_EVENT_INSTANT_ETW0 call", kAsyncId, NULL);
 439     TRACE_EVENT_INSTANT_ETW("TRACE_EVENT_INSTANT_ETW1 call", kAsyncId, "value");
 440
 441     TRACE_COUNTER1("all", "TRACE_COUNTER1 call", 31415);
 442     TRACE_COUNTER2("all", "TRACE_COUNTER2 call",
 443                    "a", 30000,
 444                    "b", 1415);
 445
 446     TRACE_COUNTER_ID1("all", "TRACE_COUNTER_ID1 call", 0x319009, 31415);
 447     TRACE_COUNTER_ID2("all", "TRACE_COUNTER_ID2 call", 0x319009,
 448                       "a", 30000, "b", 1415);
 449
 450     TRACE_EVENT_COPY_BEGIN_WITH_ID_TID_AND_TIMESTAMP0("all",
 451         "TRACE_EVENT_COPY_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 call",
 452         kAsyncId, kThreadId, 12345);
 453     TRACE_EVENT_COPY_END_WITH_ID_TID_AND_TIMESTAMP0("all",
 454         "TRACE_EVENT_COPY_END_WITH_ID_TID_AND_TIMESTAMP0 call",
 455         kAsyncId, kThreadId, 23456);
 456
 457     TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0("all",
 458         "TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 call",
 459         kAsyncId2, kThreadId, 34567);
 460     TRACE_EVENT_ASYNC_STEP_PAST0("all", "TRACE_EVENT_ASYNC_STEP_PAST0 call",
 461                                  kAsyncId2, "step_end1");
 462     TRACE_EVENT_ASYNC_STEP_PAST1("all", "TRACE_EVENT_ASYNC_STEP_PAST1 call",
 463                                  kAsyncId2, "step_end2", "name1", "value1");
 464
 465     TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0("all",
 466         "TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0 call",
 467         kAsyncId2, kThreadId, 45678);
 468
 469     TRACE_EVENT_OBJECT_CREATED_WITH_ID("all", "tracked object 1", 0x42);
 470     TRACE_EVENT_OBJECT_SNAPSHOT_WITH_ID(
 471         "all", "tracked object 1", 0x42, "hello");
 472     TRACE_EVENT_OBJECT_DELETED_WITH_ID("all", "tracked object 1", 0x42);
 473
 474     TraceScopedTrackableObject<int> trackable("all", "tracked object 2",
 475                                               0x2128506);
 476     trackable.snapshot("world");
 477
 478     TRACE_EVENT1(kControlCharacters, kControlCharacters,
 479                  kControlCharacters, kControlCharacters);
 480   }  // Scope close causes TRACE_EVENT0 etc to send their END events.
 481
 482   if (task_complete_event)
 483     task_complete_event->Signal();
 484 }
 485
 486 void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed) {
 487   const DictionaryValue* item = NULL;
 488
 489 #define EXPECT_FIND_(string) \
 490     item = FindTraceEntry(trace_parsed, string); \
 491     EXPECT_TRUE(item);
 492 #define EXPECT_NOT_FIND_(string) \
 493     item = FindTraceEntry(trace_parsed, string); \
 494     EXPECT_FALSE(item);
 495 #define EXPECT_SUB_FIND_(string) \
 496     if (item) \
 497       EXPECT_TRUE(IsStringInDict(string, item));
 498
 499   EXPECT_FIND_("ETW Trace Event");
 500   EXPECT_FIND_("all");
 501   EXPECT_FIND_("TRACE_EVENT_BEGIN_ETW call");
 502   {
 503     std::string str_val;
 504     EXPECT_TRUE(item && item->GetString("args.id", &str_val));
 505     EXPECT_STREQ("0x1122", str_val.c_str());
 506   }
 507   EXPECT_SUB_FIND_("extrastring1");
 508   EXPECT_FIND_("TRACE_EVENT_END_ETW call");
 509   EXPECT_FIND_("TRACE_EVENT_INSTANT_ETW call");
 510   EXPECT_FIND_("TRACE_EVENT0 call");
 511   {
 512     std::string ph;
 513     std::string ph_end;
 514     EXPECT_TRUE((item = FindTraceEntry(trace_parsed, "TRACE_EVENT0 call")));
 515     EXPECT_TRUE((item && item->GetString("ph", &ph)));
 516     EXPECT_EQ("X", ph);
 517     item = FindTraceEntry(trace_parsed, "TRACE_EVENT0 call", item);
 518     EXPECT_FALSE(item);
 519   }
 520   EXPECT_FIND_("TRACE_EVENT1 call");
 521   EXPECT_SUB_FIND_("name1");
 522   EXPECT_SUB_FIND_("value1");
 523   EXPECT_FIND_("TRACE_EVENT2 call");
 524   EXPECT_SUB_FIND_("name1");
 525   EXPECT_SUB_FIND_("\"value1\"");
 526   EXPECT_SUB_FIND_("name2");
 527   EXPECT_SUB_FIND_("value\\2");
 528
 529   EXPECT_FIND_("TRACE_EVENT_INSTANT0 call");
 530   {
 531     std::string scope;
 532     EXPECT_TRUE((item && item->GetString("s", &scope)));
 533     EXPECT_EQ("g", scope);
 534   }
 535   EXPECT_FIND_("TRACE_EVENT_INSTANT1 call");
 536   {
 537     std::string scope;
 538     EXPECT_TRUE((item && item->GetString("s", &scope)));
 539     EXPECT_EQ("p", scope);
 540   }
 541   EXPECT_SUB_FIND_("name1");
 542   EXPECT_SUB_FIND_("value1");
 543   EXPECT_FIND_("TRACE_EVENT_INSTANT2 call");
 544   {
 545     std::string scope;
 546     EXPECT_TRUE((item && item->GetString("s", &scope)));
 547     EXPECT_EQ("t", scope);
 548   }
 549   EXPECT_SUB_FIND_("name1");
 550   EXPECT_SUB_FIND_("value1");
 551   EXPECT_SUB_FIND_("name2");
 552   EXPECT_SUB_FIND_("value2");
 553
 554   EXPECT_FIND_("TRACE_EVENT_BEGIN0 call");
 555   EXPECT_FIND_("TRACE_EVENT_BEGIN1 call");
 556   EXPECT_SUB_FIND_("name1");
 557   EXPECT_SUB_FIND_("value1");
 558   EXPECT_FIND_("TRACE_EVENT_BEGIN2 call");
 559   EXPECT_SUB_FIND_("name1");
 560   EXPECT_SUB_FIND_("value1");
 561   EXPECT_SUB_FIND_("name2");
 562   EXPECT_SUB_FIND_("value2");
 563
 564   EXPECT_FIND_("TRACE_EVENT_END0 call");
 565   EXPECT_FIND_("TRACE_EVENT_END1 call");
 566   EXPECT_SUB_FIND_("name1");
 567   EXPECT_SUB_FIND_("value1");
 568   EXPECT_FIND_("TRACE_EVENT_END2 call");
 569   EXPECT_SUB_FIND_("name1");
 570   EXPECT_SUB_FIND_("value1");
 571   EXPECT_SUB_FIND_("name2");
 572   EXPECT_SUB_FIND_("value2");
 573
 574   EXPECT_FIND_("TRACE_EVENT_ASYNC_BEGIN0 call");
 575   EXPECT_SUB_FIND_("id");
 576   EXPECT_SUB_FIND_(kAsyncIdStr);
 577   EXPECT_FIND_("TRACE_EVENT_ASYNC_BEGIN1 call");
 578   EXPECT_SUB_FIND_("id");
 579   EXPECT_SUB_FIND_(kAsyncIdStr);
 580   EXPECT_SUB_FIND_("name1");
 581   EXPECT_SUB_FIND_("value1");
 582   EXPECT_FIND_("TRACE_EVENT_ASYNC_BEGIN2 call");
 583   EXPECT_SUB_FIND_("id");
 584   EXPECT_SUB_FIND_(kAsyncIdStr);
 585   EXPECT_SUB_FIND_("name1");
 586   EXPECT_SUB_FIND_("value1");
 587   EXPECT_SUB_FIND_("name2");
 588   EXPECT_SUB_FIND_("value2");
 589
 590   EXPECT_FIND_("TRACE_EVENT_ASYNC_STEP_INTO0 call");
 591   EXPECT_SUB_FIND_("id");
 592   EXPECT_SUB_FIND_(kAsyncIdStr);
 593   EXPECT_SUB_FIND_("step_begin1");
 594   EXPECT_FIND_("TRACE_EVENT_ASYNC_STEP_INTO1 call");
 595   EXPECT_SUB_FIND_("id");
 596   EXPECT_SUB_FIND_(kAsyncIdStr);
 597   EXPECT_SUB_FIND_("step_begin2");
 598   EXPECT_SUB_FIND_("name1");
 599   EXPECT_SUB_FIND_("value1");
 600
 601   EXPECT_FIND_("TRACE_EVENT_ASYNC_END0 call");
 602   EXPECT_SUB_FIND_("id");
 603   EXPECT_SUB_FIND_(kAsyncIdStr);
 604   EXPECT_FIND_("TRACE_EVENT_ASYNC_END1 call");
 605   EXPECT_SUB_FIND_("id");
 606   EXPECT_SUB_FIND_(kAsyncIdStr);
 607   EXPECT_SUB_FIND_("name1");
 608   EXPECT_SUB_FIND_("value1");
 609   EXPECT_FIND_("TRACE_EVENT_ASYNC_END2 call");
 610   EXPECT_SUB_FIND_("id");
 611   EXPECT_SUB_FIND_(kAsyncIdStr);
 612   EXPECT_SUB_FIND_("name1");
 613   EXPECT_SUB_FIND_("value1");
 614   EXPECT_SUB_FIND_("name2");
 615   EXPECT_SUB_FIND_("value2");
 616
 617   EXPECT_FIND_("TRACE_EVENT_BEGIN_ETW0 call");
 618   EXPECT_SUB_FIND_("id");
 619   EXPECT_SUB_FIND_(kAsyncIdStr);
 620   EXPECT_SUB_FIND_("extra");
 621   EXPECT_SUB_FIND_("NULL");
 622   EXPECT_FIND_("TRACE_EVENT_BEGIN_ETW1 call");
 623   EXPECT_SUB_FIND_("id");
 624   EXPECT_SUB_FIND_(kAsyncIdStr);
 625   EXPECT_SUB_FIND_("extra");
 626   EXPECT_SUB_FIND_("value");
 627   EXPECT_FIND_("TRACE_EVENT_END_ETW0 call");
 628   EXPECT_SUB_FIND_("id");
 629   EXPECT_SUB_FIND_(kAsyncIdStr);
 630   EXPECT_SUB_FIND_("extra");
 631   EXPECT_SUB_FIND_("NULL");
 632   EXPECT_FIND_("TRACE_EVENT_END_ETW1 call");
 633   EXPECT_SUB_FIND_("id");
 634   EXPECT_SUB_FIND_(kAsyncIdStr);
 635   EXPECT_SUB_FIND_("extra");
 636   EXPECT_SUB_FIND_("value");
 637   EXPECT_FIND_("TRACE_EVENT_INSTANT_ETW0 call");
 638   EXPECT_SUB_FIND_("id");
 639   EXPECT_SUB_FIND_(kAsyncIdStr);
 640   EXPECT_SUB_FIND_("extra");
 641   EXPECT_SUB_FIND_("NULL");
 642   EXPECT_FIND_("TRACE_EVENT_INSTANT_ETW1 call");
 643   EXPECT_SUB_FIND_("id");
 644   EXPECT_SUB_FIND_(kAsyncIdStr);
 645   EXPECT_SUB_FIND_("extra");
 646   EXPECT_SUB_FIND_("value");
 647
 648   EXPECT_FIND_("TRACE_COUNTER1 call");
 649   {
 650     std::string ph;
 651     EXPECT_TRUE((item && item->GetString("ph", &ph)));
 652     EXPECT_EQ("C", ph);
 653
 654     int value;
 655     EXPECT_TRUE((item && item->GetInteger("args.value", &value)));
 656     EXPECT_EQ(31415, value);
 657   }
 658
 659   EXPECT_FIND_("TRACE_COUNTER2 call");
 660   {
 661     std::string ph;
 662     EXPECT_TRUE((item && item->GetString("ph", &ph)));
 663     EXPECT_EQ("C", ph);
 664
 665     int value;
 666     EXPECT_TRUE((item && item->GetInteger("args.a", &value)));
 667     EXPECT_EQ(30000, value);
 668
 669     EXPECT_TRUE((item && item->GetInteger("args.b", &value)));
 670     EXPECT_EQ(1415, value);
 671   }
 672
 673   EXPECT_FIND_("TRACE_COUNTER_ID1 call");
 674   {
 675     std::string id;
 676     EXPECT_TRUE((item && item->GetString("id", &id)));
 677     EXPECT_EQ("0x319009", id);
 678
 679     std::string ph;
 680     EXPECT_TRUE((item && item->GetString("ph", &ph)));
 681     EXPECT_EQ("C", ph);
 682
 683     int value;
 684     EXPECT_TRUE((item && item->GetInteger("args.value", &value)));
 685     EXPECT_EQ(31415, value);
 686   }
 687
 688   EXPECT_FIND_("TRACE_COUNTER_ID2 call");
 689   {
 690     std::string id;
 691     EXPECT_TRUE((item && item->GetString("id", &id)));
 692     EXPECT_EQ("0x319009", id);
 693
 694     std::string ph;
 695     EXPECT_TRUE((item && item->GetString("ph", &ph)));
 696     EXPECT_EQ("C", ph);
 697
 698     int value;
 699     EXPECT_TRUE((item && item->GetInteger("args.a", &value)));
 700     EXPECT_EQ(30000, value);
 701
 702     EXPECT_TRUE((item && item->GetInteger("args.b", &value)));
 703     EXPECT_EQ(1415, value);
 704   }
 705
 706   EXPECT_FIND_("TRACE_EVENT_COPY_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 call");
 707   {
 708     int val;
 709     EXPECT_TRUE((item && item->GetInteger("ts", &val)));
 710     EXPECT_EQ(12345, val);
 711     EXPECT_TRUE((item && item->GetInteger("tid", &val)));
 712     EXPECT_EQ(kThreadId, val);
 713     std::string id;
 714     EXPECT_TRUE((item && item->GetString("id", &id)));
 715     EXPECT_EQ(kAsyncIdStr, id);
 716   }
 717
 718   EXPECT_FIND_("TRACE_EVENT_COPY_END_WITH_ID_TID_AND_TIMESTAMP0 call");
 719   {
 720     int val;
 721     EXPECT_TRUE((item && item->GetInteger("ts", &val)));
 722     EXPECT_EQ(23456, val);
 723     EXPECT_TRUE((item && item->GetInteger("tid", &val)));
 724     EXPECT_EQ(kThreadId, val);
 725     std::string id;
 726     EXPECT_TRUE((item && item->GetString("id", &id)));
 727     EXPECT_EQ(kAsyncIdStr, id);
 728   }
 729
 730   EXPECT_FIND_("TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 call");
 731   {
 732     int val;
 733     EXPECT_TRUE((item && item->GetInteger("ts", &val)));
 734     EXPECT_EQ(34567, val);
 735     EXPECT_TRUE((item && item->GetInteger("tid", &val)));
 736     EXPECT_EQ(kThreadId, val);
 737     std::string id;
 738     EXPECT_TRUE((item && item->GetString("id", &id)));
 739     EXPECT_EQ(kAsyncId2Str, id);
 740   }
 741
 742   EXPECT_FIND_("TRACE_EVENT_ASYNC_STEP_PAST0 call");
 743   {
 744     EXPECT_SUB_FIND_("id");
 745     EXPECT_SUB_FIND_(kAsyncId2Str);
 746     EXPECT_SUB_FIND_("step_end1");
 747     EXPECT_FIND_("TRACE_EVENT_ASYNC_STEP_PAST1 call");
 748     EXPECT_SUB_FIND_("id");
 749     EXPECT_SUB_FIND_(kAsyncId2Str);
 750     EXPECT_SUB_FIND_("step_end2");
 751     EXPECT_SUB_FIND_("name1");
 752     EXPECT_SUB_FIND_("value1");
 753   }
 754
 755   EXPECT_FIND_("TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0 call");
 756   {
 757     int val;
 758     EXPECT_TRUE((item && item->GetInteger("ts", &val)));
 759     EXPECT_EQ(45678, val);
 760     EXPECT_TRUE((item && item->GetInteger("tid", &val)));
 761     EXPECT_EQ(kThreadId, val);
 762     std::string id;
 763     EXPECT_TRUE((item && item->GetString("id", &id)));
 764     EXPECT_EQ(kAsyncId2Str, id);
 765   }
 766
 767   EXPECT_FIND_("tracked object 1");
 768   {
 769     std::string phase;
 770     std::string id;
 771     std::string snapshot;
 772
 773     EXPECT_TRUE((item && item->GetString("ph", &phase)));
 774     EXPECT_EQ("N", phase);
 775     EXPECT_TRUE((item && item->GetString("id", &id)));
 776     EXPECT_EQ("0x42", id);
 777
 778     item = FindTraceEntry(trace_parsed, "tracked object 1", item);
 779     EXPECT_TRUE(item);
 780     EXPECT_TRUE(item && item->GetString("ph", &phase));
 781     EXPECT_EQ("O", phase);
 782     EXPECT_TRUE(item && item->GetString("id", &id));
 783     EXPECT_EQ("0x42", id);
 784     EXPECT_TRUE(item && item->GetString("args.snapshot", &snapshot));
 785     EXPECT_EQ("hello", snapshot);
 786
 787     item = FindTraceEntry(trace_parsed, "tracked object 1", item);
 788     EXPECT_TRUE(item);
 789     EXPECT_TRUE(item && item->GetString("ph", &phase));
 790     EXPECT_EQ("D", phase);
 791     EXPECT_TRUE(item && item->GetString("id", &id));
 792     EXPECT_EQ("0x42", id);
 793   }
 794
 795   EXPECT_FIND_("tracked object 2");
 796   {
 797     std::string phase;
 798     std::string id;
 799     std::string snapshot;
 800
 801     EXPECT_TRUE(item && item->GetString("ph", &phase));
 802     EXPECT_EQ("N", phase);
 803     EXPECT_TRUE(item && item->GetString("id", &id));
 804     EXPECT_EQ("0x2128506", id);
 805
 806     item = FindTraceEntry(trace_parsed, "tracked object 2", item);
 807     EXPECT_TRUE(item);
 808     EXPECT_TRUE(item && item->GetString("ph", &phase));
 809     EXPECT_EQ("O", phase);
 810     EXPECT_TRUE(item && item->GetString("id", &id));
 811     EXPECT_EQ("0x2128506", id);
 812     EXPECT_TRUE(item && item->GetString("args.snapshot", &snapshot));
 813     EXPECT_EQ("world", snapshot);
 814
 815     item = FindTraceEntry(trace_parsed, "tracked object 2", item);
 816     EXPECT_TRUE(item);
 817     EXPECT_TRUE(item && item->GetString("ph", &phase));
 818     EXPECT_EQ("D", phase);
 819     EXPECT_TRUE(item && item->GetString("id", &id));
 820     EXPECT_EQ("0x2128506", id);
 821   }
 822
 823   EXPECT_FIND_(kControlCharacters);
 824   EXPECT_SUB_FIND_(kControlCharacters);
 825 }
 826
 827 void TraceManyInstantEvents(int thread_id, int num_events,
 828                             WaitableEvent* task_complete_event) {
 829   for (int i = 0; i < num_events; i++) {
 830     TRACE_EVENT_INSTANT2("all", "multi thread event",
 831                          TRACE_EVENT_SCOPE_THREAD,
 832                          "thread", thread_id,
 833                          "event", i);
 834   }
 835
 836   if (task_complete_event)
 837     task_complete_event->Signal();
 838 }
 839
 840 void ValidateInstantEventPresentOnEveryThread(const ListValue& trace_parsed,
 841                                               int num_threads,
 842                                               int num_events) {
 843   std::map<int, std::map<int, bool> > results;
 844
 845   size_t trace_parsed_count = trace_parsed.GetSize();
 846   for (size_t i = 0; i < trace_parsed_count; i++) {
 847     const Value* value = NULL;
 848     trace_parsed.Get(i, &value);
 849     if (!value || value->GetType() != Value::TYPE_DICTIONARY)
 850       continue;
 851     const DictionaryValue* dict = static_cast<const DictionaryValue*>(value);
 852     std::string name;
 853     dict->GetString("name", &name);
 854     if (name != "multi thread event")
 855       continue;
 856
 857     int thread = 0;
 858     int event = 0;
 859     EXPECT_TRUE(dict->GetInteger("args.thread", &thread));
 860     EXPECT_TRUE(dict->GetInteger("args.event", &event));
 861     results[thread][event] = true;
 862   }
 863
 864   EXPECT_FALSE(results[-1][-1]);
 865   for (int thread = 0; thread < num_threads; thread++) {
 866     for (int event = 0; event < num_events; event++) {
 867       EXPECT_TRUE(results[thread][event]);
 868     }
 869   }
 870 }
 871
 872 }  // namespace
 873
 874 void HighResSleepForTraceTest(base::TimeDelta elapsed) {
 875   base::TimeTicks end_time = base::TimeTicks::HighResNow() + elapsed;
 876   do {
 877     base::PlatformThread::Sleep(base::TimeDelta::FromMilliseconds(1));
 878   } while (base::TimeTicks::HighResNow() < end_time);
 879 }
 880
 881 // Simple Test for emitting data and validating it was received.
 882 TEST_F(TraceEventTestFixture, DataCaptured) {
 883   TraceLog::GetInstance()->SetEnabled(
 884       CategoryFilter("*"),
 885       TraceLog::RECORDING_MODE,
 886       TraceOptions());
 887
 888   TraceWithAllMacroVariants(NULL);
 889
 890   EndTraceAndFlush();
 891
 892   ValidateAllTraceMacrosCreatedData(trace_parsed_);
 893 }
 894
 895 class MockEnabledStateChangedObserver :
 896       public TraceLog::EnabledStateObserver {
 897  public:
 898   MOCK_METHOD0(OnTraceLogEnabled, void());
 899   MOCK_METHOD0(OnTraceLogDisabled, void());
 900 };
 901
 902 TEST_F(TraceEventTestFixture, EnabledObserverFiresOnEnable) {
 903   MockEnabledStateChangedObserver observer;
 904   TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
 905
 906   EXPECT_CALL(observer, OnTraceLogEnabled())
 907       .Times(1);
 908   TraceLog::GetInstance()->SetEnabled(
 909       CategoryFilter("*"),
 910       TraceLog::RECORDING_MODE,
 911       TraceOptions());
 912   testing::Mock::VerifyAndClear(&observer);
 913   EXPECT_TRUE(TraceLog::GetInstance()->IsEnabled());
 914
 915   // Cleanup.
 916   TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
 917   TraceLog::GetInstance()->SetDisabled();
 918 }
 919
 920 TEST_F(TraceEventTestFixture, EnabledObserverDoesntFireOnSecondEnable) {
 921   TraceLog::GetInstance()->SetEnabled(
 922       CategoryFilter("*"),
 923       TraceLog::RECORDING_MODE,
 924       TraceOptions());
 925
 926   testing::StrictMock<MockEnabledStateChangedObserver> observer;
 927   TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
 928
 929   EXPECT_CALL(observer, OnTraceLogEnabled())
 930       .Times(0);
 931   EXPECT_CALL(observer, OnTraceLogDisabled())
 932       .Times(0);
 933   TraceLog::GetInstance()->SetEnabled(
 934       CategoryFilter("*"),
 935       TraceLog::RECORDING_MODE,
 936       TraceOptions());
 937   testing::Mock::VerifyAndClear(&observer);
 938   EXPECT_TRUE(TraceLog::GetInstance()->IsEnabled());
 939
 940   // Cleanup.
 941   TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
 942   TraceLog::GetInstance()->SetDisabled();
 943   TraceLog::GetInstance()->SetDisabled();
 944 }
 945
 946 TEST_F(TraceEventTestFixture, EnabledObserverFiresOnFirstDisable) {
 947   CategoryFilter cf_inc_all("*");
 948   TraceLog::GetInstance()->SetEnabled(
 949       cf_inc_all,
 950       TraceLog::RECORDING_MODE,
 951       TraceOptions());
 952   TraceLog::GetInstance()->SetEnabled(
 953       cf_inc_all,
 954       TraceLog::RECORDING_MODE,
 955       TraceOptions());
 956
 957   testing::StrictMock<MockEnabledStateChangedObserver> observer;
 958   TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
 959
 960   EXPECT_CALL(observer, OnTraceLogEnabled())
 961       .Times(0);
 962   EXPECT_CALL(observer, OnTraceLogDisabled())
 963       .Times(1);
 964   TraceLog::GetInstance()->SetDisabled();
 965   testing::Mock::VerifyAndClear(&observer);
 966
 967   // Cleanup.
 968   TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
 969   TraceLog::GetInstance()->SetDisabled();
 970 }
 971
 972 TEST_F(TraceEventTestFixture, EnabledObserverFiresOnDisable) {
 973   TraceLog::GetInstance()->SetEnabled(
 974       CategoryFilter("*"),
 975       TraceLog::RECORDING_MODE,
 976       TraceOptions());
 977
 978   MockEnabledStateChangedObserver observer;
 979   TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
 980
 981   EXPECT_CALL(observer, OnTraceLogDisabled())
 982       .Times(1);
 983   TraceLog::GetInstance()->SetDisabled();
 984   testing::Mock::VerifyAndClear(&observer);
 985
 986   // Cleanup.
 987   TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
 988 }
 989
 990 // Tests the IsEnabled() state of TraceLog changes before callbacks.
 991 class AfterStateChangeEnabledStateObserver
 992     : public TraceLog::EnabledStateObserver {
 993  public:
 994   AfterStateChangeEnabledStateObserver() {}
 995   virtual ~AfterStateChangeEnabledStateObserver() {}
 996
 997   // TraceLog::EnabledStateObserver overrides:
 998   void OnTraceLogEnabled() override {
 999     EXPECT_TRUE(TraceLog::GetInstance()->IsEnabled());
1000   }
1001
1002   void OnTraceLogDisabled() override {
1003     EXPECT_FALSE(TraceLog::GetInstance()->IsEnabled());
1004   }
1005 };
1006
1007 TEST_F(TraceEventTestFixture, ObserversFireAfterStateChange) {
1008   AfterStateChangeEnabledStateObserver observer;
1009   TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
1010
1011   TraceLog::GetInstance()->SetEnabled(
1012       CategoryFilter("*"),
1013       TraceLog::RECORDING_MODE,
1014       TraceOptions());
1015   EXPECT_TRUE(TraceLog::GetInstance()->IsEnabled());
1016
1017   TraceLog::GetInstance()->SetDisabled();
1018   EXPECT_FALSE(TraceLog::GetInstance()->IsEnabled());
1019
1020   TraceLog::GetInstance()->RemoveEnabledStateObserver(&observer);
1021 }
1022
1023 // Tests that a state observer can remove itself during a callback.
1024 class SelfRemovingEnabledStateObserver
1025     : public TraceLog::EnabledStateObserver {
1026  public:
1027   SelfRemovingEnabledStateObserver() {}
1028   virtual ~SelfRemovingEnabledStateObserver() {}
1029
1030   // TraceLog::EnabledStateObserver overrides:
1031   void OnTraceLogEnabled() override {}
1032
1033   void OnTraceLogDisabled() override {
1034     TraceLog::GetInstance()->RemoveEnabledStateObserver(this);
1035   }
1036 };
1037
1038 TEST_F(TraceEventTestFixture, SelfRemovingObserver) {
1039   ASSERT_EQ(0u, TraceLog::GetInstance()->GetObserverCountForTest());
1040
1041   SelfRemovingEnabledStateObserver observer;
1042   TraceLog::GetInstance()->AddEnabledStateObserver(&observer);
1043   EXPECT_EQ(1u, TraceLog::GetInstance()->GetObserverCountForTest());
1044
1045   TraceLog::GetInstance()->SetEnabled(
1046       CategoryFilter("*"),
1047       TraceLog::RECORDING_MODE,
1048       TraceOptions());
1049   TraceLog::GetInstance()->SetDisabled();
1050   // The observer removed itself on disable.
1051   EXPECT_EQ(0u, TraceLog::GetInstance()->GetObserverCountForTest());
1052 }
1053
1054 bool IsNewTrace() {
1055   bool is_new_trace;
1056   TRACE_EVENT_IS_NEW_TRACE(&is_new_trace);
1057   return is_new_trace;
1058 }
1059
1060 TEST_F(TraceEventTestFixture, NewTraceRecording) {
1061   ASSERT_FALSE(IsNewTrace());
1062   TraceLog::GetInstance()->SetEnabled(
1063       CategoryFilter("*"),
1064       TraceLog::RECORDING_MODE,
1065       TraceOptions());
1066   // First call to IsNewTrace() should succeed. But, the second shouldn't.
1067   ASSERT_TRUE(IsNewTrace());
1068   ASSERT_FALSE(IsNewTrace());
1069   EndTraceAndFlush();
1070
1071   // IsNewTrace() should definitely be false now.
1072   ASSERT_FALSE(IsNewTrace());
1073
1074   // Start another trace. IsNewTrace() should become true again, briefly, as
1075   // before.
1076   TraceLog::GetInstance()->SetEnabled(
1077       CategoryFilter("*"),
1078       TraceLog::RECORDING_MODE,
1079       TraceOptions());
1080   ASSERT_TRUE(IsNewTrace());
1081   ASSERT_FALSE(IsNewTrace());
1082
1083   // Cleanup.
1084   EndTraceAndFlush();
1085 }
1086
1087
1088 // Test that categories work.
1089 TEST_F(TraceEventTestFixture, Categories) {
1090   // Test that categories that are used can be retrieved whether trace was
1091   // enabled or disabled when the trace event was encountered.
1092   TRACE_EVENT_INSTANT0("c1", "name", TRACE_EVENT_SCOPE_THREAD);
1093   TRACE_EVENT_INSTANT0("c2", "name", TRACE_EVENT_SCOPE_THREAD);
1094   BeginTrace();
1095   TRACE_EVENT_INSTANT0("c3", "name", TRACE_EVENT_SCOPE_THREAD);
1096   TRACE_EVENT_INSTANT0("c4", "name", TRACE_EVENT_SCOPE_THREAD);
1097   // Category groups containing more than one category.
1098   TRACE_EVENT_INSTANT0("c5,c6", "name", TRACE_EVENT_SCOPE_THREAD);
1099   TRACE_EVENT_INSTANT0("c7,c8", "name", TRACE_EVENT_SCOPE_THREAD);
1100   TRACE_EVENT_INSTANT0(TRACE_DISABLED_BY_DEFAULT("c9"), "name",
1101                        TRACE_EVENT_SCOPE_THREAD);
1102
1103   EndTraceAndFlush();
1104   std::vector<std::string> cat_groups;
1105   TraceLog::GetInstance()->GetKnownCategoryGroups(&cat_groups);
1106   EXPECT_TRUE(std::find(cat_groups.begin(),
1107                         cat_groups.end(), "c1") != cat_groups.end());
1108   EXPECT_TRUE(std::find(cat_groups.begin(),
1109                         cat_groups.end(), "c2") != cat_groups.end());
1110   EXPECT_TRUE(std::find(cat_groups.begin(),
1111                         cat_groups.end(), "c3") != cat_groups.end());
1112   EXPECT_TRUE(std::find(cat_groups.begin(),
1113                         cat_groups.end(), "c4") != cat_groups.end());
1114   EXPECT_TRUE(std::find(cat_groups.begin(),
1115                         cat_groups.end(), "c5,c6") != cat_groups.end());
1116   EXPECT_TRUE(std::find(cat_groups.begin(),
1117                         cat_groups.end(), "c7,c8") != cat_groups.end());
1118   EXPECT_TRUE(std::find(cat_groups.begin(),
1119                         cat_groups.end(),
1120                         "disabled-by-default-c9") != cat_groups.end());
1121   // Make sure metadata isn't returned.
1122   EXPECT_TRUE(std::find(cat_groups.begin(),
1123                         cat_groups.end(), "__metadata") == cat_groups.end());
1124
1125   const std::vector<std::string> empty_categories;
1126   std::vector<std::string> included_categories;
1127   std::vector<std::string> excluded_categories;
1128
1129   // Test that category filtering works.
1130
1131   // Include nonexistent category -> no events
1132   Clear();
1133   included_categories.clear();
1134   TraceLog::GetInstance()->SetEnabled(
1135       CategoryFilter("not_found823564786"),
1136       TraceLog::RECORDING_MODE,
1137       TraceOptions());
1138   TRACE_EVENT_INSTANT0("cat1", "name", TRACE_EVENT_SCOPE_THREAD);
1139   TRACE_EVENT_INSTANT0("cat2", "name", TRACE_EVENT_SCOPE_THREAD);
1140   EndTraceAndFlush();
1141   DropTracedMetadataRecords();
1142   EXPECT_TRUE(trace_parsed_.empty());
1143
1144   // Include existent category -> only events of that category
1145   Clear();
1146   included_categories.clear();
1147   TraceLog::GetInstance()->SetEnabled(
1148       CategoryFilter("inc"),
1149       TraceLog::RECORDING_MODE,
1150       TraceOptions());
1151   TRACE_EVENT_INSTANT0("inc", "name", TRACE_EVENT_SCOPE_THREAD);
1152   TRACE_EVENT_INSTANT0("inc2", "name", TRACE_EVENT_SCOPE_THREAD);
1153   EndTraceAndFlush();
1154   DropTracedMetadataRecords();
1155   EXPECT_TRUE(FindMatchingValue("cat", "inc"));
1156   EXPECT_FALSE(FindNonMatchingValue("cat", "inc"));
1157
1158   // Include existent wildcard -> all categories matching wildcard
1159   Clear();
1160   included_categories.clear();
1161   TraceLog::GetInstance()->SetEnabled(
1162       CategoryFilter("inc_wildcard_*,inc_wildchar_?_end"),
1163       TraceLog::RECORDING_MODE,
1164       TraceOptions());
1165   TRACE_EVENT_INSTANT0("inc_wildcard_abc", "included",
1166       TRACE_EVENT_SCOPE_THREAD);
1167   TRACE_EVENT_INSTANT0("inc_wildcard_", "included", TRACE_EVENT_SCOPE_THREAD);
1168   TRACE_EVENT_INSTANT0("inc_wildchar_x_end", "included",
1169       TRACE_EVENT_SCOPE_THREAD);
1170   TRACE_EVENT_INSTANT0("inc_wildchar_bla_end", "not_inc",
1171       TRACE_EVENT_SCOPE_THREAD);
1172   TRACE_EVENT_INSTANT0("cat1", "not_inc", TRACE_EVENT_SCOPE_THREAD);
1173   TRACE_EVENT_INSTANT0("cat2", "not_inc", TRACE_EVENT_SCOPE_THREAD);
1174   TRACE_EVENT_INSTANT0("inc_wildcard_category,other_category", "included",
1175       TRACE_EVENT_SCOPE_THREAD);
1176   TRACE_EVENT_INSTANT0(
1177       "non_included_category,inc_wildcard_category", "included",
1178       TRACE_EVENT_SCOPE_THREAD);
1179   EndTraceAndFlush();
1180   EXPECT_TRUE(FindMatchingValue("cat", "inc_wildcard_abc"));
1181   EXPECT_TRUE(FindMatchingValue("cat", "inc_wildcard_"));
1182   EXPECT_TRUE(FindMatchingValue("cat", "inc_wildchar_x_end"));
1183   EXPECT_FALSE(FindMatchingValue("name", "not_inc"));
1184   EXPECT_TRUE(FindMatchingValue("cat", "inc_wildcard_category,other_category"));
1185   EXPECT_TRUE(FindMatchingValue("cat",
1186                                 "non_included_category,inc_wildcard_category"));
1187
1188   included_categories.clear();
1189
1190   // Exclude nonexistent category -> all events
1191   Clear();
1192   TraceLog::GetInstance()->SetEnabled(
1193       CategoryFilter("-not_found823564786"),
1194       TraceLog::RECORDING_MODE,
1195       TraceOptions());
1196   TRACE_EVENT_INSTANT0("cat1", "name", TRACE_EVENT_SCOPE_THREAD);
1197   TRACE_EVENT_INSTANT0("cat2", "name", TRACE_EVENT_SCOPE_THREAD);
1198   TRACE_EVENT_INSTANT0("category1,category2", "name", TRACE_EVENT_SCOPE_THREAD);
1199   EndTraceAndFlush();
1200   EXPECT_TRUE(FindMatchingValue("cat", "cat1"));
1201   EXPECT_TRUE(FindMatchingValue("cat", "cat2"));
1202   EXPECT_TRUE(FindMatchingValue("cat", "category1,category2"));
1203
1204   // Exclude existent category -> only events of other categories
1205   Clear();
1206   TraceLog::GetInstance()->SetEnabled(
1207       CategoryFilter("-inc"),
1208       TraceLog::RECORDING_MODE,
1209       TraceOptions());
1210   TRACE_EVENT_INSTANT0("inc", "name", TRACE_EVENT_SCOPE_THREAD);
1211   TRACE_EVENT_INSTANT0("inc2", "name", TRACE_EVENT_SCOPE_THREAD);
1212   TRACE_EVENT_INSTANT0("inc2,inc", "name", TRACE_EVENT_SCOPE_THREAD);
1213   TRACE_EVENT_INSTANT0("inc,inc2", "name", TRACE_EVENT_SCOPE_THREAD);
1214   EndTraceAndFlush();
1215   EXPECT_TRUE(FindMatchingValue("cat", "inc2"));
1216   EXPECT_FALSE(FindMatchingValue("cat", "inc"));
1217   EXPECT_FALSE(FindMatchingValue("cat", "inc2,inc"));
1218   EXPECT_FALSE(FindMatchingValue("cat", "inc,inc2"));
1219
1220   // Exclude existent wildcard -> all categories not matching wildcard
1221   Clear();
1222   TraceLog::GetInstance()->SetEnabled(
1223       CategoryFilter("-inc_wildcard_*,-inc_wildchar_?_end"),
1224       TraceLog::RECORDING_MODE,
1225       TraceOptions());
1226   TRACE_EVENT_INSTANT0("inc_wildcard_abc", "not_inc",
1227       TRACE_EVENT_SCOPE_THREAD);
1228   TRACE_EVENT_INSTANT0("inc_wildcard_", "not_inc",
1229       TRACE_EVENT_SCOPE_THREAD);
1230   TRACE_EVENT_INSTANT0("inc_wildchar_x_end", "not_inc",
1231       TRACE_EVENT_SCOPE_THREAD);
1232   TRACE_EVENT_INSTANT0("inc_wildchar_bla_end", "included",
1233       TRACE_EVENT_SCOPE_THREAD);
1234   TRACE_EVENT_INSTANT0("cat1", "included", TRACE_EVENT_SCOPE_THREAD);
1235   TRACE_EVENT_INSTANT0("cat2", "included", TRACE_EVENT_SCOPE_THREAD);
1236   EndTraceAndFlush();
1237   EXPECT_TRUE(FindMatchingValue("cat", "inc_wildchar_bla_end"));
1238   EXPECT_TRUE(FindMatchingValue("cat", "cat1"));
1239   EXPECT_TRUE(FindMatchingValue("cat", "cat2"));
1240   EXPECT_FALSE(FindMatchingValue("name", "not_inc"));
1241 }
1242
1243
1244 // Test EVENT_WATCH_NOTIFICATION
1245 TEST_F(TraceEventTestFixture, EventWatchNotification) {
1246   // Basic one occurrence.
1247   BeginTrace();
1248   TraceLog::WatchEventCallback callback =
1249       base::Bind(&TraceEventTestFixture::OnWatchEventMatched,
1250                  base::Unretained(this));
1251   TraceLog::GetInstance()->SetWatchEvent("cat", "event", callback);
1252   TRACE_EVENT_INSTANT0("cat", "event", TRACE_EVENT_SCOPE_THREAD);
1253   EndTraceAndFlush();
1254   EXPECT_EQ(event_watch_notification_, 1);
1255
1256   // Auto-reset after end trace.
1257   BeginTrace();
1258   TraceLog::GetInstance()->SetWatchEvent("cat", "event", callback);
1259   EndTraceAndFlush();
1260   BeginTrace();
1261   TRACE_EVENT_INSTANT0("cat", "event", TRACE_EVENT_SCOPE_THREAD);
1262   EndTraceAndFlush();
1263   EXPECT_EQ(event_watch_notification_, 0);
1264
1265   // Multiple occurrence.
1266   BeginTrace();
1267   int num_occurrences = 5;
1268   TraceLog::GetInstance()->SetWatchEvent("cat", "event", callback);
1269   for (int i = 0; i < num_occurrences; ++i)
1270     TRACE_EVENT_INSTANT0("cat", "event", TRACE_EVENT_SCOPE_THREAD);
1271   EndTraceAndFlush();
1272   EXPECT_EQ(event_watch_notification_, num_occurrences);
1273
1274   // Wrong category.
1275   BeginTrace();
1276   TraceLog::GetInstance()->SetWatchEvent("cat", "event", callback);
1277   TRACE_EVENT_INSTANT0("wrong_cat", "event", TRACE_EVENT_SCOPE_THREAD);
1278   EndTraceAndFlush();
1279   EXPECT_EQ(event_watch_notification_, 0);
1280
1281   // Wrong name.
1282   BeginTrace();
1283   TraceLog::GetInstance()->SetWatchEvent("cat", "event", callback);
1284   TRACE_EVENT_INSTANT0("cat", "wrong_event", TRACE_EVENT_SCOPE_THREAD);
1285   EndTraceAndFlush();
1286   EXPECT_EQ(event_watch_notification_, 0);
1287
1288   // Canceled.
1289   BeginTrace();
1290   TraceLog::GetInstance()->SetWatchEvent("cat", "event", callback);
1291   TraceLog::GetInstance()->CancelWatchEvent();
1292   TRACE_EVENT_INSTANT0("cat", "event", TRACE_EVENT_SCOPE_THREAD);
1293   EndTraceAndFlush();
1294   EXPECT_EQ(event_watch_notification_, 0);
1295 }
1296
1297 // Test ASYNC_BEGIN/END events
1298 TEST_F(TraceEventTestFixture, AsyncBeginEndEvents) {
1299   BeginTrace();
1300
1301   unsigned long long id = 0xfeedbeeffeedbeefull;
1302   TRACE_EVENT_ASYNC_BEGIN0("cat", "name1", id);
1303   TRACE_EVENT_ASYNC_STEP_INTO0("cat", "name1", id, "step1");
1304   TRACE_EVENT_ASYNC_END0("cat", "name1", id);
1305   TRACE_EVENT_BEGIN0("cat", "name2");
1306   TRACE_EVENT_ASYNC_BEGIN0("cat", "name3", 0);
1307   TRACE_EVENT_ASYNC_STEP_PAST0("cat", "name3", 0, "step2");
1308
1309   EndTraceAndFlush();
1310
1311   EXPECT_TRUE(FindNamePhase("name1", "S"));
1312   EXPECT_TRUE(FindNamePhase("name1", "T"));
1313   EXPECT_TRUE(FindNamePhase("name1", "F"));
1314
1315   std::string id_str;
1316   StringAppendF(&id_str, "0x%llx", id);
1317
1318   EXPECT_TRUE(FindNamePhaseKeyValue("name1", "S", "id", id_str.c_str()));
1319   EXPECT_TRUE(FindNamePhaseKeyValue("name1", "T", "id", id_str.c_str()));
1320   EXPECT_TRUE(FindNamePhaseKeyValue("name1", "F", "id", id_str.c_str()));
1321   EXPECT_TRUE(FindNamePhaseKeyValue("name3", "S", "id", "0x0"));
1322   EXPECT_TRUE(FindNamePhaseKeyValue("name3", "p", "id", "0x0"));
1323
1324   // BEGIN events should not have id
1325   EXPECT_FALSE(FindNamePhaseKeyValue("name2", "B", "id", "0"));
1326 }
1327
1328 // Test ASYNC_BEGIN/END events
1329 TEST_F(TraceEventTestFixture, AsyncBeginEndPointerMangling) {
1330   void* ptr = this;
1331
1332   TraceLog::GetInstance()->SetProcessID(100);
1333   BeginTrace();
1334   TRACE_EVENT_ASYNC_BEGIN0("cat", "name1", ptr);
1335   TRACE_EVENT_ASYNC_BEGIN0("cat", "name2", ptr);
1336   EndTraceAndFlush();
1337
1338   TraceLog::GetInstance()->SetProcessID(200);
1339   BeginTrace();
1340   TRACE_EVENT_ASYNC_END0("cat", "name1", ptr);
1341   EndTraceAndFlush();
1342
1343   DictionaryValue* async_begin = FindNamePhase("name1", "S");
1344   DictionaryValue* async_begin2 = FindNamePhase("name2", "S");
1345   DictionaryValue* async_end = FindNamePhase("name1", "F");
1346   EXPECT_TRUE(async_begin);
1347   EXPECT_TRUE(async_begin2);
1348   EXPECT_TRUE(async_end);
1349
1350   Value* value = NULL;
1351   std::string async_begin_id_str;
1352   std::string async_begin2_id_str;
1353   std::string async_end_id_str;
1354   ASSERT_TRUE(async_begin->Get("id", &value));
1355   ASSERT_TRUE(value->GetAsString(&async_begin_id_str));
1356   ASSERT_TRUE(async_begin2->Get("id", &value));
1357   ASSERT_TRUE(value->GetAsString(&async_begin2_id_str));
1358   ASSERT_TRUE(async_end->Get("id", &value));
1359   ASSERT_TRUE(value->GetAsString(&async_end_id_str));
1360
1361   EXPECT_STREQ(async_begin_id_str.c_str(), async_begin2_id_str.c_str());
1362   EXPECT_STRNE(async_begin_id_str.c_str(), async_end_id_str.c_str());
1363 }
1364
1365 // Test that static strings are not copied.
1366 TEST_F(TraceEventTestFixture, StaticStringVsString) {
1367   TraceLog* tracer = TraceLog::GetInstance();
1368   // Make sure old events are flushed:
1369   EndTraceAndFlush();
1370   EXPECT_EQ(0u, tracer->GetEventsSize());
1371   const unsigned char* category_group_enabled =
1372       TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED("cat");
1373
1374   {
1375     BeginTrace();
1376     // Test that string arguments are copied.
1377     TraceEventHandle handle1 =
1378         trace_event_internal::AddTraceEvent(
1379             TRACE_EVENT_PHASE_INSTANT, category_group_enabled, "name1", 0, 0,
1380             "arg1", std::string("argval"), "arg2", std::string("argval"));
1381     // Test that static TRACE_STR_COPY string arguments are copied.
1382     TraceEventHandle handle2 =
1383         trace_event_internal::AddTraceEvent(
1384             TRACE_EVENT_PHASE_INSTANT, category_group_enabled, "name2", 0, 0,
1385             "arg1", TRACE_STR_COPY("argval"),
1386             "arg2", TRACE_STR_COPY("argval"));
1387     size_t num_events = tracer->GetEventsSize();
1388     EXPECT_GT(num_events, 1u);
1389     const TraceEvent* event1 = tracer->GetEventByHandle(handle1);
1390     const TraceEvent* event2 = tracer->GetEventByHandle(handle2);
1391     ASSERT_TRUE(event1);
1392     ASSERT_TRUE(event2);
1393     EXPECT_STREQ("name1", event1->name());
1394     EXPECT_STREQ("name2", event2->name());
1395     EXPECT_TRUE(event1->parameter_copy_storage() != NULL);
1396     EXPECT_TRUE(event2->parameter_copy_storage() != NULL);
1397     EXPECT_GT(event1->parameter_copy_storage()->size(), 0u);
1398     EXPECT_GT(event2->parameter_copy_storage()->size(), 0u);
1399     EndTraceAndFlush();
1400   }
1401
1402   {
1403     BeginTrace();
1404     // Test that static literal string arguments are not copied.
1405     TraceEventHandle handle1 =
1406         trace_event_internal::AddTraceEvent(
1407             TRACE_EVENT_PHASE_INSTANT, category_group_enabled, "name1", 0, 0,
1408             "arg1", "argval", "arg2", "argval");
1409     // Test that static TRACE_STR_COPY NULL string arguments are not copied.
1410     const char* str1 = NULL;
1411     const char* str2 = NULL;
1412     TraceEventHandle handle2 =
1413         trace_event_internal::AddTraceEvent(
1414             TRACE_EVENT_PHASE_INSTANT, category_group_enabled, "name2", 0, 0,
1415             "arg1", TRACE_STR_COPY(str1),
1416             "arg2", TRACE_STR_COPY(str2));
1417     size_t num_events = tracer->GetEventsSize();
1418     EXPECT_GT(num_events, 1u);
1419     const TraceEvent* event1 = tracer->GetEventByHandle(handle1);
1420     const TraceEvent* event2 = tracer->GetEventByHandle(handle2);
1421     ASSERT_TRUE(event1);
1422     ASSERT_TRUE(event2);
1423     EXPECT_STREQ("name1", event1->name());
1424     EXPECT_STREQ("name2", event2->name());
1425     EXPECT_TRUE(event1->parameter_copy_storage() == NULL);
1426     EXPECT_TRUE(event2->parameter_copy_storage() == NULL);
1427     EndTraceAndFlush();
1428   }
1429 }
1430
1431 // Test that data sent from other threads is gathered
1432 TEST_F(TraceEventTestFixture, DataCapturedOnThread) {
1433   BeginTrace();
1434
1435   Thread thread("1");
1436   WaitableEvent task_complete_event(false, false);
1437   thread.Start();
1438
1439   thread.message_loop()->PostTask(
1440       FROM_HERE, base::Bind(&TraceWithAllMacroVariants, &task_complete_event));
1441   task_complete_event.Wait();
1442   thread.Stop();
1443
1444   EndTraceAndFlush();
1445   ValidateAllTraceMacrosCreatedData(trace_parsed_);
1446 }
1447
1448 // Test that data sent from multiple threads is gathered
1449 TEST_F(TraceEventTestFixture, DataCapturedManyThreads) {
1450   BeginTrace();
1451
1452   const int num_threads = 4;
1453   const int num_events = 4000;
1454   Thread* threads[num_threads];
1455   WaitableEvent* task_complete_events[num_threads];
1456   for (int i = 0; i < num_threads; i++) {
1457     threads[i] = new Thread(StringPrintf("Thread %d", i));
1458     task_complete_events[i] = new WaitableEvent(false, false);
1459     threads[i]->Start();
1460     threads[i]->message_loop()->PostTask(
1461         FROM_HERE, base::Bind(&TraceManyInstantEvents,
1462                               i, num_events, task_complete_events[i]));
1463   }
1464
1465   for (int i = 0; i < num_threads; i++) {
1466     task_complete_events[i]->Wait();
1467   }
1468
1469   // Let half of the threads end before flush.
1470   for (int i = 0; i < num_threads / 2; i++) {
1471     threads[i]->Stop();
1472     delete threads[i];
1473     delete task_complete_events[i];
1474   }
1475
1476   EndTraceAndFlushInThreadWithMessageLoop();
1477   ValidateInstantEventPresentOnEveryThread(trace_parsed_,
1478                                            num_threads, num_events);
1479
1480   // Let the other half of the threads end after flush.
1481   for (int i = num_threads / 2; i < num_threads; i++) {
1482     threads[i]->Stop();
1483     delete threads[i];
1484     delete task_complete_events[i];
1485   }
1486 }
1487
1488 // Test that thread and process names show up in the trace
1489 TEST_F(TraceEventTestFixture, ThreadNames) {
1490   // Create threads before we enable tracing to make sure
1491   // that tracelog still captures them.
1492   const int kNumThreads = 4;
1493   const int kNumEvents = 10;
1494   Thread* threads[kNumThreads];
1495   PlatformThreadId thread_ids[kNumThreads];
1496   for (int i = 0; i < kNumThreads; i++)
1497     threads[i] = new Thread(StringPrintf("Thread %d", i));
1498
1499   // Enable tracing.
1500   BeginTrace();
1501
1502   // Now run some trace code on these threads.
1503   WaitableEvent* task_complete_events[kNumThreads];
1504   for (int i = 0; i < kNumThreads; i++) {
1505     task_complete_events[i] = new WaitableEvent(false, false);
1506     threads[i]->Start();
1507     thread_ids[i] = threads[i]->thread_id();
1508     threads[i]->message_loop()->PostTask(
1509         FROM_HERE, base::Bind(&TraceManyInstantEvents,
1510                               i, kNumEvents, task_complete_events[i]));
1511   }
1512   for (int i = 0; i < kNumThreads; i++) {
1513     task_complete_events[i]->Wait();
1514   }
1515
1516   // Shut things down.
1517   for (int i = 0; i < kNumThreads; i++) {
1518     threads[i]->Stop();
1519     delete threads[i];
1520     delete task_complete_events[i];
1521   }
1522
1523   EndTraceAndFlush();
1524
1525   std::string tmp;
1526   int tmp_int;
1527   const DictionaryValue* item;
1528
1529   // Make sure we get thread name metadata.
1530   // Note, the test suite may have created a ton of threads.
1531   // So, we'll have thread names for threads we didn't create.
1532   std::vector<const DictionaryValue*> items =
1533       FindTraceEntries(trace_parsed_, "thread_name");
1534   for (int i = 0; i < static_cast<int>(items.size()); i++) {
1535     item = items[i];
1536     ASSERT_TRUE(item);
1537     EXPECT_TRUE(item->GetInteger("tid", &tmp_int));
1538
1539     // See if this thread name is one of the threads we just created
1540     for (int j = 0; j < kNumThreads; j++) {
1541       if(static_cast<int>(thread_ids[j]) != tmp_int)
1542         continue;
1543
1544       std::string expected_name = StringPrintf("Thread %d", j);
1545       EXPECT_TRUE(item->GetString("ph", &tmp) && tmp == "M");
1546       EXPECT_TRUE(item->GetInteger("pid", &tmp_int) &&
1547                   tmp_int == static_cast<int>(base::GetCurrentProcId()));
1548       // If the thread name changes or the tid gets reused, the name will be
1549       // a comma-separated list of thread names, so look for a substring.
1550       EXPECT_TRUE(item->GetString("args.name", &tmp) &&
1551                   tmp.find(expected_name) != std::string::npos);
1552     }
1553   }
1554 }
1555
1556 TEST_F(TraceEventTestFixture, ThreadNameChanges) {
1557   BeginTrace();
1558
1559   PlatformThread::SetName("");
1560   TRACE_EVENT_INSTANT0("drink", "water", TRACE_EVENT_SCOPE_THREAD);
1561
1562   PlatformThread::SetName("cafe");
1563   TRACE_EVENT_INSTANT0("drink", "coffee", TRACE_EVENT_SCOPE_THREAD);
1564
1565   PlatformThread::SetName("shop");
1566   // No event here, so won't appear in combined name.
1567
1568   PlatformThread::SetName("pub");
1569   TRACE_EVENT_INSTANT0("drink", "beer", TRACE_EVENT_SCOPE_THREAD);
1570   TRACE_EVENT_INSTANT0("drink", "wine", TRACE_EVENT_SCOPE_THREAD);
1571
1572   PlatformThread::SetName(" bar");
1573   TRACE_EVENT_INSTANT0("drink", "whisky", TRACE_EVENT_SCOPE_THREAD);
1574
1575   EndTraceAndFlush();
1576
1577   std::vector<const DictionaryValue*> items =
1578       FindTraceEntries(trace_parsed_, "thread_name");
1579   EXPECT_EQ(1u, items.size());
1580   ASSERT_GT(items.size(), 0u);
1581   const DictionaryValue* item = items[0];
1582   ASSERT_TRUE(item);
1583   int tid;
1584   EXPECT_TRUE(item->GetInteger("tid", &tid));
1585   EXPECT_EQ(PlatformThread::CurrentId(), static_cast<PlatformThreadId>(tid));
1586
1587   std::string expected_name = "cafe,pub, bar";
1588   std::string tmp;
1589   EXPECT_TRUE(item->GetString("args.name", &tmp));
1590   EXPECT_EQ(expected_name, tmp);
1591 }
1592
1593 // Test that the disabled trace categories are included/excluded from the
1594 // trace output correctly.
1595 TEST_F(TraceEventTestFixture, DisabledCategories) {
1596   BeginTrace();
1597   TRACE_EVENT_INSTANT0(TRACE_DISABLED_BY_DEFAULT("cc"), "first",
1598                        TRACE_EVENT_SCOPE_THREAD);
1599   TRACE_EVENT_INSTANT0("included", "first", TRACE_EVENT_SCOPE_THREAD);
1600   EndTraceAndFlush();
1601   {
1602     const DictionaryValue* item = NULL;
1603     ListValue& trace_parsed = trace_parsed_;
1604     EXPECT_NOT_FIND_("disabled-by-default-cc");
1605     EXPECT_FIND_("included");
1606   }
1607   Clear();
1608
1609   BeginSpecificTrace("disabled-by-default-cc");
1610   TRACE_EVENT_INSTANT0(TRACE_DISABLED_BY_DEFAULT("cc"), "second",
1611                        TRACE_EVENT_SCOPE_THREAD);
1612   TRACE_EVENT_INSTANT0("other_included", "second", TRACE_EVENT_SCOPE_THREAD);
1613   EndTraceAndFlush();
1614
1615   {
1616     const DictionaryValue* item = NULL;
1617     ListValue& trace_parsed = trace_parsed_;
1618     EXPECT_FIND_("disabled-by-default-cc");
1619     EXPECT_FIND_("other_included");
1620   }
1621 }
1622
1623 TEST_F(TraceEventTestFixture, NormallyNoDeepCopy) {
1624   // Test that the TRACE_EVENT macros do not deep-copy their string. If they
1625   // do so it may indicate a performance regression, but more-over it would
1626   // make the DEEP_COPY overloads redundant.
1627   std::string name_string("event name");
1628
1629   BeginTrace();
1630   TRACE_EVENT_INSTANT0("category", name_string.c_str(),
1631                        TRACE_EVENT_SCOPE_THREAD);
1632
1633   // Modify the string in place (a wholesale reassignment may leave the old
1634   // string intact on the heap).
1635   name_string[0] = '@';
1636
1637   EndTraceAndFlush();
1638
1639   EXPECT_FALSE(FindTraceEntry(trace_parsed_, "event name"));
1640   EXPECT_TRUE(FindTraceEntry(trace_parsed_, name_string.c_str()));
1641 }
1642
1643 TEST_F(TraceEventTestFixture, DeepCopy) {
1644   static const char kOriginalName1[] = "name1";
1645   static const char kOriginalName2[] = "name2";
1646   static const char kOriginalName3[] = "name3";
1647   std::string name1(kOriginalName1);
1648   std::string name2(kOriginalName2);
1649   std::string name3(kOriginalName3);
1650   std::string arg1("arg1");
1651   std::string arg2("arg2");
1652   std::string val1("val1");
1653   std::string val2("val2");
1654
1655   BeginTrace();
1656   TRACE_EVENT_COPY_INSTANT0("category", name1.c_str(),
1657                             TRACE_EVENT_SCOPE_THREAD);
1658   TRACE_EVENT_COPY_BEGIN1("category", name2.c_str(),
1659                           arg1.c_str(), 5);
1660   TRACE_EVENT_COPY_END2("category", name3.c_str(),
1661                         arg1.c_str(), val1,
1662                         arg2.c_str(), val2);
1663
1664   // As per NormallyNoDeepCopy, modify the strings in place.
1665   name1[0] = name2[0] = name3[0] = arg1[0] = arg2[0] = val1[0] = val2[0] = '@';
1666
1667   EndTraceAndFlush();
1668
1669   EXPECT_FALSE(FindTraceEntry(trace_parsed_, name1.c_str()));
1670   EXPECT_FALSE(FindTraceEntry(trace_parsed_, name2.c_str()));
1671   EXPECT_FALSE(FindTraceEntry(trace_parsed_, name3.c_str()));
1672
1673   const DictionaryValue* entry1 = FindTraceEntry(trace_parsed_, kOriginalName1);
1674   const DictionaryValue* entry2 = FindTraceEntry(trace_parsed_, kOriginalName2);
1675   const DictionaryValue* entry3 = FindTraceEntry(trace_parsed_, kOriginalName3);
1676   ASSERT_TRUE(entry1);
1677   ASSERT_TRUE(entry2);
1678   ASSERT_TRUE(entry3);
1679
1680   int i;
1681   EXPECT_FALSE(entry2->GetInteger("args.@rg1", &i));
1682   EXPECT_TRUE(entry2->GetInteger("args.arg1", &i));
1683   EXPECT_EQ(5, i);
1684
1685   std::string s;
1686   EXPECT_TRUE(entry3->GetString("args.arg1", &s));
1687   EXPECT_EQ("val1", s);
1688   EXPECT_TRUE(entry3->GetString("args.arg2", &s));
1689   EXPECT_EQ("val2", s);
1690 }
1691
1692 // Test that TraceResultBuffer outputs the correct result whether it is added
1693 // in chunks or added all at once.
1694 TEST_F(TraceEventTestFixture, TraceResultBuffer) {
1695   Clear();
1696
1697   trace_buffer_.Start();
1698   trace_buffer_.AddFragment("bla1");
1699   trace_buffer_.AddFragment("bla2");
1700   trace_buffer_.AddFragment("bla3,bla4");
1701   trace_buffer_.Finish();
1702   EXPECT_STREQ(json_output_.json_output.c_str(), "[bla1,bla2,bla3,bla4]");
1703
1704   Clear();
1705
1706   trace_buffer_.Start();
1707   trace_buffer_.AddFragment("bla1,bla2,bla3,bla4");
1708   trace_buffer_.Finish();
1709   EXPECT_STREQ(json_output_.json_output.c_str(), "[bla1,bla2,bla3,bla4]");
1710 }
1711
1712 // Test that trace_event parameters are not evaluated if the tracing
1713 // system is disabled.
1714 TEST_F(TraceEventTestFixture, TracingIsLazy) {
1715   BeginTrace();
1716
1717   int a = 0;
1718   TRACE_EVENT_INSTANT1("category", "test", TRACE_EVENT_SCOPE_THREAD, "a", a++);
1719   EXPECT_EQ(1, a);
1720
1721   TraceLog::GetInstance()->SetDisabled();
1722
1723   TRACE_EVENT_INSTANT1("category", "test", TRACE_EVENT_SCOPE_THREAD, "a", a++);
1724   EXPECT_EQ(1, a);
1725
1726   EndTraceAndFlush();
1727 }
1728
1729 TEST_F(TraceEventTestFixture, TraceEnableDisable) {
1730   TraceLog* trace_log = TraceLog::GetInstance();
1731   CategoryFilter cf_inc_all("*");
1732   trace_log->SetEnabled(cf_inc_all,
1733                         TraceLog::RECORDING_MODE,
1734                         TraceOptions());
1735   EXPECT_TRUE(trace_log->IsEnabled());
1736   trace_log->SetDisabled();
1737   EXPECT_FALSE(trace_log->IsEnabled());
1738
1739   trace_log->SetEnabled(cf_inc_all,
1740                         TraceLog::RECORDING_MODE,
1741                         TraceOptions());
1742   EXPECT_TRUE(trace_log->IsEnabled());
1743   const std::vector<std::string> empty;
1744   trace_log->SetEnabled(CategoryFilter(),
1745                         TraceLog::RECORDING_MODE,
1746                         TraceOptions());
1747   EXPECT_TRUE(trace_log->IsEnabled());
1748   trace_log->SetDisabled();
1749   EXPECT_FALSE(trace_log->IsEnabled());
1750   trace_log->SetDisabled();
1751   EXPECT_FALSE(trace_log->IsEnabled());
1752 }
1753
1754 TEST_F(TraceEventTestFixture, TraceCategoriesAfterNestedEnable) {
1755   TraceLog* trace_log = TraceLog::GetInstance();
1756   trace_log->SetEnabled(CategoryFilter("foo,bar"),
1757                         TraceLog::RECORDING_MODE,
1758                         TraceOptions());
1759   EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("foo"));
1760   EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("bar"));
1761   EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("baz"));
1762   trace_log->SetEnabled(CategoryFilter("foo2"),
1763                         TraceLog::RECORDING_MODE,
1764                         TraceOptions());
1765   EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("foo2"));
1766   EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("baz"));
1767   // The "" becomes the default catergory set when applied.
1768   trace_log->SetEnabled(CategoryFilter(),
1769                         TraceLog::RECORDING_MODE,
1770                         TraceOptions());
1771   EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("foo"));
1772   EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("baz"));
1773   EXPECT_STREQ("-*Debug,-*Test",
1774                trace_log->GetCurrentCategoryFilter().ToString().c_str());
1775   trace_log->SetDisabled();
1776   trace_log->SetDisabled();
1777   trace_log->SetDisabled();
1778   EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("foo"));
1779   EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("baz"));
1780
1781   trace_log->SetEnabled(CategoryFilter("-foo,-bar"),
1782                         TraceLog::RECORDING_MODE,
1783                         TraceOptions());
1784   EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("foo"));
1785   EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("baz"));
1786   trace_log->SetEnabled(CategoryFilter("moo"),
1787                         TraceLog::RECORDING_MODE,
1788                         TraceOptions());
1789   EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("baz"));
1790   EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("moo"));
1791   EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("foo"));
1792   EXPECT_STREQ("-foo,-bar",
1793                trace_log->GetCurrentCategoryFilter().ToString().c_str());
1794   trace_log->SetDisabled();
1795   trace_log->SetDisabled();
1796
1797   // Make sure disabled categories aren't cleared if we set in the second.
1798   trace_log->SetEnabled(CategoryFilter("disabled-by-default-cc,foo"),
1799                         TraceLog::RECORDING_MODE,
1800                         TraceOptions());
1801   EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("bar"));
1802   trace_log->SetEnabled(CategoryFilter("disabled-by-default-gpu"),
1803                         TraceLog::RECORDING_MODE,
1804                         TraceOptions());
1805   EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("disabled-by-default-cc"));
1806   EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("disabled-by-default-gpu"));
1807   EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("bar"));
1808   EXPECT_STREQ("disabled-by-default-cc,disabled-by-default-gpu",
1809                trace_log->GetCurrentCategoryFilter().ToString().c_str());
1810   trace_log->SetDisabled();
1811   trace_log->SetDisabled();
1812 }
1813
1814 TEST_F(TraceEventTestFixture, TraceSampling) {
1815   TraceOptions trace_options(RECORD_UNTIL_FULL);
1816   trace_options.enable_sampling = true;
1817   TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
1818                                       TraceLog::RECORDING_MODE,
1819                                       trace_options);
1820
1821   TRACE_EVENT_SET_SAMPLING_STATE_FOR_BUCKET(1, "cc", "Stuff");
1822   TraceLog::GetInstance()->WaitSamplingEventForTesting();
1823   TRACE_EVENT_SET_SAMPLING_STATE_FOR_BUCKET(1, "cc", "Things");
1824   TraceLog::GetInstance()->WaitSamplingEventForTesting();
1825
1826   EndTraceAndFlush();
1827
1828   // Make sure we hit at least once.
1829   EXPECT_TRUE(FindNamePhase("Stuff", "P"));
1830   EXPECT_TRUE(FindNamePhase("Things", "P"));
1831 }
1832
1833 TEST_F(TraceEventTestFixture, TraceSamplingScope) {
1834   TraceOptions trace_options(RECORD_UNTIL_FULL);
1835   trace_options.enable_sampling = true;
1836   TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
1837                                       TraceLog::RECORDING_MODE,
1838                                       trace_options);
1839
1840   TRACE_EVENT_SCOPED_SAMPLING_STATE("AAA", "name");
1841   TraceLog::GetInstance()->WaitSamplingEventForTesting();
1842   {
1843     EXPECT_STREQ(TRACE_EVENT_GET_SAMPLING_STATE(), "AAA");
1844     TRACE_EVENT_SCOPED_SAMPLING_STATE("BBB", "name");
1845     TraceLog::GetInstance()->WaitSamplingEventForTesting();
1846     EXPECT_STREQ(TRACE_EVENT_GET_SAMPLING_STATE(), "BBB");
1847   }
1848   TraceLog::GetInstance()->WaitSamplingEventForTesting();
1849   {
1850     EXPECT_STREQ(TRACE_EVENT_GET_SAMPLING_STATE(), "AAA");
1851     TRACE_EVENT_SCOPED_SAMPLING_STATE("CCC", "name");
1852     TraceLog::GetInstance()->WaitSamplingEventForTesting();
1853     EXPECT_STREQ(TRACE_EVENT_GET_SAMPLING_STATE(), "CCC");
1854   }
1855   TraceLog::GetInstance()->WaitSamplingEventForTesting();
1856   {
1857     EXPECT_STREQ(TRACE_EVENT_GET_SAMPLING_STATE(), "AAA");
1858     TRACE_EVENT_SET_SAMPLING_STATE("DDD", "name");
1859     TraceLog::GetInstance()->WaitSamplingEventForTesting();
1860     EXPECT_STREQ(TRACE_EVENT_GET_SAMPLING_STATE(), "DDD");
1861   }
1862   TraceLog::GetInstance()->WaitSamplingEventForTesting();
1863   EXPECT_STREQ(TRACE_EVENT_GET_SAMPLING_STATE(), "DDD");
1864
1865   EndTraceAndFlush();
1866 }
1867
1868 TEST_F(TraceEventTestFixture, TraceContinuousSampling) {
1869   TraceOptions trace_options(RECORD_UNTIL_FULL);
1870   trace_options.enable_sampling = true;
1871
1872   TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
1873                                       TraceLog::MONITORING_MODE,
1874                                       trace_options);
1875
1876   TRACE_EVENT_SET_SAMPLING_STATE_FOR_BUCKET(1, "category", "AAA");
1877   TraceLog::GetInstance()->WaitSamplingEventForTesting();
1878   TRACE_EVENT_SET_SAMPLING_STATE_FOR_BUCKET(1, "category", "BBB");
1879   TraceLog::GetInstance()->WaitSamplingEventForTesting();
1880
1881   FlushMonitoring();
1882
1883   // Make sure we can get the profiled data.
1884   EXPECT_TRUE(FindNamePhase("AAA", "P"));
1885   EXPECT_TRUE(FindNamePhase("BBB", "P"));
1886
1887   Clear();
1888   TraceLog::GetInstance()->WaitSamplingEventForTesting();
1889
1890   TRACE_EVENT_SET_SAMPLING_STATE_FOR_BUCKET(1, "category", "CCC");
1891   TraceLog::GetInstance()->WaitSamplingEventForTesting();
1892   TRACE_EVENT_SET_SAMPLING_STATE_FOR_BUCKET(1, "category", "DDD");
1893   TraceLog::GetInstance()->WaitSamplingEventForTesting();
1894
1895   FlushMonitoring();
1896
1897   // Make sure the profiled data is accumulated.
1898   EXPECT_TRUE(FindNamePhase("AAA", "P"));
1899   EXPECT_TRUE(FindNamePhase("BBB", "P"));
1900   EXPECT_TRUE(FindNamePhase("CCC", "P"));
1901   EXPECT_TRUE(FindNamePhase("DDD", "P"));
1902
1903   Clear();
1904
1905   TraceLog::GetInstance()->SetDisabled();
1906
1907   // Make sure disabling the continuous sampling thread clears
1908   // the profiled data.
1909   EXPECT_FALSE(FindNamePhase("AAA", "P"));
1910   EXPECT_FALSE(FindNamePhase("BBB", "P"));
1911   EXPECT_FALSE(FindNamePhase("CCC", "P"));
1912   EXPECT_FALSE(FindNamePhase("DDD", "P"));
1913
1914   Clear();
1915 }
1916
1917 class MyData : public ConvertableToTraceFormat {
1918  public:
1919   MyData() {}
1920
1921   void AppendAsTraceFormat(std::string* out) const override {
1922     out->append("{\"foo\":1}");
1923   }
1924
1925  private:
1926   ~MyData() override {}
1927   DISALLOW_COPY_AND_ASSIGN(MyData);
1928 };
1929
1930 TEST_F(TraceEventTestFixture, ConvertableTypes) {
1931   TraceLog::GetInstance()->SetEnabled(
1932       CategoryFilter("*"),
1933       TraceLog::RECORDING_MODE,
1934       TraceOptions());
1935
1936   scoped_refptr<ConvertableToTraceFormat> data(new MyData());
1937   scoped_refptr<ConvertableToTraceFormat> data1(new MyData());
1938   scoped_refptr<ConvertableToTraceFormat> data2(new MyData());
1939   TRACE_EVENT1("foo", "bar", "data", data);
1940   TRACE_EVENT2("foo", "baz",
1941                "data1", data1,
1942                "data2", data2);
1943
1944
1945   scoped_refptr<ConvertableToTraceFormat> convertData1(new MyData());
1946   scoped_refptr<ConvertableToTraceFormat> convertData2(new MyData());
1947   TRACE_EVENT2(
1948       "foo",
1949       "string_first",
1950       "str",
1951       "string value 1",
1952       "convert",
1953       convertData1);
1954   TRACE_EVENT2(
1955       "foo",
1956       "string_second",
1957       "convert",
1958       convertData2,
1959       "str",
1960       "string value 2");
1961   EndTraceAndFlush();
1962
1963   // One arg version.
1964   DictionaryValue* dict = FindNamePhase("bar", "X");
1965   ASSERT_TRUE(dict);
1966
1967   const DictionaryValue* args_dict = NULL;
1968   dict->GetDictionary("args", &args_dict);
1969   ASSERT_TRUE(args_dict);
1970
1971   const Value* value = NULL;
1972   const DictionaryValue* convertable_dict = NULL;
1973   EXPECT_TRUE(args_dict->Get("data", &value));
1974   ASSERT_TRUE(value->GetAsDictionary(&convertable_dict));
1975
1976   int foo_val;
1977   EXPECT_TRUE(convertable_dict->GetInteger("foo", &foo_val));
1978   EXPECT_EQ(1, foo_val);
1979
1980   // Two arg version.
1981   dict = FindNamePhase("baz", "X");
1982   ASSERT_TRUE(dict);
1983
1984   args_dict = NULL;
1985   dict->GetDictionary("args", &args_dict);
1986   ASSERT_TRUE(args_dict);
1987
1988   value = NULL;
1989   convertable_dict = NULL;
1990   EXPECT_TRUE(args_dict->Get("data1", &value));
1991   ASSERT_TRUE(value->GetAsDictionary(&convertable_dict));
1992
1993   value = NULL;
1994   convertable_dict = NULL;
1995   EXPECT_TRUE(args_dict->Get("data2", &value));
1996   ASSERT_TRUE(value->GetAsDictionary(&convertable_dict));
1997
1998   // Convertable with other types.
1999   dict = FindNamePhase("string_first", "X");
2000   ASSERT_TRUE(dict);
2001
2002   args_dict = NULL;
2003   dict->GetDictionary("args", &args_dict);
2004   ASSERT_TRUE(args_dict);
2005
2006   std::string str_value;
2007   EXPECT_TRUE(args_dict->GetString("str", &str_value));
2008   EXPECT_STREQ("string value 1", str_value.c_str());
2009
2010   value = NULL;
2011   convertable_dict = NULL;
2012   foo_val = 0;
2013   EXPECT_TRUE(args_dict->Get("convert", &value));
2014   ASSERT_TRUE(value->GetAsDictionary(&convertable_dict));
2015   EXPECT_TRUE(convertable_dict->GetInteger("foo", &foo_val));
2016   EXPECT_EQ(1, foo_val);
2017
2018   dict = FindNamePhase("string_second", "X");
2019   ASSERT_TRUE(dict);
2020
2021   args_dict = NULL;
2022   dict->GetDictionary("args", &args_dict);
2023   ASSERT_TRUE(args_dict);
2024
2025   EXPECT_TRUE(args_dict->GetString("str", &str_value));
2026   EXPECT_STREQ("string value 2", str_value.c_str());
2027
2028   value = NULL;
2029   convertable_dict = NULL;
2030   foo_val = 0;
2031   EXPECT_TRUE(args_dict->Get("convert", &value));
2032   ASSERT_TRUE(value->GetAsDictionary(&convertable_dict));
2033   EXPECT_TRUE(convertable_dict->GetInteger("foo", &foo_val));
2034   EXPECT_EQ(1, foo_val);
2035 }
2036
2037 TEST_F(TraceEventTestFixture, PrimitiveArgs) {
2038   TraceLog::GetInstance()->SetEnabled(
2039       CategoryFilter("*"),
2040       TraceLog::RECORDING_MODE,
2041       TraceOptions());
2042
2043   TRACE_EVENT1("foo", "event1", "int_one", 1);
2044   TRACE_EVENT1("foo", "event2", "int_neg_ten", -10);
2045   TRACE_EVENT1("foo", "event3", "float_one", 1.0f);
2046   TRACE_EVENT1("foo", "event4", "float_half", .5f);
2047   TRACE_EVENT1("foo", "event5", "float_neghalf", -.5f);
2048   TRACE_EVENT1("foo", "event6", "float_infinity",
2049       std::numeric_limits<float>::infinity());
2050   TRACE_EVENT1("foo", "event6b", "float_neg_infinity",
2051       -std::numeric_limits<float>::infinity());
2052   TRACE_EVENT1("foo", "event7", "double_nan",
2053       std::numeric_limits<double>::quiet_NaN());
2054   void* p = 0;
2055   TRACE_EVENT1("foo", "event8", "pointer_null", p);
2056   p = reinterpret_cast<void*>(0xbadf00d);
2057   TRACE_EVENT1("foo", "event9", "pointer_badf00d", p);
2058   TRACE_EVENT1("foo", "event10", "bool_true", true);
2059   TRACE_EVENT1("foo", "event11", "bool_false", false);
2060   TRACE_EVENT1("foo", "event12", "time_null",
2061       base::Time());
2062   TRACE_EVENT1("foo", "event13", "time_one",
2063       base::Time::FromInternalValue(1));
2064   TRACE_EVENT1("foo", "event14", "timeticks_null",
2065       base::TimeTicks());
2066   TRACE_EVENT1("foo", "event15", "timeticks_one",
2067       base::TimeTicks::FromInternalValue(1));
2068   EndTraceAndFlush();
2069
2070   const DictionaryValue* args_dict = NULL;
2071   DictionaryValue* dict = NULL;
2072   const Value* value = NULL;
2073   std::string str_value;
2074   int int_value;
2075   double double_value;
2076   bool bool_value;
2077
2078   dict = FindNamePhase("event1", "X");
2079   ASSERT_TRUE(dict);
2080   dict->GetDictionary("args", &args_dict);
2081   ASSERT_TRUE(args_dict);
2082   EXPECT_TRUE(args_dict->GetInteger("int_one", &int_value));
2083   EXPECT_EQ(1, int_value);
2084
2085   dict = FindNamePhase("event2", "X");
2086   ASSERT_TRUE(dict);
2087   dict->GetDictionary("args", &args_dict);
2088   ASSERT_TRUE(args_dict);
2089   EXPECT_TRUE(args_dict->GetInteger("int_neg_ten", &int_value));
2090   EXPECT_EQ(-10, int_value);
2091
2092   // 1f must be serlized to JSON as "1.0" in order to be a double, not an int.
2093   dict = FindNamePhase("event3", "X");
2094   ASSERT_TRUE(dict);
2095   dict->GetDictionary("args", &args_dict);
2096   ASSERT_TRUE(args_dict);
2097   EXPECT_TRUE(args_dict->Get("float_one", &value));
2098   EXPECT_TRUE(value->IsType(Value::TYPE_DOUBLE));
2099   EXPECT_TRUE(value->GetAsDouble(&double_value));
2100   EXPECT_EQ(1, double_value);
2101
2102   // .5f must be serlized to JSON as "0.5".
2103   dict = FindNamePhase("event4", "X");
2104   ASSERT_TRUE(dict);
2105   dict->GetDictionary("args", &args_dict);
2106   ASSERT_TRUE(args_dict);
2107   EXPECT_TRUE(args_dict->Get("float_half", &value));
2108   EXPECT_TRUE(value->IsType(Value::TYPE_DOUBLE));
2109   EXPECT_TRUE(value->GetAsDouble(&double_value));
2110   EXPECT_EQ(0.5, double_value);
2111
2112   // -.5f must be serlized to JSON as "-0.5".
2113   dict = FindNamePhase("event5", "X");
2114   ASSERT_TRUE(dict);
2115   dict->GetDictionary("args", &args_dict);
2116   ASSERT_TRUE(args_dict);
2117   EXPECT_TRUE(args_dict->Get("float_neghalf", &value));
2118   EXPECT_TRUE(value->IsType(Value::TYPE_DOUBLE));
2119   EXPECT_TRUE(value->GetAsDouble(&double_value));
2120   EXPECT_EQ(-0.5, double_value);
2121
2122   // Infinity is serialized to JSON as a string.
2123   dict = FindNamePhase("event6", "X");
2124   ASSERT_TRUE(dict);
2125   dict->GetDictionary("args", &args_dict);
2126   ASSERT_TRUE(args_dict);
2127   EXPECT_TRUE(args_dict->GetString("float_infinity", &str_value));
2128   EXPECT_STREQ("Infinity", str_value.c_str());
2129   dict = FindNamePhase("event6b", "X");
2130   ASSERT_TRUE(dict);
2131   dict->GetDictionary("args", &args_dict);
2132   ASSERT_TRUE(args_dict);
2133   EXPECT_TRUE(args_dict->GetString("float_neg_infinity", &str_value));
2134   EXPECT_STREQ("-Infinity", str_value.c_str());
2135
2136   // NaN is serialized to JSON as a string.
2137   dict = FindNamePhase("event7", "X");
2138   ASSERT_TRUE(dict);
2139   dict->GetDictionary("args", &args_dict);
2140   ASSERT_TRUE(args_dict);
2141   EXPECT_TRUE(args_dict->GetString("double_nan", &str_value));
2142   EXPECT_STREQ("NaN", str_value.c_str());
2143
2144   // NULL pointers should be serialized as "0x0".
2145   dict = FindNamePhase("event8", "X");
2146   ASSERT_TRUE(dict);
2147   dict->GetDictionary("args", &args_dict);
2148   ASSERT_TRUE(args_dict);
2149   EXPECT_TRUE(args_dict->GetString("pointer_null", &str_value));
2150   EXPECT_STREQ("0x0", str_value.c_str());
2151
2152   // Other pointers should be serlized as a hex string.
2153   dict = FindNamePhase("event9", "X");
2154   ASSERT_TRUE(dict);
2155   dict->GetDictionary("args", &args_dict);
2156   ASSERT_TRUE(args_dict);
2157   EXPECT_TRUE(args_dict->GetString("pointer_badf00d", &str_value));
2158   EXPECT_STREQ("0xbadf00d", str_value.c_str());
2159
2160   dict = FindNamePhase("event10", "X");
2161   ASSERT_TRUE(dict);
2162   dict->GetDictionary("args", &args_dict);
2163   ASSERT_TRUE(args_dict);
2164   EXPECT_TRUE(args_dict->GetBoolean("bool_true", &bool_value));
2165   EXPECT_TRUE(bool_value);
2166
2167   dict = FindNamePhase("event11", "X");
2168   ASSERT_TRUE(dict);
2169   dict->GetDictionary("args", &args_dict);
2170   ASSERT_TRUE(args_dict);
2171   EXPECT_TRUE(args_dict->GetBoolean("bool_false", &bool_value));
2172   EXPECT_FALSE(bool_value);
2173
2174   dict = FindNamePhase("event12", "X");
2175   ASSERT_TRUE(dict);
2176   dict->GetDictionary("args", &args_dict);
2177   ASSERT_TRUE(args_dict);
2178   EXPECT_TRUE(args_dict->GetInteger("time_null", &int_value));
2179   EXPECT_EQ(0, int_value);
2180
2181   dict = FindNamePhase("event13", "X");
2182   ASSERT_TRUE(dict);
2183   dict->GetDictionary("args", &args_dict);
2184   ASSERT_TRUE(args_dict);
2185   EXPECT_TRUE(args_dict->GetInteger("time_one", &int_value));
2186   EXPECT_EQ(1, int_value);
2187
2188   dict = FindNamePhase("event14", "X");
2189   ASSERT_TRUE(dict);
2190   dict->GetDictionary("args", &args_dict);
2191   ASSERT_TRUE(args_dict);
2192   EXPECT_TRUE(args_dict->GetInteger("timeticks_null", &int_value));
2193   EXPECT_EQ(0, int_value);
2194
2195   dict = FindNamePhase("event15", "X");
2196   ASSERT_TRUE(dict);
2197   dict->GetDictionary("args", &args_dict);
2198   ASSERT_TRUE(args_dict);
2199   EXPECT_TRUE(args_dict->GetInteger("timeticks_one", &int_value));
2200   EXPECT_EQ(1, int_value);
2201 }
2202
2203 class TraceEventCallbackTest : public TraceEventTestFixture {
2204  public:
2205   virtual void SetUp() override {
2206     TraceEventTestFixture::SetUp();
2207     ASSERT_EQ(NULL, s_instance);
2208     s_instance = this;
2209   }
2210   virtual void TearDown() override {
2211     TraceLog::GetInstance()->SetDisabled();
2212     ASSERT_TRUE(!!s_instance);
2213     s_instance = NULL;
2214     TraceEventTestFixture::TearDown();
2215   }
2216
2217  protected:
2218   // For TraceEventCallbackAndRecordingX tests.
2219   void VerifyCallbackAndRecordedEvents(size_t expected_callback_count,
2220                                        size_t expected_recorded_count) {
2221     // Callback events.
2222     EXPECT_EQ(expected_callback_count, collected_events_names_.size());
2223     for (size_t i = 0; i < collected_events_names_.size(); ++i) {
2224       EXPECT_EQ("callback", collected_events_categories_[i]);
2225       EXPECT_EQ("yes", collected_events_names_[i]);
2226     }
2227
2228     // Recorded events.
2229     EXPECT_EQ(expected_recorded_count, trace_parsed_.GetSize());
2230     EXPECT_TRUE(FindTraceEntry(trace_parsed_, "recording"));
2231     EXPECT_FALSE(FindTraceEntry(trace_parsed_, "callback"));
2232     EXPECT_TRUE(FindTraceEntry(trace_parsed_, "yes"));
2233     EXPECT_FALSE(FindTraceEntry(trace_parsed_, "no"));
2234   }
2235
2236   void VerifyCollectedEvent(size_t i,
2237                             unsigned phase,
2238                             const std::string& category,
2239                             const std::string& name) {
2240     EXPECT_EQ(phase, collected_events_phases_[i]);
2241     EXPECT_EQ(category, collected_events_categories_[i]);
2242     EXPECT_EQ(name, collected_events_names_[i]);
2243   }
2244
2245   std::vector<std::string> collected_events_categories_;
2246   std::vector<std::string> collected_events_names_;
2247   std::vector<unsigned char> collected_events_phases_;
2248   std::vector<TimeTicks> collected_events_timestamps_;
2249
2250   static TraceEventCallbackTest* s_instance;
2251   static void Callback(TimeTicks timestamp,
2252                        char phase,
2253                        const unsigned char* category_group_enabled,
2254                        const char* name,
2255                        unsigned long long id,
2256                        int num_args,
2257                        const char* const arg_names[],
2258                        const unsigned char arg_types[],
2259                        const unsigned long long arg_values[],
2260                        unsigned char flags) {
2261     s_instance->collected_events_phases_.push_back(phase);
2262     s_instance->collected_events_categories_.push_back(
2263         TraceLog::GetCategoryGroupName(category_group_enabled));
2264     s_instance->collected_events_names_.push_back(name);
2265     s_instance->collected_events_timestamps_.push_back(timestamp);
2266   }
2267 };
2268
2269 TraceEventCallbackTest* TraceEventCallbackTest::s_instance;
2270
2271 TEST_F(TraceEventCallbackTest, TraceEventCallback) {
2272   TRACE_EVENT_INSTANT0("all", "before enable", TRACE_EVENT_SCOPE_THREAD);
2273   TraceLog::GetInstance()->SetEventCallbackEnabled(
2274       CategoryFilter("*"), Callback);
2275   TRACE_EVENT_INSTANT0("all", "event1", TRACE_EVENT_SCOPE_GLOBAL);
2276   TRACE_EVENT_INSTANT0("all", "event2", TRACE_EVENT_SCOPE_GLOBAL);
2277   {
2278     TRACE_EVENT0("all", "duration");
2279     TRACE_EVENT_INSTANT0("all", "event3", TRACE_EVENT_SCOPE_GLOBAL);
2280   }
2281   TraceLog::GetInstance()->SetEventCallbackDisabled();
2282   TRACE_EVENT_INSTANT0("all", "after callback removed",
2283                        TRACE_EVENT_SCOPE_GLOBAL);
2284   ASSERT_EQ(5u, collected_events_names_.size());
2285   EXPECT_EQ("event1", collected_events_names_[0]);
2286   EXPECT_EQ(TRACE_EVENT_PHASE_INSTANT, collected_events_phases_[0]);
2287   EXPECT_EQ("event2", collected_events_names_[1]);
2288   EXPECT_EQ(TRACE_EVENT_PHASE_INSTANT, collected_events_phases_[1]);
2289   EXPECT_EQ("duration", collected_events_names_[2]);
2290   EXPECT_EQ(TRACE_EVENT_PHASE_BEGIN, collected_events_phases_[2]);
2291   EXPECT_EQ("event3", collected_events_names_[3]);
2292   EXPECT_EQ(TRACE_EVENT_PHASE_INSTANT, collected_events_phases_[3]);
2293   EXPECT_EQ("duration", collected_events_names_[4]);
2294   EXPECT_EQ(TRACE_EVENT_PHASE_END, collected_events_phases_[4]);
2295   for (size_t i = 1; i < collected_events_timestamps_.size(); i++) {
2296     EXPECT_LE(collected_events_timestamps_[i - 1],
2297               collected_events_timestamps_[i]);
2298   }
2299 }
2300
2301 TEST_F(TraceEventCallbackTest, TraceEventCallbackWhileFull) {
2302   TraceLog::GetInstance()->SetEnabled(
2303       CategoryFilter("*"),
2304       TraceLog::RECORDING_MODE,
2305       TraceOptions());
2306   do {
2307     TRACE_EVENT_INSTANT0("all", "badger badger", TRACE_EVENT_SCOPE_GLOBAL);
2308   } while (!TraceLog::GetInstance()->BufferIsFull());
2309   TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("*"),
2310                                                    Callback);
2311   TRACE_EVENT_INSTANT0("all", "a snake", TRACE_EVENT_SCOPE_GLOBAL);
2312   TraceLog::GetInstance()->SetEventCallbackDisabled();
2313   ASSERT_EQ(1u, collected_events_names_.size());
2314   EXPECT_EQ("a snake", collected_events_names_[0]);
2315 }
2316
2317 // 1: Enable callback, enable recording, disable callback, disable recording.
2318 TEST_F(TraceEventCallbackTest, TraceEventCallbackAndRecording1) {
2319   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2320   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2321   TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("callback"),
2322                                                    Callback);
2323   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2324   TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2325   TraceLog::GetInstance()->SetEnabled(
2326       CategoryFilter("recording"),
2327       TraceLog::RECORDING_MODE,
2328       TraceOptions());
2329   TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2330   TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2331   TraceLog::GetInstance()->SetEventCallbackDisabled();
2332   TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2333   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2334   EndTraceAndFlush();
2335   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2336   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2337
2338   DropTracedMetadataRecords();
2339   VerifyCallbackAndRecordedEvents(2, 2);
2340 }
2341
2342 // 2: Enable callback, enable recording, disable recording, disable callback.
2343 TEST_F(TraceEventCallbackTest, TraceEventCallbackAndRecording2) {
2344   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2345   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2346   TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("callback"),
2347                                                    Callback);
2348   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2349   TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2350   TraceLog::GetInstance()->SetEnabled(
2351       CategoryFilter("recording"),
2352       TraceLog::RECORDING_MODE,
2353       TraceOptions());
2354   TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2355   TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2356   EndTraceAndFlush();
2357   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2358   TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2359   TraceLog::GetInstance()->SetEventCallbackDisabled();
2360   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2361   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2362
2363   DropTracedMetadataRecords();
2364   VerifyCallbackAndRecordedEvents(3, 1);
2365 }
2366
2367 // 3: Enable recording, enable callback, disable callback, disable recording.
2368 TEST_F(TraceEventCallbackTest, TraceEventCallbackAndRecording3) {
2369   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2370   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2371   TraceLog::GetInstance()->SetEnabled(
2372       CategoryFilter("recording"),
2373       TraceLog::RECORDING_MODE,
2374       TraceOptions());
2375   TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2376   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2377   TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("callback"),
2378                                                    Callback);
2379   TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2380   TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2381   TraceLog::GetInstance()->SetEventCallbackDisabled();
2382   TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2383   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2384   EndTraceAndFlush();
2385   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2386   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2387
2388   DropTracedMetadataRecords();
2389   VerifyCallbackAndRecordedEvents(1, 3);
2390 }
2391
2392 // 4: Enable recording, enable callback, disable recording, disable callback.
2393 TEST_F(TraceEventCallbackTest, TraceEventCallbackAndRecording4) {
2394   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2395   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2396   TraceLog::GetInstance()->SetEnabled(
2397       CategoryFilter("recording"),
2398       TraceLog::RECORDING_MODE,
2399       TraceOptions());
2400   TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2401   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2402   TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("callback"),
2403                                                    Callback);
2404   TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2405   TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2406   EndTraceAndFlush();
2407   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2408   TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2409   TraceLog::GetInstance()->SetEventCallbackDisabled();
2410   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2411   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2412
2413   DropTracedMetadataRecords();
2414   VerifyCallbackAndRecordedEvents(2, 2);
2415 }
2416
2417 TEST_F(TraceEventCallbackTest, TraceEventCallbackAndRecordingDuration) {
2418   TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("*"),
2419                                                    Callback);
2420   {
2421     TRACE_EVENT0("callback", "duration1");
2422     TraceLog::GetInstance()->SetEnabled(
2423         CategoryFilter("*"),
2424         TraceLog::RECORDING_MODE,
2425         TraceOptions());
2426     TRACE_EVENT0("callback", "duration2");
2427     EndTraceAndFlush();
2428     TRACE_EVENT0("callback", "duration3");
2429   }
2430   TraceLog::GetInstance()->SetEventCallbackDisabled();
2431
2432   ASSERT_EQ(6u, collected_events_names_.size());
2433   VerifyCollectedEvent(0, TRACE_EVENT_PHASE_BEGIN, "callback", "duration1");
2434   VerifyCollectedEvent(1, TRACE_EVENT_PHASE_BEGIN, "callback", "duration2");
2435   VerifyCollectedEvent(2, TRACE_EVENT_PHASE_BEGIN, "callback", "duration3");
2436   VerifyCollectedEvent(3, TRACE_EVENT_PHASE_END, "callback", "duration3");
2437   VerifyCollectedEvent(4, TRACE_EVENT_PHASE_END, "callback", "duration2");
2438   VerifyCollectedEvent(5, TRACE_EVENT_PHASE_END, "callback", "duration1");
2439 }
2440
2441 TEST_F(TraceEventTestFixture, TraceBufferVectorReportFull) {
2442   TraceLog* trace_log = TraceLog::GetInstance();
2443   trace_log->SetEnabled(CategoryFilter("*"),
2444                         TraceLog::RECORDING_MODE,
2445                         TraceOptions());
2446   trace_log->logged_events_.reset(
2447       trace_log->CreateTraceBufferVectorOfSize(100));
2448   do {
2449     TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0(
2450         "all", "with_timestamp", 0, 0,
2451         TimeTicks::NowFromSystemTraceTime().ToInternalValue());
2452     TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0(
2453         "all", "with_timestamp", 0, 0,
2454         TimeTicks::NowFromSystemTraceTime().ToInternalValue());
2455   } while (!trace_log->BufferIsFull());
2456
2457   EndTraceAndFlush();
2458
2459   const DictionaryValue* trace_full_metadata = NULL;
2460
2461   trace_full_metadata = FindTraceEntry(trace_parsed_,
2462                                        "overflowed_at_ts");
2463   std::string phase;
2464   double buffer_limit_reached_timestamp = 0;
2465
2466   EXPECT_TRUE(trace_full_metadata);
2467   EXPECT_TRUE(trace_full_metadata->GetString("ph", &phase));
2468   EXPECT_EQ("M", phase);
2469   EXPECT_TRUE(trace_full_metadata->GetDouble(
2470       "args.overflowed_at_ts", &buffer_limit_reached_timestamp));
2471   EXPECT_DOUBLE_EQ(
2472       static_cast<double>(
2473           trace_log->buffer_limit_reached_timestamp_.ToInternalValue()),
2474       buffer_limit_reached_timestamp);
2475
2476   // Test that buffer_limit_reached_timestamp's value is between the timestamp
2477   // of the last trace event and current time.
2478   DropTracedMetadataRecords();
2479   const DictionaryValue* last_trace_event = NULL;
2480   double last_trace_event_timestamp = 0;
2481   EXPECT_TRUE(trace_parsed_.GetDictionary(trace_parsed_.GetSize() - 1,
2482                                           &last_trace_event));
2483   EXPECT_TRUE(last_trace_event->GetDouble("ts", &last_trace_event_timestamp));
2484   EXPECT_LE(last_trace_event_timestamp, buffer_limit_reached_timestamp);
2485   EXPECT_LE(buffer_limit_reached_timestamp,
2486             trace_log->OffsetNow().ToInternalValue());
2487 }
2488
2489 TEST_F(TraceEventTestFixture, TraceBufferRingBufferGetReturnChunk) {
2490   TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
2491                                       TraceLog::RECORDING_MODE,
2492                                       TraceOptions(RECORD_CONTINUOUSLY));
2493   TraceBuffer* buffer = TraceLog::GetInstance()->trace_buffer();
2494   size_t capacity = buffer->Capacity();
2495   size_t num_chunks = capacity / TraceBufferChunk::kTraceBufferChunkSize;
2496   uint32 last_seq = 0;
2497   size_t chunk_index;
2498   EXPECT_EQ(0u, buffer->Size());
2499
2500   scoped_ptr<TraceBufferChunk*[]> chunks(new TraceBufferChunk*[num_chunks]);
2501   for (size_t i = 0; i < num_chunks; ++i) {
2502     chunks[i] = buffer->GetChunk(&chunk_index).release();
2503     EXPECT_TRUE(chunks[i]);
2504     EXPECT_EQ(i, chunk_index);
2505     EXPECT_GT(chunks[i]->seq(), last_seq);
2506     EXPECT_EQ((i + 1) * TraceBufferChunk::kTraceBufferChunkSize,
2507               buffer->Size());
2508     last_seq = chunks[i]->seq();
2509   }
2510
2511   // Ring buffer is never full.
2512   EXPECT_FALSE(buffer->IsFull());
2513
2514   // Return all chunks in original order.
2515   for (size_t i = 0; i < num_chunks; ++i)
2516     buffer->ReturnChunk(i, scoped_ptr<TraceBufferChunk>(chunks[i]));
2517
2518   // Should recycle the chunks in the returned order.
2519   for (size_t i = 0; i < num_chunks; ++i) {
2520     chunks[i] = buffer->GetChunk(&chunk_index).release();
2521     EXPECT_TRUE(chunks[i]);
2522     EXPECT_EQ(i, chunk_index);
2523     EXPECT_GT(chunks[i]->seq(), last_seq);
2524     last_seq = chunks[i]->seq();
2525   }
2526
2527   // Return all chunks in reverse order.
2528   for (size_t i = 0; i < num_chunks; ++i) {
2529     buffer->ReturnChunk(
2530         num_chunks - i - 1,
2531         scoped_ptr<TraceBufferChunk>(chunks[num_chunks - i - 1]));
2532   }
2533
2534   // Should recycle the chunks in the returned order.
2535   for (size_t i = 0; i < num_chunks; ++i) {
2536     chunks[i] = buffer->GetChunk(&chunk_index).release();
2537     EXPECT_TRUE(chunks[i]);
2538     EXPECT_EQ(num_chunks - i - 1, chunk_index);
2539     EXPECT_GT(chunks[i]->seq(), last_seq);
2540     last_seq = chunks[i]->seq();
2541   }
2542
2543   for (size_t i = 0; i < num_chunks; ++i)
2544     buffer->ReturnChunk(i, scoped_ptr<TraceBufferChunk>(chunks[i]));
2545
2546   TraceLog::GetInstance()->SetDisabled();
2547 }
2548
2549 TEST_F(TraceEventTestFixture, TraceBufferRingBufferHalfIteration) {
2550   TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
2551                                       TraceLog::RECORDING_MODE,
2552                                       TraceOptions(RECORD_CONTINUOUSLY));
2553   TraceBuffer* buffer = TraceLog::GetInstance()->trace_buffer();
2554   size_t capacity = buffer->Capacity();
2555   size_t num_chunks = capacity / TraceBufferChunk::kTraceBufferChunkSize;
2556   size_t chunk_index;
2557   EXPECT_EQ(0u, buffer->Size());
2558   EXPECT_FALSE(buffer->NextChunk());
2559
2560   size_t half_chunks = num_chunks / 2;
2561   scoped_ptr<TraceBufferChunk*[]> chunks(new TraceBufferChunk*[half_chunks]);
2562
2563   for (size_t i = 0; i < half_chunks; ++i) {
2564     chunks[i] = buffer->GetChunk(&chunk_index).release();
2565     EXPECT_TRUE(chunks[i]);
2566     EXPECT_EQ(i, chunk_index);
2567   }
2568   for (size_t i = 0; i < half_chunks; ++i)
2569     buffer->ReturnChunk(i, scoped_ptr<TraceBufferChunk>(chunks[i]));
2570
2571   for (size_t i = 0; i < half_chunks; ++i)
2572     EXPECT_EQ(chunks[i], buffer->NextChunk());
2573   EXPECT_FALSE(buffer->NextChunk());
2574   TraceLog::GetInstance()->SetDisabled();
2575 }
2576
2577 TEST_F(TraceEventTestFixture, TraceBufferRingBufferFullIteration) {
2578   TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
2579                                       TraceLog::RECORDING_MODE,
2580                                       TraceOptions(RECORD_CONTINUOUSLY));
2581   TraceBuffer* buffer = TraceLog::GetInstance()->trace_buffer();
2582   size_t capacity = buffer->Capacity();
2583   size_t num_chunks = capacity / TraceBufferChunk::kTraceBufferChunkSize;
2584   size_t chunk_index;
2585   EXPECT_EQ(0u, buffer->Size());
2586   EXPECT_FALSE(buffer->NextChunk());
2587
2588   scoped_ptr<TraceBufferChunk*[]> chunks(new TraceBufferChunk*[num_chunks]);
2589
2590   for (size_t i = 0; i < num_chunks; ++i) {
2591     chunks[i] = buffer->GetChunk(&chunk_index).release();
2592     EXPECT_TRUE(chunks[i]);
2593     EXPECT_EQ(i, chunk_index);
2594   }
2595   for (size_t i = 0; i < num_chunks; ++i)
2596     buffer->ReturnChunk(i, scoped_ptr<TraceBufferChunk>(chunks[i]));
2597
2598   for (size_t i = 0; i < num_chunks; ++i)
2599     EXPECT_TRUE(chunks[i] == buffer->NextChunk());
2600   EXPECT_FALSE(buffer->NextChunk());
2601   TraceLog::GetInstance()->SetDisabled();
2602 }
2603
2604 TEST_F(TraceEventTestFixture, TraceRecordAsMuchAsPossibleMode) {
2605   TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
2606                                       TraceLog::RECORDING_MODE,
2607                                       TraceOptions(RECORD_AS_MUCH_AS_POSSIBLE));
2608   TraceBuffer* buffer = TraceLog::GetInstance()->trace_buffer();
2609   EXPECT_EQ(512000000UL, buffer->Capacity());
2610   TraceLog::GetInstance()->SetDisabled();
2611 }
2612
2613 // Test the category filter.
2614 TEST_F(TraceEventTestFixture, CategoryFilter) {
2615   // Using the default filter.
2616   CategoryFilter default_cf = CategoryFilter(
2617       CategoryFilter::kDefaultCategoryFilterString);
2618   std::string category_filter_str = default_cf.ToString();
2619   EXPECT_STREQ("-*Debug,-*Test", category_filter_str.c_str());
2620   EXPECT_TRUE(default_cf.IsCategoryGroupEnabled("not-excluded-category"));
2621   EXPECT_FALSE(
2622       default_cf.IsCategoryGroupEnabled("disabled-by-default-category"));
2623   EXPECT_FALSE(default_cf.IsCategoryGroupEnabled("Category1,CategoryDebug"));
2624   EXPECT_FALSE(default_cf.IsCategoryGroupEnabled("CategoryDebug,Category1"));
2625   EXPECT_FALSE(default_cf.IsCategoryGroupEnabled("CategoryTest,Category2"));
2626
2627   // Make sure that upon an empty string, we fall back to the default filter.
2628   default_cf = CategoryFilter();
2629   category_filter_str = default_cf.ToString();
2630   EXPECT_STREQ("-*Debug,-*Test", category_filter_str.c_str());
2631   EXPECT_TRUE(default_cf.IsCategoryGroupEnabled("not-excluded-category"));
2632   EXPECT_FALSE(default_cf.IsCategoryGroupEnabled("Category1,CategoryDebug"));
2633   EXPECT_FALSE(default_cf.IsCategoryGroupEnabled("CategoryDebug,Category1"));
2634   EXPECT_FALSE(default_cf.IsCategoryGroupEnabled("CategoryTest,Category2"));
2635
2636   // Using an arbitrary non-empty filter.
2637   CategoryFilter cf("included,-excluded,inc_pattern*,-exc_pattern*");
2638   category_filter_str = cf.ToString();
2639   EXPECT_STREQ("included,inc_pattern*,-excluded,-exc_pattern*",
2640                category_filter_str.c_str());
2641   EXPECT_TRUE(cf.IsCategoryGroupEnabled("included"));
2642   EXPECT_TRUE(cf.IsCategoryGroupEnabled("inc_pattern_category"));
2643   EXPECT_FALSE(cf.IsCategoryGroupEnabled("exc_pattern_category"));
2644   EXPECT_FALSE(cf.IsCategoryGroupEnabled("excluded"));
2645   EXPECT_FALSE(cf.IsCategoryGroupEnabled("not-excluded-nor-included"));
2646   EXPECT_FALSE(cf.IsCategoryGroupEnabled("Category1,CategoryDebug"));
2647   EXPECT_FALSE(cf.IsCategoryGroupEnabled("CategoryDebug,Category1"));
2648   EXPECT_FALSE(cf.IsCategoryGroupEnabled("CategoryTest,Category2"));
2649
2650   cf.Merge(default_cf);
2651   category_filter_str = cf.ToString();
2652   EXPECT_STREQ("-excluded,-exc_pattern*,-*Debug,-*Test",
2653                 category_filter_str.c_str());
2654   cf.Clear();
2655
2656   CategoryFilter reconstructed_cf(category_filter_str);
2657   category_filter_str = reconstructed_cf.ToString();
2658   EXPECT_STREQ("-excluded,-exc_pattern*,-*Debug,-*Test",
2659                category_filter_str.c_str());
2660
2661   // One included category.
2662   CategoryFilter one_inc_cf("only_inc_cat");
2663   category_filter_str = one_inc_cf.ToString();
2664   EXPECT_STREQ("only_inc_cat", category_filter_str.c_str());
2665
2666   // One excluded category.
2667   CategoryFilter one_exc_cf("-only_exc_cat");
2668   category_filter_str = one_exc_cf.ToString();
2669   EXPECT_STREQ("-only_exc_cat", category_filter_str.c_str());
2670
2671   // Enabling a disabled- category does not require all categories to be traced
2672   // to be included.
2673   CategoryFilter disabled_cat("disabled-by-default-cc,-excluded");
2674   EXPECT_STREQ("disabled-by-default-cc,-excluded",
2675                disabled_cat.ToString().c_str());
2676   EXPECT_TRUE(disabled_cat.IsCategoryGroupEnabled("disabled-by-default-cc"));
2677   EXPECT_TRUE(disabled_cat.IsCategoryGroupEnabled("some_other_group"));
2678   EXPECT_FALSE(disabled_cat.IsCategoryGroupEnabled("excluded"));
2679
2680   // Enabled a disabled- category and also including makes all categories to
2681   // be traced require including.
2682   CategoryFilter disabled_inc_cat("disabled-by-default-cc,included");
2683   EXPECT_STREQ("included,disabled-by-default-cc",
2684                disabled_inc_cat.ToString().c_str());
2685   EXPECT_TRUE(
2686       disabled_inc_cat.IsCategoryGroupEnabled("disabled-by-default-cc"));
2687   EXPECT_TRUE(disabled_inc_cat.IsCategoryGroupEnabled("included"));
2688   EXPECT_FALSE(disabled_inc_cat.IsCategoryGroupEnabled("other_included"));
2689
2690   // Test that IsEmptyOrContainsLeadingOrTrailingWhitespace actually catches
2691   // categories that are explicitly forbiden.
2692   // This method is called in a DCHECK to assert that we don't have these types
2693   // of strings as categories.
2694   EXPECT_TRUE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2695       " bad_category "));
2696   EXPECT_TRUE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2697       " bad_category"));
2698   EXPECT_TRUE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2699       "bad_category "));
2700   EXPECT_TRUE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2701       "   bad_category"));
2702   EXPECT_TRUE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2703       "bad_category   "));
2704   EXPECT_TRUE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2705       "   bad_category   "));
2706   EXPECT_TRUE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2707       ""));
2708   EXPECT_FALSE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2709       "good_category"));
2710 }
2711
2712 void BlockUntilStopped(WaitableEvent* task_start_event,
2713                        WaitableEvent* task_stop_event) {
2714   task_start_event->Signal();
2715   task_stop_event->Wait();
2716 }
2717
2718 TEST_F(TraceEventTestFixture, SetCurrentThreadBlocksMessageLoopBeforeTracing) {
2719   BeginTrace();
2720
2721   Thread thread("1");
2722   WaitableEvent task_complete_event(false, false);
2723   thread.Start();
2724   thread.message_loop()->PostTask(
2725       FROM_HERE, Bind(&TraceLog::SetCurrentThreadBlocksMessageLoop,
2726                       Unretained(TraceLog::GetInstance())));
2727
2728   thread.message_loop()->PostTask(
2729       FROM_HERE, Bind(&TraceWithAllMacroVariants, &task_complete_event));
2730   task_complete_event.Wait();
2731
2732   WaitableEvent task_start_event(false, false);
2733   WaitableEvent task_stop_event(false, false);
2734   thread.message_loop()->PostTask(
2735       FROM_HERE, Bind(&BlockUntilStopped, &task_start_event, &task_stop_event));
2736   task_start_event.Wait();
2737
2738   EndTraceAndFlush();
2739   ValidateAllTraceMacrosCreatedData(trace_parsed_);
2740
2741   task_stop_event.Signal();
2742   thread.Stop();
2743 }
2744
2745 TEST_F(TraceEventTestFixture, ConvertTraceOptionsToInternalOptions) {
2746   TraceLog* trace_log = TraceLog::GetInstance();
2747   TraceOptions options(RECORD_UNTIL_FULL);
2748   EXPECT_EQ(TraceLog::kInternalRecordUntilFull,
2749             trace_log->GetInternalOptionsFromTraceOptions(options));
2750
2751   options.record_mode = RECORD_CONTINUOUSLY;
2752   EXPECT_EQ(TraceLog::kInternalRecordContinuously,
2753             trace_log->GetInternalOptionsFromTraceOptions(options));
2754
2755   options.record_mode = ECHO_TO_CONSOLE;
2756   EXPECT_EQ(TraceLog::kInternalEchoToConsole,
2757             trace_log->GetInternalOptionsFromTraceOptions(options));
2758
2759   options.enable_sampling = true;
2760
2761   options.record_mode = RECORD_UNTIL_FULL;
2762   EXPECT_EQ(
2763       TraceLog::kInternalRecordUntilFull | TraceLog::kInternalEnableSampling,
2764       trace_log->GetInternalOptionsFromTraceOptions(options));
2765
2766   options.record_mode = RECORD_CONTINUOUSLY;
2767   EXPECT_EQ(
2768       TraceLog::kInternalRecordContinuously | TraceLog::kInternalEnableSampling,
2769       trace_log->GetInternalOptionsFromTraceOptions(options));
2770
2771   options.record_mode = ECHO_TO_CONSOLE;
2772   EXPECT_EQ(
2773       TraceLog::kInternalEchoToConsole | TraceLog::kInternalEnableSampling,
2774       trace_log->GetInternalOptionsFromTraceOptions(options));
2775
2776   options.enable_systrace = true;
2777   EXPECT_EQ(
2778       TraceLog::kInternalEchoToConsole | TraceLog::kInternalEnableSampling,
2779       trace_log->GetInternalOptionsFromTraceOptions(options));
2780 }
2781
2782 void SetBlockingFlagAndBlockUntilStopped(WaitableEvent* task_start_event,
2783                                          WaitableEvent* task_stop_event) {
2784   TraceLog::GetInstance()->SetCurrentThreadBlocksMessageLoop();
2785   BlockUntilStopped(task_start_event, task_stop_event);
2786 }
2787
2788 TEST_F(TraceEventTestFixture, SetCurrentThreadBlocksMessageLoopAfterTracing) {
2789   BeginTrace();
2790
2791   Thread thread("1");
2792   WaitableEvent task_complete_event(false, false);
2793   thread.Start();
2794
2795   thread.message_loop()->PostTask(
2796       FROM_HERE, Bind(&TraceWithAllMacroVariants, &task_complete_event));
2797   task_complete_event.Wait();
2798
2799   WaitableEvent task_start_event(false, false);
2800   WaitableEvent task_stop_event(false, false);
2801   thread.message_loop()->PostTask(
2802       FROM_HERE, Bind(&SetBlockingFlagAndBlockUntilStopped,
2803                       &task_start_event, &task_stop_event));
2804   task_start_event.Wait();
2805
2806   EndTraceAndFlush();
2807   ValidateAllTraceMacrosCreatedData(trace_parsed_);
2808
2809   task_stop_event.Signal();
2810   thread.Stop();
2811 }
2812
2813 TEST_F(TraceEventTestFixture, ThreadOnceBlocking) {
2814   BeginTrace();
2815
2816   Thread thread("1");
2817   WaitableEvent task_complete_event(false, false);
2818   thread.Start();
2819
2820   thread.message_loop()->PostTask(
2821       FROM_HERE, Bind(&TraceWithAllMacroVariants, &task_complete_event));
2822   task_complete_event.Wait();
2823   task_complete_event.Reset();
2824
2825   WaitableEvent task_start_event(false, false);
2826   WaitableEvent task_stop_event(false, false);
2827   thread.message_loop()->PostTask(
2828       FROM_HERE, Bind(&BlockUntilStopped, &task_start_event, &task_stop_event));
2829   task_start_event.Wait();
2830
2831   // The thread will timeout in this flush.
2832   EndTraceAndFlushInThreadWithMessageLoop();
2833   Clear();
2834
2835   // Let the thread's message loop continue to spin.
2836   task_stop_event.Signal();
2837
2838   // The following sequence ensures that the FlushCurrentThread task has been
2839   // executed in the thread before continuing.
2840   task_start_event.Reset();
2841   task_stop_event.Reset();
2842   thread.message_loop()->PostTask(
2843       FROM_HERE, Bind(&BlockUntilStopped, &task_start_event, &task_stop_event));
2844   task_start_event.Wait();
2845   task_stop_event.Signal();
2846   Clear();
2847
2848   // TraceLog should discover the generation mismatch and recover the thread
2849   // local buffer for the thread without any error.
2850   BeginTrace();
2851   thread.message_loop()->PostTask(
2852       FROM_HERE, Bind(&TraceWithAllMacroVariants, &task_complete_event));
2853   task_complete_event.Wait();
2854   task_complete_event.Reset();
2855   EndTraceAndFlushInThreadWithMessageLoop();
2856   ValidateAllTraceMacrosCreatedData(trace_parsed_);
2857 }
2858
2859 std::string* g_log_buffer = NULL;
2860 bool MockLogMessageHandler(int, const char*, int, size_t,
2861                            const std::string& str) {
2862   if (!g_log_buffer)
2863     g_log_buffer = new std::string();
2864   g_log_buffer->append(str);
2865   return false;
2866 }
2867
2868 TEST_F(TraceEventTestFixture, EchoToConsole) {
2869   logging::LogMessageHandlerFunction old_log_message_handler =
2870       logging::GetLogMessageHandler();
2871   logging::SetLogMessageHandler(MockLogMessageHandler);
2872
2873   TraceLog::GetInstance()->SetEnabled(
2874       CategoryFilter("*"),
2875       TraceLog::RECORDING_MODE,
2876       TraceOptions(ECHO_TO_CONSOLE));
2877   TRACE_EVENT_BEGIN0("a", "begin_end");
2878   {
2879     TRACE_EVENT0("b", "duration");
2880     TRACE_EVENT0("b1", "duration1");
2881   }
2882   TRACE_EVENT_INSTANT0("c", "instant", TRACE_EVENT_SCOPE_GLOBAL);
2883   TRACE_EVENT_END0("a", "begin_end");
2884
2885   EXPECT_NE(std::string::npos, g_log_buffer->find("begin_end[a]\x1b"));
2886   EXPECT_NE(std::string::npos, g_log_buffer->find("| duration[b]\x1b"));
2887   EXPECT_NE(std::string::npos, g_log_buffer->find("| | duration1[b1]\x1b"));
2888   EXPECT_NE(std::string::npos, g_log_buffer->find("| | duration1[b1] ("));
2889   EXPECT_NE(std::string::npos, g_log_buffer->find("| duration[b] ("));
2890   EXPECT_NE(std::string::npos, g_log_buffer->find("| instant[c]\x1b"));
2891   EXPECT_NE(std::string::npos, g_log_buffer->find("begin_end[a] ("));
2892
2893   EndTraceAndFlush();
2894   delete g_log_buffer;
2895   logging::SetLogMessageHandler(old_log_message_handler);
2896   g_log_buffer = NULL;
2897 }
2898
2899 bool LogMessageHandlerWithTraceEvent(int, const char*, int, size_t,
2900                                      const std::string&) {
2901   TRACE_EVENT0("log", "trace_event");
2902   return false;
2903 }
2904
2905 TEST_F(TraceEventTestFixture, EchoToConsoleTraceEventRecursion) {
2906   logging::LogMessageHandlerFunction old_log_message_handler =
2907       logging::GetLogMessageHandler();
2908   logging::SetLogMessageHandler(LogMessageHandlerWithTraceEvent);
2909
2910   TraceLog::GetInstance()->SetEnabled(
2911       CategoryFilter("*"),
2912       TraceLog::RECORDING_MODE,
2913       TraceOptions(ECHO_TO_CONSOLE));
2914   {
2915     // This should not cause deadlock or infinite recursion.
2916     TRACE_EVENT0("b", "duration");
2917   }
2918
2919   EndTraceAndFlush();
2920   logging::SetLogMessageHandler(old_log_message_handler);
2921 }
2922
2923 TEST_F(TraceEventTestFixture, TimeOffset) {
2924   BeginTrace();
2925   // Let TraceLog timer start from 0.
2926   TimeDelta time_offset = TimeTicks::NowFromSystemTraceTime() - TimeTicks();
2927   TraceLog::GetInstance()->SetTimeOffset(time_offset);
2928
2929   {
2930     TRACE_EVENT0("all", "duration1");
2931     TRACE_EVENT0("all", "duration2");
2932   }
2933   TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0(
2934       "all", "with_timestamp", 0, 0,
2935       TimeTicks::NowFromSystemTraceTime().ToInternalValue());
2936   TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0(
2937       "all", "with_timestamp", 0, 0,
2938       TimeTicks::NowFromSystemTraceTime().ToInternalValue());
2939
2940   EndTraceAndFlush();
2941   DropTracedMetadataRecords();
2942
2943   double end_time = static_cast<double>(
2944       (TimeTicks::NowFromSystemTraceTime() - time_offset).ToInternalValue());
2945   double last_timestamp = 0;
2946   for (size_t i = 0; i < trace_parsed_.GetSize(); ++i) {
2947     const DictionaryValue* item;
2948     EXPECT_TRUE(trace_parsed_.GetDictionary(i, &item));
2949     double timestamp;
2950     EXPECT_TRUE(item->GetDouble("ts", &timestamp));
2951     EXPECT_GE(timestamp, last_timestamp);
2952     EXPECT_LE(timestamp, end_time);
2953     last_timestamp = timestamp;
2954   }
2955 }
2956
2957 TEST_F(TraceEventTestFixture, ConfigureSyntheticDelays) {
2958   BeginSpecificTrace("DELAY(test.Delay;0.05)");
2959
2960   base::TimeTicks start = base::TimeTicks::Now();
2961   {
2962     TRACE_EVENT_SYNTHETIC_DELAY("test.Delay");
2963   }
2964   base::TimeDelta duration = base::TimeTicks::Now() - start;
2965   EXPECT_GE(duration.InMilliseconds(), 50);
2966
2967   EndTraceAndFlush();
2968 }
2969
2970 TEST_F(TraceEventTestFixture, BadSyntheticDelayConfigurations) {
2971   const char* const configs[] = {
2972     "",
2973     "DELAY(",
2974     "DELAY(;",
2975     "DELAY(;)",
2976     "DELAY(test.Delay)",
2977     "DELAY(test.Delay;)"
2978   };
2979   for (size_t i = 0; i < arraysize(configs); i++) {
2980     BeginSpecificTrace(configs[i]);
2981     EndTraceAndFlush();
2982     CategoryFilter filter = TraceLog::GetInstance()->GetCurrentCategoryFilter();
2983     EXPECT_EQ(0u, filter.GetSyntheticDelayValues().size());
2984   }
2985 }
2986
2987 TEST_F(TraceEventTestFixture, SyntheticDelayConfigurationMerging) {
2988   CategoryFilter filter1("DELAY(test.Delay1;16)");
2989   CategoryFilter filter2("DELAY(test.Delay2;32)");
2990   filter1.Merge(filter2);
2991   EXPECT_EQ(2u, filter1.GetSyntheticDelayValues().size());
2992 }
2993
2994 TEST_F(TraceEventTestFixture, SyntheticDelayConfigurationToString) {
2995   const char config[] = "DELAY(test.Delay;16;oneshot)";
2996   CategoryFilter filter(config);
2997   EXPECT_EQ(config, filter.ToString());
2998 }
2999
3000 TEST(TraceOptionsTest, TraceOptionsFromString) {
3001   TraceOptions options;
3002   EXPECT_TRUE(options.SetFromString("record-until-full"));
3003   EXPECT_EQ(RECORD_UNTIL_FULL, options.record_mode);
3004   EXPECT_FALSE(options.enable_sampling);
3005   EXPECT_FALSE(options.enable_systrace);
3006
3007   EXPECT_TRUE(options.SetFromString("record-continuously"));
3008   EXPECT_EQ(RECORD_CONTINUOUSLY, options.record_mode);
3009   EXPECT_FALSE(options.enable_sampling);
3010   EXPECT_FALSE(options.enable_systrace);
3011
3012   EXPECT_TRUE(options.SetFromString("trace-to-console"));
3013   EXPECT_EQ(ECHO_TO_CONSOLE, options.record_mode);
3014   EXPECT_FALSE(options.enable_sampling);
3015   EXPECT_FALSE(options.enable_systrace);
3016
3017   EXPECT_TRUE(options.SetFromString("record-as-much-as-possible"));
3018   EXPECT_EQ(RECORD_AS_MUCH_AS_POSSIBLE, options.record_mode);
3019   EXPECT_FALSE(options.enable_sampling);
3020   EXPECT_FALSE(options.enable_systrace);
3021
3022   EXPECT_TRUE(options.SetFromString("record-until-full, enable-sampling"));
3023   EXPECT_EQ(RECORD_UNTIL_FULL, options.record_mode);
3024   EXPECT_TRUE(options.enable_sampling);
3025   EXPECT_FALSE(options.enable_systrace);
3026
3027   EXPECT_TRUE(options.SetFromString("enable-systrace,record-continuously"));
3028   EXPECT_EQ(RECORD_CONTINUOUSLY, options.record_mode);
3029   EXPECT_FALSE(options.enable_sampling);
3030   EXPECT_TRUE(options.enable_systrace);
3031
3032   EXPECT_TRUE(options.SetFromString(
3033       "enable-systrace, trace-to-console,enable-sampling"));
3034   EXPECT_EQ(ECHO_TO_CONSOLE, options.record_mode);
3035   EXPECT_TRUE(options.enable_sampling);
3036   EXPECT_TRUE(options.enable_systrace);
3037
3038   EXPECT_TRUE(options.SetFromString(
3039       "record-continuously,record-until-full,trace-to-console"));
3040   EXPECT_EQ(ECHO_TO_CONSOLE, options.record_mode);
3041   EXPECT_FALSE(options.enable_systrace);
3042   EXPECT_FALSE(options.enable_sampling);
3043
3044   EXPECT_TRUE(options.SetFromString(""));
3045   EXPECT_EQ(RECORD_UNTIL_FULL, options.record_mode);
3046   EXPECT_FALSE(options.enable_systrace);
3047   EXPECT_FALSE(options.enable_sampling);
3048
3049   EXPECT_FALSE(options.SetFromString("foo-bar-baz"));
3050 }
3051
3052 TEST(TraceOptionsTest, TraceOptionsToString) {
3053   // Test that we can intialize TraceOptions from a string got from
3054   // TraceOptions.ToString() method to get a same TraceOptions.
3055   TraceRecordMode modes[] = {RECORD_UNTIL_FULL,
3056                              RECORD_CONTINUOUSLY,
3057                              ECHO_TO_CONSOLE,
3058                              RECORD_AS_MUCH_AS_POSSIBLE};
3059   bool enable_sampling_options[] = {true, false};
3060   bool enable_systrace_options[] = {true, false};
3061
3062   for (int i = 0; i < 4; ++i) {
3063     for (int j = 0; j < 2; ++j) {
3064       for (int k = 0; k < 2; ++k) {
3065         TraceOptions original_option = TraceOptions(modes[i]);
3066         original_option.enable_sampling = enable_sampling_options[j];
3067         original_option.enable_systrace = enable_systrace_options[k];
3068         TraceOptions new_options;
3069         EXPECT_TRUE(new_options.SetFromString(original_option.ToString()));
3070         EXPECT_EQ(original_option.record_mode, new_options.record_mode);
3071         EXPECT_EQ(original_option.enable_sampling, new_options.enable_sampling);
3072         EXPECT_EQ(original_option.enable_systrace, new_options.enable_systrace);
3073       }
3074     }
3075   }
3076 }
3077
3078
3079 }  // namespace debug
3080 }  // namespace base