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