base/trace_event/trace_log.cc

   1 // Copyright 2015 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/trace_event/trace_log.h"
   6
   7 #include <algorithm>
   8 #include <cmath>
   9
  10 #include "base/base_switches.h"
  11 #include "base/bind.h"
  12 #include "base/command_line.h"
  13 #include "base/debug/leak_annotations.h"
  14 #include "base/lazy_instance.h"
  15 #include "base/location.h"
  16 #include "base/memory/singleton.h"
  17 #include "base/process/process_metrics.h"
  18 #include "base/strings/string_split.h"
  19 #include "base/strings/string_tokenizer.h"
  20 #include "base/strings/stringprintf.h"
  21 #include "base/sys_info.h"
  22 #include "base/third_party/dynamic_annotations/dynamic_annotations.h"
  23 #include "base/thread_task_runner_handle.h"
  24 #include "base/threading/platform_thread.h"
  25 #include "base/threading/thread_id_name_manager.h"
  26 #include "base/threading/worker_pool.h"
  27 #include "base/time/time.h"
  28 #include "base/trace_event/memory_dump_manager.h"
  29 #include "base/trace_event/memory_dump_provider.h"
  30 #include "base/trace_event/process_memory_dump.h"
  31 #include "base/trace_event/trace_buffer.h"
  32 #include "base/trace_event/trace_event.h"
  33 #include "base/trace_event/trace_event_synthetic_delay.h"
  34 #include "base/trace_event/trace_log.h"
  35 #include "base/trace_event/trace_sampling_thread.h"
  36
  37 #if defined(OS_WIN)
  38 #include "base/trace_event/trace_event_etw_export_win.h"
  39 #include "base/trace_event/trace_event_win.h"
  40 #endif
  41
  42 // The thread buckets for the sampling profiler.
  43 BASE_EXPORT TRACE_EVENT_API_ATOMIC_WORD g_trace_state[3];
  44
  45 namespace base {
  46 namespace internal {
  47
  48 class DeleteTraceLogForTesting {
  49  public:
  50   static void Delete() {
  51     Singleton<trace_event::TraceLog,
  52               LeakySingletonTraits<trace_event::TraceLog>>::OnExit(0);
  53   }
  54 };
  55
  56 }  // namespace internal
  57
  58 namespace trace_event {
  59
  60 namespace {
  61
  62 // Controls the number of trace events we will buffer in-memory
  63 // before throwing them away.
  64 const size_t kTraceBufferChunkSize = TraceBufferChunk::kTraceBufferChunkSize;
  65
  66 const size_t kTraceEventVectorBigBufferChunks =
  67     512000000 / kTraceBufferChunkSize;
  68 static_assert(
  69     kTraceEventVectorBigBufferChunks <= TraceBufferChunk::kMaxChunkIndex,
  70     "Too many big buffer chunks");
  71 const size_t kTraceEventVectorBufferChunks = 256000 / kTraceBufferChunkSize;
  72 static_assert(
  73     kTraceEventVectorBufferChunks <= TraceBufferChunk::kMaxChunkIndex,
  74     "Too many vector buffer chunks");
  75 const size_t kTraceEventRingBufferChunks = kTraceEventVectorBufferChunks / 4;
  76
  77 // Can store results for 30 seconds with 1 ms sampling interval.
  78 const size_t kMonitorTraceEventBufferChunks = 30000 / kTraceBufferChunkSize;
  79 // ECHO_TO_CONSOLE needs a small buffer to hold the unfinished COMPLETE events.
  80 const size_t kEchoToConsoleTraceEventBufferChunks = 256;
  81
  82 // The overhead of TraceEvent above this threshold will be reported in the
  83 // trace.
  84 const int kOverheadReportThresholdInMicroseconds = 50;
  85 const size_t kTraceEventBufferSizeInBytes = 100 * 1024;
  86 const int kThreadFlushTimeoutMs = 3000;
  87
  88 #if !defined(OS_NACL)
  89 // These categories will cause deadlock when ECHO_TO_CONSOLE. crbug.com/325575.
  90 const char kEchoToConsoleCategoryFilter[] = "-ipc,-task";
  91 #endif
  92
  93 #define MAX_CATEGORY_GROUPS 100
  94
  95 // Parallel arrays g_category_groups and g_category_group_enabled are separate
  96 // so that a pointer to a member of g_category_group_enabled can be easily
  97 // converted to an index into g_category_groups. This allows macros to deal
  98 // only with char enabled pointers from g_category_group_enabled, and we can
  99 // convert internally to determine the category name from the char enabled
 100 // pointer.
 101 const char* g_category_groups[MAX_CATEGORY_GROUPS] = {
 102     "toplevel",
 103     "tracing already shutdown",
 104     "tracing categories exhausted; must increase MAX_CATEGORY_GROUPS",
 105     "__metadata",
 106     // For reporting trace_event overhead. For thread local event buffers only.
 107     "trace_event_overhead"};
 108
 109 // The enabled flag is char instead of bool so that the API can be used from C.
 110 unsigned char g_category_group_enabled[MAX_CATEGORY_GROUPS] = {0};
 111 // Indexes here have to match the g_category_groups array indexes above.
 112 const int g_category_already_shutdown = 1;
 113 const int g_category_categories_exhausted = 2;
 114 const int g_category_metadata = 3;
 115 const int g_category_trace_event_overhead = 4;
 116 const int g_num_builtin_categories = 5;
 117 // Skip default categories.
 118 base::subtle::AtomicWord g_category_index = g_num_builtin_categories;
 119
 120 // The name of the current thread. This is used to decide if the current
 121 // thread name has changed. We combine all the seen thread names into the
 122 // output name for the thread.
 123 LazyInstance<ThreadLocalPointer<const char>>::Leaky g_current_thread_name =
 124     LAZY_INSTANCE_INITIALIZER;
 125
 126 ThreadTicks ThreadNow() {
 127   return ThreadTicks::IsSupported() ? ThreadTicks::Now() : ThreadTicks();
 128 }
 129
 130 template <typename T>
 131 void InitializeMetadataEvent(TraceEvent* trace_event,
 132                              int thread_id,
 133                              const char* metadata_name,
 134                              const char* arg_name,
 135                              const T& value) {
 136   if (!trace_event)
 137     return;
 138
 139   int num_args = 1;
 140   unsigned char arg_type;
 141   unsigned long long arg_value;
 142   ::trace_event_internal::SetTraceValue(value, &arg_type, &arg_value);
 143   trace_event->Initialize(
 144       thread_id,
 145       TraceTicks(),
 146       ThreadTicks(),
 147       TRACE_EVENT_PHASE_METADATA,
 148       &g_category_group_enabled[g_category_metadata],
 149       metadata_name,
 150       trace_event_internal::kNoId,  // id
 151       trace_event_internal::kNoId,  // context_id
 152       trace_event_internal::kNoId,  // bind_id
 153       num_args,
 154       &arg_name,
 155       &arg_type,
 156       &arg_value,
 157       nullptr,
 158       TRACE_EVENT_FLAG_NONE);
 159 }
 160
 161 class AutoThreadLocalBoolean {
 162  public:
 163   explicit AutoThreadLocalBoolean(ThreadLocalBoolean* thread_local_boolean)
 164       : thread_local_boolean_(thread_local_boolean) {
 165     DCHECK(!thread_local_boolean_->Get());
 166     thread_local_boolean_->Set(true);
 167   }
 168   ~AutoThreadLocalBoolean() { thread_local_boolean_->Set(false); }
 169
 170  private:
 171   ThreadLocalBoolean* thread_local_boolean_;
 172   DISALLOW_COPY_AND_ASSIGN(AutoThreadLocalBoolean);
 173 };
 174
 175 // Use this function instead of TraceEventHandle constructor to keep the
 176 // overhead of ScopedTracer (trace_event.h) constructor minimum.
 177 void MakeHandle(uint32 chunk_seq,
 178                 size_t chunk_index,
 179                 size_t event_index,
 180                 TraceEventHandle* handle) {
 181   DCHECK(chunk_seq);
 182   DCHECK(chunk_index <= TraceBufferChunk::kMaxChunkIndex);
 183   DCHECK(event_index < TraceBufferChunk::kTraceBufferChunkSize);
 184   handle->chunk_seq = chunk_seq;
 185   handle->chunk_index = static_cast<uint16>(chunk_index);
 186   handle->event_index = static_cast<uint16>(event_index);
 187 }
 188
 189 }  // namespace
 190
 191 // A helper class that allows the lock to be acquired in the middle of the scope
 192 // and unlocks at the end of scope if locked.
 193 class TraceLog::OptionalAutoLock {
 194  public:
 195   explicit OptionalAutoLock(Lock* lock) : lock_(lock), locked_(false) {}
 196
 197   ~OptionalAutoLock() {
 198     if (locked_)
 199       lock_->Release();
 200   }
 201
 202   void EnsureAcquired() {
 203     if (!locked_) {
 204       lock_->Acquire();
 205       locked_ = true;
 206     }
 207   }
 208
 209  private:
 210   Lock* lock_;
 211   bool locked_;
 212   DISALLOW_COPY_AND_ASSIGN(OptionalAutoLock);
 213 };
 214
 215 class TraceLog::ThreadLocalEventBuffer
 216     : public MessageLoop::DestructionObserver,
 217       public MemoryDumpProvider {
 218  public:
 219   ThreadLocalEventBuffer(TraceLog* trace_log);
 220   ~ThreadLocalEventBuffer() override;
 221
 222   TraceEvent* AddTraceEvent(TraceEventHandle* handle);
 223
 224   void ReportOverhead(const TraceTicks& event_timestamp,
 225                       const ThreadTicks& event_thread_timestamp);
 226
 227   TraceEvent* GetEventByHandle(TraceEventHandle handle) {
 228     if (!chunk_ || handle.chunk_seq != chunk_->seq() ||
 229         handle.chunk_index != chunk_index_)
 230       return NULL;
 231
 232     return chunk_->GetEventAt(handle.event_index);
 233   }
 234
 235   int generation() const { return generation_; }
 236
 237  private:
 238   // MessageLoop::DestructionObserver
 239   void WillDestroyCurrentMessageLoop() override;
 240
 241   // MemoryDumpProvider implementation.
 242   bool OnMemoryDump(const MemoryDumpArgs& args,
 243                     ProcessMemoryDump* pmd) override;
 244
 245   void FlushWhileLocked();
 246
 247   void CheckThisIsCurrentBuffer() const {
 248     DCHECK(trace_log_->thread_local_event_buffer_.Get() == this);
 249   }
 250
 251   // Since TraceLog is a leaky singleton, trace_log_ will always be valid
 252   // as long as the thread exists.
 253   TraceLog* trace_log_;
 254   scoped_ptr<TraceBufferChunk> chunk_;
 255   size_t chunk_index_;
 256   int event_count_;
 257   TimeDelta overhead_;
 258   int generation_;
 259
 260   DISALLOW_COPY_AND_ASSIGN(ThreadLocalEventBuffer);
 261 };
 262
 263 TraceLog::ThreadLocalEventBuffer::ThreadLocalEventBuffer(TraceLog* trace_log)
 264     : trace_log_(trace_log),
 265       chunk_index_(0),
 266       event_count_(0),
 267       generation_(trace_log->generation()) {
 268   // ThreadLocalEventBuffer is created only if the thread has a message loop, so
 269   // the following message_loop won't be NULL.
 270   MessageLoop* message_loop = MessageLoop::current();
 271   message_loop->AddDestructionObserver(this);
 272
 273   // This is to report the local memory usage when memory-infra is enabled.
 274   MemoryDumpManager::GetInstance()->RegisterDumpProvider(
 275       this, ThreadTaskRunnerHandle::Get());
 276
 277   AutoLock lock(trace_log->lock_);
 278   trace_log->thread_message_loops_.insert(message_loop);
 279 }
 280
 281 TraceLog::ThreadLocalEventBuffer::~ThreadLocalEventBuffer() {
 282   CheckThisIsCurrentBuffer();
 283   MessageLoop::current()->RemoveDestructionObserver(this);
 284   MemoryDumpManager::GetInstance()->UnregisterDumpProvider(this);
 285
 286   // Zero event_count_ happens in either of the following cases:
 287   // - no event generated for the thread;
 288   // - the thread has no message loop;
 289   // - trace_event_overhead is disabled.
 290   if (event_count_) {
 291     InitializeMetadataEvent(AddTraceEvent(NULL),
 292                             static_cast<int>(base::PlatformThread::CurrentId()),
 293                             "overhead", "average_overhead",
 294                             overhead_.InMillisecondsF() / event_count_);
 295   }
 296
 297   {
 298     AutoLock lock(trace_log_->lock_);
 299     FlushWhileLocked();
 300     trace_log_->thread_message_loops_.erase(MessageLoop::current());
 301   }
 302   trace_log_->thread_local_event_buffer_.Set(NULL);
 303 }
 304
 305 TraceEvent* TraceLog::ThreadLocalEventBuffer::AddTraceEvent(
 306     TraceEventHandle* handle) {
 307   CheckThisIsCurrentBuffer();
 308
 309   if (chunk_ && chunk_->IsFull()) {
 310     AutoLock lock(trace_log_->lock_);
 311     FlushWhileLocked();
 312     chunk_.reset();
 313   }
 314   if (!chunk_) {
 315     AutoLock lock(trace_log_->lock_);
 316     chunk_ = trace_log_->logged_events_->GetChunk(&chunk_index_);
 317     trace_log_->CheckIfBufferIsFullWhileLocked();
 318   }
 319   if (!chunk_)
 320     return NULL;
 321
 322   size_t event_index;
 323   TraceEvent* trace_event = chunk_->AddTraceEvent(&event_index);
 324   if (trace_event && handle)
 325     MakeHandle(chunk_->seq(), chunk_index_, event_index, handle);
 326
 327   return trace_event;
 328 }
 329
 330 void TraceLog::ThreadLocalEventBuffer::ReportOverhead(
 331     const TraceTicks& event_timestamp,
 332     const ThreadTicks& event_thread_timestamp) {
 333   if (!g_category_group_enabled[g_category_trace_event_overhead])
 334     return;
 335
 336   CheckThisIsCurrentBuffer();
 337
 338   event_count_++;
 339   ThreadTicks thread_now = ThreadNow();
 340   TraceTicks now = trace_log_->OffsetNow();
 341   TimeDelta overhead = now - event_timestamp;
 342   if (overhead.InMicroseconds() >= kOverheadReportThresholdInMicroseconds) {
 343     TraceEvent* trace_event = AddTraceEvent(NULL);
 344     if (trace_event) {
 345       trace_event->Initialize(
 346           static_cast<int>(PlatformThread::CurrentId()),
 347           event_timestamp,
 348           event_thread_timestamp,
 349           TRACE_EVENT_PHASE_COMPLETE,
 350           &g_category_group_enabled[g_category_trace_event_overhead],
 351           "overhead",
 352           trace_event_internal::kNoId,  // id
 353           trace_event_internal::kNoId,  // context_id
 354           trace_event_internal::kNoId,  // bind_id
 355           ::trace_event_internal::kZeroNumArgs,
 356           nullptr,
 357           nullptr,
 358           nullptr,
 359           nullptr,
 360           TRACE_EVENT_FLAG_NONE);
 361       trace_event->UpdateDuration(now, thread_now);
 362     }
 363   }
 364   overhead_ += overhead;
 365 }
 366
 367 void TraceLog::ThreadLocalEventBuffer::WillDestroyCurrentMessageLoop() {
 368   delete this;
 369 }
 370
 371 bool TraceLog::ThreadLocalEventBuffer::OnMemoryDump(const MemoryDumpArgs& args,
 372                                                     ProcessMemoryDump* pmd) {
 373   if (!chunk_)
 374     return true;
 375   std::string dump_base_name = StringPrintf(
 376       "tracing/thread_%d", static_cast<int>(PlatformThread::CurrentId()));
 377   TraceEventMemoryOverhead overhead;
 378   chunk_->EstimateTraceMemoryOverhead(&overhead);
 379   overhead.DumpInto(dump_base_name.c_str(), pmd);
 380   return true;
 381 }
 382
 383 void TraceLog::ThreadLocalEventBuffer::FlushWhileLocked() {
 384   if (!chunk_)
 385     return;
 386
 387   trace_log_->lock_.AssertAcquired();
 388   if (trace_log_->CheckGeneration(generation_)) {
 389     // Return the chunk to the buffer only if the generation matches.
 390     trace_log_->logged_events_->ReturnChunk(chunk_index_, chunk_.Pass());
 391   }
 392   // Otherwise this method may be called from the destructor, or TraceLog will
 393   // find the generation mismatch and delete this buffer soon.
 394 }
 395
 396 TraceLogStatus::TraceLogStatus() : event_capacity(0), event_count(0) {}
 397
 398 TraceLogStatus::~TraceLogStatus() {}
 399
 400 // static
 401 TraceLog* TraceLog::GetInstance() {
 402   return Singleton<TraceLog, LeakySingletonTraits<TraceLog>>::get();
 403 }
 404
 405 TraceLog::TraceLog()
 406     : mode_(DISABLED),
 407       num_traces_recorded_(0),
 408       event_callback_(0),
 409       dispatching_to_observer_list_(false),
 410       process_sort_index_(0),
 411       process_id_hash_(0),
 412       process_id_(0),
 413       watch_category_(0),
 414       trace_options_(kInternalRecordUntilFull),
 415       sampling_thread_handle_(0),
 416       trace_config_(TraceConfig()),
 417       event_callback_trace_config_(TraceConfig()),
 418       thread_shared_chunk_index_(0),
 419       generation_(0),
 420       use_worker_thread_(false) {
 421   // Trace is enabled or disabled on one thread while other threads are
 422   // accessing the enabled flag. We don't care whether edge-case events are
 423   // traced or not, so we allow races on the enabled flag to keep the trace
 424   // macros fast.
 425   // TODO(jbates): ANNOTATE_BENIGN_RACE_SIZED crashes windows TSAN bots:
 426   // ANNOTATE_BENIGN_RACE_SIZED(g_category_group_enabled,
 427   //                            sizeof(g_category_group_enabled),
 428   //                           "trace_event category enabled");
 429   for (int i = 0; i < MAX_CATEGORY_GROUPS; ++i) {
 430     ANNOTATE_BENIGN_RACE(&g_category_group_enabled[i],
 431                          "trace_event category enabled");
 432   }
 433 #if defined(OS_NACL)  // NaCl shouldn't expose the process id.
 434   SetProcessID(0);
 435 #else
 436   SetProcessID(static_cast<int>(GetCurrentProcId()));
 437
 438   // NaCl also shouldn't access the command line.
 439   if (CommandLine::InitializedForCurrentProcess() &&
 440       CommandLine::ForCurrentProcess()->HasSwitch(switches::kTraceToConsole)) {
 441     std::string filter = CommandLine::ForCurrentProcess()->GetSwitchValueASCII(
 442         switches::kTraceToConsole);
 443     if (filter.empty()) {
 444       filter = kEchoToConsoleCategoryFilter;
 445     } else {
 446       filter.append(",");
 447       filter.append(kEchoToConsoleCategoryFilter);
 448     }
 449
 450     LOG(ERROR) << "Start " << switches::kTraceToConsole
 451                << " with CategoryFilter '" << filter << "'.";
 452     SetEnabled(TraceConfig(filter, ECHO_TO_CONSOLE), RECORDING_MODE);
 453   }
 454 #endif
 455
 456   logged_events_.reset(CreateTraceBuffer());
 457
 458   MemoryDumpManager::GetInstance()->RegisterDumpProvider(this);
 459 }
 460
 461 TraceLog::~TraceLog() {}
 462
 463 void TraceLog::InitializeThreadLocalEventBufferIfSupported() {
 464   // A ThreadLocalEventBuffer needs the message loop
 465   // - to know when the thread exits;
 466   // - to handle the final flush.
 467   // For a thread without a message loop or the message loop may be blocked, the
 468   // trace events will be added into the main buffer directly.
 469   if (thread_blocks_message_loop_.Get() || !MessageLoop::current())
 470     return;
 471   auto thread_local_event_buffer = thread_local_event_buffer_.Get();
 472   if (thread_local_event_buffer &&
 473       !CheckGeneration(thread_local_event_buffer->generation())) {
 474     delete thread_local_event_buffer;
 475     thread_local_event_buffer = NULL;
 476   }
 477   if (!thread_local_event_buffer) {
 478     thread_local_event_buffer = new ThreadLocalEventBuffer(this);
 479     thread_local_event_buffer_.Set(thread_local_event_buffer);
 480   }
 481 }
 482
 483 bool TraceLog::OnMemoryDump(const MemoryDumpArgs& args,
 484                             ProcessMemoryDump* pmd) {
 485   // TODO(ssid): Use MemoryDumpArgs to create light dumps when requested
 486   // (crbug.com/499731).
 487   TraceEventMemoryOverhead overhead;
 488   overhead.Add("TraceLog", sizeof(*this));
 489   {
 490     AutoLock lock(lock_);
 491     if (logged_events_)
 492       logged_events_->EstimateTraceMemoryOverhead(&overhead);
 493   }
 494   overhead.AddSelf();
 495   overhead.DumpInto("tracing/main_trace_log", pmd);
 496   return true;
 497 }
 498
 499 const unsigned char* TraceLog::GetCategoryGroupEnabled(
 500     const char* category_group) {
 501   TraceLog* tracelog = GetInstance();
 502   if (!tracelog) {
 503     DCHECK(!g_category_group_enabled[g_category_already_shutdown]);
 504     return &g_category_group_enabled[g_category_already_shutdown];
 505   }
 506   return tracelog->GetCategoryGroupEnabledInternal(category_group);
 507 }
 508
 509 const char* TraceLog::GetCategoryGroupName(
 510     const unsigned char* category_group_enabled) {
 511   // Calculate the index of the category group by finding
 512   // category_group_enabled in g_category_group_enabled array.
 513   uintptr_t category_begin =
 514       reinterpret_cast<uintptr_t>(g_category_group_enabled);
 515   uintptr_t category_ptr = reinterpret_cast<uintptr_t>(category_group_enabled);
 516   DCHECK(category_ptr >= category_begin &&
 517          category_ptr < reinterpret_cast<uintptr_t>(g_category_group_enabled +
 518                                                     MAX_CATEGORY_GROUPS))
 519       << "out of bounds category pointer";
 520   uintptr_t category_index =
 521       (category_ptr - category_begin) / sizeof(g_category_group_enabled[0]);
 522   return g_category_groups[category_index];
 523 }
 524
 525 void TraceLog::UpdateCategoryGroupEnabledFlag(size_t category_index) {
 526   unsigned char enabled_flag = 0;
 527   const char* category_group = g_category_groups[category_index];
 528   if (mode_ == RECORDING_MODE &&
 529       trace_config_.IsCategoryGroupEnabled(category_group))
 530     enabled_flag |= ENABLED_FOR_RECORDING;
 531   else if (mode_ == MONITORING_MODE &&
 532            trace_config_.IsCategoryGroupEnabled(category_group))
 533     enabled_flag |= ENABLED_FOR_MONITORING;
 534   if (event_callback_ &&
 535       event_callback_trace_config_.IsCategoryGroupEnabled(category_group))
 536     enabled_flag |= ENABLED_FOR_EVENT_CALLBACK;
 537 #if defined(OS_WIN)
 538   if (base::trace_event::TraceEventETWExport::IsCategoryGroupEnabled(
 539           category_group)) {
 540     enabled_flag |= ENABLED_FOR_ETW_EXPORT;
 541   }
 542 #endif
 543
 544   g_category_group_enabled[category_index] = enabled_flag;
 545 }
 546
 547 void TraceLog::UpdateCategoryGroupEnabledFlags() {
 548   size_t category_index = base::subtle::NoBarrier_Load(&g_category_index);
 549   for (size_t i = 0; i < category_index; i++)
 550     UpdateCategoryGroupEnabledFlag(i);
 551 }
 552
 553 void TraceLog::UpdateSyntheticDelaysFromTraceConfig() {
 554   ResetTraceEventSyntheticDelays();
 555   const TraceConfig::StringList& delays =
 556       trace_config_.GetSyntheticDelayValues();
 557   TraceConfig::StringList::const_iterator ci;
 558   for (ci = delays.begin(); ci != delays.end(); ++ci) {
 559     StringTokenizer tokens(*ci, ";");
 560     if (!tokens.GetNext())
 561       continue;
 562     TraceEventSyntheticDelay* delay =
 563         TraceEventSyntheticDelay::Lookup(tokens.token());
 564     while (tokens.GetNext()) {
 565       std::string token = tokens.token();
 566       char* duration_end;
 567       double target_duration = strtod(token.c_str(), &duration_end);
 568       if (duration_end != token.c_str()) {
 569         delay->SetTargetDuration(TimeDelta::FromMicroseconds(
 570             static_cast<int64>(target_duration * 1e6)));
 571       } else if (token == "static") {
 572         delay->SetMode(TraceEventSyntheticDelay::STATIC);
 573       } else if (token == "oneshot") {
 574         delay->SetMode(TraceEventSyntheticDelay::ONE_SHOT);
 575       } else if (token == "alternating") {
 576         delay->SetMode(TraceEventSyntheticDelay::ALTERNATING);
 577       }
 578     }
 579   }
 580 }
 581
 582 const unsigned char* TraceLog::GetCategoryGroupEnabledInternal(
 583     const char* category_group) {
 584   DCHECK(!strchr(category_group, '"'))
 585       << "Category groups may not contain double quote";
 586   // The g_category_groups is append only, avoid using a lock for the fast path.
 587   size_t current_category_index = base::subtle::Acquire_Load(&g_category_index);
 588
 589   // Search for pre-existing category group.
 590   for (size_t i = 0; i < current_category_index; ++i) {
 591     if (strcmp(g_category_groups[i], category_group) == 0) {
 592       return &g_category_group_enabled[i];
 593     }
 594   }
 595
 596   unsigned char* category_group_enabled = NULL;
 597   // This is the slow path: the lock is not held in the case above, so more
 598   // than one thread could have reached here trying to add the same category.
 599   // Only hold to lock when actually appending a new category, and
 600   // check the categories groups again.
 601   AutoLock lock(lock_);
 602   size_t category_index = base::subtle::Acquire_Load(&g_category_index);
 603   for (size_t i = 0; i < category_index; ++i) {
 604     if (strcmp(g_category_groups[i], category_group) == 0) {
 605       return &g_category_group_enabled[i];
 606     }
 607   }
 608
 609   // Create a new category group.
 610   DCHECK(category_index < MAX_CATEGORY_GROUPS)
 611       << "must increase MAX_CATEGORY_GROUPS";
 612   if (category_index < MAX_CATEGORY_GROUPS) {
 613     // Don't hold on to the category_group pointer, so that we can create
 614     // category groups with strings not known at compile time (this is
 615     // required by SetWatchEvent).
 616     const char* new_group = strdup(category_group);
 617     ANNOTATE_LEAKING_OBJECT_PTR(new_group);
 618     g_category_groups[category_index] = new_group;
 619     DCHECK(!g_category_group_enabled[category_index]);
 620     // Note that if both included and excluded patterns in the
 621     // TraceConfig are empty, we exclude nothing,
 622     // thereby enabling this category group.
 623     UpdateCategoryGroupEnabledFlag(category_index);
 624     category_group_enabled = &g_category_group_enabled[category_index];
 625     // Update the max index now.
 626     base::subtle::Release_Store(&g_category_index, category_index + 1);
 627   } else {
 628     category_group_enabled =
 629         &g_category_group_enabled[g_category_categories_exhausted];
 630   }
 631   return category_group_enabled;
 632 }
 633
 634 void TraceLog::GetKnownCategoryGroups(
 635     std::vector<std::string>* category_groups) {
 636   AutoLock lock(lock_);
 637   category_groups->push_back(
 638       g_category_groups[g_category_trace_event_overhead]);
 639   size_t category_index = base::subtle::NoBarrier_Load(&g_category_index);
 640   for (size_t i = g_num_builtin_categories; i < category_index; i++)
 641     category_groups->push_back(g_category_groups[i]);
 642 }
 643
 644 void TraceLog::SetEnabled(const TraceConfig& trace_config, Mode mode) {
 645   std::vector<EnabledStateObserver*> observer_list;
 646   {
 647     AutoLock lock(lock_);
 648
 649     // Can't enable tracing when Flush() is in progress.
 650     DCHECK(!flush_task_runner_);
 651
 652     InternalTraceOptions new_options =
 653         GetInternalOptionsFromTraceConfig(trace_config);
 654
 655     InternalTraceOptions old_options = trace_options();
 656
 657     if (IsEnabled()) {
 658       if (new_options != old_options) {
 659         DLOG(ERROR) << "Attempting to re-enable tracing with a different "
 660                     << "set of options.";
 661       }
 662
 663       if (mode != mode_) {
 664         DLOG(ERROR) << "Attempting to re-enable tracing with a different mode.";
 665       }
 666
 667       trace_config_.Merge(trace_config);
 668       UpdateCategoryGroupEnabledFlags();
 669       return;
 670     }
 671
 672     if (dispatching_to_observer_list_) {
 673       DLOG(ERROR)
 674           << "Cannot manipulate TraceLog::Enabled state from an observer.";
 675       return;
 676     }
 677
 678     mode_ = mode;
 679
 680     if (new_options != old_options) {
 681       subtle::NoBarrier_Store(&trace_options_, new_options);
 682       UseNextTraceBuffer();
 683     }
 684
 685     num_traces_recorded_++;
 686
 687     trace_config_ = TraceConfig(trace_config);
 688     UpdateCategoryGroupEnabledFlags();
 689     UpdateSyntheticDelaysFromTraceConfig();
 690
 691     if (new_options & kInternalEnableSampling) {
 692       sampling_thread_.reset(new TraceSamplingThread);
 693       sampling_thread_->RegisterSampleBucket(
 694           &g_trace_state[0], "bucket0",
 695           Bind(&TraceSamplingThread::DefaultSamplingCallback));
 696       sampling_thread_->RegisterSampleBucket(
 697           &g_trace_state[1], "bucket1",
 698           Bind(&TraceSamplingThread::DefaultSamplingCallback));
 699       sampling_thread_->RegisterSampleBucket(
 700           &g_trace_state[2], "bucket2",
 701           Bind(&TraceSamplingThread::DefaultSamplingCallback));
 702       if (!PlatformThread::Create(0, sampling_thread_.get(),
 703                                   &sampling_thread_handle_)) {
 704         DCHECK(false) << "failed to create thread";
 705       }
 706     }
 707
 708     dispatching_to_observer_list_ = true;
 709     observer_list = enabled_state_observer_list_;
 710   }
 711   // Notify observers outside the lock in case they trigger trace events.
 712   for (size_t i = 0; i < observer_list.size(); ++i)
 713     observer_list[i]->OnTraceLogEnabled();
 714
 715   {
 716     AutoLock lock(lock_);
 717     dispatching_to_observer_list_ = false;
 718   }
 719 }
 720
 721 void TraceLog::SetArgumentFilterPredicate(
 722     const ArgumentFilterPredicate& argument_filter_predicate) {
 723   AutoLock lock(lock_);
 724   DCHECK(!argument_filter_predicate.is_null());
 725   DCHECK(argument_filter_predicate_.is_null());
 726   argument_filter_predicate_ = argument_filter_predicate;
 727 }
 728
 729 TraceLog::InternalTraceOptions TraceLog::GetInternalOptionsFromTraceConfig(
 730     const TraceConfig& config) {
 731   InternalTraceOptions ret =
 732       config.IsSamplingEnabled() ? kInternalEnableSampling : kInternalNone;
 733   if (config.IsArgumentFilterEnabled())
 734     ret |= kInternalEnableArgumentFilter;
 735   switch (config.GetTraceRecordMode()) {
 736     case RECORD_UNTIL_FULL:
 737       return ret | kInternalRecordUntilFull;
 738     case RECORD_CONTINUOUSLY:
 739       return ret | kInternalRecordContinuously;
 740     case ECHO_TO_CONSOLE:
 741       return ret | kInternalEchoToConsole;
 742     case RECORD_AS_MUCH_AS_POSSIBLE:
 743       return ret | kInternalRecordAsMuchAsPossible;
 744   }
 745   NOTREACHED();
 746   return kInternalNone;
 747 }
 748
 749 TraceConfig TraceLog::GetCurrentTraceConfig() const {
 750   AutoLock lock(lock_);
 751   return trace_config_;
 752 }
 753
 754 void TraceLog::SetDisabled() {
 755   AutoLock lock(lock_);
 756   SetDisabledWhileLocked();
 757 }
 758
 759 void TraceLog::SetDisabledWhileLocked() {
 760   lock_.AssertAcquired();
 761
 762   if (!IsEnabled())
 763     return;
 764
 765   if (dispatching_to_observer_list_) {
 766     DLOG(ERROR)
 767         << "Cannot manipulate TraceLog::Enabled state from an observer.";
 768     return;
 769   }
 770
 771   mode_ = DISABLED;
 772
 773   if (sampling_thread_.get()) {
 774     // Stop the sampling thread.
 775     sampling_thread_->Stop();
 776     lock_.Release();
 777     PlatformThread::Join(sampling_thread_handle_);
 778     lock_.Acquire();
 779     sampling_thread_handle_ = PlatformThreadHandle();
 780     sampling_thread_.reset();
 781   }
 782
 783   trace_config_.Clear();
 784   subtle::NoBarrier_Store(&watch_category_, 0);
 785   watch_event_name_ = "";
 786   UpdateCategoryGroupEnabledFlags();
 787   AddMetadataEventsWhileLocked();
 788
 789   dispatching_to_observer_list_ = true;
 790   std::vector<EnabledStateObserver*> observer_list =
 791       enabled_state_observer_list_;
 792
 793   {
 794     // Dispatch to observers outside the lock in case the observer triggers a
 795     // trace event.
 796     AutoUnlock unlock(lock_);
 797     for (size_t i = 0; i < observer_list.size(); ++i)
 798       observer_list[i]->OnTraceLogDisabled();
 799   }
 800   dispatching_to_observer_list_ = false;
 801 }
 802
 803 int TraceLog::GetNumTracesRecorded() {
 804   AutoLock lock(lock_);
 805   if (!IsEnabled())
 806     return -1;
 807   return num_traces_recorded_;
 808 }
 809
 810 void TraceLog::AddEnabledStateObserver(EnabledStateObserver* listener) {
 811   enabled_state_observer_list_.push_back(listener);
 812 }
 813
 814 void TraceLog::RemoveEnabledStateObserver(EnabledStateObserver* listener) {
 815   std::vector<EnabledStateObserver*>::iterator it =
 816       std::find(enabled_state_observer_list_.begin(),
 817                 enabled_state_observer_list_.end(), listener);
 818   if (it != enabled_state_observer_list_.end())
 819     enabled_state_observer_list_.erase(it);
 820 }
 821
 822 bool TraceLog::HasEnabledStateObserver(EnabledStateObserver* listener) const {
 823   std::vector<EnabledStateObserver*>::const_iterator it =
 824       std::find(enabled_state_observer_list_.begin(),
 825                 enabled_state_observer_list_.end(), listener);
 826   return it != enabled_state_observer_list_.end();
 827 }
 828
 829 TraceLogStatus TraceLog::GetStatus() const {
 830   AutoLock lock(lock_);
 831   TraceLogStatus result;
 832   result.event_capacity = logged_events_->Capacity();
 833   result.event_count = logged_events_->Size();
 834   return result;
 835 }
 836
 837 bool TraceLog::BufferIsFull() const {
 838   AutoLock lock(lock_);
 839   return logged_events_->IsFull();
 840 }
 841
 842 TraceEvent* TraceLog::AddEventToThreadSharedChunkWhileLocked(
 843     TraceEventHandle* handle,
 844     bool check_buffer_is_full) {
 845   lock_.AssertAcquired();
 846
 847   if (thread_shared_chunk_ && thread_shared_chunk_->IsFull()) {
 848     logged_events_->ReturnChunk(thread_shared_chunk_index_,
 849                                 thread_shared_chunk_.Pass());
 850   }
 851
 852   if (!thread_shared_chunk_) {
 853     thread_shared_chunk_ =
 854         logged_events_->GetChunk(&thread_shared_chunk_index_);
 855     if (check_buffer_is_full)
 856       CheckIfBufferIsFullWhileLocked();
 857   }
 858   if (!thread_shared_chunk_)
 859     return NULL;
 860
 861   size_t event_index;
 862   TraceEvent* trace_event = thread_shared_chunk_->AddTraceEvent(&event_index);
 863   if (trace_event && handle) {
 864     MakeHandle(thread_shared_chunk_->seq(), thread_shared_chunk_index_,
 865                event_index, handle);
 866   }
 867   return trace_event;
 868 }
 869
 870 void TraceLog::CheckIfBufferIsFullWhileLocked() {
 871   lock_.AssertAcquired();
 872   if (logged_events_->IsFull()) {
 873     if (buffer_limit_reached_timestamp_.is_null()) {
 874       buffer_limit_reached_timestamp_ = OffsetNow();
 875     }
 876     SetDisabledWhileLocked();
 877   }
 878 }
 879
 880 void TraceLog::SetEventCallbackEnabled(const TraceConfig& trace_config,
 881                                        EventCallback cb) {
 882   AutoLock lock(lock_);
 883   subtle::NoBarrier_Store(&event_callback_,
 884                           reinterpret_cast<subtle::AtomicWord>(cb));
 885   event_callback_trace_config_ = trace_config;
 886   UpdateCategoryGroupEnabledFlags();
 887 };
 888
 889 void TraceLog::SetEventCallbackDisabled() {
 890   AutoLock lock(lock_);
 891   subtle::NoBarrier_Store(&event_callback_, 0);
 892   UpdateCategoryGroupEnabledFlags();
 893 }
 894
 895 // Flush() works as the following:
 896 // 1. Flush() is called in thread A whose task runner is saved in
 897 //    flush_task_runner_;
 898 // 2. If thread_message_loops_ is not empty, thread A posts task to each message
 899 //    loop to flush the thread local buffers; otherwise finish the flush;
 900 // 3. FlushCurrentThread() deletes the thread local event buffer:
 901 //    - The last batch of events of the thread are flushed into the main buffer;
 902 //    - The message loop will be removed from thread_message_loops_;
 903 //    If this is the last message loop, finish the flush;
 904 // 4. If any thread hasn't finish its flush in time, finish the flush.
 905 void TraceLog::Flush(const TraceLog::OutputCallback& cb,
 906                      bool use_worker_thread) {
 907   FlushInternal(cb, use_worker_thread, false);
 908 }
 909
 910 void TraceLog::CancelTracing(const OutputCallback& cb) {
 911   SetDisabled();
 912   FlushInternal(cb, false, true);
 913 }
 914
 915 void TraceLog::FlushInternal(const TraceLog::OutputCallback& cb,
 916                              bool use_worker_thread,
 917                              bool discard_events) {
 918   use_worker_thread_ = use_worker_thread;
 919   if (IsEnabled()) {
 920     // Can't flush when tracing is enabled because otherwise PostTask would
 921     // - generate more trace events;
 922     // - deschedule the calling thread on some platforms causing inaccurate
 923     //   timing of the trace events.
 924     scoped_refptr<RefCountedString> empty_result = new RefCountedString;
 925     if (!cb.is_null())
 926       cb.Run(empty_result, false);
 927     LOG(WARNING) << "Ignored TraceLog::Flush called when tracing is enabled";
 928     return;
 929   }
 930
 931   int generation = this->generation();
 932   // Copy of thread_message_loops_ to be used without locking.
 933   std::vector<scoped_refptr<SingleThreadTaskRunner>>
 934       thread_message_loop_task_runners;
 935   {
 936     AutoLock lock(lock_);
 937     DCHECK(!flush_task_runner_);
 938     flush_task_runner_ = ThreadTaskRunnerHandle::IsSet()
 939                              ? ThreadTaskRunnerHandle::Get()
 940                              : nullptr;
 941     DCHECK_IMPLIES(thread_message_loops_.size(), flush_task_runner_);
 942     flush_output_callback_ = cb;
 943
 944     if (thread_shared_chunk_) {
 945       logged_events_->ReturnChunk(thread_shared_chunk_index_,
 946                                   thread_shared_chunk_.Pass());
 947     }
 948
 949     if (thread_message_loops_.size()) {
 950       for (hash_set<MessageLoop*>::const_iterator it =
 951                thread_message_loops_.begin();
 952            it != thread_message_loops_.end(); ++it) {
 953         thread_message_loop_task_runners.push_back((*it)->task_runner());
 954       }
 955     }
 956   }
 957
 958   if (thread_message_loop_task_runners.size()) {
 959     for (size_t i = 0; i < thread_message_loop_task_runners.size(); ++i) {
 960       thread_message_loop_task_runners[i]->PostTask(
 961           FROM_HERE, Bind(&TraceLog::FlushCurrentThread, Unretained(this),
 962                           generation, discard_events));
 963     }
 964     flush_task_runner_->PostDelayedTask(
 965         FROM_HERE, Bind(&TraceLog::OnFlushTimeout, Unretained(this), generation,
 966                         discard_events),
 967         TimeDelta::FromMilliseconds(kThreadFlushTimeoutMs));
 968     return;
 969   }
 970
 971   FinishFlush(generation, discard_events);
 972 }
 973
 974 // Usually it runs on a different thread.
 975 void TraceLog::ConvertTraceEventsToTraceFormat(
 976     scoped_ptr<TraceBuffer> logged_events,
 977     const OutputCallback& flush_output_callback,
 978     const ArgumentFilterPredicate& argument_filter_predicate) {
 979   if (flush_output_callback.is_null())
 980     return;
 981
 982   // The callback need to be called at least once even if there is no events
 983   // to let the caller know the completion of flush.
 984   scoped_refptr<RefCountedString> json_events_str_ptr = new RefCountedString();
 985   while (const TraceBufferChunk* chunk = logged_events->NextChunk()) {
 986     for (size_t j = 0; j < chunk->size(); ++j) {
 987       size_t size = json_events_str_ptr->size();
 988       if (size > kTraceEventBufferSizeInBytes) {
 989         flush_output_callback.Run(json_events_str_ptr, true);
 990         json_events_str_ptr = new RefCountedString();
 991       } else if (size) {
 992         json_events_str_ptr->data().append(",\n");
 993       }
 994       chunk->GetEventAt(j)->AppendAsJSON(&(json_events_str_ptr->data()),
 995                                          argument_filter_predicate);
 996     }
 997   }
 998   flush_output_callback.Run(json_events_str_ptr, false);
 999 }
1000
1001 void TraceLog::FinishFlush(int generation, bool discard_events) {
1002   scoped_ptr<TraceBuffer> previous_logged_events;
1003   OutputCallback flush_output_callback;
1004   ArgumentFilterPredicate argument_filter_predicate;
1005
1006   if (!CheckGeneration(generation))
1007     return;
1008
1009   {
1010     AutoLock lock(lock_);
1011
1012     previous_logged_events.swap(logged_events_);
1013     UseNextTraceBuffer();
1014     thread_message_loops_.clear();
1015
1016     flush_task_runner_ = NULL;
1017     flush_output_callback = flush_output_callback_;
1018     flush_output_callback_.Reset();
1019
1020     if (trace_options() & kInternalEnableArgumentFilter) {
1021       CHECK(!argument_filter_predicate_.is_null());
1022       argument_filter_predicate = argument_filter_predicate_;
1023     }
1024   }
1025
1026   if (discard_events) {
1027     if (!flush_output_callback.is_null()) {
1028       scoped_refptr<RefCountedString> empty_result = new RefCountedString;
1029       flush_output_callback.Run(empty_result, false);
1030     }
1031     return;
1032   }
1033
1034   if (use_worker_thread_ &&
1035       WorkerPool::PostTask(
1036           FROM_HERE, Bind(&TraceLog::ConvertTraceEventsToTraceFormat,
1037                           Passed(&previous_logged_events),
1038                           flush_output_callback, argument_filter_predicate),
1039           true)) {
1040     return;
1041   }
1042
1043   ConvertTraceEventsToTraceFormat(previous_logged_events.Pass(),
1044                                   flush_output_callback,
1045                                   argument_filter_predicate);
1046 }
1047
1048 // Run in each thread holding a local event buffer.
1049 void TraceLog::FlushCurrentThread(int generation, bool discard_events) {
1050   {
1051     AutoLock lock(lock_);
1052     if (!CheckGeneration(generation) || !flush_task_runner_) {
1053       // This is late. The corresponding flush has finished.
1054       return;
1055     }
1056   }
1057
1058   // This will flush the thread local buffer.
1059   delete thread_local_event_buffer_.Get();
1060
1061   AutoLock lock(lock_);
1062   if (!CheckGeneration(generation) || !flush_task_runner_ ||
1063       thread_message_loops_.size())
1064     return;
1065
1066   flush_task_runner_->PostTask(
1067       FROM_HERE, Bind(&TraceLog::FinishFlush, Unretained(this), generation,
1068                       discard_events));
1069 }
1070
1071 void TraceLog::OnFlushTimeout(int generation, bool discard_events) {
1072   {
1073     AutoLock lock(lock_);
1074     if (!CheckGeneration(generation) || !flush_task_runner_) {
1075       // Flush has finished before timeout.
1076       return;
1077     }
1078
1079     LOG(WARNING)
1080         << "The following threads haven't finished flush in time. "
1081            "If this happens stably for some thread, please call "
1082            "TraceLog::GetInstance()->SetCurrentThreadBlocksMessageLoop() from "
1083            "the thread to avoid its trace events from being lost.";
1084     for (hash_set<MessageLoop*>::const_iterator it =
1085              thread_message_loops_.begin();
1086          it != thread_message_loops_.end(); ++it) {
1087       LOG(WARNING) << "Thread: " << (*it)->thread_name();
1088     }
1089   }
1090   FinishFlush(generation, discard_events);
1091 }
1092
1093 void TraceLog::FlushButLeaveBufferIntact(
1094     const TraceLog::OutputCallback& flush_output_callback) {
1095   scoped_ptr<TraceBuffer> previous_logged_events;
1096   ArgumentFilterPredicate argument_filter_predicate;
1097   {
1098     AutoLock lock(lock_);
1099     AddMetadataEventsWhileLocked();
1100     if (thread_shared_chunk_) {
1101       // Return the chunk to the main buffer to flush the sampling data.
1102       logged_events_->ReturnChunk(thread_shared_chunk_index_,
1103                                   thread_shared_chunk_.Pass());
1104     }
1105     previous_logged_events = logged_events_->CloneForIteration().Pass();
1106
1107     if (trace_options() & kInternalEnableArgumentFilter) {
1108       CHECK(!argument_filter_predicate_.is_null());
1109       argument_filter_predicate = argument_filter_predicate_;
1110     }
1111   }  // release lock
1112
1113   ConvertTraceEventsToTraceFormat(previous_logged_events.Pass(),
1114                                   flush_output_callback,
1115                                   argument_filter_predicate);
1116 }
1117
1118 void TraceLog::UseNextTraceBuffer() {
1119   logged_events_.reset(CreateTraceBuffer());
1120   subtle::NoBarrier_AtomicIncrement(&generation_, 1);
1121   thread_shared_chunk_.reset();
1122   thread_shared_chunk_index_ = 0;
1123 }
1124
1125 TraceEventHandle TraceLog::AddTraceEvent(
1126     char phase,
1127     const unsigned char* category_group_enabled,
1128     const char* name,
1129     unsigned long long id,
1130     int num_args,
1131     const char** arg_names,
1132     const unsigned char* arg_types,
1133     const unsigned long long* arg_values,
1134     const scoped_refptr<ConvertableToTraceFormat>* convertable_values,
1135     unsigned int flags) {
1136   int thread_id = static_cast<int>(base::PlatformThread::CurrentId());
1137   base::TraceTicks now = base::TraceTicks::Now();
1138   return AddTraceEventWithThreadIdAndTimestamp(
1139       phase,
1140       category_group_enabled,
1141       name,
1142       id,
1143       trace_event_internal::kNoId,  // context_id
1144       trace_event_internal::kNoId,  // bind_id
1145       thread_id,
1146       now,
1147       num_args,
1148       arg_names,
1149       arg_types,
1150       arg_values,
1151       convertable_values,
1152       flags);
1153 }
1154
1155 TraceEventHandle TraceLog::AddTraceEventWithContextId(
1156     char phase,
1157     const unsigned char* category_group_enabled,
1158     const char* name,
1159     unsigned long long id,
1160     unsigned long long context_id,
1161     int num_args,
1162     const char** arg_names,
1163     const unsigned char* arg_types,
1164     const unsigned long long* arg_values,
1165     const scoped_refptr<ConvertableToTraceFormat>* convertable_values,
1166     unsigned int flags) {
1167   int thread_id = static_cast<int>(base::PlatformThread::CurrentId());
1168   base::TraceTicks now = base::TraceTicks::Now();
1169   return AddTraceEventWithThreadIdAndTimestamp(
1170       phase,
1171       category_group_enabled,
1172       name,
1173       id,
1174       context_id,
1175       trace_event_internal::kNoId,  // bind_id
1176       thread_id,
1177       now,
1178       num_args,
1179       arg_names,
1180       arg_types,
1181       arg_values,
1182       convertable_values,
1183       flags | TRACE_EVENT_FLAG_HAS_CONTEXT_ID);
1184 }
1185
1186 // Handle legacy calls to AddTraceEventWithThreadIdAndTimestamp
1187 // with kNoId as bind_id
1188 TraceEventHandle TraceLog::AddTraceEventWithThreadIdAndTimestamp(
1189     char phase,
1190     const unsigned char* category_group_enabled,
1191     const char* name,
1192     unsigned long long id,
1193     unsigned long long context_id,
1194     int thread_id,
1195     const TraceTicks& timestamp,
1196     int num_args,
1197     const char** arg_names,
1198     const unsigned char* arg_types,
1199     const unsigned long long* arg_values,
1200     const scoped_refptr<ConvertableToTraceFormat>* convertable_values,
1201     unsigned int flags) {
1202   return AddTraceEventWithThreadIdAndTimestamp(
1203       phase,
1204       category_group_enabled,
1205       name,
1206       id,
1207       context_id,
1208       trace_event_internal::kNoId,  // bind_id
1209       thread_id,
1210       timestamp,
1211       num_args,
1212       arg_names,
1213       arg_types,
1214       arg_values,
1215       convertable_values,
1216       flags);
1217 }
1218
1219 TraceEventHandle TraceLog::AddTraceEventWithThreadIdAndTimestamp(
1220     char phase,
1221     const unsigned char* category_group_enabled,
1222     const char* name,
1223     unsigned long long id,
1224     unsigned long long context_id,
1225     unsigned long long bind_id,
1226     int thread_id,
1227     const TraceTicks& timestamp,
1228     int num_args,
1229     const char** arg_names,
1230     const unsigned char* arg_types,
1231     const unsigned long long* arg_values,
1232     const scoped_refptr<ConvertableToTraceFormat>* convertable_values,
1233     unsigned int flags) {
1234   TraceEventHandle handle = {0, 0, 0};
1235   if (!*category_group_enabled)
1236     return handle;
1237
1238   // Avoid re-entrance of AddTraceEvent. This may happen in GPU process when
1239   // ECHO_TO_CONSOLE is enabled: AddTraceEvent -> LOG(ERROR) ->
1240   // GpuProcessLogMessageHandler -> PostPendingTask -> TRACE_EVENT ...
1241   if (thread_is_in_trace_event_.Get())
1242     return handle;
1243
1244   AutoThreadLocalBoolean thread_is_in_trace_event(&thread_is_in_trace_event_);
1245
1246   DCHECK(name);
1247   DCHECK(!timestamp.is_null());
1248
1249   if (flags & TRACE_EVENT_FLAG_MANGLE_ID) {
1250     if ((flags & TRACE_EVENT_FLAG_FLOW_IN) ||
1251         (flags & TRACE_EVENT_FLAG_FLOW_OUT))
1252       bind_id = MangleEventId(bind_id);
1253     id = MangleEventId(id);
1254   }
1255
1256   TraceTicks offset_event_timestamp = OffsetTimestamp(timestamp);
1257   TraceTicks now = flags & TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP
1258                        ? OffsetNow()
1259                        : offset_event_timestamp;
1260   ThreadTicks thread_now = ThreadNow();
1261
1262   // |thread_local_event_buffer_| can be null if the current thread doesn't have
1263   // a message loop or the message loop is blocked.
1264   InitializeThreadLocalEventBufferIfSupported();
1265   auto thread_local_event_buffer = thread_local_event_buffer_.Get();
1266
1267   // Check and update the current thread name only if the event is for the
1268   // current thread to avoid locks in most cases.
1269   if (thread_id == static_cast<int>(PlatformThread::CurrentId())) {
1270     const char* new_name =
1271         ThreadIdNameManager::GetInstance()->GetName(thread_id);
1272     // Check if the thread name has been set or changed since the previous
1273     // call (if any), but don't bother if the new name is empty. Note this will
1274     // not detect a thread name change within the same char* buffer address: we
1275     // favor common case performance over corner case correctness.
1276     if (new_name != g_current_thread_name.Get().Get() && new_name &&
1277         *new_name) {
1278       g_current_thread_name.Get().Set(new_name);
1279
1280       AutoLock thread_info_lock(thread_info_lock_);
1281
1282       hash_map<int, std::string>::iterator existing_name =
1283           thread_names_.find(thread_id);
1284       if (existing_name == thread_names_.end()) {
1285         // This is a new thread id, and a new name.
1286         thread_names_[thread_id] = new_name;
1287       } else {
1288         // This is a thread id that we've seen before, but potentially with a
1289         // new name.
1290         std::vector<StringPiece> existing_names = base::SplitStringPiece(
1291             existing_name->second, ",", base::KEEP_WHITESPACE,
1292             base::SPLIT_WANT_NONEMPTY);
1293         bool found = std::find(existing_names.begin(), existing_names.end(),
1294                                new_name) != existing_names.end();
1295         if (!found) {
1296           if (existing_names.size())
1297             existing_name->second.push_back(',');
1298           existing_name->second.append(new_name);
1299         }
1300       }
1301     }
1302   }
1303
1304 #if defined(OS_WIN)
1305   // This is done sooner rather than later, to avoid creating the event and
1306   // acquiring the lock, which is not needed for ETW as it's already threadsafe.
1307   if (*category_group_enabled & ENABLED_FOR_ETW_EXPORT)
1308     TraceEventETWExport::AddEvent(phase, category_group_enabled, name, id,
1309                                   num_args, arg_names, arg_types, arg_values,
1310                                   convertable_values);
1311 #endif  // OS_WIN
1312
1313   std::string console_message;
1314   if (*category_group_enabled &
1315       (ENABLED_FOR_RECORDING | ENABLED_FOR_MONITORING)) {
1316     OptionalAutoLock lock(&lock_);
1317
1318     TraceEvent* trace_event = NULL;
1319     if (thread_local_event_buffer) {
1320       trace_event = thread_local_event_buffer->AddTraceEvent(&handle);
1321     } else {
1322       lock.EnsureAcquired();
1323       trace_event = AddEventToThreadSharedChunkWhileLocked(&handle, true);
1324     }
1325
1326     if (trace_event) {
1327       trace_event->Initialize(thread_id,
1328                               offset_event_timestamp,
1329                               thread_now,
1330                               phase,
1331                               category_group_enabled,
1332                               name,
1333                               id,
1334                               context_id,
1335                               bind_id,
1336                               num_args,
1337                               arg_names,
1338                               arg_types,
1339                               arg_values,
1340                               convertable_values,
1341                               flags);
1342
1343 #if defined(OS_ANDROID)
1344       trace_event->SendToATrace();
1345 #endif
1346     }
1347
1348     if (trace_options() & kInternalEchoToConsole) {
1349       console_message = EventToConsoleMessage(
1350           phase == TRACE_EVENT_PHASE_COMPLETE ? TRACE_EVENT_PHASE_BEGIN : phase,
1351           timestamp, trace_event);
1352     }
1353   }
1354
1355   if (console_message.size())
1356     LOG(ERROR) << console_message;
1357
1358   if (reinterpret_cast<const unsigned char*>(
1359           subtle::NoBarrier_Load(&watch_category_)) == category_group_enabled) {
1360     bool event_name_matches;
1361     WatchEventCallback watch_event_callback_copy;
1362     {
1363       AutoLock lock(lock_);
1364       event_name_matches = watch_event_name_ == name;
1365       watch_event_callback_copy = watch_event_callback_;
1366     }
1367     if (event_name_matches) {
1368       if (!watch_event_callback_copy.is_null())
1369         watch_event_callback_copy.Run();
1370     }
1371   }
1372
1373   if (*category_group_enabled & ENABLED_FOR_EVENT_CALLBACK) {
1374     EventCallback event_callback = reinterpret_cast<EventCallback>(
1375         subtle::NoBarrier_Load(&event_callback_));
1376     if (event_callback) {
1377       event_callback(
1378           offset_event_timestamp,
1379           phase == TRACE_EVENT_PHASE_COMPLETE ? TRACE_EVENT_PHASE_BEGIN : phase,
1380           category_group_enabled, name, id, num_args, arg_names, arg_types,
1381           arg_values, flags);
1382     }
1383   }
1384
1385   if (thread_local_event_buffer)
1386     thread_local_event_buffer->ReportOverhead(now, thread_now);
1387
1388   return handle;
1389 }
1390
1391 // May be called when a COMPELETE event ends and the unfinished event has been
1392 // recycled (phase == TRACE_EVENT_PHASE_END and trace_event == NULL).
1393 std::string TraceLog::EventToConsoleMessage(unsigned char phase,
1394                                             const TraceTicks& timestamp,
1395                                             TraceEvent* trace_event) {
1396   AutoLock thread_info_lock(thread_info_lock_);
1397
1398   // The caller should translate TRACE_EVENT_PHASE_COMPLETE to
1399   // TRACE_EVENT_PHASE_BEGIN or TRACE_EVENT_END.
1400   DCHECK(phase != TRACE_EVENT_PHASE_COMPLETE);
1401
1402   TimeDelta duration;
1403   int thread_id =
1404       trace_event ? trace_event->thread_id() : PlatformThread::CurrentId();
1405   if (phase == TRACE_EVENT_PHASE_END) {
1406     duration = timestamp - thread_event_start_times_[thread_id].top();
1407     thread_event_start_times_[thread_id].pop();
1408   }
1409
1410   std::string thread_name = thread_names_[thread_id];
1411   if (thread_colors_.find(thread_name) == thread_colors_.end())
1412     thread_colors_[thread_name] = (thread_colors_.size() % 6) + 1;
1413
1414   std::ostringstream log;
1415   log << base::StringPrintf("%s: \x1b[0;3%dm", thread_name.c_str(),
1416                             thread_colors_[thread_name]);
1417
1418   size_t depth = 0;
1419   if (thread_event_start_times_.find(thread_id) !=
1420       thread_event_start_times_.end())
1421     depth = thread_event_start_times_[thread_id].size();
1422
1423   for (size_t i = 0; i < depth; ++i)
1424     log << "| ";
1425
1426   if (trace_event)
1427     trace_event->AppendPrettyPrinted(&log);
1428   if (phase == TRACE_EVENT_PHASE_END)
1429     log << base::StringPrintf(" (%.3f ms)", duration.InMillisecondsF());
1430
1431   log << "\x1b[0;m";
1432
1433   if (phase == TRACE_EVENT_PHASE_BEGIN)
1434     thread_event_start_times_[thread_id].push(timestamp);
1435
1436   return log.str();
1437 }
1438
1439 void TraceLog::AddTraceEventEtw(char phase,
1440                                 const char* name,
1441                                 const void* id,
1442                                 const char* extra) {
1443 #if defined(OS_WIN)
1444   TraceEventETWProvider::Trace(name, phase, id, extra);
1445 #endif
1446   INTERNAL_TRACE_EVENT_ADD(phase, "ETW Trace Event", name,
1447                            TRACE_EVENT_FLAG_COPY, "id", id, "extra", extra);
1448 }
1449
1450 void TraceLog::AddTraceEventEtw(char phase,
1451                                 const char* name,
1452                                 const void* id,
1453                                 const std::string& extra) {
1454 #if defined(OS_WIN)
1455   TraceEventETWProvider::Trace(name, phase, id, extra);
1456 #endif
1457   INTERNAL_TRACE_EVENT_ADD(phase, "ETW Trace Event", name,
1458                            TRACE_EVENT_FLAG_COPY, "id", id, "extra", extra);
1459 }
1460
1461 void TraceLog::UpdateTraceEventDuration(
1462     const unsigned char* category_group_enabled,
1463     const char* name,
1464     TraceEventHandle handle) {
1465   // Avoid re-entrance of AddTraceEvent. This may happen in GPU process when
1466   // ECHO_TO_CONSOLE is enabled: AddTraceEvent -> LOG(ERROR) ->
1467   // GpuProcessLogMessageHandler -> PostPendingTask -> TRACE_EVENT ...
1468   if (thread_is_in_trace_event_.Get())
1469     return;
1470
1471   AutoThreadLocalBoolean thread_is_in_trace_event(&thread_is_in_trace_event_);
1472
1473   ThreadTicks thread_now = ThreadNow();
1474   TraceTicks now = OffsetNow();
1475
1476   std::string console_message;
1477   if (*category_group_enabled & ENABLED_FOR_RECORDING) {
1478     OptionalAutoLock lock(&lock_);
1479
1480     TraceEvent* trace_event = GetEventByHandleInternal(handle, &lock);
1481     if (trace_event) {
1482       DCHECK(trace_event->phase() == TRACE_EVENT_PHASE_COMPLETE);
1483       trace_event->UpdateDuration(now, thread_now);
1484 #if defined(OS_ANDROID)
1485       trace_event->SendToATrace();
1486 #endif
1487     }
1488
1489     if (trace_options() & kInternalEchoToConsole) {
1490       console_message =
1491           EventToConsoleMessage(TRACE_EVENT_PHASE_END, now, trace_event);
1492     }
1493   }
1494
1495   if (console_message.size())
1496     LOG(ERROR) << console_message;
1497
1498   if (*category_group_enabled & ENABLED_FOR_EVENT_CALLBACK) {
1499     EventCallback event_callback = reinterpret_cast<EventCallback>(
1500         subtle::NoBarrier_Load(&event_callback_));
1501     if (event_callback) {
1502       event_callback(now, TRACE_EVENT_PHASE_END, category_group_enabled, name,
1503                      trace_event_internal::kNoId, 0,
1504                      nullptr, nullptr, nullptr, TRACE_EVENT_FLAG_NONE);
1505     }
1506   }
1507 }
1508
1509 void TraceLog::SetWatchEvent(const std::string& category_name,
1510                              const std::string& event_name,
1511                              const WatchEventCallback& callback) {
1512   const unsigned char* category =
1513       GetCategoryGroupEnabled(category_name.c_str());
1514   AutoLock lock(lock_);
1515   subtle::NoBarrier_Store(&watch_category_,
1516                           reinterpret_cast<subtle::AtomicWord>(category));
1517   watch_event_name_ = event_name;
1518   watch_event_callback_ = callback;
1519 }
1520
1521 void TraceLog::CancelWatchEvent() {
1522   AutoLock lock(lock_);
1523   subtle::NoBarrier_Store(&watch_category_, 0);
1524   watch_event_name_ = "";
1525   watch_event_callback_.Reset();
1526 }
1527
1528 uint64 TraceLog::MangleEventId(uint64 id) {
1529   return id ^ process_id_hash_;
1530 }
1531
1532 void TraceLog::AddMetadataEventsWhileLocked() {
1533   lock_.AssertAcquired();
1534
1535 #if !defined(OS_NACL)  // NaCl shouldn't expose the process id.
1536   InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
1537                           0, "num_cpus", "number",
1538                           base::SysInfo::NumberOfProcessors());
1539 #endif
1540
1541   int current_thread_id = static_cast<int>(base::PlatformThread::CurrentId());
1542   if (process_sort_index_ != 0) {
1543     InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
1544                             current_thread_id, "process_sort_index",
1545                             "sort_index", process_sort_index_);
1546   }
1547
1548   if (process_name_.size()) {
1549     InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
1550                             current_thread_id, "process_name", "name",
1551                             process_name_);
1552   }
1553
1554   if (process_labels_.size() > 0) {
1555     std::vector<std::string> labels;
1556     for (base::hash_map<int, std::string>::iterator it =
1557              process_labels_.begin();
1558          it != process_labels_.end(); it++) {
1559       labels.push_back(it->second);
1560     }
1561     InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
1562                             current_thread_id, "process_labels", "labels",
1563                             base::JoinString(labels, ","));
1564   }
1565
1566   // Thread sort indices.
1567   for (hash_map<int, int>::iterator it = thread_sort_indices_.begin();
1568        it != thread_sort_indices_.end(); it++) {
1569     if (it->second == 0)
1570       continue;
1571     InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
1572                             it->first, "thread_sort_index", "sort_index",
1573                             it->second);
1574   }
1575
1576   // Thread names.
1577   AutoLock thread_info_lock(thread_info_lock_);
1578   for (hash_map<int, std::string>::iterator it = thread_names_.begin();
1579        it != thread_names_.end(); it++) {
1580     if (it->second.empty())
1581       continue;
1582     InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
1583                             it->first, "thread_name", "name", it->second);
1584   }
1585
1586   // If buffer is full, add a metadata record to report this.
1587   if (!buffer_limit_reached_timestamp_.is_null()) {
1588     InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
1589                             current_thread_id, "trace_buffer_overflowed",
1590                             "overflowed_at_ts",
1591                             buffer_limit_reached_timestamp_);
1592   }
1593 }
1594
1595 void TraceLog::WaitSamplingEventForTesting() {
1596   if (!sampling_thread_)
1597     return;
1598   sampling_thread_->WaitSamplingEventForTesting();
1599 }
1600
1601 void TraceLog::DeleteForTesting() {
1602   internal::DeleteTraceLogForTesting::Delete();
1603 }
1604
1605 TraceEvent* TraceLog::GetEventByHandle(TraceEventHandle handle) {
1606   return GetEventByHandleInternal(handle, NULL);
1607 }
1608
1609 TraceEvent* TraceLog::GetEventByHandleInternal(TraceEventHandle handle,
1610                                                OptionalAutoLock* lock) {
1611   if (!handle.chunk_seq)
1612     return NULL;
1613
1614   if (thread_local_event_buffer_.Get()) {
1615     TraceEvent* trace_event =
1616         thread_local_event_buffer_.Get()->GetEventByHandle(handle);
1617     if (trace_event)
1618       return trace_event;
1619   }
1620
1621   // The event has been out-of-control of the thread local buffer.
1622   // Try to get the event from the main buffer with a lock.
1623   if (lock)
1624     lock->EnsureAcquired();
1625
1626   if (thread_shared_chunk_ &&
1627       handle.chunk_index == thread_shared_chunk_index_) {
1628     return handle.chunk_seq == thread_shared_chunk_->seq()
1629                ? thread_shared_chunk_->GetEventAt(handle.event_index)
1630                : NULL;
1631   }
1632
1633   return logged_events_->GetEventByHandle(handle);
1634 }
1635
1636 void TraceLog::SetProcessID(int process_id) {
1637   process_id_ = process_id;
1638   // Create a FNV hash from the process ID for XORing.
1639   // See http://isthe.com/chongo/tech/comp/fnv/ for algorithm details.
1640   unsigned long long offset_basis = 14695981039346656037ull;
1641   unsigned long long fnv_prime = 1099511628211ull;
1642   unsigned long long pid = static_cast<unsigned long long>(process_id_);
1643   process_id_hash_ = (offset_basis ^ pid) * fnv_prime;
1644 }
1645
1646 void TraceLog::SetProcessSortIndex(int sort_index) {
1647   AutoLock lock(lock_);
1648   process_sort_index_ = sort_index;
1649 }
1650
1651 void TraceLog::SetProcessName(const std::string& process_name) {
1652   AutoLock lock(lock_);
1653   process_name_ = process_name;
1654 }
1655
1656 void TraceLog::UpdateProcessLabel(int label_id,
1657                                   const std::string& current_label) {
1658   if (!current_label.length())
1659     return RemoveProcessLabel(label_id);
1660
1661   AutoLock lock(lock_);
1662   process_labels_[label_id] = current_label;
1663 }
1664
1665 void TraceLog::RemoveProcessLabel(int label_id) {
1666   AutoLock lock(lock_);
1667   base::hash_map<int, std::string>::iterator it =
1668       process_labels_.find(label_id);
1669   if (it == process_labels_.end())
1670     return;
1671
1672   process_labels_.erase(it);
1673 }
1674
1675 void TraceLog::SetThreadSortIndex(PlatformThreadId thread_id, int sort_index) {
1676   AutoLock lock(lock_);
1677   thread_sort_indices_[static_cast<int>(thread_id)] = sort_index;
1678 }
1679
1680 void TraceLog::SetTimeOffset(TimeDelta offset) {
1681   time_offset_ = offset;
1682 }
1683
1684 size_t TraceLog::GetObserverCountForTest() const {
1685   return enabled_state_observer_list_.size();
1686 }
1687
1688 void TraceLog::SetCurrentThreadBlocksMessageLoop() {
1689   thread_blocks_message_loop_.Set(true);
1690   if (thread_local_event_buffer_.Get()) {
1691     // This will flush the thread local buffer.
1692     delete thread_local_event_buffer_.Get();
1693   }
1694 }
1695
1696 TraceBuffer* TraceLog::CreateTraceBuffer() {
1697   InternalTraceOptions options = trace_options();
1698   if (options & kInternalRecordContinuously)
1699     return TraceBuffer::CreateTraceBufferRingBuffer(
1700         kTraceEventRingBufferChunks);
1701   else if ((options & kInternalEnableSampling) && mode_ == MONITORING_MODE)
1702     return TraceBuffer::CreateTraceBufferRingBuffer(
1703         kMonitorTraceEventBufferChunks);
1704   else if (options & kInternalEchoToConsole)
1705     return TraceBuffer::CreateTraceBufferRingBuffer(
1706         kEchoToConsoleTraceEventBufferChunks);
1707   else if (options & kInternalRecordAsMuchAsPossible)
1708     return TraceBuffer::CreateTraceBufferVectorOfSize(
1709         kTraceEventVectorBigBufferChunks);
1710   return TraceBuffer::CreateTraceBufferVectorOfSize(
1711       kTraceEventVectorBufferChunks);
1712 }
1713
1714 #if defined(OS_WIN)
1715 void TraceLog::UpdateETWCategoryGroupEnabledFlags() {
1716   AutoLock lock(lock_);
1717   size_t category_index = base::subtle::NoBarrier_Load(&g_category_index);
1718   // Go through each category and set/clear the ETW bit depending on whether the
1719   // category is enabled.
1720   for (size_t i = 0; i < category_index; i++) {
1721     const char* category_group = g_category_groups[i];
1722     DCHECK(category_group);
1723     if (base::trace_event::TraceEventETWExport::IsCategoryGroupEnabled(
1724             category_group)) {
1725       g_category_group_enabled[i] |= ENABLED_FOR_ETW_EXPORT;
1726     } else {
1727       g_category_group_enabled[i] &= ~ENABLED_FOR_ETW_EXPORT;
1728     }
1729   }
1730 }
1731 #endif  // defined(OS_WIN)
1732
1733 void ConvertableToTraceFormat::EstimateTraceMemoryOverhead(
1734     TraceEventMemoryOverhead* overhead) {
1735   overhead->Add("ConvertableToTraceFormat(Unknown)", sizeof(*this));
1736 }
1737
1738 }  // namespace trace_event
1739 }  // namespace base
1740
1741 namespace trace_event_internal {
1742
1743 ScopedTraceBinaryEfficient::ScopedTraceBinaryEfficient(
1744     const char* category_group,
1745     const char* name) {
1746   // The single atom works because for now the category_group can only be "gpu".
1747   DCHECK_EQ(strcmp(category_group, "gpu"), 0);
1748   static TRACE_EVENT_API_ATOMIC_WORD atomic = 0;
1749   INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO_CUSTOM_VARIABLES(
1750       category_group, atomic, category_group_enabled_);
1751   name_ = name;
1752   if (*category_group_enabled_) {
1753     event_handle_ =
1754         TRACE_EVENT_API_ADD_TRACE_EVENT_WITH_THREAD_ID_AND_TIMESTAMP(
1755             TRACE_EVENT_PHASE_COMPLETE,
1756             category_group_enabled_,
1757             name,
1758             trace_event_internal::kNoId,  // id
1759             trace_event_internal::kNoId,  // context_id
1760             static_cast<int>(base::PlatformThread::CurrentId()),  // thread_id
1761             base::TraceTicks::Now(),
1762             trace_event_internal::kZeroNumArgs,
1763             nullptr,
1764             nullptr,
1765             nullptr,
1766             nullptr,
1767             TRACE_EVENT_FLAG_NONE);
1768   }
1769 }
1770
1771 ScopedTraceBinaryEfficient::~ScopedTraceBinaryEfficient() {
1772   if (*category_group_enabled_) {
1773     TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION(category_group_enabled_, name_,
1774                                                 event_handle_);
1775   }
1776 }
1777
1778 }  // namespace trace_event_internal