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