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