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