src/base/debug/trace_event_impl.cc

   1 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "base/debug/trace_event_impl.h"
   6
   7 #include <algorithm>
   8
   9 #include "base/base_switches.h"
  10 #include "base/bind.h"
  11 #include "base/command_line.h"
  12 #include "base/debug/leak_annotations.h"
  13 #include "base/debug/trace_event.h"
  14 #include "base/debug/trace_event_synthetic_delay.h"
  15 #include "base/float_util.h"
  16 #include "base/format_macros.h"
  17 #include "base/json/string_escape.h"
  18 #include "base/lazy_instance.h"
  19 #include "base/memory/singleton.h"
  20 #include "base/message_loop/message_loop.h"
  21 #include "base/process/process_metrics.h"
  22 #include "base/stl_util.h"
  23 #include "base/strings/string_number_conversions.h"
  24 #include "base/strings/string_split.h"
  25 #include "base/strings/string_tokenizer.h"
  26 #include "base/strings/string_util.h"
  27 #include "base/strings/stringprintf.h"
  28 #include "base/strings/utf_string_conversions.h"
  29 #include "base/synchronization/cancellation_flag.h"
  30 #include "base/synchronization/waitable_event.h"
  31 #include "base/sys_info.h"
  32 #include "base/third_party/dynamic_annotations/dynamic_annotations.h"
  33 #include "base/threading/platform_thread.h"
  34 #include "base/threading/thread_id_name_manager.h"
  35 #include "base/time/time.h"
  36
  37 #if defined(OS_WIN)
  38 #include "base/debug/trace_event_win.h"
  39 #endif
  40
  41 class DeleteTraceLogForTesting {
  42  public:
  43   static void Delete() {
  44     Singleton<base::debug::TraceLog,
  45               LeakySingletonTraits<base::debug::TraceLog> >::OnExit(0);
  46   }
  47 };
  48
  49 // The thread buckets for the sampling profiler.
  50 BASE_EXPORT TRACE_EVENT_API_ATOMIC_WORD g_trace_state[3];
  51
  52 namespace base {
  53 namespace debug {
  54
  55 namespace {
  56
  57 // The overhead of TraceEvent above this threshold will be reported in the
  58 // trace.
  59 const int kOverheadReportThresholdInMicroseconds = 50;
  60
  61 // String options that can be used to initialize TraceOptions.
  62 const char kRecordUntilFull[] = "record-until-full";
  63 const char kRecordContinuously[] = "record-continuously";
  64 const char kRecordAsMuchAsPossible[] = "record-as-much-as-possible";
  65 const char kTraceToConsole[] = "trace-to-console";
  66 const char kEnableSampling[] = "enable-sampling";
  67 const char kEnableSystrace[] = "enable-systrace";
  68
  69 // Controls the number of trace events we will buffer in-memory
  70 // before throwing them away.
  71 const size_t kTraceBufferChunkSize = TraceBufferChunk::kTraceBufferChunkSize;
  72 const size_t kTraceEventVectorBigBufferChunks =
  73     512000000 / kTraceBufferChunkSize;
  74 const size_t kTraceEventVectorBufferChunks = 256000 / kTraceBufferChunkSize;
  75 const size_t kTraceEventRingBufferChunks = kTraceEventVectorBufferChunks / 4;
  76 const size_t kTraceEventBatchChunks = 1000 / kTraceBufferChunkSize;
  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 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 const char kSyntheticDelayCategoryFilterPrefix[] = "DELAY(";
  90
  91 #define MAX_CATEGORY_GROUPS 100
  92
  93 // Parallel arrays g_category_groups and g_category_group_enabled are separate
  94 // so that a pointer to a member of g_category_group_enabled can be easily
  95 // converted to an index into g_category_groups. This allows macros to deal
  96 // only with char enabled pointers from g_category_group_enabled, and we can
  97 // convert internally to determine the category name from the char enabled
  98 // pointer.
  99 const char* g_category_groups[MAX_CATEGORY_GROUPS] = {
 100   "toplevel",
 101   "tracing already shutdown",
 102   "tracing categories exhausted; must increase MAX_CATEGORY_GROUPS",
 103   "__metadata",
 104   // For reporting trace_event overhead. For thread local event buffers only.
 105   "trace_event_overhead"};
 106
 107 // The enabled flag is char instead of bool so that the API can be used from C.
 108 unsigned char g_category_group_enabled[MAX_CATEGORY_GROUPS] = { 0 };
 109 // Indexes here have to match the g_category_groups array indexes above.
 110 const int g_category_already_shutdown = 1;
 111 const int g_category_categories_exhausted = 2;
 112 const int g_category_metadata = 3;
 113 const int g_category_trace_event_overhead = 4;
 114 const int g_num_builtin_categories = 5;
 115 // Skip default categories.
 116 base::subtle::AtomicWord g_category_index = g_num_builtin_categories;
 117
 118 // The name of the current thread. This is used to decide if the current
 119 // thread name has changed. We combine all the seen thread names into the
 120 // output name for the thread.
 121 LazyInstance<ThreadLocalPointer<const char> >::Leaky
 122     g_current_thread_name = LAZY_INSTANCE_INITIALIZER;
 123
 124 TimeTicks ThreadNow() {
 125   return TimeTicks::IsThreadNowSupported() ?
 126       TimeTicks::ThreadNow() : TimeTicks();
 127 }
 128
 129 class TraceBufferRingBuffer : public TraceBuffer {
 130  public:
 131   TraceBufferRingBuffer(size_t max_chunks)
 132       : max_chunks_(max_chunks),
 133         recyclable_chunks_queue_(new size_t[queue_capacity()]),
 134         queue_head_(0),
 135         queue_tail_(max_chunks),
 136         current_iteration_index_(0),
 137         current_chunk_seq_(1) {
 138     chunks_.reserve(max_chunks);
 139     for (size_t i = 0; i < max_chunks; ++i)
 140       recyclable_chunks_queue_[i] = i;
 141   }
 142
 143   scoped_ptr<TraceBufferChunk> GetChunk(size_t* index) override {
 144     // Because the number of threads is much less than the number of chunks,
 145     // the queue should never be empty.
 146     DCHECK(!QueueIsEmpty());
 147
 148     *index = recyclable_chunks_queue_[queue_head_];
 149     queue_head_ = NextQueueIndex(queue_head_);
 150     current_iteration_index_ = queue_head_;
 151
 152     if (*index >= chunks_.size())
 153       chunks_.resize(*index + 1);
 154
 155     TraceBufferChunk* chunk = chunks_[*index];
 156     chunks_[*index] = NULL;  // Put NULL in the slot of a in-flight chunk.
 157     if (chunk)
 158       chunk->Reset(current_chunk_seq_++);
 159     else
 160       chunk = new TraceBufferChunk(current_chunk_seq_++);
 161
 162     return scoped_ptr<TraceBufferChunk>(chunk);
 163   }
 164
 165   void ReturnChunk(size_t index, scoped_ptr<TraceBufferChunk> chunk) override {
 166     // When this method is called, the queue should not be full because it
 167     // can contain all chunks including the one to be returned.
 168     DCHECK(!QueueIsFull());
 169     DCHECK(chunk);
 170     DCHECK_LT(index, chunks_.size());
 171     DCHECK(!chunks_[index]);
 172     chunks_[index] = chunk.release();
 173     recyclable_chunks_queue_[queue_tail_] = index;
 174     queue_tail_ = NextQueueIndex(queue_tail_);
 175   }
 176
 177   bool IsFull() const override { return false; }
 178
 179   size_t Size() const override {
 180     // This is approximate because not all of the chunks are full.
 181     return chunks_.size() * kTraceBufferChunkSize;
 182   }
 183
 184   size_t Capacity() const override {
 185     return max_chunks_ * kTraceBufferChunkSize;
 186   }
 187
 188   TraceEvent* GetEventByHandle(TraceEventHandle handle) override {
 189     if (handle.chunk_index >= chunks_.size())
 190       return NULL;
 191     TraceBufferChunk* chunk = chunks_[handle.chunk_index];
 192     if (!chunk || chunk->seq() != handle.chunk_seq)
 193       return NULL;
 194     return chunk->GetEventAt(handle.event_index);
 195   }
 196
 197   const TraceBufferChunk* NextChunk() override {
 198     if (chunks_.empty())
 199       return NULL;
 200
 201     while (current_iteration_index_ != queue_tail_) {
 202       size_t chunk_index = recyclable_chunks_queue_[current_iteration_index_];
 203       current_iteration_index_ = NextQueueIndex(current_iteration_index_);
 204       if (chunk_index >= chunks_.size()) // Skip uninitialized chunks.
 205         continue;
 206       DCHECK(chunks_[chunk_index]);
 207       return chunks_[chunk_index];
 208     }
 209     return NULL;
 210   }
 211
 212   scoped_ptr<TraceBuffer> CloneForIteration() const override {
 213     scoped_ptr<ClonedTraceBuffer> cloned_buffer(new ClonedTraceBuffer());
 214     for (size_t queue_index = queue_head_; queue_index != queue_tail_;
 215         queue_index = NextQueueIndex(queue_index)) {
 216       size_t chunk_index = recyclable_chunks_queue_[queue_index];
 217       if (chunk_index >= chunks_.size()) // Skip uninitialized chunks.
 218         continue;
 219       TraceBufferChunk* chunk = chunks_[chunk_index];
 220       cloned_buffer->chunks_.push_back(chunk ? chunk->Clone().release() : NULL);
 221     }
 222     return cloned_buffer.Pass();
 223   }
 224
 225  private:
 226   class ClonedTraceBuffer : public TraceBuffer {
 227    public:
 228     ClonedTraceBuffer() : current_iteration_index_(0) {}
 229
 230     // The only implemented method.
 231     const TraceBufferChunk* NextChunk() override {
 232       return current_iteration_index_ < chunks_.size() ?
 233           chunks_[current_iteration_index_++] : NULL;
 234     }
 235
 236     scoped_ptr<TraceBufferChunk> GetChunk(size_t* index) override {
 237       NOTIMPLEMENTED();
 238       return scoped_ptr<TraceBufferChunk>();
 239     }
 240     void ReturnChunk(size_t index, scoped_ptr<TraceBufferChunk>) override {
 241       NOTIMPLEMENTED();
 242     }
 243     bool IsFull() const override { return false; }
 244     size_t Size() const override { return 0; }
 245     size_t Capacity() const override { return 0; }
 246     TraceEvent* GetEventByHandle(TraceEventHandle handle) override {
 247       return NULL;
 248     }
 249     scoped_ptr<TraceBuffer> CloneForIteration() const override {
 250       NOTIMPLEMENTED();
 251       return scoped_ptr<TraceBuffer>();
 252     }
 253
 254     size_t current_iteration_index_;
 255     ScopedVector<TraceBufferChunk> chunks_;
 256   };
 257
 258   bool QueueIsEmpty() const {
 259     return queue_head_ == queue_tail_;
 260   }
 261
 262   size_t QueueSize() const {
 263     return queue_tail_ > queue_head_ ? queue_tail_ - queue_head_ :
 264         queue_tail_ + queue_capacity() - queue_head_;
 265   }
 266
 267   bool QueueIsFull() const {
 268     return QueueSize() == queue_capacity() - 1;
 269   }
 270
 271   size_t queue_capacity() const {
 272     // One extra space to help distinguish full state and empty state.
 273     return max_chunks_ + 1;
 274   }
 275
 276   size_t NextQueueIndex(size_t index) const {
 277     index++;
 278     if (index >= queue_capacity())
 279       index = 0;
 280     return index;
 281   }
 282
 283   size_t max_chunks_;
 284   ScopedVector<TraceBufferChunk> chunks_;
 285
 286   scoped_ptr<size_t[]> recyclable_chunks_queue_;
 287   size_t queue_head_;
 288   size_t queue_tail_;
 289
 290   size_t current_iteration_index_;
 291   uint32 current_chunk_seq_;
 292
 293   DISALLOW_COPY_AND_ASSIGN(TraceBufferRingBuffer);
 294 };
 295
 296 class TraceBufferVector : public TraceBuffer {
 297  public:
 298   TraceBufferVector(size_t max_chunks)
 299       : in_flight_chunk_count_(0),
 300         current_iteration_index_(0),
 301         max_chunks_(max_chunks) {
 302     chunks_.reserve(max_chunks_);
 303   }
 304
 305   scoped_ptr<TraceBufferChunk> GetChunk(size_t* index) override {
 306     // This function may be called when adding normal events or indirectly from
 307     // AddMetadataEventsWhileLocked(). We can not DECHECK(!IsFull()) because we
 308     // have to add the metadata events and flush thread-local buffers even if
 309     // the buffer is full.
 310     *index = chunks_.size();
 311     chunks_.push_back(NULL);  // Put NULL in the slot of a in-flight chunk.
 312     ++in_flight_chunk_count_;
 313     // + 1 because zero chunk_seq is not allowed.
 314     return scoped_ptr<TraceBufferChunk>(
 315         new TraceBufferChunk(static_cast<uint32>(*index) + 1));
 316   }
 317
 318   void ReturnChunk(size_t index, scoped_ptr<TraceBufferChunk> chunk) override {
 319     DCHECK_GT(in_flight_chunk_count_, 0u);
 320     DCHECK_LT(index, chunks_.size());
 321     DCHECK(!chunks_[index]);
 322     --in_flight_chunk_count_;
 323     chunks_[index] = chunk.release();
 324   }
 325
 326   bool IsFull() const override { return chunks_.size() >= max_chunks_; }
 327
 328   size_t Size() const override {
 329     // This is approximate because not all of the chunks are full.
 330     return chunks_.size() * kTraceBufferChunkSize;
 331   }
 332
 333   size_t Capacity() const override {
 334     return max_chunks_ * kTraceBufferChunkSize;
 335   }
 336
 337   TraceEvent* GetEventByHandle(TraceEventHandle handle) override {
 338     if (handle.chunk_index >= chunks_.size())
 339       return NULL;
 340     TraceBufferChunk* chunk = chunks_[handle.chunk_index];
 341     if (!chunk || chunk->seq() != handle.chunk_seq)
 342       return NULL;
 343     return chunk->GetEventAt(handle.event_index);
 344   }
 345
 346   const TraceBufferChunk* NextChunk() override {
 347     while (current_iteration_index_ < chunks_.size()) {
 348       // Skip in-flight chunks.
 349       const TraceBufferChunk* chunk = chunks_[current_iteration_index_++];
 350       if (chunk)
 351         return chunk;
 352     }
 353     return NULL;
 354   }
 355
 356   scoped_ptr<TraceBuffer> CloneForIteration() const override {
 357     NOTIMPLEMENTED();
 358     return scoped_ptr<TraceBuffer>();
 359   }
 360
 361  private:
 362   size_t in_flight_chunk_count_;
 363   size_t current_iteration_index_;
 364   size_t max_chunks_;
 365   ScopedVector<TraceBufferChunk> chunks_;
 366
 367   DISALLOW_COPY_AND_ASSIGN(TraceBufferVector);
 368 };
 369
 370 template <typename T>
 371 void InitializeMetadataEvent(TraceEvent* trace_event,
 372                              int thread_id,
 373                              const char* metadata_name, const char* arg_name,
 374                              const T& value) {
 375   if (!trace_event)
 376     return;
 377
 378   int num_args = 1;
 379   unsigned char arg_type;
 380   unsigned long long arg_value;
 381   ::trace_event_internal::SetTraceValue(value, &arg_type, &arg_value);
 382   trace_event->Initialize(thread_id,
 383                           TimeTicks(), TimeTicks(), TRACE_EVENT_PHASE_METADATA,
 384                           &g_category_group_enabled[g_category_metadata],
 385                           metadata_name, ::trace_event_internal::kNoEventId,
 386                           num_args, &arg_name, &arg_type, &arg_value, NULL,
 387                           TRACE_EVENT_FLAG_NONE);
 388 }
 389
 390 class AutoThreadLocalBoolean {
 391  public:
 392   explicit AutoThreadLocalBoolean(ThreadLocalBoolean* thread_local_boolean)
 393       : thread_local_boolean_(thread_local_boolean) {
 394     DCHECK(!thread_local_boolean_->Get());
 395     thread_local_boolean_->Set(true);
 396   }
 397   ~AutoThreadLocalBoolean() {
 398     thread_local_boolean_->Set(false);
 399   }
 400
 401  private:
 402   ThreadLocalBoolean* thread_local_boolean_;
 403   DISALLOW_COPY_AND_ASSIGN(AutoThreadLocalBoolean);
 404 };
 405
 406 }  // namespace
 407
 408 void TraceBufferChunk::Reset(uint32 new_seq) {
 409   for (size_t i = 0; i < next_free_; ++i)
 410     chunk_[i].Reset();
 411   next_free_ = 0;
 412   seq_ = new_seq;
 413 }
 414
 415 TraceEvent* TraceBufferChunk::AddTraceEvent(size_t* event_index) {
 416   DCHECK(!IsFull());
 417   *event_index = next_free_++;
 418   return &chunk_[*event_index];
 419 }
 420
 421 scoped_ptr<TraceBufferChunk> TraceBufferChunk::Clone() const {
 422   scoped_ptr<TraceBufferChunk> cloned_chunk(new TraceBufferChunk(seq_));
 423   cloned_chunk->next_free_ = next_free_;
 424   for (size_t i = 0; i < next_free_; ++i)
 425     cloned_chunk->chunk_[i].CopyFrom(chunk_[i]);
 426   return cloned_chunk.Pass();
 427 }
 428
 429 // A helper class that allows the lock to be acquired in the middle of the scope
 430 // and unlocks at the end of scope if locked.
 431 class TraceLog::OptionalAutoLock {
 432  public:
 433   explicit OptionalAutoLock(Lock& lock)
 434       : lock_(lock),
 435         locked_(false) {
 436   }
 437
 438   ~OptionalAutoLock() {
 439     if (locked_)
 440       lock_.Release();
 441   }
 442
 443   void EnsureAcquired() {
 444     if (!locked_) {
 445       lock_.Acquire();
 446       locked_ = true;
 447     }
 448   }
 449
 450  private:
 451   Lock& lock_;
 452   bool locked_;
 453   DISALLOW_COPY_AND_ASSIGN(OptionalAutoLock);
 454 };
 455
 456 // Use this function instead of TraceEventHandle constructor to keep the
 457 // overhead of ScopedTracer (trace_event.h) constructor minimum.
 458 void MakeHandle(uint32 chunk_seq, size_t chunk_index, size_t event_index,
 459                 TraceEventHandle* handle) {
 460   DCHECK(chunk_seq);
 461   DCHECK(chunk_index < (1u << 16));
 462   DCHECK(event_index < (1u << 16));
 463   handle->chunk_seq = chunk_seq;
 464   handle->chunk_index = static_cast<uint16>(chunk_index);
 465   handle->event_index = static_cast<uint16>(event_index);
 466 }
 467
 468 ////////////////////////////////////////////////////////////////////////////////
 469 //
 470 // TraceEvent
 471 //
 472 ////////////////////////////////////////////////////////////////////////////////
 473
 474 namespace {
 475
 476 size_t GetAllocLength(const char* str) { return str ? strlen(str) + 1 : 0; }
 477
 478 // Copies |*member| into |*buffer|, sets |*member| to point to this new
 479 // location, and then advances |*buffer| by the amount written.
 480 void CopyTraceEventParameter(char** buffer,
 481                              const char** member,
 482                              const char* end) {
 483   if (*member) {
 484     size_t written = strlcpy(*buffer, *member, end - *buffer) + 1;
 485     DCHECK_LE(static_cast<int>(written), end - *buffer);
 486     *member = *buffer;
 487     *buffer += written;
 488   }
 489 }
 490
 491 }  // namespace
 492
 493 TraceEvent::TraceEvent()
 494     : duration_(TimeDelta::FromInternalValue(-1)),
 495       id_(0u),
 496       category_group_enabled_(NULL),
 497       name_(NULL),
 498       thread_id_(0),
 499       phase_(TRACE_EVENT_PHASE_BEGIN),
 500       flags_(0) {
 501   for (int i = 0; i < kTraceMaxNumArgs; ++i)
 502     arg_names_[i] = NULL;
 503   memset(arg_values_, 0, sizeof(arg_values_));
 504 }
 505
 506 TraceEvent::~TraceEvent() {
 507 }
 508
 509 void TraceEvent::CopyFrom(const TraceEvent& other) {
 510   timestamp_ = other.timestamp_;
 511   thread_timestamp_ = other.thread_timestamp_;
 512   duration_ = other.duration_;
 513   id_ = other.id_;
 514   category_group_enabled_ = other.category_group_enabled_;
 515   name_ = other.name_;
 516   thread_id_ = other.thread_id_;
 517   phase_ = other.phase_;
 518   flags_ = other.flags_;
 519   parameter_copy_storage_ = other.parameter_copy_storage_;
 520
 521   for (int i = 0; i < kTraceMaxNumArgs; ++i) {
 522     arg_names_[i] = other.arg_names_[i];
 523     arg_types_[i] = other.arg_types_[i];
 524     arg_values_[i] = other.arg_values_[i];
 525     convertable_values_[i] = other.convertable_values_[i];
 526   }
 527 }
 528
 529 void TraceEvent::Initialize(
 530     int thread_id,
 531     TimeTicks timestamp,
 532     TimeTicks thread_timestamp,
 533     char phase,
 534     const unsigned char* category_group_enabled,
 535     const char* name,
 536     unsigned long long id,
 537     int num_args,
 538     const char** arg_names,
 539     const unsigned char* arg_types,
 540     const unsigned long long* arg_values,
 541     const scoped_refptr<ConvertableToTraceFormat>* convertable_values,
 542     unsigned char flags) {
 543   timestamp_ = timestamp;
 544   thread_timestamp_ = thread_timestamp;
 545   duration_ = TimeDelta::FromInternalValue(-1);
 546   id_ = id;
 547   category_group_enabled_ = category_group_enabled;
 548   name_ = name;
 549   thread_id_ = thread_id;
 550   phase_ = phase;
 551   flags_ = flags;
 552
 553   // Clamp num_args since it may have been set by a third_party library.
 554   num_args = (num_args > kTraceMaxNumArgs) ? kTraceMaxNumArgs : num_args;
 555   int i = 0;
 556   for (; i < num_args; ++i) {
 557     arg_names_[i] = arg_names[i];
 558     arg_types_[i] = arg_types[i];
 559
 560     if (arg_types[i] == TRACE_VALUE_TYPE_CONVERTABLE)
 561       convertable_values_[i] = convertable_values[i];
 562     else
 563       arg_values_[i].as_uint = arg_values[i];
 564   }
 565   for (; i < kTraceMaxNumArgs; ++i) {
 566     arg_names_[i] = NULL;
 567     arg_values_[i].as_uint = 0u;
 568     convertable_values_[i] = NULL;
 569     arg_types_[i] = TRACE_VALUE_TYPE_UINT;
 570   }
 571
 572   bool copy = !!(flags & TRACE_EVENT_FLAG_COPY);
 573   size_t alloc_size = 0;
 574   if (copy) {
 575     alloc_size += GetAllocLength(name);
 576     for (i = 0; i < num_args; ++i) {
 577       alloc_size += GetAllocLength(arg_names_[i]);
 578       if (arg_types_[i] == TRACE_VALUE_TYPE_STRING)
 579         arg_types_[i] = TRACE_VALUE_TYPE_COPY_STRING;
 580     }
 581   }
 582
 583   bool arg_is_copy[kTraceMaxNumArgs];
 584   for (i = 0; i < num_args; ++i) {
 585     // No copying of convertable types, we retain ownership.
 586     if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
 587       continue;
 588
 589     // We only take a copy of arg_vals if they are of type COPY_STRING.
 590     arg_is_copy[i] = (arg_types_[i] == TRACE_VALUE_TYPE_COPY_STRING);
 591     if (arg_is_copy[i])
 592       alloc_size += GetAllocLength(arg_values_[i].as_string);
 593   }
 594
 595   if (alloc_size) {
 596     parameter_copy_storage_ = new RefCountedString;
 597     parameter_copy_storage_->data().resize(alloc_size);
 598     char* ptr = string_as_array(&parameter_copy_storage_->data());
 599     const char* end = ptr + alloc_size;
 600     if (copy) {
 601       CopyTraceEventParameter(&ptr, &name_, end);
 602       for (i = 0; i < num_args; ++i) {
 603         CopyTraceEventParameter(&ptr, &arg_names_[i], end);
 604       }
 605     }
 606     for (i = 0; i < num_args; ++i) {
 607       if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
 608         continue;
 609       if (arg_is_copy[i])
 610         CopyTraceEventParameter(&ptr, &arg_values_[i].as_string, end);
 611     }
 612     DCHECK_EQ(end, ptr) << "Overrun by " << ptr - end;
 613   }
 614 }
 615
 616 void TraceEvent::Reset() {
 617   // Only reset fields that won't be initialized in Initialize(), or that may
 618   // hold references to other objects.
 619   duration_ = TimeDelta::FromInternalValue(-1);
 620   parameter_copy_storage_ = NULL;
 621   for (int i = 0; i < kTraceMaxNumArgs; ++i)
 622     convertable_values_[i] = NULL;
 623 }
 624
 625 void TraceEvent::UpdateDuration(const TimeTicks& now,
 626                                 const TimeTicks& thread_now) {
 627   DCHECK(duration_.ToInternalValue() == -1);
 628   duration_ = now - timestamp_;
 629   thread_duration_ = thread_now - thread_timestamp_;
 630 }
 631
 632 // static
 633 void TraceEvent::AppendValueAsJSON(unsigned char type,
 634                                    TraceEvent::TraceValue value,
 635                                    std::string* out) {
 636   switch (type) {
 637     case TRACE_VALUE_TYPE_BOOL:
 638       *out += value.as_bool ? "true" : "false";
 639       break;
 640     case TRACE_VALUE_TYPE_UINT:
 641       StringAppendF(out, "%" PRIu64, static_cast<uint64>(value.as_uint));
 642       break;
 643     case TRACE_VALUE_TYPE_INT:
 644       StringAppendF(out, "%" PRId64, static_cast<int64>(value.as_int));
 645       break;
 646     case TRACE_VALUE_TYPE_DOUBLE: {
 647       // FIXME: base/json/json_writer.cc is using the same code,
 648       //        should be made into a common method.
 649       std::string real;
 650       double val = value.as_double;
 651       if (IsFinite(val)) {
 652         real = DoubleToString(val);
 653         // Ensure that the number has a .0 if there's no decimal or 'e'.  This
 654         // makes sure that when we read the JSON back, it's interpreted as a
 655         // real rather than an int.
 656         if (real.find('.') == std::string::npos &&
 657             real.find('e') == std::string::npos &&
 658             real.find('E') == std::string::npos) {
 659           real.append(".0");
 660         }
 661         // The JSON spec requires that non-integer values in the range (-1,1)
 662         // have a zero before the decimal point - ".52" is not valid, "0.52" is.
 663         if (real[0] == '.') {
 664           real.insert(0, "0");
 665         } else if (real.length() > 1 && real[0] == '-' && real[1] == '.') {
 666           // "-.1" bad "-0.1" good
 667           real.insert(1, "0");
 668         }
 669       } else if (IsNaN(val)){
 670         // The JSON spec doesn't allow NaN and Infinity (since these are
 671         // objects in EcmaScript).  Use strings instead.
 672         real = "\"NaN\"";
 673       } else if (val < 0) {
 674         real = "\"-Infinity\"";
 675       } else {
 676         real = "\"Infinity\"";
 677       }
 678       StringAppendF(out, "%s", real.c_str());
 679       break;
 680     }
 681     case TRACE_VALUE_TYPE_POINTER:
 682       // JSON only supports double and int numbers.
 683       // So as not to lose bits from a 64-bit pointer, output as a hex string.
 684       StringAppendF(out, "\"0x%" PRIx64 "\"", static_cast<uint64>(
 685                                      reinterpret_cast<intptr_t>(
 686                                      value.as_pointer)));
 687       break;
 688     case TRACE_VALUE_TYPE_STRING:
 689     case TRACE_VALUE_TYPE_COPY_STRING:
 690       EscapeJSONString(value.as_string ? value.as_string : "NULL", true, out);
 691       break;
 692     default:
 693       NOTREACHED() << "Don't know how to print this value";
 694       break;
 695   }
 696 }
 697
 698 void TraceEvent::AppendAsJSON(std::string* out) const {
 699   int64 time_int64 = timestamp_.ToInternalValue();
 700   int process_id = TraceLog::GetInstance()->process_id();
 701   // Category group checked at category creation time.
 702   DCHECK(!strchr(name_, '"'));
 703   StringAppendF(out,
 704       "{\"cat\":\"%s\",\"pid\":%i,\"tid\":%i,\"ts\":%" PRId64 ","
 705       "\"ph\":\"%c\",\"name\":\"%s\",\"args\":{",
 706       TraceLog::GetCategoryGroupName(category_group_enabled_),
 707       process_id,
 708       thread_id_,
 709       time_int64,
 710       phase_,
 711       name_);
 712
 713   // Output argument names and values, stop at first NULL argument name.
 714   for (int i = 0; i < kTraceMaxNumArgs && arg_names_[i]; ++i) {
 715     if (i > 0)
 716       *out += ",";
 717     *out += "\"";
 718     *out += arg_names_[i];
 719     *out += "\":";
 720
 721     if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
 722       convertable_values_[i]->AppendAsTraceFormat(out);
 723     else
 724       AppendValueAsJSON(arg_types_[i], arg_values_[i], out);
 725   }
 726   *out += "}";
 727
 728   if (phase_ == TRACE_EVENT_PHASE_COMPLETE) {
 729     int64 duration = duration_.ToInternalValue();
 730     if (duration != -1)
 731       StringAppendF(out, ",\"dur\":%" PRId64, duration);
 732     if (!thread_timestamp_.is_null()) {
 733       int64 thread_duration = thread_duration_.ToInternalValue();
 734       if (thread_duration != -1)
 735         StringAppendF(out, ",\"tdur\":%" PRId64, thread_duration);
 736     }
 737   }
 738
 739   // Output tts if thread_timestamp is valid.
 740   if (!thread_timestamp_.is_null()) {
 741     int64 thread_time_int64 = thread_timestamp_.ToInternalValue();
 742     StringAppendF(out, ",\"tts\":%" PRId64, thread_time_int64);
 743   }
 744
 745   // If id_ is set, print it out as a hex string so we don't loose any
 746   // bits (it might be a 64-bit pointer).
 747   if (flags_ & TRACE_EVENT_FLAG_HAS_ID)
 748     StringAppendF(out, ",\"id\":\"0x%" PRIx64 "\"", static_cast<uint64>(id_));
 749
 750   // Instant events also output their scope.
 751   if (phase_ == TRACE_EVENT_PHASE_INSTANT) {
 752     char scope = '?';
 753     switch (flags_ & TRACE_EVENT_FLAG_SCOPE_MASK) {
 754       case TRACE_EVENT_SCOPE_GLOBAL:
 755         scope = TRACE_EVENT_SCOPE_NAME_GLOBAL;
 756         break;
 757
 758       case TRACE_EVENT_SCOPE_PROCESS:
 759         scope = TRACE_EVENT_SCOPE_NAME_PROCESS;
 760         break;
 761
 762       case TRACE_EVENT_SCOPE_THREAD:
 763         scope = TRACE_EVENT_SCOPE_NAME_THREAD;
 764         break;
 765     }
 766     StringAppendF(out, ",\"s\":\"%c\"", scope);
 767   }
 768
 769   *out += "}";
 770 }
 771
 772 void TraceEvent::AppendPrettyPrinted(std::ostringstream* out) const {
 773   *out << name_ << "[";
 774   *out << TraceLog::GetCategoryGroupName(category_group_enabled_);
 775   *out << "]";
 776   if (arg_names_[0]) {
 777     *out << ", {";
 778     for (int i = 0; i < kTraceMaxNumArgs && arg_names_[i]; ++i) {
 779       if (i > 0)
 780         *out << ", ";
 781       *out << arg_names_[i] << ":";
 782       std::string value_as_text;
 783
 784       if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
 785         convertable_values_[i]->AppendAsTraceFormat(&value_as_text);
 786       else
 787         AppendValueAsJSON(arg_types_[i], arg_values_[i], &value_as_text);
 788
 789       *out << value_as_text;
 790     }
 791     *out << "}";
 792   }
 793 }
 794
 795 ////////////////////////////////////////////////////////////////////////////////
 796 //
 797 // TraceResultBuffer
 798 //
 799 ////////////////////////////////////////////////////////////////////////////////
 800
 801 TraceResultBuffer::OutputCallback
 802     TraceResultBuffer::SimpleOutput::GetCallback() {
 803   return Bind(&SimpleOutput::Append, Unretained(this));
 804 }
 805
 806 void TraceResultBuffer::SimpleOutput::Append(
 807     const std::string& json_trace_output) {
 808   json_output += json_trace_output;
 809 }
 810
 811 TraceResultBuffer::TraceResultBuffer() : append_comma_(false) {
 812 }
 813
 814 TraceResultBuffer::~TraceResultBuffer() {
 815 }
 816
 817 void TraceResultBuffer::SetOutputCallback(
 818     const OutputCallback& json_chunk_callback) {
 819   output_callback_ = json_chunk_callback;
 820 }
 821
 822 void TraceResultBuffer::Start() {
 823   append_comma_ = false;
 824   output_callback_.Run("[");
 825 }
 826
 827 void TraceResultBuffer::AddFragment(const std::string& trace_fragment) {
 828   if (append_comma_)
 829     output_callback_.Run(",");
 830   append_comma_ = true;
 831   output_callback_.Run(trace_fragment);
 832 }
 833
 834 void TraceResultBuffer::Finish() {
 835   output_callback_.Run("]");
 836 }
 837
 838 ////////////////////////////////////////////////////////////////////////////////
 839 //
 840 // TraceSamplingThread
 841 //
 842 ////////////////////////////////////////////////////////////////////////////////
 843 class TraceBucketData;
 844 typedef base::Callback<void(TraceBucketData*)> TraceSampleCallback;
 845
 846 class TraceBucketData {
 847  public:
 848   TraceBucketData(base::subtle::AtomicWord* bucket,
 849                   const char* name,
 850                   TraceSampleCallback callback);
 851   ~TraceBucketData();
 852
 853   TRACE_EVENT_API_ATOMIC_WORD* bucket;
 854   const char* bucket_name;
 855   TraceSampleCallback callback;
 856 };
 857
 858 // This object must be created on the IO thread.
 859 class TraceSamplingThread : public PlatformThread::Delegate {
 860  public:
 861   TraceSamplingThread();
 862   ~TraceSamplingThread() override;
 863
 864   // Implementation of PlatformThread::Delegate:
 865   void ThreadMain() override;
 866
 867   static void DefaultSamplingCallback(TraceBucketData* bucekt_data);
 868
 869   void Stop();
 870   void WaitSamplingEventForTesting();
 871
 872  private:
 873   friend class TraceLog;
 874
 875   void GetSamples();
 876   // Not thread-safe. Once the ThreadMain has been called, this can no longer
 877   // be called.
 878   void RegisterSampleBucket(TRACE_EVENT_API_ATOMIC_WORD* bucket,
 879                             const char* const name,
 880                             TraceSampleCallback callback);
 881   // Splits a combined "category\0name" into the two component parts.
 882   static void ExtractCategoryAndName(const char* combined,
 883                                      const char** category,
 884                                      const char** name);
 885   std::vector<TraceBucketData> sample_buckets_;
 886   bool thread_running_;
 887   CancellationFlag cancellation_flag_;
 888   WaitableEvent waitable_event_for_testing_;
 889 };
 890
 891
 892 TraceSamplingThread::TraceSamplingThread()
 893     : thread_running_(false),
 894       waitable_event_for_testing_(false, false) {
 895 }
 896
 897 TraceSamplingThread::~TraceSamplingThread() {
 898 }
 899
 900 void TraceSamplingThread::ThreadMain() {
 901   PlatformThread::SetName("Sampling Thread");
 902   thread_running_ = true;
 903   const int kSamplingFrequencyMicroseconds = 1000;
 904   while (!cancellation_flag_.IsSet()) {
 905     PlatformThread::Sleep(
 906         TimeDelta::FromMicroseconds(kSamplingFrequencyMicroseconds));
 907     GetSamples();
 908     waitable_event_for_testing_.Signal();
 909   }
 910 }
 911
 912 // static
 913 void TraceSamplingThread::DefaultSamplingCallback(
 914     TraceBucketData* bucket_data) {
 915   TRACE_EVENT_API_ATOMIC_WORD category_and_name =
 916       TRACE_EVENT_API_ATOMIC_LOAD(*bucket_data->bucket);
 917   if (!category_and_name)
 918     return;
 919   const char* const combined =
 920       reinterpret_cast<const char* const>(category_and_name);
 921   const char* category_group;
 922   const char* name;
 923   ExtractCategoryAndName(combined, &category_group, &name);
 924   TRACE_EVENT_API_ADD_TRACE_EVENT(TRACE_EVENT_PHASE_SAMPLE,
 925       TraceLog::GetCategoryGroupEnabled(category_group),
 926       name, 0, 0, NULL, NULL, NULL, NULL, 0);
 927 }
 928
 929 void TraceSamplingThread::GetSamples() {
 930   for (size_t i = 0; i < sample_buckets_.size(); ++i) {
 931     TraceBucketData* bucket_data = &sample_buckets_[i];
 932     bucket_data->callback.Run(bucket_data);
 933   }
 934 }
 935
 936 void TraceSamplingThread::RegisterSampleBucket(
 937     TRACE_EVENT_API_ATOMIC_WORD* bucket,
 938     const char* const name,
 939     TraceSampleCallback callback) {
 940   // Access to sample_buckets_ doesn't cause races with the sampling thread
 941   // that uses the sample_buckets_, because it is guaranteed that
 942   // RegisterSampleBucket is called before the sampling thread is created.
 943   DCHECK(!thread_running_);
 944   sample_buckets_.push_back(TraceBucketData(bucket, name, callback));
 945 }
 946
 947 // static
 948 void TraceSamplingThread::ExtractCategoryAndName(const char* combined,
 949                                                  const char** category,
 950                                                  const char** name) {
 951   *category = combined;
 952   *name = &combined[strlen(combined) + 1];
 953 }
 954
 955 void TraceSamplingThread::Stop() {
 956   cancellation_flag_.Set();
 957 }
 958
 959 void TraceSamplingThread::WaitSamplingEventForTesting() {
 960   waitable_event_for_testing_.Wait();
 961 }
 962
 963 TraceBucketData::TraceBucketData(base::subtle::AtomicWord* bucket,
 964                                  const char* name,
 965                                  TraceSampleCallback callback)
 966     : bucket(bucket),
 967       bucket_name(name),
 968       callback(callback) {
 969 }
 970
 971 TraceBucketData::~TraceBucketData() {
 972 }
 973
 974 ////////////////////////////////////////////////////////////////////////////////
 975 //
 976 // TraceOptions
 977 //
 978 ////////////////////////////////////////////////////////////////////////////////
 979
 980 bool TraceOptions::SetFromString(const std::string& options_string) {
 981   record_mode = RECORD_UNTIL_FULL;
 982   enable_sampling = false;
 983   enable_systrace = false;
 984
 985   std::vector<std::string> split;
 986   std::vector<std::string>::iterator iter;
 987   base::SplitString(options_string, ',', &split);
 988   for (iter = split.begin(); iter != split.end(); ++iter) {
 989     if (*iter == kRecordUntilFull) {
 990       record_mode = RECORD_UNTIL_FULL;
 991     } else if (*iter == kRecordContinuously) {
 992       record_mode = RECORD_CONTINUOUSLY;
 993     } else if (*iter == kTraceToConsole) {
 994       record_mode = ECHO_TO_CONSOLE;
 995     } else if (*iter == kRecordAsMuchAsPossible) {
 996       record_mode = RECORD_AS_MUCH_AS_POSSIBLE;
 997     } else if (*iter == kEnableSampling) {
 998       enable_sampling = true;
 999     } else if (*iter == kEnableSystrace) {
1000       enable_systrace = true;
1001     } else {
1002       return false;
1003     }
1004   }
1005   return true;
1006 }
1007
1008 std::string TraceOptions::ToString() const {
1009   std::string ret;
1010   switch (record_mode) {
1011     case RECORD_UNTIL_FULL:
1012       ret = kRecordUntilFull;
1013       break;
1014     case RECORD_CONTINUOUSLY:
1015       ret = kRecordContinuously;
1016       break;
1017     case ECHO_TO_CONSOLE:
1018       ret = kTraceToConsole;
1019       break;
1020     case RECORD_AS_MUCH_AS_POSSIBLE:
1021       ret = kRecordAsMuchAsPossible;
1022       break;
1023     default:
1024       NOTREACHED();
1025   }
1026   if (enable_sampling)
1027     ret = ret + "," + kEnableSampling;
1028   if (enable_systrace)
1029     ret = ret + "," + kEnableSystrace;
1030   return ret;
1031 }
1032
1033 ////////////////////////////////////////////////////////////////////////////////
1034 //
1035 // TraceLog
1036 //
1037 ////////////////////////////////////////////////////////////////////////////////
1038
1039 class TraceLog::ThreadLocalEventBuffer
1040     : public MessageLoop::DestructionObserver {
1041  public:
1042   ThreadLocalEventBuffer(TraceLog* trace_log);
1043   ~ThreadLocalEventBuffer() override;
1044
1045   TraceEvent* AddTraceEvent(TraceEventHandle* handle);
1046
1047   void ReportOverhead(const TimeTicks& event_timestamp,
1048                       const TimeTicks& event_thread_timestamp);
1049
1050   TraceEvent* GetEventByHandle(TraceEventHandle handle) {
1051     if (!chunk_ || handle.chunk_seq != chunk_->seq() ||
1052         handle.chunk_index != chunk_index_)
1053       return NULL;
1054
1055     return chunk_->GetEventAt(handle.event_index);
1056   }
1057
1058   int generation() const { return generation_; }
1059
1060  private:
1061   // MessageLoop::DestructionObserver
1062   void WillDestroyCurrentMessageLoop() override;
1063
1064   void FlushWhileLocked();
1065
1066   void CheckThisIsCurrentBuffer() const {
1067     DCHECK(trace_log_->thread_local_event_buffer_.Get() == this);
1068   }
1069
1070   // Since TraceLog is a leaky singleton, trace_log_ will always be valid
1071   // as long as the thread exists.
1072   TraceLog* trace_log_;
1073   scoped_ptr<TraceBufferChunk> chunk_;
1074   size_t chunk_index_;
1075   int event_count_;
1076   TimeDelta overhead_;
1077   int generation_;
1078
1079   DISALLOW_COPY_AND_ASSIGN(ThreadLocalEventBuffer);
1080 };
1081
1082 TraceLog::ThreadLocalEventBuffer::ThreadLocalEventBuffer(TraceLog* trace_log)
1083     : trace_log_(trace_log),
1084       chunk_index_(0),
1085       event_count_(0),
1086       generation_(trace_log->generation()) {
1087   // ThreadLocalEventBuffer is created only if the thread has a message loop, so
1088   // the following message_loop won't be NULL.
1089   MessageLoop* message_loop = MessageLoop::current();
1090   message_loop->AddDestructionObserver(this);
1091
1092   AutoLock lock(trace_log->lock_);
1093   trace_log->thread_message_loops_.insert(message_loop);
1094 }
1095
1096 TraceLog::ThreadLocalEventBuffer::~ThreadLocalEventBuffer() {
1097   CheckThisIsCurrentBuffer();
1098   MessageLoop::current()->RemoveDestructionObserver(this);
1099
1100   // Zero event_count_ happens in either of the following cases:
1101   // - no event generated for the thread;
1102   // - the thread has no message loop;
1103   // - trace_event_overhead is disabled.
1104   if (event_count_) {
1105     InitializeMetadataEvent(AddTraceEvent(NULL),
1106                             static_cast<int>(base::PlatformThread::CurrentId()),
1107                             "overhead", "average_overhead",
1108                             overhead_.InMillisecondsF() / event_count_);
1109   }
1110
1111   {
1112     AutoLock lock(trace_log_->lock_);
1113     FlushWhileLocked();
1114     trace_log_->thread_message_loops_.erase(MessageLoop::current());
1115   }
1116   trace_log_->thread_local_event_buffer_.Set(NULL);
1117 }
1118
1119 TraceEvent* TraceLog::ThreadLocalEventBuffer::AddTraceEvent(
1120     TraceEventHandle* handle) {
1121   CheckThisIsCurrentBuffer();
1122
1123   if (chunk_ && chunk_->IsFull()) {
1124     AutoLock lock(trace_log_->lock_);
1125     FlushWhileLocked();
1126     chunk_.reset();
1127   }
1128   if (!chunk_) {
1129     AutoLock lock(trace_log_->lock_);
1130     chunk_ = trace_log_->logged_events_->GetChunk(&chunk_index_);
1131     trace_log_->CheckIfBufferIsFullWhileLocked();
1132   }
1133   if (!chunk_)
1134     return NULL;
1135
1136   size_t event_index;
1137   TraceEvent* trace_event = chunk_->AddTraceEvent(&event_index);
1138   if (trace_event && handle)
1139     MakeHandle(chunk_->seq(), chunk_index_, event_index, handle);
1140
1141   return trace_event;
1142 }
1143
1144 void TraceLog::ThreadLocalEventBuffer::ReportOverhead(
1145     const TimeTicks& event_timestamp,
1146     const TimeTicks& event_thread_timestamp) {
1147   if (!g_category_group_enabled[g_category_trace_event_overhead])
1148     return;
1149
1150   CheckThisIsCurrentBuffer();
1151
1152   event_count_++;
1153   TimeTicks thread_now = ThreadNow();
1154   TimeTicks now = trace_log_->OffsetNow();
1155   TimeDelta overhead = now - event_timestamp;
1156   if (overhead.InMicroseconds() >= kOverheadReportThresholdInMicroseconds) {
1157     TraceEvent* trace_event = AddTraceEvent(NULL);
1158     if (trace_event) {
1159       trace_event->Initialize(
1160           static_cast<int>(PlatformThread::CurrentId()),
1161           event_timestamp, event_thread_timestamp,
1162           TRACE_EVENT_PHASE_COMPLETE,
1163           &g_category_group_enabled[g_category_trace_event_overhead],
1164           "overhead", 0, 0, NULL, NULL, NULL, NULL, 0);
1165       trace_event->UpdateDuration(now, thread_now);
1166     }
1167   }
1168   overhead_ += overhead;
1169 }
1170
1171 void TraceLog::ThreadLocalEventBuffer::WillDestroyCurrentMessageLoop() {
1172   delete this;
1173 }
1174
1175 void TraceLog::ThreadLocalEventBuffer::FlushWhileLocked() {
1176   if (!chunk_)
1177     return;
1178
1179   trace_log_->lock_.AssertAcquired();
1180   if (trace_log_->CheckGeneration(generation_)) {
1181     // Return the chunk to the buffer only if the generation matches.
1182     trace_log_->logged_events_->ReturnChunk(chunk_index_, chunk_.Pass());
1183   }
1184   // Otherwise this method may be called from the destructor, or TraceLog will
1185   // find the generation mismatch and delete this buffer soon.
1186 }
1187
1188 // static
1189 TraceLog* TraceLog::GetInstance() {
1190   return Singleton<TraceLog, LeakySingletonTraits<TraceLog> >::get();
1191 }
1192
1193 TraceLog::TraceLog()
1194     : mode_(DISABLED),
1195       num_traces_recorded_(0),
1196       event_callback_(0),
1197       dispatching_to_observer_list_(false),
1198       process_sort_index_(0),
1199       process_id_hash_(0),
1200       process_id_(0),
1201       watch_category_(0),
1202       trace_options_(kInternalRecordUntilFull),
1203       sampling_thread_handle_(0),
1204       category_filter_(CategoryFilter::kDefaultCategoryFilterString),
1205       event_callback_category_filter_(
1206           CategoryFilter::kDefaultCategoryFilterString),
1207       thread_shared_chunk_index_(0),
1208       generation_(0) {
1209   // Trace is enabled or disabled on one thread while other threads are
1210   // accessing the enabled flag. We don't care whether edge-case events are
1211   // traced or not, so we allow races on the enabled flag to keep the trace
1212   // macros fast.
1213   // TODO(jbates): ANNOTATE_BENIGN_RACE_SIZED crashes windows TSAN bots:
1214   // ANNOTATE_BENIGN_RACE_SIZED(g_category_group_enabled,
1215   //                            sizeof(g_category_group_enabled),
1216   //                           "trace_event category enabled");
1217   for (int i = 0; i < MAX_CATEGORY_GROUPS; ++i) {
1218     ANNOTATE_BENIGN_RACE(&g_category_group_enabled[i],
1219                          "trace_event category enabled");
1220   }
1221 #if defined(OS_NACL)  // NaCl shouldn't expose the process id.
1222   SetProcessID(0);
1223 #else
1224   SetProcessID(static_cast<int>(GetCurrentProcId()));
1225
1226   // NaCl also shouldn't access the command line.
1227   if (CommandLine::InitializedForCurrentProcess() &&
1228       CommandLine::ForCurrentProcess()->HasSwitch(switches::kTraceToConsole)) {
1229     std::string filter = CommandLine::ForCurrentProcess()->GetSwitchValueASCII(
1230         switches::kTraceToConsole);
1231     if (filter.empty()) {
1232       filter = kEchoToConsoleCategoryFilter;
1233     } else {
1234       filter.append(",");
1235       filter.append(kEchoToConsoleCategoryFilter);
1236     }
1237
1238     LOG(ERROR) << "Start " << switches::kTraceToConsole
1239                << " with CategoryFilter '" << filter << "'.";
1240     SetEnabled(CategoryFilter(filter),
1241                RECORDING_MODE,
1242                TraceOptions(ECHO_TO_CONSOLE));
1243   }
1244 #endif
1245
1246   logged_events_.reset(CreateTraceBuffer());
1247 }
1248
1249 TraceLog::~TraceLog() {
1250 }
1251
1252 const unsigned char* TraceLog::GetCategoryGroupEnabled(
1253     const char* category_group) {
1254   TraceLog* tracelog = GetInstance();
1255   if (!tracelog) {
1256     DCHECK(!g_category_group_enabled[g_category_already_shutdown]);
1257     return &g_category_group_enabled[g_category_already_shutdown];
1258   }
1259   return tracelog->GetCategoryGroupEnabledInternal(category_group);
1260 }
1261
1262 const char* TraceLog::GetCategoryGroupName(
1263     const unsigned char* category_group_enabled) {
1264   // Calculate the index of the category group by finding
1265   // category_group_enabled in g_category_group_enabled array.
1266   uintptr_t category_begin =
1267       reinterpret_cast<uintptr_t>(g_category_group_enabled);
1268   uintptr_t category_ptr = reinterpret_cast<uintptr_t>(category_group_enabled);
1269   DCHECK(category_ptr >= category_begin &&
1270          category_ptr < reinterpret_cast<uintptr_t>(
1271              g_category_group_enabled + MAX_CATEGORY_GROUPS)) <<
1272       "out of bounds category pointer";
1273   uintptr_t category_index =
1274       (category_ptr - category_begin) / sizeof(g_category_group_enabled[0]);
1275   return g_category_groups[category_index];
1276 }
1277
1278 void TraceLog::UpdateCategoryGroupEnabledFlag(size_t category_index) {
1279   unsigned char enabled_flag = 0;
1280   const char* category_group = g_category_groups[category_index];
1281   if (mode_ == RECORDING_MODE &&
1282       category_filter_.IsCategoryGroupEnabled(category_group))
1283     enabled_flag |= ENABLED_FOR_RECORDING;
1284   else if (mode_ == MONITORING_MODE &&
1285       category_filter_.IsCategoryGroupEnabled(category_group))
1286     enabled_flag |= ENABLED_FOR_MONITORING;
1287   if (event_callback_ &&
1288       event_callback_category_filter_.IsCategoryGroupEnabled(category_group))
1289     enabled_flag |= ENABLED_FOR_EVENT_CALLBACK;
1290   g_category_group_enabled[category_index] = enabled_flag;
1291 }
1292
1293 void TraceLog::UpdateCategoryGroupEnabledFlags() {
1294   size_t category_index = base::subtle::NoBarrier_Load(&g_category_index);
1295   for (size_t i = 0; i < category_index; i++)
1296     UpdateCategoryGroupEnabledFlag(i);
1297 }
1298
1299 void TraceLog::UpdateSyntheticDelaysFromCategoryFilter() {
1300   ResetTraceEventSyntheticDelays();
1301   const CategoryFilter::StringList& delays =
1302       category_filter_.GetSyntheticDelayValues();
1303   CategoryFilter::StringList::const_iterator ci;
1304   for (ci = delays.begin(); ci != delays.end(); ++ci) {
1305     StringTokenizer tokens(*ci, ";");
1306     if (!tokens.GetNext())
1307       continue;
1308     TraceEventSyntheticDelay* delay =
1309         TraceEventSyntheticDelay::Lookup(tokens.token());
1310     while (tokens.GetNext()) {
1311       std::string token = tokens.token();
1312       char* duration_end;
1313       double target_duration = strtod(token.c_str(), &duration_end);
1314       if (duration_end != token.c_str()) {
1315         delay->SetTargetDuration(TimeDelta::FromMicroseconds(
1316             static_cast<int64>(target_duration * 1e6)));
1317       } else if (token == "static") {
1318         delay->SetMode(TraceEventSyntheticDelay::STATIC);
1319       } else if (token == "oneshot") {
1320         delay->SetMode(TraceEventSyntheticDelay::ONE_SHOT);
1321       } else if (token == "alternating") {
1322         delay->SetMode(TraceEventSyntheticDelay::ALTERNATING);
1323       }
1324     }
1325   }
1326 }
1327
1328 const unsigned char* TraceLog::GetCategoryGroupEnabledInternal(
1329     const char* category_group) {
1330   DCHECK(!strchr(category_group, '"')) <<
1331       "Category groups may not contain double quote";
1332   // The g_category_groups is append only, avoid using a lock for the fast path.
1333   size_t current_category_index = base::subtle::Acquire_Load(&g_category_index);
1334
1335   // Search for pre-existing category group.
1336   for (size_t i = 0; i < current_category_index; ++i) {
1337     if (strcmp(g_category_groups[i], category_group) == 0) {
1338       return &g_category_group_enabled[i];
1339     }
1340   }
1341
1342   unsigned char* category_group_enabled = NULL;
1343   // This is the slow path: the lock is not held in the case above, so more
1344   // than one thread could have reached here trying to add the same category.
1345   // Only hold to lock when actually appending a new category, and
1346   // check the categories groups again.
1347   AutoLock lock(lock_);
1348   size_t category_index = base::subtle::Acquire_Load(&g_category_index);
1349   for (size_t i = 0; i < category_index; ++i) {
1350     if (strcmp(g_category_groups[i], category_group) == 0) {
1351       return &g_category_group_enabled[i];
1352     }
1353   }
1354
1355   // Create a new category group.
1356   DCHECK(category_index < MAX_CATEGORY_GROUPS) <<
1357       "must increase MAX_CATEGORY_GROUPS";
1358   if (category_index < MAX_CATEGORY_GROUPS) {
1359     // Don't hold on to the category_group pointer, so that we can create
1360     // category groups with strings not known at compile time (this is
1361     // required by SetWatchEvent).
1362     const char* new_group = strdup(category_group);
1363     ANNOTATE_LEAKING_OBJECT_PTR(new_group);
1364     g_category_groups[category_index] = new_group;
1365     DCHECK(!g_category_group_enabled[category_index]);
1366     // Note that if both included and excluded patterns in the
1367     // CategoryFilter are empty, we exclude nothing,
1368     // thereby enabling this category group.
1369     UpdateCategoryGroupEnabledFlag(category_index);
1370     category_group_enabled = &g_category_group_enabled[category_index];
1371     // Update the max index now.
1372     base::subtle::Release_Store(&g_category_index, category_index + 1);
1373   } else {
1374     category_group_enabled =
1375         &g_category_group_enabled[g_category_categories_exhausted];
1376   }
1377   return category_group_enabled;
1378 }
1379
1380 void TraceLog::GetKnownCategoryGroups(
1381     std::vector<std::string>* category_groups) {
1382   AutoLock lock(lock_);
1383   category_groups->push_back(
1384       g_category_groups[g_category_trace_event_overhead]);
1385   size_t category_index = base::subtle::NoBarrier_Load(&g_category_index);
1386   for (size_t i = g_num_builtin_categories; i < category_index; i++)
1387     category_groups->push_back(g_category_groups[i]);
1388 }
1389
1390 void TraceLog::SetEnabled(const CategoryFilter& category_filter,
1391                           Mode mode,
1392                           const TraceOptions& options) {
1393   std::vector<EnabledStateObserver*> observer_list;
1394   {
1395     AutoLock lock(lock_);
1396
1397     // Can't enable tracing when Flush() is in progress.
1398     DCHECK(!flush_message_loop_proxy_.get());
1399
1400     InternalTraceOptions new_options =
1401         GetInternalOptionsFromTraceOptions(options);
1402
1403    InternalTraceOptions old_options = trace_options();
1404
1405     if (IsEnabled()) {
1406       if (new_options != old_options) {
1407         DLOG(ERROR) << "Attempting to re-enable tracing with a different "
1408                     << "set of options.";
1409       }
1410
1411       if (mode != mode_) {
1412         DLOG(ERROR) << "Attempting to re-enable tracing with a different mode.";
1413       }
1414
1415       category_filter_.Merge(category_filter);
1416       UpdateCategoryGroupEnabledFlags();
1417       return;
1418     }
1419
1420     if (dispatching_to_observer_list_) {
1421       DLOG(ERROR) <<
1422           "Cannot manipulate TraceLog::Enabled state from an observer.";
1423       return;
1424     }
1425
1426     mode_ = mode;
1427
1428     if (new_options != old_options) {
1429       subtle::NoBarrier_Store(&trace_options_, new_options);
1430       UseNextTraceBuffer();
1431     }
1432
1433     num_traces_recorded_++;
1434
1435     category_filter_ = CategoryFilter(category_filter);
1436     UpdateCategoryGroupEnabledFlags();
1437     UpdateSyntheticDelaysFromCategoryFilter();
1438
1439     if (new_options & kInternalEnableSampling) {
1440       sampling_thread_.reset(new TraceSamplingThread);
1441       sampling_thread_->RegisterSampleBucket(
1442           &g_trace_state[0],
1443           "bucket0",
1444           Bind(&TraceSamplingThread::DefaultSamplingCallback));
1445       sampling_thread_->RegisterSampleBucket(
1446           &g_trace_state[1],
1447           "bucket1",
1448           Bind(&TraceSamplingThread::DefaultSamplingCallback));
1449       sampling_thread_->RegisterSampleBucket(
1450           &g_trace_state[2],
1451           "bucket2",
1452           Bind(&TraceSamplingThread::DefaultSamplingCallback));
1453       if (!PlatformThread::Create(
1454             0, sampling_thread_.get(), &sampling_thread_handle_)) {
1455         DCHECK(false) << "failed to create thread";
1456       }
1457     }
1458
1459     dispatching_to_observer_list_ = true;
1460     observer_list = enabled_state_observer_list_;
1461   }
1462   // Notify observers outside the lock in case they trigger trace events.
1463   for (size_t i = 0; i < observer_list.size(); ++i)
1464     observer_list[i]->OnTraceLogEnabled();
1465
1466   {
1467     AutoLock lock(lock_);
1468     dispatching_to_observer_list_ = false;
1469   }
1470 }
1471
1472 TraceLog::InternalTraceOptions TraceLog::GetInternalOptionsFromTraceOptions(
1473     const TraceOptions& options) {
1474   InternalTraceOptions ret =
1475       options.enable_sampling ? kInternalEnableSampling : kInternalNone;
1476   switch (options.record_mode) {
1477     case RECORD_UNTIL_FULL:
1478       return ret | kInternalRecordUntilFull;
1479     case RECORD_CONTINUOUSLY:
1480       return ret | kInternalRecordContinuously;
1481     case ECHO_TO_CONSOLE:
1482       return ret | kInternalEchoToConsole;
1483     case RECORD_AS_MUCH_AS_POSSIBLE:
1484       return ret | kInternalRecordAsMuchAsPossible;
1485   }
1486   NOTREACHED();
1487   return kInternalNone;
1488 }
1489
1490 CategoryFilter TraceLog::GetCurrentCategoryFilter() {
1491   AutoLock lock(lock_);
1492   return category_filter_;
1493 }
1494
1495 TraceOptions TraceLog::GetCurrentTraceOptions() const {
1496   TraceOptions ret;
1497   InternalTraceOptions option = trace_options();
1498   ret.enable_sampling = (option & kInternalEnableSampling) != 0;
1499   if (option & kInternalRecordUntilFull)
1500     ret.record_mode = RECORD_UNTIL_FULL;
1501   else if (option & kInternalRecordContinuously)
1502     ret.record_mode = RECORD_CONTINUOUSLY;
1503   else if (option & kInternalEchoToConsole)
1504     ret.record_mode = ECHO_TO_CONSOLE;
1505   else if (option & kInternalRecordAsMuchAsPossible)
1506     ret.record_mode = RECORD_AS_MUCH_AS_POSSIBLE;
1507   else
1508     NOTREACHED();
1509   return ret;
1510 }
1511
1512 void TraceLog::SetDisabled() {
1513   AutoLock lock(lock_);
1514   SetDisabledWhileLocked();
1515 }
1516
1517 void TraceLog::SetDisabledWhileLocked() {
1518   lock_.AssertAcquired();
1519
1520   if (!IsEnabled())
1521     return;
1522
1523   if (dispatching_to_observer_list_) {
1524     DLOG(ERROR)
1525         << "Cannot manipulate TraceLog::Enabled state from an observer.";
1526     return;
1527   }
1528
1529   mode_ = DISABLED;
1530
1531   if (sampling_thread_.get()) {
1532     // Stop the sampling thread.
1533     sampling_thread_->Stop();
1534     lock_.Release();
1535     PlatformThread::Join(sampling_thread_handle_);
1536     lock_.Acquire();
1537     sampling_thread_handle_ = PlatformThreadHandle();
1538     sampling_thread_.reset();
1539   }
1540
1541   category_filter_.Clear();
1542   subtle::NoBarrier_Store(&watch_category_, 0);
1543   watch_event_name_ = "";
1544   UpdateCategoryGroupEnabledFlags();
1545   AddMetadataEventsWhileLocked();
1546
1547   dispatching_to_observer_list_ = true;
1548   std::vector<EnabledStateObserver*> observer_list =
1549       enabled_state_observer_list_;
1550
1551   {
1552     // Dispatch to observers outside the lock in case the observer triggers a
1553     // trace event.
1554     AutoUnlock unlock(lock_);
1555     for (size_t i = 0; i < observer_list.size(); ++i)
1556       observer_list[i]->OnTraceLogDisabled();
1557   }
1558   dispatching_to_observer_list_ = false;
1559 }
1560
1561 int TraceLog::GetNumTracesRecorded() {
1562   AutoLock lock(lock_);
1563   if (!IsEnabled())
1564     return -1;
1565   return num_traces_recorded_;
1566 }
1567
1568 void TraceLog::AddEnabledStateObserver(EnabledStateObserver* listener) {
1569   enabled_state_observer_list_.push_back(listener);
1570 }
1571
1572 void TraceLog::RemoveEnabledStateObserver(EnabledStateObserver* listener) {
1573   std::vector<EnabledStateObserver*>::iterator it =
1574       std::find(enabled_state_observer_list_.begin(),
1575                 enabled_state_observer_list_.end(),
1576                 listener);
1577   if (it != enabled_state_observer_list_.end())
1578     enabled_state_observer_list_.erase(it);
1579 }
1580
1581 bool TraceLog::HasEnabledStateObserver(EnabledStateObserver* listener) const {
1582   std::vector<EnabledStateObserver*>::const_iterator it =
1583       std::find(enabled_state_observer_list_.begin(),
1584                 enabled_state_observer_list_.end(),
1585                 listener);
1586   return it != enabled_state_observer_list_.end();
1587 }
1588
1589 float TraceLog::GetBufferPercentFull() const {
1590   AutoLock lock(lock_);
1591   return static_cast<float>(static_cast<double>(logged_events_->Size()) /
1592                             logged_events_->Capacity());
1593 }
1594
1595 bool TraceLog::BufferIsFull() const {
1596   AutoLock lock(lock_);
1597   return logged_events_->IsFull();
1598 }
1599
1600 TraceBuffer* TraceLog::CreateTraceBuffer() {
1601   InternalTraceOptions options = trace_options();
1602   if (options & kInternalRecordContinuously)
1603     return new TraceBufferRingBuffer(kTraceEventRingBufferChunks);
1604   else if ((options & kInternalEnableSampling) && mode_ == MONITORING_MODE)
1605     return new TraceBufferRingBuffer(kMonitorTraceEventBufferChunks);
1606   else if (options & kInternalEchoToConsole)
1607     return new TraceBufferRingBuffer(kEchoToConsoleTraceEventBufferChunks);
1608   else if (options & kInternalRecordAsMuchAsPossible)
1609     return CreateTraceBufferVectorOfSize(kTraceEventVectorBigBufferChunks);
1610   return CreateTraceBufferVectorOfSize(kTraceEventVectorBufferChunks);
1611 }
1612
1613 TraceBuffer* TraceLog::CreateTraceBufferVectorOfSize(size_t max_chunks) {
1614   return new TraceBufferVector(max_chunks);
1615 }
1616
1617 TraceEvent* TraceLog::AddEventToThreadSharedChunkWhileLocked(
1618     TraceEventHandle* handle, bool check_buffer_is_full) {
1619   lock_.AssertAcquired();
1620
1621   if (thread_shared_chunk_ && thread_shared_chunk_->IsFull()) {
1622     logged_events_->ReturnChunk(thread_shared_chunk_index_,
1623                                 thread_shared_chunk_.Pass());
1624   }
1625
1626   if (!thread_shared_chunk_) {
1627     thread_shared_chunk_ = logged_events_->GetChunk(
1628         &thread_shared_chunk_index_);
1629     if (check_buffer_is_full)
1630       CheckIfBufferIsFullWhileLocked();
1631   }
1632   if (!thread_shared_chunk_)
1633     return NULL;
1634
1635   size_t event_index;
1636   TraceEvent* trace_event = thread_shared_chunk_->AddTraceEvent(&event_index);
1637   if (trace_event && handle) {
1638     MakeHandle(thread_shared_chunk_->seq(), thread_shared_chunk_index_,
1639                event_index, handle);
1640   }
1641   return trace_event;
1642 }
1643
1644 void TraceLog::CheckIfBufferIsFullWhileLocked() {
1645   lock_.AssertAcquired();
1646   if (logged_events_->IsFull()) {
1647     if (buffer_limit_reached_timestamp_.is_null()) {
1648       buffer_limit_reached_timestamp_ = OffsetNow();
1649     }
1650     SetDisabledWhileLocked();
1651   }
1652 }
1653
1654 void TraceLog::SetEventCallbackEnabled(const CategoryFilter& category_filter,
1655                                        EventCallback cb) {
1656   AutoLock lock(lock_);
1657   subtle::NoBarrier_Store(&event_callback_,
1658                           reinterpret_cast<subtle::AtomicWord>(cb));
1659   event_callback_category_filter_ = category_filter;
1660   UpdateCategoryGroupEnabledFlags();
1661 };
1662
1663 void TraceLog::SetEventCallbackDisabled() {
1664   AutoLock lock(lock_);
1665   subtle::NoBarrier_Store(&event_callback_, 0);
1666   UpdateCategoryGroupEnabledFlags();
1667 }
1668
1669 // Flush() works as the following:
1670 // 1. Flush() is called in threadA whose message loop is saved in
1671 //    flush_message_loop_proxy_;
1672 // 2. If thread_message_loops_ is not empty, threadA posts task to each message
1673 //    loop to flush the thread local buffers; otherwise finish the flush;
1674 // 3. FlushCurrentThread() deletes the thread local event buffer:
1675 //    - The last batch of events of the thread are flushed into the main buffer;
1676 //    - The message loop will be removed from thread_message_loops_;
1677 //    If this is the last message loop, finish the flush;
1678 // 4. If any thread hasn't finish its flush in time, finish the flush.
1679 void TraceLog::Flush(const TraceLog::OutputCallback& cb) {
1680   if (IsEnabled()) {
1681     // Can't flush when tracing is enabled because otherwise PostTask would
1682     // - generate more trace events;
1683     // - deschedule the calling thread on some platforms causing inaccurate
1684     //   timing of the trace events.
1685     scoped_refptr<RefCountedString> empty_result = new RefCountedString;
1686     if (!cb.is_null())
1687       cb.Run(empty_result, false);
1688     LOG(WARNING) << "Ignored TraceLog::Flush called when tracing is enabled";
1689     return;
1690   }
1691
1692   int generation = this->generation();
1693   // Copy of thread_message_loops_ to be used without locking.
1694   std::vector<scoped_refptr<SingleThreadTaskRunner> >
1695       thread_message_loop_task_runners;
1696   {
1697     AutoLock lock(lock_);
1698     DCHECK(!flush_message_loop_proxy_.get());
1699     flush_message_loop_proxy_ = MessageLoopProxy::current();
1700     DCHECK(!thread_message_loops_.size() || flush_message_loop_proxy_.get());
1701     flush_output_callback_ = cb;
1702
1703     if (thread_shared_chunk_) {
1704       logged_events_->ReturnChunk(thread_shared_chunk_index_,
1705                                   thread_shared_chunk_.Pass());
1706     }
1707
1708     if (thread_message_loops_.size()) {
1709       for (hash_set<MessageLoop*>::const_iterator it =
1710            thread_message_loops_.begin();
1711            it != thread_message_loops_.end(); ++it) {
1712         thread_message_loop_task_runners.push_back((*it)->task_runner());
1713       }
1714     }
1715   }
1716
1717   if (thread_message_loop_task_runners.size()) {
1718     for (size_t i = 0; i < thread_message_loop_task_runners.size(); ++i) {
1719       thread_message_loop_task_runners[i]->PostTask(
1720           FROM_HERE,
1721           Bind(&TraceLog::FlushCurrentThread, Unretained(this), generation));
1722     }
1723     flush_message_loop_proxy_->PostDelayedTask(
1724         FROM_HERE,
1725         Bind(&TraceLog::OnFlushTimeout, Unretained(this), generation),
1726         TimeDelta::FromMilliseconds(kThreadFlushTimeoutMs));
1727     return;
1728   }
1729
1730   FinishFlush(generation);
1731 }
1732
1733 void TraceLog::ConvertTraceEventsToTraceFormat(
1734     scoped_ptr<TraceBuffer> logged_events,
1735     const TraceLog::OutputCallback& flush_output_callback) {
1736
1737   if (flush_output_callback.is_null())
1738     return;
1739
1740   // The callback need to be called at least once even if there is no events
1741   // to let the caller know the completion of flush.
1742   bool has_more_events = true;
1743   do {
1744     scoped_refptr<RefCountedString> json_events_str_ptr =
1745         new RefCountedString();
1746
1747     for (size_t i = 0; i < kTraceEventBatchChunks; ++i) {
1748       const TraceBufferChunk* chunk = logged_events->NextChunk();
1749       if (!chunk) {
1750         has_more_events = false;
1751         break;
1752       }
1753       for (size_t j = 0; j < chunk->size(); ++j) {
1754         if (i > 0 || j > 0)
1755           json_events_str_ptr->data().append(",");
1756         chunk->GetEventAt(j)->AppendAsJSON(&(json_events_str_ptr->data()));
1757       }
1758     }
1759
1760     flush_output_callback.Run(json_events_str_ptr, has_more_events);
1761   } while (has_more_events);
1762 }
1763
1764 void TraceLog::FinishFlush(int generation) {
1765   scoped_ptr<TraceBuffer> previous_logged_events;
1766   OutputCallback flush_output_callback;
1767
1768   if (!CheckGeneration(generation))
1769     return;
1770
1771   {
1772     AutoLock lock(lock_);
1773
1774     previous_logged_events.swap(logged_events_);
1775     UseNextTraceBuffer();
1776     thread_message_loops_.clear();
1777
1778     flush_message_loop_proxy_ = NULL;
1779     flush_output_callback = flush_output_callback_;
1780     flush_output_callback_.Reset();
1781   }
1782
1783   ConvertTraceEventsToTraceFormat(previous_logged_events.Pass(),
1784                                   flush_output_callback);
1785 }
1786
1787 // Run in each thread holding a local event buffer.
1788 void TraceLog::FlushCurrentThread(int generation) {
1789   {
1790     AutoLock lock(lock_);
1791     if (!CheckGeneration(generation) || !flush_message_loop_proxy_.get()) {
1792       // This is late. The corresponding flush has finished.
1793       return;
1794     }
1795   }
1796
1797   // This will flush the thread local buffer.
1798   delete thread_local_event_buffer_.Get();
1799
1800   AutoLock lock(lock_);
1801   if (!CheckGeneration(generation) || !flush_message_loop_proxy_.get() ||
1802       thread_message_loops_.size())
1803     return;
1804
1805   flush_message_loop_proxy_->PostTask(
1806       FROM_HERE,
1807       Bind(&TraceLog::FinishFlush, Unretained(this), generation));
1808 }
1809
1810 void TraceLog::OnFlushTimeout(int generation) {
1811   {
1812     AutoLock lock(lock_);
1813     if (!CheckGeneration(generation) || !flush_message_loop_proxy_.get()) {
1814       // Flush has finished before timeout.
1815       return;
1816     }
1817
1818     LOG(WARNING) <<
1819         "The following threads haven't finished flush in time. "
1820         "If this happens stably for some thread, please call "
1821         "TraceLog::GetInstance()->SetCurrentThreadBlocksMessageLoop() from "
1822         "the thread to avoid its trace events from being lost.";
1823     for (hash_set<MessageLoop*>::const_iterator it =
1824          thread_message_loops_.begin();
1825          it != thread_message_loops_.end(); ++it) {
1826       LOG(WARNING) << "Thread: " << (*it)->thread_name();
1827     }
1828   }
1829   FinishFlush(generation);
1830 }
1831
1832 void TraceLog::FlushButLeaveBufferIntact(
1833     const TraceLog::OutputCallback& flush_output_callback) {
1834   scoped_ptr<TraceBuffer> previous_logged_events;
1835   {
1836     AutoLock lock(lock_);
1837     AddMetadataEventsWhileLocked();
1838     if (thread_shared_chunk_) {
1839       // Return the chunk to the main buffer to flush the sampling data.
1840       logged_events_->ReturnChunk(thread_shared_chunk_index_,
1841                                   thread_shared_chunk_.Pass());
1842     }
1843     previous_logged_events = logged_events_->CloneForIteration().Pass();
1844   }  // release lock
1845
1846   ConvertTraceEventsToTraceFormat(previous_logged_events.Pass(),
1847                                   flush_output_callback);
1848 }
1849
1850 void TraceLog::UseNextTraceBuffer() {
1851   logged_events_.reset(CreateTraceBuffer());
1852   subtle::NoBarrier_AtomicIncrement(&generation_, 1);
1853   thread_shared_chunk_.reset();
1854   thread_shared_chunk_index_ = 0;
1855 }
1856
1857 TraceEventHandle TraceLog::AddTraceEvent(
1858     char phase,
1859     const unsigned char* category_group_enabled,
1860     const char* name,
1861     unsigned long long id,
1862     int num_args,
1863     const char** arg_names,
1864     const unsigned char* arg_types,
1865     const unsigned long long* arg_values,
1866     const scoped_refptr<ConvertableToTraceFormat>* convertable_values,
1867     unsigned char flags) {
1868   int thread_id = static_cast<int>(base::PlatformThread::CurrentId());
1869   base::TimeTicks now = base::TimeTicks::NowFromSystemTraceTime();
1870   return AddTraceEventWithThreadIdAndTimestamp(phase, category_group_enabled,
1871                                                name, id, thread_id, now,
1872                                                num_args, arg_names,
1873                                                arg_types, arg_values,
1874                                                convertable_values, flags);
1875 }
1876
1877 TraceEventHandle TraceLog::AddTraceEventWithThreadIdAndTimestamp(
1878     char phase,
1879     const unsigned char* category_group_enabled,
1880     const char* name,
1881     unsigned long long id,
1882     int thread_id,
1883     const TimeTicks& timestamp,
1884     int num_args,
1885     const char** arg_names,
1886     const unsigned char* arg_types,
1887     const unsigned long long* arg_values,
1888     const scoped_refptr<ConvertableToTraceFormat>* convertable_values,
1889     unsigned char flags) {
1890   TraceEventHandle handle = { 0, 0, 0 };
1891   if (!*category_group_enabled)
1892     return handle;
1893
1894   // Avoid re-entrance of AddTraceEvent. This may happen in GPU process when
1895   // ECHO_TO_CONSOLE is enabled: AddTraceEvent -> LOG(ERROR) ->
1896   // GpuProcessLogMessageHandler -> PostPendingTask -> TRACE_EVENT ...
1897   if (thread_is_in_trace_event_.Get())
1898     return handle;
1899
1900   AutoThreadLocalBoolean thread_is_in_trace_event(&thread_is_in_trace_event_);
1901
1902   DCHECK(name);
1903
1904   if (flags & TRACE_EVENT_FLAG_MANGLE_ID)
1905     id ^= process_id_hash_;
1906
1907   TimeTicks now = OffsetTimestamp(timestamp);
1908   TimeTicks thread_now = ThreadNow();
1909
1910   ThreadLocalEventBuffer* thread_local_event_buffer = NULL;
1911   // A ThreadLocalEventBuffer needs the message loop
1912   // - to know when the thread exits;
1913   // - to handle the final flush.
1914   // For a thread without a message loop or the message loop may be blocked, the
1915   // trace events will be added into the main buffer directly.
1916   if (!thread_blocks_message_loop_.Get() && MessageLoop::current()) {
1917     thread_local_event_buffer = thread_local_event_buffer_.Get();
1918     if (thread_local_event_buffer &&
1919         !CheckGeneration(thread_local_event_buffer->generation())) {
1920       delete thread_local_event_buffer;
1921       thread_local_event_buffer = NULL;
1922     }
1923     if (!thread_local_event_buffer) {
1924       thread_local_event_buffer = new ThreadLocalEventBuffer(this);
1925       thread_local_event_buffer_.Set(thread_local_event_buffer);
1926     }
1927   }
1928
1929   // Check and update the current thread name only if the event is for the
1930   // current thread to avoid locks in most cases.
1931   if (thread_id == static_cast<int>(PlatformThread::CurrentId())) {
1932     const char* new_name = ThreadIdNameManager::GetInstance()->
1933         GetName(thread_id);
1934     // Check if the thread name has been set or changed since the previous
1935     // call (if any), but don't bother if the new name is empty. Note this will
1936     // not detect a thread name change within the same char* buffer address: we
1937     // favor common case performance over corner case correctness.
1938     if (new_name != g_current_thread_name.Get().Get() &&
1939         new_name && *new_name) {
1940       g_current_thread_name.Get().Set(new_name);
1941
1942       AutoLock thread_info_lock(thread_info_lock_);
1943
1944       hash_map<int, std::string>::iterator existing_name =
1945           thread_names_.find(thread_id);
1946       if (existing_name == thread_names_.end()) {
1947         // This is a new thread id, and a new name.
1948         thread_names_[thread_id] = new_name;
1949       } else {
1950         // This is a thread id that we've seen before, but potentially with a
1951         // new name.
1952         std::vector<StringPiece> existing_names;
1953         Tokenize(existing_name->second, ",", &existing_names);
1954         bool found = std::find(existing_names.begin(),
1955                                existing_names.end(),
1956                                new_name) != existing_names.end();
1957         if (!found) {
1958           if (existing_names.size())
1959             existing_name->second.push_back(',');
1960           existing_name->second.append(new_name);
1961         }
1962       }
1963     }
1964   }
1965
1966   std::string console_message;
1967   if (*category_group_enabled &
1968       (ENABLED_FOR_RECORDING | ENABLED_FOR_MONITORING)) {
1969     OptionalAutoLock lock(lock_);
1970
1971     TraceEvent* trace_event = NULL;
1972     if (thread_local_event_buffer) {
1973       trace_event = thread_local_event_buffer->AddTraceEvent(&handle);
1974     } else {
1975       lock.EnsureAcquired();
1976       trace_event = AddEventToThreadSharedChunkWhileLocked(&handle, true);
1977     }
1978
1979     if (trace_event) {
1980       trace_event->Initialize(thread_id, now, thread_now, phase,
1981                               category_group_enabled, name, id,
1982                               num_args, arg_names, arg_types, arg_values,
1983                               convertable_values, flags);
1984
1985 #if defined(OS_ANDROID)
1986       trace_event->SendToATrace();
1987 #endif
1988     }
1989
1990     if (trace_options() & kInternalEchoToConsole) {
1991       console_message = EventToConsoleMessage(
1992           phase == TRACE_EVENT_PHASE_COMPLETE ? TRACE_EVENT_PHASE_BEGIN : phase,
1993           timestamp, trace_event);
1994     }
1995   }
1996
1997   if (console_message.size())
1998     LOG(ERROR) << console_message;
1999
2000   if (reinterpret_cast<const unsigned char*>(subtle::NoBarrier_Load(
2001       &watch_category_)) == category_group_enabled) {
2002     bool event_name_matches;
2003     WatchEventCallback watch_event_callback_copy;
2004     {
2005       AutoLock lock(lock_);
2006       event_name_matches = watch_event_name_ == name;
2007       watch_event_callback_copy = watch_event_callback_;
2008     }
2009     if (event_name_matches) {
2010       if (!watch_event_callback_copy.is_null())
2011         watch_event_callback_copy.Run();
2012     }
2013   }
2014
2015   if (*category_group_enabled & ENABLED_FOR_EVENT_CALLBACK) {
2016     EventCallback event_callback = reinterpret_cast<EventCallback>(
2017         subtle::NoBarrier_Load(&event_callback_));
2018     if (event_callback) {
2019       event_callback(now,
2020                      phase == TRACE_EVENT_PHASE_COMPLETE ?
2021                          TRACE_EVENT_PHASE_BEGIN : phase,
2022                      category_group_enabled, name, id,
2023                      num_args, arg_names, arg_types, arg_values,
2024                      flags);
2025     }
2026   }
2027
2028   if (thread_local_event_buffer)
2029     thread_local_event_buffer->ReportOverhead(now, thread_now);
2030
2031   return handle;
2032 }
2033
2034 // May be called when a COMPELETE event ends and the unfinished event has been
2035 // recycled (phase == TRACE_EVENT_PHASE_END and trace_event == NULL).
2036 std::string TraceLog::EventToConsoleMessage(unsigned char phase,
2037                                             const TimeTicks& timestamp,
2038                                             TraceEvent* trace_event) {
2039   AutoLock thread_info_lock(thread_info_lock_);
2040
2041   // The caller should translate TRACE_EVENT_PHASE_COMPLETE to
2042   // TRACE_EVENT_PHASE_BEGIN or TRACE_EVENT_END.
2043   DCHECK(phase != TRACE_EVENT_PHASE_COMPLETE);
2044
2045   TimeDelta duration;
2046   int thread_id = trace_event ?
2047       trace_event->thread_id() : PlatformThread::CurrentId();
2048   if (phase == TRACE_EVENT_PHASE_END) {
2049     duration = timestamp - thread_event_start_times_[thread_id].top();
2050     thread_event_start_times_[thread_id].pop();
2051   }
2052
2053   std::string thread_name = thread_names_[thread_id];
2054   if (thread_colors_.find(thread_name) == thread_colors_.end())
2055     thread_colors_[thread_name] = (thread_colors_.size() % 6) + 1;
2056
2057   std::ostringstream log;
2058   log << base::StringPrintf("%s: \x1b[0;3%dm",
2059                             thread_name.c_str(),
2060                             thread_colors_[thread_name]);
2061
2062   size_t depth = 0;
2063   if (thread_event_start_times_.find(thread_id) !=
2064       thread_event_start_times_.end())
2065     depth = thread_event_start_times_[thread_id].size();
2066
2067   for (size_t i = 0; i < depth; ++i)
2068     log << "| ";
2069
2070   if (trace_event)
2071     trace_event->AppendPrettyPrinted(&log);
2072   if (phase == TRACE_EVENT_PHASE_END)
2073     log << base::StringPrintf(" (%.3f ms)", duration.InMillisecondsF());
2074
2075   log << "\x1b[0;m";
2076
2077   if (phase == TRACE_EVENT_PHASE_BEGIN)
2078     thread_event_start_times_[thread_id].push(timestamp);
2079
2080   return log.str();
2081 }
2082
2083 void TraceLog::AddTraceEventEtw(char phase,
2084                                 const char* name,
2085                                 const void* id,
2086                                 const char* extra) {
2087 #if defined(OS_WIN)
2088   TraceEventETWProvider::Trace(name, phase, id, extra);
2089 #endif
2090   INTERNAL_TRACE_EVENT_ADD(phase, "ETW Trace Event", name,
2091                            TRACE_EVENT_FLAG_COPY, "id", id, "extra", extra);
2092 }
2093
2094 void TraceLog::AddTraceEventEtw(char phase,
2095                                 const char* name,
2096                                 const void* id,
2097                                 const std::string& extra) {
2098 #if defined(OS_WIN)
2099   TraceEventETWProvider::Trace(name, phase, id, extra);
2100 #endif
2101   INTERNAL_TRACE_EVENT_ADD(phase, "ETW Trace Event", name,
2102                            TRACE_EVENT_FLAG_COPY, "id", id, "extra", extra);
2103 }
2104
2105 void TraceLog::UpdateTraceEventDuration(
2106     const unsigned char* category_group_enabled,
2107     const char* name,
2108     TraceEventHandle handle) {
2109   // Avoid re-entrance of AddTraceEvent. This may happen in GPU process when
2110   // ECHO_TO_CONSOLE is enabled: AddTraceEvent -> LOG(ERROR) ->
2111   // GpuProcessLogMessageHandler -> PostPendingTask -> TRACE_EVENT ...
2112   if (thread_is_in_trace_event_.Get())
2113     return;
2114
2115   AutoThreadLocalBoolean thread_is_in_trace_event(&thread_is_in_trace_event_);
2116
2117   TimeTicks thread_now = ThreadNow();
2118   TimeTicks now = OffsetNow();
2119
2120   std::string console_message;
2121   if (*category_group_enabled & ENABLED_FOR_RECORDING) {
2122     OptionalAutoLock lock(lock_);
2123
2124     TraceEvent* trace_event = GetEventByHandleInternal(handle, &lock);
2125     if (trace_event) {
2126       DCHECK(trace_event->phase() == TRACE_EVENT_PHASE_COMPLETE);
2127       trace_event->UpdateDuration(now, thread_now);
2128 #if defined(OS_ANDROID)
2129       trace_event->SendToATrace();
2130 #endif
2131     }
2132
2133     if (trace_options() & kInternalEchoToConsole) {
2134       console_message = EventToConsoleMessage(TRACE_EVENT_PHASE_END,
2135                                               now, trace_event);
2136     }
2137   }
2138
2139   if (console_message.size())
2140     LOG(ERROR) << console_message;
2141
2142   if (*category_group_enabled & ENABLED_FOR_EVENT_CALLBACK) {
2143     EventCallback event_callback = reinterpret_cast<EventCallback>(
2144         subtle::NoBarrier_Load(&event_callback_));
2145     if (event_callback) {
2146       event_callback(now, TRACE_EVENT_PHASE_END, category_group_enabled, name,
2147                      trace_event_internal::kNoEventId, 0, NULL, NULL, NULL,
2148                      TRACE_EVENT_FLAG_NONE);
2149     }
2150   }
2151 }
2152
2153 void TraceLog::SetWatchEvent(const std::string& category_name,
2154                              const std::string& event_name,
2155                              const WatchEventCallback& callback) {
2156   const unsigned char* category = GetCategoryGroupEnabled(
2157       category_name.c_str());
2158   AutoLock lock(lock_);
2159   subtle::NoBarrier_Store(&watch_category_,
2160                           reinterpret_cast<subtle::AtomicWord>(category));
2161   watch_event_name_ = event_name;
2162   watch_event_callback_ = callback;
2163 }
2164
2165 void TraceLog::CancelWatchEvent() {
2166   AutoLock lock(lock_);
2167   subtle::NoBarrier_Store(&watch_category_, 0);
2168   watch_event_name_ = "";
2169   watch_event_callback_.Reset();
2170 }
2171
2172 void TraceLog::AddMetadataEventsWhileLocked() {
2173   lock_.AssertAcquired();
2174
2175 #if !defined(OS_NACL)  // NaCl shouldn't expose the process id.
2176   InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
2177                           0,
2178                           "num_cpus", "number",
2179                           base::SysInfo::NumberOfProcessors());
2180 #endif
2181
2182
2183   int current_thread_id = static_cast<int>(base::PlatformThread::CurrentId());
2184   if (process_sort_index_ != 0) {
2185     InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
2186                             current_thread_id,
2187                             "process_sort_index", "sort_index",
2188                             process_sort_index_);
2189   }
2190
2191   if (process_name_.size()) {
2192     InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
2193                             current_thread_id,
2194                             "process_name", "name",
2195                             process_name_);
2196   }
2197
2198   if (process_labels_.size() > 0) {
2199     std::vector<std::string> labels;
2200     for(base::hash_map<int, std::string>::iterator it = process_labels_.begin();
2201         it != process_labels_.end();
2202         it++) {
2203       labels.push_back(it->second);
2204     }
2205     InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
2206                             current_thread_id,
2207                             "process_labels", "labels",
2208                             JoinString(labels, ','));
2209   }
2210
2211   // Thread sort indices.
2212   for(hash_map<int, int>::iterator it = thread_sort_indices_.begin();
2213       it != thread_sort_indices_.end();
2214       it++) {
2215     if (it->second == 0)
2216       continue;
2217     InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
2218                             it->first,
2219                             "thread_sort_index", "sort_index",
2220                             it->second);
2221   }
2222
2223   // Thread names.
2224   AutoLock thread_info_lock(thread_info_lock_);
2225   for(hash_map<int, std::string>::iterator it = thread_names_.begin();
2226       it != thread_names_.end();
2227       it++) {
2228     if (it->second.empty())
2229       continue;
2230     InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
2231                             it->first,
2232                             "thread_name", "name",
2233                             it->second);
2234   }
2235
2236   // If buffer is full, add a metadata record to report this.
2237   if (!buffer_limit_reached_timestamp_.is_null()) {
2238     InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
2239                             current_thread_id,
2240                             "trace_buffer_overflowed",
2241                             "overflowed_at_ts",
2242                             buffer_limit_reached_timestamp_);
2243   }
2244 }
2245
2246 void TraceLog::WaitSamplingEventForTesting() {
2247   if (!sampling_thread_)
2248     return;
2249   sampling_thread_->WaitSamplingEventForTesting();
2250 }
2251
2252 void TraceLog::DeleteForTesting() {
2253   DeleteTraceLogForTesting::Delete();
2254 }
2255
2256 TraceEvent* TraceLog::GetEventByHandle(TraceEventHandle handle) {
2257   return GetEventByHandleInternal(handle, NULL);
2258 }
2259
2260 TraceEvent* TraceLog::GetEventByHandleInternal(TraceEventHandle handle,
2261                                                OptionalAutoLock* lock) {
2262   if (!handle.chunk_seq)
2263     return NULL;
2264
2265   if (thread_local_event_buffer_.Get()) {
2266     TraceEvent* trace_event =
2267         thread_local_event_buffer_.Get()->GetEventByHandle(handle);
2268     if (trace_event)
2269       return trace_event;
2270   }
2271
2272   // The event has been out-of-control of the thread local buffer.
2273   // Try to get the event from the main buffer with a lock.
2274   if (lock)
2275     lock->EnsureAcquired();
2276
2277   if (thread_shared_chunk_ &&
2278       handle.chunk_index == thread_shared_chunk_index_) {
2279     return handle.chunk_seq == thread_shared_chunk_->seq() ?
2280         thread_shared_chunk_->GetEventAt(handle.event_index) : NULL;
2281   }
2282
2283   return logged_events_->GetEventByHandle(handle);
2284 }
2285
2286 void TraceLog::SetProcessID(int process_id) {
2287   process_id_ = process_id;
2288   // Create a FNV hash from the process ID for XORing.
2289   // See http://isthe.com/chongo/tech/comp/fnv/ for algorithm details.
2290   unsigned long long offset_basis = 14695981039346656037ull;
2291   unsigned long long fnv_prime = 1099511628211ull;
2292   unsigned long long pid = static_cast<unsigned long long>(process_id_);
2293   process_id_hash_ = (offset_basis ^ pid) * fnv_prime;
2294 }
2295
2296 void TraceLog::SetProcessSortIndex(int sort_index) {
2297   AutoLock lock(lock_);
2298   process_sort_index_ = sort_index;
2299 }
2300
2301 void TraceLog::SetProcessName(const std::string& process_name) {
2302   AutoLock lock(lock_);
2303   process_name_ = process_name;
2304 }
2305
2306 void TraceLog::UpdateProcessLabel(
2307     int label_id, const std::string& current_label) {
2308   if(!current_label.length())
2309     return RemoveProcessLabel(label_id);
2310
2311   AutoLock lock(lock_);
2312   process_labels_[label_id] = current_label;
2313 }
2314
2315 void TraceLog::RemoveProcessLabel(int label_id) {
2316   AutoLock lock(lock_);
2317   base::hash_map<int, std::string>::iterator it = process_labels_.find(
2318       label_id);
2319   if (it == process_labels_.end())
2320     return;
2321
2322   process_labels_.erase(it);
2323 }
2324
2325 void TraceLog::SetThreadSortIndex(PlatformThreadId thread_id, int sort_index) {
2326   AutoLock lock(lock_);
2327   thread_sort_indices_[static_cast<int>(thread_id)] = sort_index;
2328 }
2329
2330 void TraceLog::SetTimeOffset(TimeDelta offset) {
2331   time_offset_ = offset;
2332 }
2333
2334 size_t TraceLog::GetObserverCountForTest() const {
2335   return enabled_state_observer_list_.size();
2336 }
2337
2338 void TraceLog::SetCurrentThreadBlocksMessageLoop() {
2339   thread_blocks_message_loop_.Set(true);
2340   if (thread_local_event_buffer_.Get()) {
2341     // This will flush the thread local buffer.
2342     delete thread_local_event_buffer_.Get();
2343   }
2344 }
2345
2346 bool CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2347     const std::string& str) {
2348   return  str.empty() ||
2349           str.at(0) == ' ' ||
2350           str.at(str.length() - 1) == ' ';
2351 }
2352
2353 bool CategoryFilter::DoesCategoryGroupContainCategory(
2354     const char* category_group,
2355     const char* category) const {
2356   DCHECK(category);
2357   CStringTokenizer category_group_tokens(category_group,
2358                           category_group + strlen(category_group), ",");
2359   while (category_group_tokens.GetNext()) {
2360     std::string category_group_token = category_group_tokens.token();
2361     // Don't allow empty tokens, nor tokens with leading or trailing space.
2362     DCHECK(!CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2363         category_group_token))
2364         << "Disallowed category string";
2365     if (MatchPattern(category_group_token.c_str(), category))
2366       return true;
2367   }
2368   return false;
2369 }
2370
2371 CategoryFilter::CategoryFilter(const std::string& filter_string) {
2372   if (!filter_string.empty())
2373     Initialize(filter_string);
2374   else
2375     Initialize(CategoryFilter::kDefaultCategoryFilterString);
2376 }
2377
2378 CategoryFilter::CategoryFilter() {
2379     Initialize(CategoryFilter::kDefaultCategoryFilterString);
2380 }
2381
2382 CategoryFilter::CategoryFilter(const CategoryFilter& cf)
2383     : included_(cf.included_),
2384       disabled_(cf.disabled_),
2385       excluded_(cf.excluded_),
2386       delays_(cf.delays_) {
2387 }
2388
2389 CategoryFilter::~CategoryFilter() {
2390 }
2391
2392 CategoryFilter& CategoryFilter::operator=(const CategoryFilter& rhs) {
2393   if (this == &rhs)
2394     return *this;
2395
2396   included_ = rhs.included_;
2397   disabled_ = rhs.disabled_;
2398   excluded_ = rhs.excluded_;
2399   delays_ = rhs.delays_;
2400   return *this;
2401 }
2402
2403 void CategoryFilter::Initialize(const std::string& filter_string) {
2404   // Tokenize list of categories, delimited by ','.
2405   StringTokenizer tokens(filter_string, ",");
2406   // Add each token to the appropriate list (included_,excluded_).
2407   while (tokens.GetNext()) {
2408     std::string category = tokens.token();
2409     // Ignore empty categories.
2410     if (category.empty())
2411       continue;
2412     // Synthetic delays are of the form 'DELAY(delay;option;option;...)'.
2413     if (category.find(kSyntheticDelayCategoryFilterPrefix) == 0 &&
2414         category.at(category.size() - 1) == ')') {
2415       category = category.substr(
2416           strlen(kSyntheticDelayCategoryFilterPrefix),
2417           category.size() - strlen(kSyntheticDelayCategoryFilterPrefix) - 1);
2418       size_t name_length = category.find(';');
2419       if (name_length != std::string::npos && name_length > 0 &&
2420           name_length != category.size() - 1) {
2421         delays_.push_back(category);
2422       }
2423     } else if (category.at(0) == '-') {
2424       // Excluded categories start with '-'.
2425       // Remove '-' from category string.
2426       category = category.substr(1);
2427       excluded_.push_back(category);
2428     } else if (category.compare(0, strlen(TRACE_DISABLED_BY_DEFAULT("")),
2429                                 TRACE_DISABLED_BY_DEFAULT("")) == 0) {
2430       disabled_.push_back(category);
2431     } else {
2432       included_.push_back(category);
2433     }
2434   }
2435 }
2436
2437 void CategoryFilter::WriteString(const StringList& values,
2438                                  std::string* out,
2439                                  bool included) const {
2440   bool prepend_comma = !out->empty();
2441   int token_cnt = 0;
2442   for (StringList::const_iterator ci = values.begin();
2443        ci != values.end(); ++ci) {
2444     if (token_cnt > 0 || prepend_comma)
2445       StringAppendF(out, ",");
2446     StringAppendF(out, "%s%s", (included ? "" : "-"), ci->c_str());
2447     ++token_cnt;
2448   }
2449 }
2450
2451 void CategoryFilter::WriteString(const StringList& delays,
2452                                  std::string* out) const {
2453   bool prepend_comma = !out->empty();
2454   int token_cnt = 0;
2455   for (StringList::const_iterator ci = delays.begin();
2456        ci != delays.end(); ++ci) {
2457     if (token_cnt > 0 || prepend_comma)
2458       StringAppendF(out, ",");
2459     StringAppendF(out, "%s%s)", kSyntheticDelayCategoryFilterPrefix,
2460                   ci->c_str());
2461     ++token_cnt;
2462   }
2463 }
2464
2465 std::string CategoryFilter::ToString() const {
2466   std::string filter_string;
2467   WriteString(included_, &filter_string, true);
2468   WriteString(disabled_, &filter_string, true);
2469   WriteString(excluded_, &filter_string, false);
2470   WriteString(delays_, &filter_string);
2471   return filter_string;
2472 }
2473
2474 bool CategoryFilter::IsCategoryGroupEnabled(
2475     const char* category_group_name) const {
2476   // TraceLog should call this method only as  part of enabling/disabling
2477   // categories.
2478   StringList::const_iterator ci;
2479
2480   // Check the disabled- filters and the disabled-* wildcard first so that a
2481   // "*" filter does not include the disabled.
2482   for (ci = disabled_.begin(); ci != disabled_.end(); ++ci) {
2483     if (DoesCategoryGroupContainCategory(category_group_name, ci->c_str()))
2484       return true;
2485   }
2486   if (DoesCategoryGroupContainCategory(category_group_name,
2487                                        TRACE_DISABLED_BY_DEFAULT("*")))
2488     return false;
2489
2490   for (ci = included_.begin(); ci != included_.end(); ++ci) {
2491     if (DoesCategoryGroupContainCategory(category_group_name, ci->c_str()))
2492       return true;
2493   }
2494
2495   for (ci = excluded_.begin(); ci != excluded_.end(); ++ci) {
2496     if (DoesCategoryGroupContainCategory(category_group_name, ci->c_str()))
2497       return false;
2498   }
2499   // If the category group is not excluded, and there are no included patterns
2500   // we consider this pattern enabled.
2501   return included_.empty();
2502 }
2503
2504 bool CategoryFilter::HasIncludedPatterns() const {
2505   return !included_.empty();
2506 }
2507
2508 void CategoryFilter::Merge(const CategoryFilter& nested_filter) {
2509   // Keep included patterns only if both filters have an included entry.
2510   // Otherwise, one of the filter was specifying "*" and we want to honour the
2511   // broadest filter.
2512   if (HasIncludedPatterns() && nested_filter.HasIncludedPatterns()) {
2513     included_.insert(included_.end(),
2514                      nested_filter.included_.begin(),
2515                      nested_filter.included_.end());
2516   } else {
2517     included_.clear();
2518   }
2519
2520   disabled_.insert(disabled_.end(),
2521                    nested_filter.disabled_.begin(),
2522                    nested_filter.disabled_.end());
2523   excluded_.insert(excluded_.end(),
2524                    nested_filter.excluded_.begin(),
2525                    nested_filter.excluded_.end());
2526   delays_.insert(delays_.end(),
2527                  nested_filter.delays_.begin(),
2528                  nested_filter.delays_.end());
2529 }
2530
2531 void CategoryFilter::Clear() {
2532   included_.clear();
2533   disabled_.clear();
2534   excluded_.clear();
2535 }
2536
2537 const CategoryFilter::StringList&
2538     CategoryFilter::GetSyntheticDelayValues() const {
2539   return delays_;
2540 }
2541
2542 }  // namespace debug
2543 }  // namespace base
2544
2545 namespace trace_event_internal {
2546
2547 ScopedTraceBinaryEfficient::ScopedTraceBinaryEfficient(
2548     const char* category_group, const char* name) {
2549   // The single atom works because for now the category_group can only be "gpu".
2550   DCHECK(strcmp(category_group, "gpu") == 0);
2551   static TRACE_EVENT_API_ATOMIC_WORD atomic = 0;
2552   INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO_CUSTOM_VARIABLES(
2553       category_group, atomic, category_group_enabled_);
2554   name_ = name;
2555   if (*category_group_enabled_) {
2556     event_handle_ =
2557         TRACE_EVENT_API_ADD_TRACE_EVENT_WITH_THREAD_ID_AND_TIMESTAMP(
2558             TRACE_EVENT_PHASE_COMPLETE, category_group_enabled_, name,
2559             trace_event_internal::kNoEventId,
2560             static_cast<int>(base::PlatformThread::CurrentId()),
2561             base::TimeTicks::NowFromSystemTraceTime(),
2562             0, NULL, NULL, NULL, NULL, TRACE_EVENT_FLAG_NONE);
2563   }
2564 }
2565
2566 ScopedTraceBinaryEfficient::~ScopedTraceBinaryEfficient() {
2567   if (*category_group_enabled_) {
2568     TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION(category_group_enabled_,
2569                                                 name_, event_handle_);
2570   }
2571 }
2572
2573 }  // namespace trace_event_internal