src/base/debug/trace_event_unittest.cc

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