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   EXPECT_EQ(0u, tracer->GetStatus().event_count);
1370   const unsigned char* category_group_enabled =
1371       TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED("cat");
1372
1373   {
1374     BeginTrace();
1375     // Test that string arguments are copied.
1376     TraceEventHandle handle1 =
1377         trace_event_internal::AddTraceEvent(
1378             TRACE_EVENT_PHASE_INSTANT, category_group_enabled, "name1", 0, 0,
1379             "arg1", std::string("argval"), "arg2", std::string("argval"));
1380     // Test that static TRACE_STR_COPY string arguments are copied.
1381     TraceEventHandle handle2 =
1382         trace_event_internal::AddTraceEvent(
1383             TRACE_EVENT_PHASE_INSTANT, category_group_enabled, "name2", 0, 0,
1384             "arg1", TRACE_STR_COPY("argval"),
1385             "arg2", TRACE_STR_COPY("argval"));
1386     EXPECT_GT(tracer->GetStatus().event_count, 1u);
1387     const TraceEvent* event1 = tracer->GetEventByHandle(handle1);
1388     const TraceEvent* event2 = tracer->GetEventByHandle(handle2);
1389     ASSERT_TRUE(event1);
1390     ASSERT_TRUE(event2);
1391     EXPECT_STREQ("name1", event1->name());
1392     EXPECT_STREQ("name2", event2->name());
1393     EXPECT_TRUE(event1->parameter_copy_storage() != NULL);
1394     EXPECT_TRUE(event2->parameter_copy_storage() != NULL);
1395     EXPECT_GT(event1->parameter_copy_storage()->size(), 0u);
1396     EXPECT_GT(event2->parameter_copy_storage()->size(), 0u);
1397     EndTraceAndFlush();
1398   }
1399
1400   {
1401     BeginTrace();
1402     // Test that static literal string arguments are not copied.
1403     TraceEventHandle handle1 =
1404         trace_event_internal::AddTraceEvent(
1405             TRACE_EVENT_PHASE_INSTANT, category_group_enabled, "name1", 0, 0,
1406             "arg1", "argval", "arg2", "argval");
1407     // Test that static TRACE_STR_COPY NULL string arguments are not copied.
1408     const char* str1 = NULL;
1409     const char* str2 = NULL;
1410     TraceEventHandle handle2 =
1411         trace_event_internal::AddTraceEvent(
1412             TRACE_EVENT_PHASE_INSTANT, category_group_enabled, "name2", 0, 0,
1413             "arg1", TRACE_STR_COPY(str1),
1414             "arg2", TRACE_STR_COPY(str2));
1415     EXPECT_GT(tracer->GetStatus().event_count, 1u);
1416     const TraceEvent* event1 = tracer->GetEventByHandle(handle1);
1417     const TraceEvent* event2 = tracer->GetEventByHandle(handle2);
1418     ASSERT_TRUE(event1);
1419     ASSERT_TRUE(event2);
1420     EXPECT_STREQ("name1", event1->name());
1421     EXPECT_STREQ("name2", event2->name());
1422     EXPECT_TRUE(event1->parameter_copy_storage() == NULL);
1423     EXPECT_TRUE(event2->parameter_copy_storage() == NULL);
1424     EndTraceAndFlush();
1425   }
1426 }
1427
1428 // Test that data sent from other threads is gathered
1429 TEST_F(TraceEventTestFixture, DataCapturedOnThread) {
1430   BeginTrace();
1431
1432   Thread thread("1");
1433   WaitableEvent task_complete_event(false, false);
1434   thread.Start();
1435
1436   thread.message_loop()->PostTask(
1437       FROM_HERE, base::Bind(&TraceWithAllMacroVariants, &task_complete_event));
1438   task_complete_event.Wait();
1439   thread.Stop();
1440
1441   EndTraceAndFlush();
1442   ValidateAllTraceMacrosCreatedData(trace_parsed_);
1443 }
1444
1445 // Test that data sent from multiple threads is gathered
1446 TEST_F(TraceEventTestFixture, DataCapturedManyThreads) {
1447   BeginTrace();
1448
1449   const int num_threads = 4;
1450   const int num_events = 4000;
1451   Thread* threads[num_threads];
1452   WaitableEvent* task_complete_events[num_threads];
1453   for (int i = 0; i < num_threads; i++) {
1454     threads[i] = new Thread(StringPrintf("Thread %d", i));
1455     task_complete_events[i] = new WaitableEvent(false, false);
1456     threads[i]->Start();
1457     threads[i]->message_loop()->PostTask(
1458         FROM_HERE, base::Bind(&TraceManyInstantEvents,
1459                               i, num_events, task_complete_events[i]));
1460   }
1461
1462   for (int i = 0; i < num_threads; i++) {
1463     task_complete_events[i]->Wait();
1464   }
1465
1466   // Let half of the threads end before flush.
1467   for (int i = 0; i < num_threads / 2; i++) {
1468     threads[i]->Stop();
1469     delete threads[i];
1470     delete task_complete_events[i];
1471   }
1472
1473   EndTraceAndFlushInThreadWithMessageLoop();
1474   ValidateInstantEventPresentOnEveryThread(trace_parsed_,
1475                                            num_threads, num_events);
1476
1477   // Let the other half of the threads end after flush.
1478   for (int i = num_threads / 2; i < num_threads; i++) {
1479     threads[i]->Stop();
1480     delete threads[i];
1481     delete task_complete_events[i];
1482   }
1483 }
1484
1485 // Test that thread and process names show up in the trace
1486 TEST_F(TraceEventTestFixture, ThreadNames) {
1487   // Create threads before we enable tracing to make sure
1488   // that tracelog still captures them.
1489   const int kNumThreads = 4;
1490   const int kNumEvents = 10;
1491   Thread* threads[kNumThreads];
1492   PlatformThreadId thread_ids[kNumThreads];
1493   for (int i = 0; i < kNumThreads; i++)
1494     threads[i] = new Thread(StringPrintf("Thread %d", i));
1495
1496   // Enable tracing.
1497   BeginTrace();
1498
1499   // Now run some trace code on these threads.
1500   WaitableEvent* task_complete_events[kNumThreads];
1501   for (int i = 0; i < kNumThreads; i++) {
1502     task_complete_events[i] = new WaitableEvent(false, false);
1503     threads[i]->Start();
1504     thread_ids[i] = threads[i]->thread_id();
1505     threads[i]->message_loop()->PostTask(
1506         FROM_HERE, base::Bind(&TraceManyInstantEvents,
1507                               i, kNumEvents, task_complete_events[i]));
1508   }
1509   for (int i = 0; i < kNumThreads; i++) {
1510     task_complete_events[i]->Wait();
1511   }
1512
1513   // Shut things down.
1514   for (int i = 0; i < kNumThreads; i++) {
1515     threads[i]->Stop();
1516     delete threads[i];
1517     delete task_complete_events[i];
1518   }
1519
1520   EndTraceAndFlush();
1521
1522   std::string tmp;
1523   int tmp_int;
1524   const DictionaryValue* item;
1525
1526   // Make sure we get thread name metadata.
1527   // Note, the test suite may have created a ton of threads.
1528   // So, we'll have thread names for threads we didn't create.
1529   std::vector<const DictionaryValue*> items =
1530       FindTraceEntries(trace_parsed_, "thread_name");
1531   for (int i = 0; i < static_cast<int>(items.size()); i++) {
1532     item = items[i];
1533     ASSERT_TRUE(item);
1534     EXPECT_TRUE(item->GetInteger("tid", &tmp_int));
1535
1536     // See if this thread name is one of the threads we just created
1537     for (int j = 0; j < kNumThreads; j++) {
1538       if(static_cast<int>(thread_ids[j]) != tmp_int)
1539         continue;
1540
1541       std::string expected_name = StringPrintf("Thread %d", j);
1542       EXPECT_TRUE(item->GetString("ph", &tmp) && tmp == "M");
1543       EXPECT_TRUE(item->GetInteger("pid", &tmp_int) &&
1544                   tmp_int == static_cast<int>(base::GetCurrentProcId()));
1545       // If the thread name changes or the tid gets reused, the name will be
1546       // a comma-separated list of thread names, so look for a substring.
1547       EXPECT_TRUE(item->GetString("args.name", &tmp) &&
1548                   tmp.find(expected_name) != std::string::npos);
1549     }
1550   }
1551 }
1552
1553 TEST_F(TraceEventTestFixture, ThreadNameChanges) {
1554   BeginTrace();
1555
1556   PlatformThread::SetName("");
1557   TRACE_EVENT_INSTANT0("drink", "water", TRACE_EVENT_SCOPE_THREAD);
1558
1559   PlatformThread::SetName("cafe");
1560   TRACE_EVENT_INSTANT0("drink", "coffee", TRACE_EVENT_SCOPE_THREAD);
1561
1562   PlatformThread::SetName("shop");
1563   // No event here, so won't appear in combined name.
1564
1565   PlatformThread::SetName("pub");
1566   TRACE_EVENT_INSTANT0("drink", "beer", TRACE_EVENT_SCOPE_THREAD);
1567   TRACE_EVENT_INSTANT0("drink", "wine", TRACE_EVENT_SCOPE_THREAD);
1568
1569   PlatformThread::SetName(" bar");
1570   TRACE_EVENT_INSTANT0("drink", "whisky", TRACE_EVENT_SCOPE_THREAD);
1571
1572   EndTraceAndFlush();
1573
1574   std::vector<const DictionaryValue*> items =
1575       FindTraceEntries(trace_parsed_, "thread_name");
1576   EXPECT_EQ(1u, items.size());
1577   ASSERT_GT(items.size(), 0u);
1578   const DictionaryValue* item = items[0];
1579   ASSERT_TRUE(item);
1580   int tid;
1581   EXPECT_TRUE(item->GetInteger("tid", &tid));
1582   EXPECT_EQ(PlatformThread::CurrentId(), static_cast<PlatformThreadId>(tid));
1583
1584   std::string expected_name = "cafe,pub, bar";
1585   std::string tmp;
1586   EXPECT_TRUE(item->GetString("args.name", &tmp));
1587   EXPECT_EQ(expected_name, tmp);
1588 }
1589
1590 // Test that the disabled trace categories are included/excluded from the
1591 // trace output correctly.
1592 TEST_F(TraceEventTestFixture, DisabledCategories) {
1593   BeginTrace();
1594   TRACE_EVENT_INSTANT0(TRACE_DISABLED_BY_DEFAULT("cc"), "first",
1595                        TRACE_EVENT_SCOPE_THREAD);
1596   TRACE_EVENT_INSTANT0("included", "first", TRACE_EVENT_SCOPE_THREAD);
1597   EndTraceAndFlush();
1598   {
1599     const DictionaryValue* item = NULL;
1600     ListValue& trace_parsed = trace_parsed_;
1601     EXPECT_NOT_FIND_("disabled-by-default-cc");
1602     EXPECT_FIND_("included");
1603   }
1604   Clear();
1605
1606   BeginSpecificTrace("disabled-by-default-cc");
1607   TRACE_EVENT_INSTANT0(TRACE_DISABLED_BY_DEFAULT("cc"), "second",
1608                        TRACE_EVENT_SCOPE_THREAD);
1609   TRACE_EVENT_INSTANT0("other_included", "second", TRACE_EVENT_SCOPE_THREAD);
1610   EndTraceAndFlush();
1611
1612   {
1613     const DictionaryValue* item = NULL;
1614     ListValue& trace_parsed = trace_parsed_;
1615     EXPECT_FIND_("disabled-by-default-cc");
1616     EXPECT_FIND_("other_included");
1617   }
1618 }
1619
1620 TEST_F(TraceEventTestFixture, NormallyNoDeepCopy) {
1621   // Test that the TRACE_EVENT macros do not deep-copy their string. If they
1622   // do so it may indicate a performance regression, but more-over it would
1623   // make the DEEP_COPY overloads redundant.
1624   std::string name_string("event name");
1625
1626   BeginTrace();
1627   TRACE_EVENT_INSTANT0("category", name_string.c_str(),
1628                        TRACE_EVENT_SCOPE_THREAD);
1629
1630   // Modify the string in place (a wholesale reassignment may leave the old
1631   // string intact on the heap).
1632   name_string[0] = '@';
1633
1634   EndTraceAndFlush();
1635
1636   EXPECT_FALSE(FindTraceEntry(trace_parsed_, "event name"));
1637   EXPECT_TRUE(FindTraceEntry(trace_parsed_, name_string.c_str()));
1638 }
1639
1640 TEST_F(TraceEventTestFixture, DeepCopy) {
1641   static const char kOriginalName1[] = "name1";
1642   static const char kOriginalName2[] = "name2";
1643   static const char kOriginalName3[] = "name3";
1644   std::string name1(kOriginalName1);
1645   std::string name2(kOriginalName2);
1646   std::string name3(kOriginalName3);
1647   std::string arg1("arg1");
1648   std::string arg2("arg2");
1649   std::string val1("val1");
1650   std::string val2("val2");
1651
1652   BeginTrace();
1653   TRACE_EVENT_COPY_INSTANT0("category", name1.c_str(),
1654                             TRACE_EVENT_SCOPE_THREAD);
1655   TRACE_EVENT_COPY_BEGIN1("category", name2.c_str(),
1656                           arg1.c_str(), 5);
1657   TRACE_EVENT_COPY_END2("category", name3.c_str(),
1658                         arg1.c_str(), val1,
1659                         arg2.c_str(), val2);
1660
1661   // As per NormallyNoDeepCopy, modify the strings in place.
1662   name1[0] = name2[0] = name3[0] = arg1[0] = arg2[0] = val1[0] = val2[0] = '@';
1663
1664   EndTraceAndFlush();
1665
1666   EXPECT_FALSE(FindTraceEntry(trace_parsed_, name1.c_str()));
1667   EXPECT_FALSE(FindTraceEntry(trace_parsed_, name2.c_str()));
1668   EXPECT_FALSE(FindTraceEntry(trace_parsed_, name3.c_str()));
1669
1670   const DictionaryValue* entry1 = FindTraceEntry(trace_parsed_, kOriginalName1);
1671   const DictionaryValue* entry2 = FindTraceEntry(trace_parsed_, kOriginalName2);
1672   const DictionaryValue* entry3 = FindTraceEntry(trace_parsed_, kOriginalName3);
1673   ASSERT_TRUE(entry1);
1674   ASSERT_TRUE(entry2);
1675   ASSERT_TRUE(entry3);
1676
1677   int i;
1678   EXPECT_FALSE(entry2->GetInteger("args.@rg1", &i));
1679   EXPECT_TRUE(entry2->GetInteger("args.arg1", &i));
1680   EXPECT_EQ(5, i);
1681
1682   std::string s;
1683   EXPECT_TRUE(entry3->GetString("args.arg1", &s));
1684   EXPECT_EQ("val1", s);
1685   EXPECT_TRUE(entry3->GetString("args.arg2", &s));
1686   EXPECT_EQ("val2", s);
1687 }
1688
1689 // Test that TraceResultBuffer outputs the correct result whether it is added
1690 // in chunks or added all at once.
1691 TEST_F(TraceEventTestFixture, TraceResultBuffer) {
1692   Clear();
1693
1694   trace_buffer_.Start();
1695   trace_buffer_.AddFragment("bla1");
1696   trace_buffer_.AddFragment("bla2");
1697   trace_buffer_.AddFragment("bla3,bla4");
1698   trace_buffer_.Finish();
1699   EXPECT_STREQ(json_output_.json_output.c_str(), "[bla1,bla2,bla3,bla4]");
1700
1701   Clear();
1702
1703   trace_buffer_.Start();
1704   trace_buffer_.AddFragment("bla1,bla2,bla3,bla4");
1705   trace_buffer_.Finish();
1706   EXPECT_STREQ(json_output_.json_output.c_str(), "[bla1,bla2,bla3,bla4]");
1707 }
1708
1709 // Test that trace_event parameters are not evaluated if the tracing
1710 // system is disabled.
1711 TEST_F(TraceEventTestFixture, TracingIsLazy) {
1712   BeginTrace();
1713
1714   int a = 0;
1715   TRACE_EVENT_INSTANT1("category", "test", TRACE_EVENT_SCOPE_THREAD, "a", a++);
1716   EXPECT_EQ(1, a);
1717
1718   TraceLog::GetInstance()->SetDisabled();
1719
1720   TRACE_EVENT_INSTANT1("category", "test", TRACE_EVENT_SCOPE_THREAD, "a", a++);
1721   EXPECT_EQ(1, a);
1722
1723   EndTraceAndFlush();
1724 }
1725
1726 TEST_F(TraceEventTestFixture, TraceEnableDisable) {
1727   TraceLog* trace_log = TraceLog::GetInstance();
1728   CategoryFilter cf_inc_all("*");
1729   trace_log->SetEnabled(cf_inc_all,
1730                         TraceLog::RECORDING_MODE,
1731                         TraceOptions());
1732   EXPECT_TRUE(trace_log->IsEnabled());
1733   trace_log->SetDisabled();
1734   EXPECT_FALSE(trace_log->IsEnabled());
1735
1736   trace_log->SetEnabled(cf_inc_all,
1737                         TraceLog::RECORDING_MODE,
1738                         TraceOptions());
1739   EXPECT_TRUE(trace_log->IsEnabled());
1740   const std::vector<std::string> empty;
1741   trace_log->SetEnabled(CategoryFilter(),
1742                         TraceLog::RECORDING_MODE,
1743                         TraceOptions());
1744   EXPECT_TRUE(trace_log->IsEnabled());
1745   trace_log->SetDisabled();
1746   EXPECT_FALSE(trace_log->IsEnabled());
1747   trace_log->SetDisabled();
1748   EXPECT_FALSE(trace_log->IsEnabled());
1749 }
1750
1751 TEST_F(TraceEventTestFixture, TraceCategoriesAfterNestedEnable) {
1752   TraceLog* trace_log = TraceLog::GetInstance();
1753   trace_log->SetEnabled(CategoryFilter("foo,bar"),
1754                         TraceLog::RECORDING_MODE,
1755                         TraceOptions());
1756   EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("foo"));
1757   EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("bar"));
1758   EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("baz"));
1759   trace_log->SetEnabled(CategoryFilter("foo2"),
1760                         TraceLog::RECORDING_MODE,
1761                         TraceOptions());
1762   EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("foo2"));
1763   EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("baz"));
1764   // The "" becomes the default catergory set when applied.
1765   trace_log->SetEnabled(CategoryFilter(),
1766                         TraceLog::RECORDING_MODE,
1767                         TraceOptions());
1768   EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("foo"));
1769   EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("baz"));
1770   EXPECT_STREQ("-*Debug,-*Test",
1771                trace_log->GetCurrentCategoryFilter().ToString().c_str());
1772   trace_log->SetDisabled();
1773   trace_log->SetDisabled();
1774   trace_log->SetDisabled();
1775   EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("foo"));
1776   EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("baz"));
1777
1778   trace_log->SetEnabled(CategoryFilter("-foo,-bar"),
1779                         TraceLog::RECORDING_MODE,
1780                         TraceOptions());
1781   EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("foo"));
1782   EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("baz"));
1783   trace_log->SetEnabled(CategoryFilter("moo"),
1784                         TraceLog::RECORDING_MODE,
1785                         TraceOptions());
1786   EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("baz"));
1787   EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("moo"));
1788   EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("foo"));
1789   EXPECT_STREQ("-foo,-bar",
1790                trace_log->GetCurrentCategoryFilter().ToString().c_str());
1791   trace_log->SetDisabled();
1792   trace_log->SetDisabled();
1793
1794   // Make sure disabled categories aren't cleared if we set in the second.
1795   trace_log->SetEnabled(CategoryFilter("disabled-by-default-cc,foo"),
1796                         TraceLog::RECORDING_MODE,
1797                         TraceOptions());
1798   EXPECT_FALSE(*trace_log->GetCategoryGroupEnabled("bar"));
1799   trace_log->SetEnabled(CategoryFilter("disabled-by-default-gpu"),
1800                         TraceLog::RECORDING_MODE,
1801                         TraceOptions());
1802   EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("disabled-by-default-cc"));
1803   EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("disabled-by-default-gpu"));
1804   EXPECT_TRUE(*trace_log->GetCategoryGroupEnabled("bar"));
1805   EXPECT_STREQ("disabled-by-default-cc,disabled-by-default-gpu",
1806                trace_log->GetCurrentCategoryFilter().ToString().c_str());
1807   trace_log->SetDisabled();
1808   trace_log->SetDisabled();
1809 }
1810
1811 TEST_F(TraceEventTestFixture, TraceSampling) {
1812   TraceOptions trace_options(RECORD_UNTIL_FULL);
1813   trace_options.enable_sampling = true;
1814   TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
1815                                       TraceLog::RECORDING_MODE,
1816                                       trace_options);
1817
1818   TRACE_EVENT_SET_SAMPLING_STATE_FOR_BUCKET(1, "cc", "Stuff");
1819   TraceLog::GetInstance()->WaitSamplingEventForTesting();
1820   TRACE_EVENT_SET_SAMPLING_STATE_FOR_BUCKET(1, "cc", "Things");
1821   TraceLog::GetInstance()->WaitSamplingEventForTesting();
1822
1823   EndTraceAndFlush();
1824
1825   // Make sure we hit at least once.
1826   EXPECT_TRUE(FindNamePhase("Stuff", "P"));
1827   EXPECT_TRUE(FindNamePhase("Things", "P"));
1828 }
1829
1830 TEST_F(TraceEventTestFixture, TraceSamplingScope) {
1831   TraceOptions trace_options(RECORD_UNTIL_FULL);
1832   trace_options.enable_sampling = true;
1833   TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
1834                                       TraceLog::RECORDING_MODE,
1835                                       trace_options);
1836
1837   TRACE_EVENT_SCOPED_SAMPLING_STATE("AAA", "name");
1838   TraceLog::GetInstance()->WaitSamplingEventForTesting();
1839   {
1840     EXPECT_STREQ(TRACE_EVENT_GET_SAMPLING_STATE(), "AAA");
1841     TRACE_EVENT_SCOPED_SAMPLING_STATE("BBB", "name");
1842     TraceLog::GetInstance()->WaitSamplingEventForTesting();
1843     EXPECT_STREQ(TRACE_EVENT_GET_SAMPLING_STATE(), "BBB");
1844   }
1845   TraceLog::GetInstance()->WaitSamplingEventForTesting();
1846   {
1847     EXPECT_STREQ(TRACE_EVENT_GET_SAMPLING_STATE(), "AAA");
1848     TRACE_EVENT_SCOPED_SAMPLING_STATE("CCC", "name");
1849     TraceLog::GetInstance()->WaitSamplingEventForTesting();
1850     EXPECT_STREQ(TRACE_EVENT_GET_SAMPLING_STATE(), "CCC");
1851   }
1852   TraceLog::GetInstance()->WaitSamplingEventForTesting();
1853   {
1854     EXPECT_STREQ(TRACE_EVENT_GET_SAMPLING_STATE(), "AAA");
1855     TRACE_EVENT_SET_SAMPLING_STATE("DDD", "name");
1856     TraceLog::GetInstance()->WaitSamplingEventForTesting();
1857     EXPECT_STREQ(TRACE_EVENT_GET_SAMPLING_STATE(), "DDD");
1858   }
1859   TraceLog::GetInstance()->WaitSamplingEventForTesting();
1860   EXPECT_STREQ(TRACE_EVENT_GET_SAMPLING_STATE(), "DDD");
1861
1862   EndTraceAndFlush();
1863 }
1864
1865 TEST_F(TraceEventTestFixture, TraceContinuousSampling) {
1866   TraceOptions trace_options(RECORD_UNTIL_FULL);
1867   trace_options.enable_sampling = true;
1868
1869   TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
1870                                       TraceLog::MONITORING_MODE,
1871                                       trace_options);
1872
1873   TRACE_EVENT_SET_SAMPLING_STATE_FOR_BUCKET(1, "category", "AAA");
1874   TraceLog::GetInstance()->WaitSamplingEventForTesting();
1875   TRACE_EVENT_SET_SAMPLING_STATE_FOR_BUCKET(1, "category", "BBB");
1876   TraceLog::GetInstance()->WaitSamplingEventForTesting();
1877
1878   FlushMonitoring();
1879
1880   // Make sure we can get the profiled data.
1881   EXPECT_TRUE(FindNamePhase("AAA", "P"));
1882   EXPECT_TRUE(FindNamePhase("BBB", "P"));
1883
1884   Clear();
1885   TraceLog::GetInstance()->WaitSamplingEventForTesting();
1886
1887   TRACE_EVENT_SET_SAMPLING_STATE_FOR_BUCKET(1, "category", "CCC");
1888   TraceLog::GetInstance()->WaitSamplingEventForTesting();
1889   TRACE_EVENT_SET_SAMPLING_STATE_FOR_BUCKET(1, "category", "DDD");
1890   TraceLog::GetInstance()->WaitSamplingEventForTesting();
1891
1892   FlushMonitoring();
1893
1894   // Make sure the profiled data is accumulated.
1895   EXPECT_TRUE(FindNamePhase("AAA", "P"));
1896   EXPECT_TRUE(FindNamePhase("BBB", "P"));
1897   EXPECT_TRUE(FindNamePhase("CCC", "P"));
1898   EXPECT_TRUE(FindNamePhase("DDD", "P"));
1899
1900   Clear();
1901
1902   TraceLog::GetInstance()->SetDisabled();
1903
1904   // Make sure disabling the continuous sampling thread clears
1905   // the profiled data.
1906   EXPECT_FALSE(FindNamePhase("AAA", "P"));
1907   EXPECT_FALSE(FindNamePhase("BBB", "P"));
1908   EXPECT_FALSE(FindNamePhase("CCC", "P"));
1909   EXPECT_FALSE(FindNamePhase("DDD", "P"));
1910
1911   Clear();
1912 }
1913
1914 class MyData : public ConvertableToTraceFormat {
1915  public:
1916   MyData() {}
1917
1918   void AppendAsTraceFormat(std::string* out) const override {
1919     out->append("{\"foo\":1}");
1920   }
1921
1922  private:
1923   ~MyData() override {}
1924   DISALLOW_COPY_AND_ASSIGN(MyData);
1925 };
1926
1927 TEST_F(TraceEventTestFixture, ConvertableTypes) {
1928   TraceLog::GetInstance()->SetEnabled(
1929       CategoryFilter("*"),
1930       TraceLog::RECORDING_MODE,
1931       TraceOptions());
1932
1933   scoped_refptr<ConvertableToTraceFormat> data(new MyData());
1934   scoped_refptr<ConvertableToTraceFormat> data1(new MyData());
1935   scoped_refptr<ConvertableToTraceFormat> data2(new MyData());
1936   TRACE_EVENT1("foo", "bar", "data", data);
1937   TRACE_EVENT2("foo", "baz",
1938                "data1", data1,
1939                "data2", data2);
1940
1941
1942   scoped_refptr<ConvertableToTraceFormat> convertData1(new MyData());
1943   scoped_refptr<ConvertableToTraceFormat> convertData2(new MyData());
1944   TRACE_EVENT2(
1945       "foo",
1946       "string_first",
1947       "str",
1948       "string value 1",
1949       "convert",
1950       convertData1);
1951   TRACE_EVENT2(
1952       "foo",
1953       "string_second",
1954       "convert",
1955       convertData2,
1956       "str",
1957       "string value 2");
1958   EndTraceAndFlush();
1959
1960   // One arg version.
1961   DictionaryValue* dict = FindNamePhase("bar", "X");
1962   ASSERT_TRUE(dict);
1963
1964   const DictionaryValue* args_dict = NULL;
1965   dict->GetDictionary("args", &args_dict);
1966   ASSERT_TRUE(args_dict);
1967
1968   const Value* value = NULL;
1969   const DictionaryValue* convertable_dict = NULL;
1970   EXPECT_TRUE(args_dict->Get("data", &value));
1971   ASSERT_TRUE(value->GetAsDictionary(&convertable_dict));
1972
1973   int foo_val;
1974   EXPECT_TRUE(convertable_dict->GetInteger("foo", &foo_val));
1975   EXPECT_EQ(1, foo_val);
1976
1977   // Two arg version.
1978   dict = FindNamePhase("baz", "X");
1979   ASSERT_TRUE(dict);
1980
1981   args_dict = NULL;
1982   dict->GetDictionary("args", &args_dict);
1983   ASSERT_TRUE(args_dict);
1984
1985   value = NULL;
1986   convertable_dict = NULL;
1987   EXPECT_TRUE(args_dict->Get("data1", &value));
1988   ASSERT_TRUE(value->GetAsDictionary(&convertable_dict));
1989
1990   value = NULL;
1991   convertable_dict = NULL;
1992   EXPECT_TRUE(args_dict->Get("data2", &value));
1993   ASSERT_TRUE(value->GetAsDictionary(&convertable_dict));
1994
1995   // Convertable with other types.
1996   dict = FindNamePhase("string_first", "X");
1997   ASSERT_TRUE(dict);
1998
1999   args_dict = NULL;
2000   dict->GetDictionary("args", &args_dict);
2001   ASSERT_TRUE(args_dict);
2002
2003   std::string str_value;
2004   EXPECT_TRUE(args_dict->GetString("str", &str_value));
2005   EXPECT_STREQ("string value 1", str_value.c_str());
2006
2007   value = NULL;
2008   convertable_dict = NULL;
2009   foo_val = 0;
2010   EXPECT_TRUE(args_dict->Get("convert", &value));
2011   ASSERT_TRUE(value->GetAsDictionary(&convertable_dict));
2012   EXPECT_TRUE(convertable_dict->GetInteger("foo", &foo_val));
2013   EXPECT_EQ(1, foo_val);
2014
2015   dict = FindNamePhase("string_second", "X");
2016   ASSERT_TRUE(dict);
2017
2018   args_dict = NULL;
2019   dict->GetDictionary("args", &args_dict);
2020   ASSERT_TRUE(args_dict);
2021
2022   EXPECT_TRUE(args_dict->GetString("str", &str_value));
2023   EXPECT_STREQ("string value 2", str_value.c_str());
2024
2025   value = NULL;
2026   convertable_dict = NULL;
2027   foo_val = 0;
2028   EXPECT_TRUE(args_dict->Get("convert", &value));
2029   ASSERT_TRUE(value->GetAsDictionary(&convertable_dict));
2030   EXPECT_TRUE(convertable_dict->GetInteger("foo", &foo_val));
2031   EXPECT_EQ(1, foo_val);
2032 }
2033
2034 TEST_F(TraceEventTestFixture, PrimitiveArgs) {
2035   TraceLog::GetInstance()->SetEnabled(
2036       CategoryFilter("*"),
2037       TraceLog::RECORDING_MODE,
2038       TraceOptions());
2039
2040   TRACE_EVENT1("foo", "event1", "int_one", 1);
2041   TRACE_EVENT1("foo", "event2", "int_neg_ten", -10);
2042   TRACE_EVENT1("foo", "event3", "float_one", 1.0f);
2043   TRACE_EVENT1("foo", "event4", "float_half", .5f);
2044   TRACE_EVENT1("foo", "event5", "float_neghalf", -.5f);
2045   TRACE_EVENT1("foo", "event6", "float_infinity",
2046       std::numeric_limits<float>::infinity());
2047   TRACE_EVENT1("foo", "event6b", "float_neg_infinity",
2048       -std::numeric_limits<float>::infinity());
2049   TRACE_EVENT1("foo", "event7", "double_nan",
2050       std::numeric_limits<double>::quiet_NaN());
2051   void* p = 0;
2052   TRACE_EVENT1("foo", "event8", "pointer_null", p);
2053   p = reinterpret_cast<void*>(0xbadf00d);
2054   TRACE_EVENT1("foo", "event9", "pointer_badf00d", p);
2055   TRACE_EVENT1("foo", "event10", "bool_true", true);
2056   TRACE_EVENT1("foo", "event11", "bool_false", false);
2057   TRACE_EVENT1("foo", "event12", "time_null",
2058       base::Time());
2059   TRACE_EVENT1("foo", "event13", "time_one",
2060       base::Time::FromInternalValue(1));
2061   TRACE_EVENT1("foo", "event14", "timeticks_null",
2062       base::TimeTicks());
2063   TRACE_EVENT1("foo", "event15", "timeticks_one",
2064       base::TimeTicks::FromInternalValue(1));
2065   EndTraceAndFlush();
2066
2067   const DictionaryValue* args_dict = NULL;
2068   DictionaryValue* dict = NULL;
2069   const Value* value = NULL;
2070   std::string str_value;
2071   int int_value;
2072   double double_value;
2073   bool bool_value;
2074
2075   dict = FindNamePhase("event1", "X");
2076   ASSERT_TRUE(dict);
2077   dict->GetDictionary("args", &args_dict);
2078   ASSERT_TRUE(args_dict);
2079   EXPECT_TRUE(args_dict->GetInteger("int_one", &int_value));
2080   EXPECT_EQ(1, int_value);
2081
2082   dict = FindNamePhase("event2", "X");
2083   ASSERT_TRUE(dict);
2084   dict->GetDictionary("args", &args_dict);
2085   ASSERT_TRUE(args_dict);
2086   EXPECT_TRUE(args_dict->GetInteger("int_neg_ten", &int_value));
2087   EXPECT_EQ(-10, int_value);
2088
2089   // 1f must be serlized to JSON as "1.0" in order to be a double, not an int.
2090   dict = FindNamePhase("event3", "X");
2091   ASSERT_TRUE(dict);
2092   dict->GetDictionary("args", &args_dict);
2093   ASSERT_TRUE(args_dict);
2094   EXPECT_TRUE(args_dict->Get("float_one", &value));
2095   EXPECT_TRUE(value->IsType(Value::TYPE_DOUBLE));
2096   EXPECT_TRUE(value->GetAsDouble(&double_value));
2097   EXPECT_EQ(1, double_value);
2098
2099   // .5f must be serlized to JSON as "0.5".
2100   dict = FindNamePhase("event4", "X");
2101   ASSERT_TRUE(dict);
2102   dict->GetDictionary("args", &args_dict);
2103   ASSERT_TRUE(args_dict);
2104   EXPECT_TRUE(args_dict->Get("float_half", &value));
2105   EXPECT_TRUE(value->IsType(Value::TYPE_DOUBLE));
2106   EXPECT_TRUE(value->GetAsDouble(&double_value));
2107   EXPECT_EQ(0.5, double_value);
2108
2109   // -.5f must be serlized to JSON as "-0.5".
2110   dict = FindNamePhase("event5", "X");
2111   ASSERT_TRUE(dict);
2112   dict->GetDictionary("args", &args_dict);
2113   ASSERT_TRUE(args_dict);
2114   EXPECT_TRUE(args_dict->Get("float_neghalf", &value));
2115   EXPECT_TRUE(value->IsType(Value::TYPE_DOUBLE));
2116   EXPECT_TRUE(value->GetAsDouble(&double_value));
2117   EXPECT_EQ(-0.5, double_value);
2118
2119   // Infinity is serialized to JSON as a string.
2120   dict = FindNamePhase("event6", "X");
2121   ASSERT_TRUE(dict);
2122   dict->GetDictionary("args", &args_dict);
2123   ASSERT_TRUE(args_dict);
2124   EXPECT_TRUE(args_dict->GetString("float_infinity", &str_value));
2125   EXPECT_STREQ("Infinity", str_value.c_str());
2126   dict = FindNamePhase("event6b", "X");
2127   ASSERT_TRUE(dict);
2128   dict->GetDictionary("args", &args_dict);
2129   ASSERT_TRUE(args_dict);
2130   EXPECT_TRUE(args_dict->GetString("float_neg_infinity", &str_value));
2131   EXPECT_STREQ("-Infinity", str_value.c_str());
2132
2133   // NaN is serialized to JSON as a string.
2134   dict = FindNamePhase("event7", "X");
2135   ASSERT_TRUE(dict);
2136   dict->GetDictionary("args", &args_dict);
2137   ASSERT_TRUE(args_dict);
2138   EXPECT_TRUE(args_dict->GetString("double_nan", &str_value));
2139   EXPECT_STREQ("NaN", str_value.c_str());
2140
2141   // NULL pointers should be serialized as "0x0".
2142   dict = FindNamePhase("event8", "X");
2143   ASSERT_TRUE(dict);
2144   dict->GetDictionary("args", &args_dict);
2145   ASSERT_TRUE(args_dict);
2146   EXPECT_TRUE(args_dict->GetString("pointer_null", &str_value));
2147   EXPECT_STREQ("0x0", str_value.c_str());
2148
2149   // Other pointers should be serlized as a hex string.
2150   dict = FindNamePhase("event9", "X");
2151   ASSERT_TRUE(dict);
2152   dict->GetDictionary("args", &args_dict);
2153   ASSERT_TRUE(args_dict);
2154   EXPECT_TRUE(args_dict->GetString("pointer_badf00d", &str_value));
2155   EXPECT_STREQ("0xbadf00d", str_value.c_str());
2156
2157   dict = FindNamePhase("event10", "X");
2158   ASSERT_TRUE(dict);
2159   dict->GetDictionary("args", &args_dict);
2160   ASSERT_TRUE(args_dict);
2161   EXPECT_TRUE(args_dict->GetBoolean("bool_true", &bool_value));
2162   EXPECT_TRUE(bool_value);
2163
2164   dict = FindNamePhase("event11", "X");
2165   ASSERT_TRUE(dict);
2166   dict->GetDictionary("args", &args_dict);
2167   ASSERT_TRUE(args_dict);
2168   EXPECT_TRUE(args_dict->GetBoolean("bool_false", &bool_value));
2169   EXPECT_FALSE(bool_value);
2170
2171   dict = FindNamePhase("event12", "X");
2172   ASSERT_TRUE(dict);
2173   dict->GetDictionary("args", &args_dict);
2174   ASSERT_TRUE(args_dict);
2175   EXPECT_TRUE(args_dict->GetInteger("time_null", &int_value));
2176   EXPECT_EQ(0, int_value);
2177
2178   dict = FindNamePhase("event13", "X");
2179   ASSERT_TRUE(dict);
2180   dict->GetDictionary("args", &args_dict);
2181   ASSERT_TRUE(args_dict);
2182   EXPECT_TRUE(args_dict->GetInteger("time_one", &int_value));
2183   EXPECT_EQ(1, int_value);
2184
2185   dict = FindNamePhase("event14", "X");
2186   ASSERT_TRUE(dict);
2187   dict->GetDictionary("args", &args_dict);
2188   ASSERT_TRUE(args_dict);
2189   EXPECT_TRUE(args_dict->GetInteger("timeticks_null", &int_value));
2190   EXPECT_EQ(0, int_value);
2191
2192   dict = FindNamePhase("event15", "X");
2193   ASSERT_TRUE(dict);
2194   dict->GetDictionary("args", &args_dict);
2195   ASSERT_TRUE(args_dict);
2196   EXPECT_TRUE(args_dict->GetInteger("timeticks_one", &int_value));
2197   EXPECT_EQ(1, int_value);
2198 }
2199
2200 class TraceEventCallbackTest : public TraceEventTestFixture {
2201  public:
2202   virtual void SetUp() override {
2203     TraceEventTestFixture::SetUp();
2204     ASSERT_EQ(NULL, s_instance);
2205     s_instance = this;
2206   }
2207   virtual void TearDown() override {
2208     TraceLog::GetInstance()->SetDisabled();
2209     ASSERT_TRUE(!!s_instance);
2210     s_instance = NULL;
2211     TraceEventTestFixture::TearDown();
2212   }
2213
2214  protected:
2215   // For TraceEventCallbackAndRecordingX tests.
2216   void VerifyCallbackAndRecordedEvents(size_t expected_callback_count,
2217                                        size_t expected_recorded_count) {
2218     // Callback events.
2219     EXPECT_EQ(expected_callback_count, collected_events_names_.size());
2220     for (size_t i = 0; i < collected_events_names_.size(); ++i) {
2221       EXPECT_EQ("callback", collected_events_categories_[i]);
2222       EXPECT_EQ("yes", collected_events_names_[i]);
2223     }
2224
2225     // Recorded events.
2226     EXPECT_EQ(expected_recorded_count, trace_parsed_.GetSize());
2227     EXPECT_TRUE(FindTraceEntry(trace_parsed_, "recording"));
2228     EXPECT_FALSE(FindTraceEntry(trace_parsed_, "callback"));
2229     EXPECT_TRUE(FindTraceEntry(trace_parsed_, "yes"));
2230     EXPECT_FALSE(FindTraceEntry(trace_parsed_, "no"));
2231   }
2232
2233   void VerifyCollectedEvent(size_t i,
2234                             unsigned phase,
2235                             const std::string& category,
2236                             const std::string& name) {
2237     EXPECT_EQ(phase, collected_events_phases_[i]);
2238     EXPECT_EQ(category, collected_events_categories_[i]);
2239     EXPECT_EQ(name, collected_events_names_[i]);
2240   }
2241
2242   std::vector<std::string> collected_events_categories_;
2243   std::vector<std::string> collected_events_names_;
2244   std::vector<unsigned char> collected_events_phases_;
2245   std::vector<TimeTicks> collected_events_timestamps_;
2246
2247   static TraceEventCallbackTest* s_instance;
2248   static void Callback(TimeTicks timestamp,
2249                        char phase,
2250                        const unsigned char* category_group_enabled,
2251                        const char* name,
2252                        unsigned long long id,
2253                        int num_args,
2254                        const char* const arg_names[],
2255                        const unsigned char arg_types[],
2256                        const unsigned long long arg_values[],
2257                        unsigned char flags) {
2258     s_instance->collected_events_phases_.push_back(phase);
2259     s_instance->collected_events_categories_.push_back(
2260         TraceLog::GetCategoryGroupName(category_group_enabled));
2261     s_instance->collected_events_names_.push_back(name);
2262     s_instance->collected_events_timestamps_.push_back(timestamp);
2263   }
2264 };
2265
2266 TraceEventCallbackTest* TraceEventCallbackTest::s_instance;
2267
2268 TEST_F(TraceEventCallbackTest, TraceEventCallback) {
2269   TRACE_EVENT_INSTANT0("all", "before enable", TRACE_EVENT_SCOPE_THREAD);
2270   TraceLog::GetInstance()->SetEventCallbackEnabled(
2271       CategoryFilter("*"), Callback);
2272   TRACE_EVENT_INSTANT0("all", "event1", TRACE_EVENT_SCOPE_GLOBAL);
2273   TRACE_EVENT_INSTANT0("all", "event2", TRACE_EVENT_SCOPE_GLOBAL);
2274   {
2275     TRACE_EVENT0("all", "duration");
2276     TRACE_EVENT_INSTANT0("all", "event3", TRACE_EVENT_SCOPE_GLOBAL);
2277   }
2278   TraceLog::GetInstance()->SetEventCallbackDisabled();
2279   TRACE_EVENT_INSTANT0("all", "after callback removed",
2280                        TRACE_EVENT_SCOPE_GLOBAL);
2281   ASSERT_EQ(5u, collected_events_names_.size());
2282   EXPECT_EQ("event1", collected_events_names_[0]);
2283   EXPECT_EQ(TRACE_EVENT_PHASE_INSTANT, collected_events_phases_[0]);
2284   EXPECT_EQ("event2", collected_events_names_[1]);
2285   EXPECT_EQ(TRACE_EVENT_PHASE_INSTANT, collected_events_phases_[1]);
2286   EXPECT_EQ("duration", collected_events_names_[2]);
2287   EXPECT_EQ(TRACE_EVENT_PHASE_BEGIN, collected_events_phases_[2]);
2288   EXPECT_EQ("event3", collected_events_names_[3]);
2289   EXPECT_EQ(TRACE_EVENT_PHASE_INSTANT, collected_events_phases_[3]);
2290   EXPECT_EQ("duration", collected_events_names_[4]);
2291   EXPECT_EQ(TRACE_EVENT_PHASE_END, collected_events_phases_[4]);
2292   for (size_t i = 1; i < collected_events_timestamps_.size(); i++) {
2293     EXPECT_LE(collected_events_timestamps_[i - 1],
2294               collected_events_timestamps_[i]);
2295   }
2296 }
2297
2298 TEST_F(TraceEventCallbackTest, TraceEventCallbackWhileFull) {
2299   TraceLog::GetInstance()->SetEnabled(
2300       CategoryFilter("*"),
2301       TraceLog::RECORDING_MODE,
2302       TraceOptions());
2303   do {
2304     TRACE_EVENT_INSTANT0("all", "badger badger", TRACE_EVENT_SCOPE_GLOBAL);
2305   } while (!TraceLog::GetInstance()->BufferIsFull());
2306   TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("*"),
2307                                                    Callback);
2308   TRACE_EVENT_INSTANT0("all", "a snake", TRACE_EVENT_SCOPE_GLOBAL);
2309   TraceLog::GetInstance()->SetEventCallbackDisabled();
2310   ASSERT_EQ(1u, collected_events_names_.size());
2311   EXPECT_EQ("a snake", collected_events_names_[0]);
2312 }
2313
2314 // 1: Enable callback, enable recording, disable callback, disable recording.
2315 TEST_F(TraceEventCallbackTest, TraceEventCallbackAndRecording1) {
2316   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2317   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2318   TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("callback"),
2319                                                    Callback);
2320   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2321   TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2322   TraceLog::GetInstance()->SetEnabled(
2323       CategoryFilter("recording"),
2324       TraceLog::RECORDING_MODE,
2325       TraceOptions());
2326   TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2327   TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2328   TraceLog::GetInstance()->SetEventCallbackDisabled();
2329   TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2330   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2331   EndTraceAndFlush();
2332   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2333   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2334
2335   DropTracedMetadataRecords();
2336   VerifyCallbackAndRecordedEvents(2, 2);
2337 }
2338
2339 // 2: Enable callback, enable recording, disable recording, disable callback.
2340 TEST_F(TraceEventCallbackTest, TraceEventCallbackAndRecording2) {
2341   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2342   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2343   TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("callback"),
2344                                                    Callback);
2345   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2346   TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2347   TraceLog::GetInstance()->SetEnabled(
2348       CategoryFilter("recording"),
2349       TraceLog::RECORDING_MODE,
2350       TraceOptions());
2351   TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2352   TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2353   EndTraceAndFlush();
2354   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2355   TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2356   TraceLog::GetInstance()->SetEventCallbackDisabled();
2357   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2358   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2359
2360   DropTracedMetadataRecords();
2361   VerifyCallbackAndRecordedEvents(3, 1);
2362 }
2363
2364 // 3: Enable recording, enable callback, disable callback, disable recording.
2365 TEST_F(TraceEventCallbackTest, TraceEventCallbackAndRecording3) {
2366   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2367   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2368   TraceLog::GetInstance()->SetEnabled(
2369       CategoryFilter("recording"),
2370       TraceLog::RECORDING_MODE,
2371       TraceOptions());
2372   TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2373   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2374   TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("callback"),
2375                                                    Callback);
2376   TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2377   TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2378   TraceLog::GetInstance()->SetEventCallbackDisabled();
2379   TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2380   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2381   EndTraceAndFlush();
2382   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2383   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2384
2385   DropTracedMetadataRecords();
2386   VerifyCallbackAndRecordedEvents(1, 3);
2387 }
2388
2389 // 4: Enable recording, enable callback, disable recording, disable callback.
2390 TEST_F(TraceEventCallbackTest, TraceEventCallbackAndRecording4) {
2391   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2392   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2393   TraceLog::GetInstance()->SetEnabled(
2394       CategoryFilter("recording"),
2395       TraceLog::RECORDING_MODE,
2396       TraceOptions());
2397   TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2398   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2399   TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("callback"),
2400                                                    Callback);
2401   TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2402   TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2403   EndTraceAndFlush();
2404   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2405   TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL);
2406   TraceLog::GetInstance()->SetEventCallbackDisabled();
2407   TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL);
2408   TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL);
2409
2410   DropTracedMetadataRecords();
2411   VerifyCallbackAndRecordedEvents(2, 2);
2412 }
2413
2414 TEST_F(TraceEventCallbackTest, TraceEventCallbackAndRecordingDuration) {
2415   TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("*"),
2416                                                    Callback);
2417   {
2418     TRACE_EVENT0("callback", "duration1");
2419     TraceLog::GetInstance()->SetEnabled(
2420         CategoryFilter("*"),
2421         TraceLog::RECORDING_MODE,
2422         TraceOptions());
2423     TRACE_EVENT0("callback", "duration2");
2424     EndTraceAndFlush();
2425     TRACE_EVENT0("callback", "duration3");
2426   }
2427   TraceLog::GetInstance()->SetEventCallbackDisabled();
2428
2429   ASSERT_EQ(6u, collected_events_names_.size());
2430   VerifyCollectedEvent(0, TRACE_EVENT_PHASE_BEGIN, "callback", "duration1");
2431   VerifyCollectedEvent(1, TRACE_EVENT_PHASE_BEGIN, "callback", "duration2");
2432   VerifyCollectedEvent(2, TRACE_EVENT_PHASE_BEGIN, "callback", "duration3");
2433   VerifyCollectedEvent(3, TRACE_EVENT_PHASE_END, "callback", "duration3");
2434   VerifyCollectedEvent(4, TRACE_EVENT_PHASE_END, "callback", "duration2");
2435   VerifyCollectedEvent(5, TRACE_EVENT_PHASE_END, "callback", "duration1");
2436 }
2437
2438 TEST_F(TraceEventTestFixture, TraceBufferVectorReportFull) {
2439   TraceLog* trace_log = TraceLog::GetInstance();
2440   trace_log->SetEnabled(CategoryFilter("*"),
2441                         TraceLog::RECORDING_MODE,
2442                         TraceOptions());
2443   trace_log->logged_events_.reset(
2444       trace_log->CreateTraceBufferVectorOfSize(100));
2445   do {
2446     TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0(
2447         "all", "with_timestamp", 0, 0,
2448         TimeTicks::NowFromSystemTraceTime().ToInternalValue());
2449     TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0(
2450         "all", "with_timestamp", 0, 0,
2451         TimeTicks::NowFromSystemTraceTime().ToInternalValue());
2452   } while (!trace_log->BufferIsFull());
2453
2454   EndTraceAndFlush();
2455
2456   const DictionaryValue* trace_full_metadata = NULL;
2457
2458   trace_full_metadata = FindTraceEntry(trace_parsed_,
2459                                        "overflowed_at_ts");
2460   std::string phase;
2461   double buffer_limit_reached_timestamp = 0;
2462
2463   EXPECT_TRUE(trace_full_metadata);
2464   EXPECT_TRUE(trace_full_metadata->GetString("ph", &phase));
2465   EXPECT_EQ("M", phase);
2466   EXPECT_TRUE(trace_full_metadata->GetDouble(
2467       "args.overflowed_at_ts", &buffer_limit_reached_timestamp));
2468   EXPECT_DOUBLE_EQ(
2469       static_cast<double>(
2470           trace_log->buffer_limit_reached_timestamp_.ToInternalValue()),
2471       buffer_limit_reached_timestamp);
2472
2473   // Test that buffer_limit_reached_timestamp's value is between the timestamp
2474   // of the last trace event and current time.
2475   DropTracedMetadataRecords();
2476   const DictionaryValue* last_trace_event = NULL;
2477   double last_trace_event_timestamp = 0;
2478   EXPECT_TRUE(trace_parsed_.GetDictionary(trace_parsed_.GetSize() - 1,
2479                                           &last_trace_event));
2480   EXPECT_TRUE(last_trace_event->GetDouble("ts", &last_trace_event_timestamp));
2481   EXPECT_LE(last_trace_event_timestamp, buffer_limit_reached_timestamp);
2482   EXPECT_LE(buffer_limit_reached_timestamp,
2483             trace_log->OffsetNow().ToInternalValue());
2484 }
2485
2486 TEST_F(TraceEventTestFixture, TraceBufferRingBufferGetReturnChunk) {
2487   TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
2488                                       TraceLog::RECORDING_MODE,
2489                                       TraceOptions(RECORD_CONTINUOUSLY));
2490   TraceBuffer* buffer = TraceLog::GetInstance()->trace_buffer();
2491   size_t capacity = buffer->Capacity();
2492   size_t num_chunks = capacity / TraceBufferChunk::kTraceBufferChunkSize;
2493   uint32 last_seq = 0;
2494   size_t chunk_index;
2495   EXPECT_EQ(0u, buffer->Size());
2496
2497   scoped_ptr<TraceBufferChunk*[]> chunks(new TraceBufferChunk*[num_chunks]);
2498   for (size_t i = 0; i < num_chunks; ++i) {
2499     chunks[i] = buffer->GetChunk(&chunk_index).release();
2500     EXPECT_TRUE(chunks[i]);
2501     EXPECT_EQ(i, chunk_index);
2502     EXPECT_GT(chunks[i]->seq(), last_seq);
2503     EXPECT_EQ((i + 1) * TraceBufferChunk::kTraceBufferChunkSize,
2504               buffer->Size());
2505     last_seq = chunks[i]->seq();
2506   }
2507
2508   // Ring buffer is never full.
2509   EXPECT_FALSE(buffer->IsFull());
2510
2511   // Return all chunks in original order.
2512   for (size_t i = 0; i < num_chunks; ++i)
2513     buffer->ReturnChunk(i, scoped_ptr<TraceBufferChunk>(chunks[i]));
2514
2515   // Should recycle the chunks in the returned order.
2516   for (size_t i = 0; i < num_chunks; ++i) {
2517     chunks[i] = buffer->GetChunk(&chunk_index).release();
2518     EXPECT_TRUE(chunks[i]);
2519     EXPECT_EQ(i, chunk_index);
2520     EXPECT_GT(chunks[i]->seq(), last_seq);
2521     last_seq = chunks[i]->seq();
2522   }
2523
2524   // Return all chunks in reverse order.
2525   for (size_t i = 0; i < num_chunks; ++i) {
2526     buffer->ReturnChunk(
2527         num_chunks - i - 1,
2528         scoped_ptr<TraceBufferChunk>(chunks[num_chunks - i - 1]));
2529   }
2530
2531   // Should recycle the chunks in the returned order.
2532   for (size_t i = 0; i < num_chunks; ++i) {
2533     chunks[i] = buffer->GetChunk(&chunk_index).release();
2534     EXPECT_TRUE(chunks[i]);
2535     EXPECT_EQ(num_chunks - i - 1, chunk_index);
2536     EXPECT_GT(chunks[i]->seq(), last_seq);
2537     last_seq = chunks[i]->seq();
2538   }
2539
2540   for (size_t i = 0; i < num_chunks; ++i)
2541     buffer->ReturnChunk(i, scoped_ptr<TraceBufferChunk>(chunks[i]));
2542
2543   TraceLog::GetInstance()->SetDisabled();
2544 }
2545
2546 TEST_F(TraceEventTestFixture, TraceBufferRingBufferHalfIteration) {
2547   TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
2548                                       TraceLog::RECORDING_MODE,
2549                                       TraceOptions(RECORD_CONTINUOUSLY));
2550   TraceBuffer* buffer = TraceLog::GetInstance()->trace_buffer();
2551   size_t capacity = buffer->Capacity();
2552   size_t num_chunks = capacity / TraceBufferChunk::kTraceBufferChunkSize;
2553   size_t chunk_index;
2554   EXPECT_EQ(0u, buffer->Size());
2555   EXPECT_FALSE(buffer->NextChunk());
2556
2557   size_t half_chunks = num_chunks / 2;
2558   scoped_ptr<TraceBufferChunk*[]> chunks(new TraceBufferChunk*[half_chunks]);
2559
2560   for (size_t i = 0; i < half_chunks; ++i) {
2561     chunks[i] = buffer->GetChunk(&chunk_index).release();
2562     EXPECT_TRUE(chunks[i]);
2563     EXPECT_EQ(i, chunk_index);
2564   }
2565   for (size_t i = 0; i < half_chunks; ++i)
2566     buffer->ReturnChunk(i, scoped_ptr<TraceBufferChunk>(chunks[i]));
2567
2568   for (size_t i = 0; i < half_chunks; ++i)
2569     EXPECT_EQ(chunks[i], buffer->NextChunk());
2570   EXPECT_FALSE(buffer->NextChunk());
2571   TraceLog::GetInstance()->SetDisabled();
2572 }
2573
2574 TEST_F(TraceEventTestFixture, TraceBufferRingBufferFullIteration) {
2575   TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
2576                                       TraceLog::RECORDING_MODE,
2577                                       TraceOptions(RECORD_CONTINUOUSLY));
2578   TraceBuffer* buffer = TraceLog::GetInstance()->trace_buffer();
2579   size_t capacity = buffer->Capacity();
2580   size_t num_chunks = capacity / TraceBufferChunk::kTraceBufferChunkSize;
2581   size_t chunk_index;
2582   EXPECT_EQ(0u, buffer->Size());
2583   EXPECT_FALSE(buffer->NextChunk());
2584
2585   scoped_ptr<TraceBufferChunk*[]> chunks(new TraceBufferChunk*[num_chunks]);
2586
2587   for (size_t i = 0; i < num_chunks; ++i) {
2588     chunks[i] = buffer->GetChunk(&chunk_index).release();
2589     EXPECT_TRUE(chunks[i]);
2590     EXPECT_EQ(i, chunk_index);
2591   }
2592   for (size_t i = 0; i < num_chunks; ++i)
2593     buffer->ReturnChunk(i, scoped_ptr<TraceBufferChunk>(chunks[i]));
2594
2595   for (size_t i = 0; i < num_chunks; ++i)
2596     EXPECT_TRUE(chunks[i] == buffer->NextChunk());
2597   EXPECT_FALSE(buffer->NextChunk());
2598   TraceLog::GetInstance()->SetDisabled();
2599 }
2600
2601 TEST_F(TraceEventTestFixture, TraceRecordAsMuchAsPossibleMode) {
2602   TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
2603                                       TraceLog::RECORDING_MODE,
2604                                       TraceOptions(RECORD_AS_MUCH_AS_POSSIBLE));
2605   TraceBuffer* buffer = TraceLog::GetInstance()->trace_buffer();
2606   EXPECT_EQ(512000000UL, buffer->Capacity());
2607   TraceLog::GetInstance()->SetDisabled();
2608 }
2609
2610 // Test the category filter.
2611 TEST_F(TraceEventTestFixture, CategoryFilter) {
2612   // Using the default filter.
2613   CategoryFilter default_cf = CategoryFilter(
2614       CategoryFilter::kDefaultCategoryFilterString);
2615   std::string category_filter_str = default_cf.ToString();
2616   EXPECT_STREQ("-*Debug,-*Test", category_filter_str.c_str());
2617   EXPECT_TRUE(default_cf.IsCategoryGroupEnabled("not-excluded-category"));
2618   EXPECT_FALSE(
2619       default_cf.IsCategoryGroupEnabled("disabled-by-default-category"));
2620   EXPECT_FALSE(default_cf.IsCategoryGroupEnabled("Category1,CategoryDebug"));
2621   EXPECT_FALSE(default_cf.IsCategoryGroupEnabled("CategoryDebug,Category1"));
2622   EXPECT_FALSE(default_cf.IsCategoryGroupEnabled("CategoryTest,Category2"));
2623
2624   // Make sure that upon an empty string, we fall back to the default filter.
2625   default_cf = CategoryFilter();
2626   category_filter_str = default_cf.ToString();
2627   EXPECT_STREQ("-*Debug,-*Test", category_filter_str.c_str());
2628   EXPECT_TRUE(default_cf.IsCategoryGroupEnabled("not-excluded-category"));
2629   EXPECT_FALSE(default_cf.IsCategoryGroupEnabled("Category1,CategoryDebug"));
2630   EXPECT_FALSE(default_cf.IsCategoryGroupEnabled("CategoryDebug,Category1"));
2631   EXPECT_FALSE(default_cf.IsCategoryGroupEnabled("CategoryTest,Category2"));
2632
2633   // Using an arbitrary non-empty filter.
2634   CategoryFilter cf("included,-excluded,inc_pattern*,-exc_pattern*");
2635   category_filter_str = cf.ToString();
2636   EXPECT_STREQ("included,inc_pattern*,-excluded,-exc_pattern*",
2637                category_filter_str.c_str());
2638   EXPECT_TRUE(cf.IsCategoryGroupEnabled("included"));
2639   EXPECT_TRUE(cf.IsCategoryGroupEnabled("inc_pattern_category"));
2640   EXPECT_FALSE(cf.IsCategoryGroupEnabled("exc_pattern_category"));
2641   EXPECT_FALSE(cf.IsCategoryGroupEnabled("excluded"));
2642   EXPECT_FALSE(cf.IsCategoryGroupEnabled("not-excluded-nor-included"));
2643   EXPECT_FALSE(cf.IsCategoryGroupEnabled("Category1,CategoryDebug"));
2644   EXPECT_FALSE(cf.IsCategoryGroupEnabled("CategoryDebug,Category1"));
2645   EXPECT_FALSE(cf.IsCategoryGroupEnabled("CategoryTest,Category2"));
2646
2647   cf.Merge(default_cf);
2648   category_filter_str = cf.ToString();
2649   EXPECT_STREQ("-excluded,-exc_pattern*,-*Debug,-*Test",
2650                 category_filter_str.c_str());
2651   cf.Clear();
2652
2653   CategoryFilter reconstructed_cf(category_filter_str);
2654   category_filter_str = reconstructed_cf.ToString();
2655   EXPECT_STREQ("-excluded,-exc_pattern*,-*Debug,-*Test",
2656                category_filter_str.c_str());
2657
2658   // One included category.
2659   CategoryFilter one_inc_cf("only_inc_cat");
2660   category_filter_str = one_inc_cf.ToString();
2661   EXPECT_STREQ("only_inc_cat", category_filter_str.c_str());
2662
2663   // One excluded category.
2664   CategoryFilter one_exc_cf("-only_exc_cat");
2665   category_filter_str = one_exc_cf.ToString();
2666   EXPECT_STREQ("-only_exc_cat", category_filter_str.c_str());
2667
2668   // Enabling a disabled- category does not require all categories to be traced
2669   // to be included.
2670   CategoryFilter disabled_cat("disabled-by-default-cc,-excluded");
2671   EXPECT_STREQ("disabled-by-default-cc,-excluded",
2672                disabled_cat.ToString().c_str());
2673   EXPECT_TRUE(disabled_cat.IsCategoryGroupEnabled("disabled-by-default-cc"));
2674   EXPECT_TRUE(disabled_cat.IsCategoryGroupEnabled("some_other_group"));
2675   EXPECT_FALSE(disabled_cat.IsCategoryGroupEnabled("excluded"));
2676
2677   // Enabled a disabled- category and also including makes all categories to
2678   // be traced require including.
2679   CategoryFilter disabled_inc_cat("disabled-by-default-cc,included");
2680   EXPECT_STREQ("included,disabled-by-default-cc",
2681                disabled_inc_cat.ToString().c_str());
2682   EXPECT_TRUE(
2683       disabled_inc_cat.IsCategoryGroupEnabled("disabled-by-default-cc"));
2684   EXPECT_TRUE(disabled_inc_cat.IsCategoryGroupEnabled("included"));
2685   EXPECT_FALSE(disabled_inc_cat.IsCategoryGroupEnabled("other_included"));
2686
2687   // Test that IsEmptyOrContainsLeadingOrTrailingWhitespace actually catches
2688   // categories that are explicitly forbiden.
2689   // This method is called in a DCHECK to assert that we don't have these types
2690   // of strings as categories.
2691   EXPECT_TRUE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2692       " bad_category "));
2693   EXPECT_TRUE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2694       " bad_category"));
2695   EXPECT_TRUE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2696       "bad_category "));
2697   EXPECT_TRUE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2698       "   bad_category"));
2699   EXPECT_TRUE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2700       "bad_category   "));
2701   EXPECT_TRUE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2702       "   bad_category   "));
2703   EXPECT_TRUE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2704       ""));
2705   EXPECT_FALSE(CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2706       "good_category"));
2707 }
2708
2709 void BlockUntilStopped(WaitableEvent* task_start_event,
2710                        WaitableEvent* task_stop_event) {
2711   task_start_event->Signal();
2712   task_stop_event->Wait();
2713 }
2714
2715 TEST_F(TraceEventTestFixture, SetCurrentThreadBlocksMessageLoopBeforeTracing) {
2716   BeginTrace();
2717
2718   Thread thread("1");
2719   WaitableEvent task_complete_event(false, false);
2720   thread.Start();
2721   thread.message_loop()->PostTask(
2722       FROM_HERE, Bind(&TraceLog::SetCurrentThreadBlocksMessageLoop,
2723                       Unretained(TraceLog::GetInstance())));
2724
2725   thread.message_loop()->PostTask(
2726       FROM_HERE, Bind(&TraceWithAllMacroVariants, &task_complete_event));
2727   task_complete_event.Wait();
2728
2729   WaitableEvent task_start_event(false, false);
2730   WaitableEvent task_stop_event(false, false);
2731   thread.message_loop()->PostTask(
2732       FROM_HERE, Bind(&BlockUntilStopped, &task_start_event, &task_stop_event));
2733   task_start_event.Wait();
2734
2735   EndTraceAndFlush();
2736   ValidateAllTraceMacrosCreatedData(trace_parsed_);
2737
2738   task_stop_event.Signal();
2739   thread.Stop();
2740 }
2741
2742 TEST_F(TraceEventTestFixture, ConvertTraceOptionsToInternalOptions) {
2743   TraceLog* trace_log = TraceLog::GetInstance();
2744   TraceOptions options(RECORD_UNTIL_FULL);
2745   EXPECT_EQ(TraceLog::kInternalRecordUntilFull,
2746             trace_log->GetInternalOptionsFromTraceOptions(options));
2747
2748   options.record_mode = RECORD_CONTINUOUSLY;
2749   EXPECT_EQ(TraceLog::kInternalRecordContinuously,
2750             trace_log->GetInternalOptionsFromTraceOptions(options));
2751
2752   options.record_mode = ECHO_TO_CONSOLE;
2753   EXPECT_EQ(TraceLog::kInternalEchoToConsole,
2754             trace_log->GetInternalOptionsFromTraceOptions(options));
2755
2756   options.enable_sampling = true;
2757
2758   options.record_mode = RECORD_UNTIL_FULL;
2759   EXPECT_EQ(
2760       TraceLog::kInternalRecordUntilFull | TraceLog::kInternalEnableSampling,
2761       trace_log->GetInternalOptionsFromTraceOptions(options));
2762
2763   options.record_mode = RECORD_CONTINUOUSLY;
2764   EXPECT_EQ(
2765       TraceLog::kInternalRecordContinuously | TraceLog::kInternalEnableSampling,
2766       trace_log->GetInternalOptionsFromTraceOptions(options));
2767
2768   options.record_mode = ECHO_TO_CONSOLE;
2769   EXPECT_EQ(
2770       TraceLog::kInternalEchoToConsole | TraceLog::kInternalEnableSampling,
2771       trace_log->GetInternalOptionsFromTraceOptions(options));
2772
2773   options.enable_systrace = true;
2774   EXPECT_EQ(
2775       TraceLog::kInternalEchoToConsole | TraceLog::kInternalEnableSampling,
2776       trace_log->GetInternalOptionsFromTraceOptions(options));
2777 }
2778
2779 void SetBlockingFlagAndBlockUntilStopped(WaitableEvent* task_start_event,
2780                                          WaitableEvent* task_stop_event) {
2781   TraceLog::GetInstance()->SetCurrentThreadBlocksMessageLoop();
2782   BlockUntilStopped(task_start_event, task_stop_event);
2783 }
2784
2785 TEST_F(TraceEventTestFixture, SetCurrentThreadBlocksMessageLoopAfterTracing) {
2786   BeginTrace();
2787
2788   Thread thread("1");
2789   WaitableEvent task_complete_event(false, false);
2790   thread.Start();
2791
2792   thread.message_loop()->PostTask(
2793       FROM_HERE, Bind(&TraceWithAllMacroVariants, &task_complete_event));
2794   task_complete_event.Wait();
2795
2796   WaitableEvent task_start_event(false, false);
2797   WaitableEvent task_stop_event(false, false);
2798   thread.message_loop()->PostTask(
2799       FROM_HERE, Bind(&SetBlockingFlagAndBlockUntilStopped,
2800                       &task_start_event, &task_stop_event));
2801   task_start_event.Wait();
2802
2803   EndTraceAndFlush();
2804   ValidateAllTraceMacrosCreatedData(trace_parsed_);
2805
2806   task_stop_event.Signal();
2807   thread.Stop();
2808 }
2809
2810 TEST_F(TraceEventTestFixture, ThreadOnceBlocking) {
2811   BeginTrace();
2812
2813   Thread thread("1");
2814   WaitableEvent task_complete_event(false, false);
2815   thread.Start();
2816
2817   thread.message_loop()->PostTask(
2818       FROM_HERE, Bind(&TraceWithAllMacroVariants, &task_complete_event));
2819   task_complete_event.Wait();
2820   task_complete_event.Reset();
2821
2822   WaitableEvent task_start_event(false, false);
2823   WaitableEvent task_stop_event(false, false);
2824   thread.message_loop()->PostTask(
2825       FROM_HERE, Bind(&BlockUntilStopped, &task_start_event, &task_stop_event));
2826   task_start_event.Wait();
2827
2828   // The thread will timeout in this flush.
2829   EndTraceAndFlushInThreadWithMessageLoop();
2830   Clear();
2831
2832   // Let the thread's message loop continue to spin.
2833   task_stop_event.Signal();
2834
2835   // The following sequence ensures that the FlushCurrentThread task has been
2836   // executed in the thread before continuing.
2837   task_start_event.Reset();
2838   task_stop_event.Reset();
2839   thread.message_loop()->PostTask(
2840       FROM_HERE, Bind(&BlockUntilStopped, &task_start_event, &task_stop_event));
2841   task_start_event.Wait();
2842   task_stop_event.Signal();
2843   Clear();
2844
2845   // TraceLog should discover the generation mismatch and recover the thread
2846   // local buffer for the thread without any error.
2847   BeginTrace();
2848   thread.message_loop()->PostTask(
2849       FROM_HERE, Bind(&TraceWithAllMacroVariants, &task_complete_event));
2850   task_complete_event.Wait();
2851   task_complete_event.Reset();
2852   EndTraceAndFlushInThreadWithMessageLoop();
2853   ValidateAllTraceMacrosCreatedData(trace_parsed_);
2854 }
2855
2856 std::string* g_log_buffer = NULL;
2857 bool MockLogMessageHandler(int, const char*, int, size_t,
2858                            const std::string& str) {
2859   if (!g_log_buffer)
2860     g_log_buffer = new std::string();
2861   g_log_buffer->append(str);
2862   return false;
2863 }
2864
2865 TEST_F(TraceEventTestFixture, EchoToConsole) {
2866   logging::LogMessageHandlerFunction old_log_message_handler =
2867       logging::GetLogMessageHandler();
2868   logging::SetLogMessageHandler(MockLogMessageHandler);
2869
2870   TraceLog::GetInstance()->SetEnabled(
2871       CategoryFilter("*"),
2872       TraceLog::RECORDING_MODE,
2873       TraceOptions(ECHO_TO_CONSOLE));
2874   TRACE_EVENT_BEGIN0("a", "begin_end");
2875   {
2876     TRACE_EVENT0("b", "duration");
2877     TRACE_EVENT0("b1", "duration1");
2878   }
2879   TRACE_EVENT_INSTANT0("c", "instant", TRACE_EVENT_SCOPE_GLOBAL);
2880   TRACE_EVENT_END0("a", "begin_end");
2881
2882   EXPECT_NE(std::string::npos, g_log_buffer->find("begin_end[a]\x1b"));
2883   EXPECT_NE(std::string::npos, g_log_buffer->find("| duration[b]\x1b"));
2884   EXPECT_NE(std::string::npos, g_log_buffer->find("| | duration1[b1]\x1b"));
2885   EXPECT_NE(std::string::npos, g_log_buffer->find("| | duration1[b1] ("));
2886   EXPECT_NE(std::string::npos, g_log_buffer->find("| duration[b] ("));
2887   EXPECT_NE(std::string::npos, g_log_buffer->find("| instant[c]\x1b"));
2888   EXPECT_NE(std::string::npos, g_log_buffer->find("begin_end[a] ("));
2889
2890   EndTraceAndFlush();
2891   delete g_log_buffer;
2892   logging::SetLogMessageHandler(old_log_message_handler);
2893   g_log_buffer = NULL;
2894 }
2895
2896 bool LogMessageHandlerWithTraceEvent(int, const char*, int, size_t,
2897                                      const std::string&) {
2898   TRACE_EVENT0("log", "trace_event");
2899   return false;
2900 }
2901
2902 TEST_F(TraceEventTestFixture, EchoToConsoleTraceEventRecursion) {
2903   logging::LogMessageHandlerFunction old_log_message_handler =
2904       logging::GetLogMessageHandler();
2905   logging::SetLogMessageHandler(LogMessageHandlerWithTraceEvent);
2906
2907   TraceLog::GetInstance()->SetEnabled(
2908       CategoryFilter("*"),
2909       TraceLog::RECORDING_MODE,
2910       TraceOptions(ECHO_TO_CONSOLE));
2911   {
2912     // This should not cause deadlock or infinite recursion.
2913     TRACE_EVENT0("b", "duration");
2914   }
2915
2916   EndTraceAndFlush();
2917   logging::SetLogMessageHandler(old_log_message_handler);
2918 }
2919
2920 TEST_F(TraceEventTestFixture, TimeOffset) {
2921   BeginTrace();
2922   // Let TraceLog timer start from 0.
2923   TimeDelta time_offset = TimeTicks::NowFromSystemTraceTime() - TimeTicks();
2924   TraceLog::GetInstance()->SetTimeOffset(time_offset);
2925
2926   {
2927     TRACE_EVENT0("all", "duration1");
2928     TRACE_EVENT0("all", "duration2");
2929   }
2930   TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0(
2931       "all", "with_timestamp", 0, 0,
2932       TimeTicks::NowFromSystemTraceTime().ToInternalValue());
2933   TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0(
2934       "all", "with_timestamp", 0, 0,
2935       TimeTicks::NowFromSystemTraceTime().ToInternalValue());
2936
2937   EndTraceAndFlush();
2938   DropTracedMetadataRecords();
2939
2940   double end_time = static_cast<double>(
2941       (TimeTicks::NowFromSystemTraceTime() - time_offset).ToInternalValue());
2942   double last_timestamp = 0;
2943   for (size_t i = 0; i < trace_parsed_.GetSize(); ++i) {
2944     const DictionaryValue* item;
2945     EXPECT_TRUE(trace_parsed_.GetDictionary(i, &item));
2946     double timestamp;
2947     EXPECT_TRUE(item->GetDouble("ts", &timestamp));
2948     EXPECT_GE(timestamp, last_timestamp);
2949     EXPECT_LE(timestamp, end_time);
2950     last_timestamp = timestamp;
2951   }
2952 }
2953
2954 TEST_F(TraceEventTestFixture, ConfigureSyntheticDelays) {
2955   BeginSpecificTrace("DELAY(test.Delay;0.05)");
2956
2957   base::TimeTicks start = base::TimeTicks::Now();
2958   {
2959     TRACE_EVENT_SYNTHETIC_DELAY("test.Delay");
2960   }
2961   base::TimeDelta duration = base::TimeTicks::Now() - start;
2962   EXPECT_GE(duration.InMilliseconds(), 50);
2963
2964   EndTraceAndFlush();
2965 }
2966
2967 TEST_F(TraceEventTestFixture, BadSyntheticDelayConfigurations) {
2968   const char* const configs[] = {
2969     "",
2970     "DELAY(",
2971     "DELAY(;",
2972     "DELAY(;)",
2973     "DELAY(test.Delay)",
2974     "DELAY(test.Delay;)"
2975   };
2976   for (size_t i = 0; i < arraysize(configs); i++) {
2977     BeginSpecificTrace(configs[i]);
2978     EndTraceAndFlush();
2979     CategoryFilter filter = TraceLog::GetInstance()->GetCurrentCategoryFilter();
2980     EXPECT_EQ(0u, filter.GetSyntheticDelayValues().size());
2981   }
2982 }
2983
2984 TEST_F(TraceEventTestFixture, SyntheticDelayConfigurationMerging) {
2985   CategoryFilter filter1("DELAY(test.Delay1;16)");
2986   CategoryFilter filter2("DELAY(test.Delay2;32)");
2987   filter1.Merge(filter2);
2988   EXPECT_EQ(2u, filter1.GetSyntheticDelayValues().size());
2989 }
2990
2991 TEST_F(TraceEventTestFixture, SyntheticDelayConfigurationToString) {
2992   const char config[] = "DELAY(test.Delay;16;oneshot)";
2993   CategoryFilter filter(config);
2994   EXPECT_EQ(config, filter.ToString());
2995 }
2996
2997 TEST(TraceOptionsTest, TraceOptionsFromString) {
2998   TraceOptions options;
2999   EXPECT_TRUE(options.SetFromString("record-until-full"));
3000   EXPECT_EQ(RECORD_UNTIL_FULL, options.record_mode);
3001   EXPECT_FALSE(options.enable_sampling);
3002   EXPECT_FALSE(options.enable_systrace);
3003
3004   EXPECT_TRUE(options.SetFromString("record-continuously"));
3005   EXPECT_EQ(RECORD_CONTINUOUSLY, options.record_mode);
3006   EXPECT_FALSE(options.enable_sampling);
3007   EXPECT_FALSE(options.enable_systrace);
3008
3009   EXPECT_TRUE(options.SetFromString("trace-to-console"));
3010   EXPECT_EQ(ECHO_TO_CONSOLE, options.record_mode);
3011   EXPECT_FALSE(options.enable_sampling);
3012   EXPECT_FALSE(options.enable_systrace);
3013
3014   EXPECT_TRUE(options.SetFromString("record-as-much-as-possible"));
3015   EXPECT_EQ(RECORD_AS_MUCH_AS_POSSIBLE, options.record_mode);
3016   EXPECT_FALSE(options.enable_sampling);
3017   EXPECT_FALSE(options.enable_systrace);
3018
3019   EXPECT_TRUE(options.SetFromString("record-until-full, enable-sampling"));
3020   EXPECT_EQ(RECORD_UNTIL_FULL, options.record_mode);
3021   EXPECT_TRUE(options.enable_sampling);
3022   EXPECT_FALSE(options.enable_systrace);
3023
3024   EXPECT_TRUE(options.SetFromString("enable-systrace,record-continuously"));
3025   EXPECT_EQ(RECORD_CONTINUOUSLY, options.record_mode);
3026   EXPECT_FALSE(options.enable_sampling);
3027   EXPECT_TRUE(options.enable_systrace);
3028
3029   EXPECT_TRUE(options.SetFromString(
3030       "enable-systrace, trace-to-console,enable-sampling"));
3031   EXPECT_EQ(ECHO_TO_CONSOLE, options.record_mode);
3032   EXPECT_TRUE(options.enable_sampling);
3033   EXPECT_TRUE(options.enable_systrace);
3034
3035   EXPECT_TRUE(options.SetFromString(
3036       "record-continuously,record-until-full,trace-to-console"));
3037   EXPECT_EQ(ECHO_TO_CONSOLE, options.record_mode);
3038   EXPECT_FALSE(options.enable_systrace);
3039   EXPECT_FALSE(options.enable_sampling);
3040
3041   EXPECT_TRUE(options.SetFromString(""));
3042   EXPECT_EQ(RECORD_UNTIL_FULL, options.record_mode);
3043   EXPECT_FALSE(options.enable_systrace);
3044   EXPECT_FALSE(options.enable_sampling);
3045
3046   EXPECT_FALSE(options.SetFromString("foo-bar-baz"));
3047 }
3048
3049 TEST(TraceOptionsTest, TraceOptionsToString) {
3050   // Test that we can intialize TraceOptions from a string got from
3051   // TraceOptions.ToString() method to get a same TraceOptions.
3052   TraceRecordMode modes[] = {RECORD_UNTIL_FULL,
3053                              RECORD_CONTINUOUSLY,
3054                              ECHO_TO_CONSOLE,
3055                              RECORD_AS_MUCH_AS_POSSIBLE};
3056   bool enable_sampling_options[] = {true, false};
3057   bool enable_systrace_options[] = {true, false};
3058
3059   for (int i = 0; i < 4; ++i) {
3060     for (int j = 0; j < 2; ++j) {
3061       for (int k = 0; k < 2; ++k) {
3062         TraceOptions original_option = TraceOptions(modes[i]);
3063         original_option.enable_sampling = enable_sampling_options[j];
3064         original_option.enable_systrace = enable_systrace_options[k];
3065         TraceOptions new_options;
3066         EXPECT_TRUE(new_options.SetFromString(original_option.ToString()));
3067         EXPECT_EQ(original_option.record_mode, new_options.record_mode);
3068         EXPECT_EQ(original_option.enable_sampling, new_options.enable_sampling);
3069         EXPECT_EQ(original_option.enable_systrace, new_options.enable_systrace);
3070       }
3071     }
3072   }
3073 }
3074
3075
3076 }  // namespace debug
3077 }  // namespace base