trace_event_impl.cc

// Copyright (c) 2012 The Chromium Authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

#include "base/trace_event/trace_event_impl.h"

#include <algorithm>

#include "base/base_switches.h"
#include "base/bind.h"
#include "base/command_line.h"
#include "base/debug/leak_annotations.h"
#include "base/float_util.h"
#include "base/format_macros.h"
#include "base/json/string_escape.h"
#include "base/lazy_instance.h"
#include "base/memory/singleton.h"
#include "base/message_loop/message_loop.h"
#include "base/process/process_metrics.h"
#include "base/stl_util.h"
#include "base/strings/string_number_conversions.h"
#include "base/strings/string_split.h"
#include "base/strings/string_tokenizer.h"
#include "base/strings/string_util.h"
#include "base/strings/stringprintf.h"
#include "base/strings/utf_string_conversions.h"
#include "base/synchronization/cancellation_flag.h"
#include "base/synchronization/waitable_event.h"
#include "base/sys_info.h"
#include "base/third_party/dynamic_annotations/dynamic_annotations.h"
#include "base/threading/platform_thread.h"
#include "base/threading/thread_id_name_manager.h"
#include "base/time/time.h"
#include "base/trace_event/trace_event.h"
#include "base/trace_event/trace_event_synthetic_delay.h"

#if defined(OS_WIN)
#include "base/trace_event/trace_event_win.h"
#endif

class DeleteTraceLogForTesting {
 public:
  static void Delete() {
    Singleton<base::debug::TraceLog,
              LeakySingletonTraits<base::debug::TraceLog> >::OnExit(0);
  }
};

// The thread buckets for the sampling profiler.
BASE_EXPORT TRACE_EVENT_API_ATOMIC_WORD g_trace_state[3];

namespace base {
namespace debug {

namespace {

// The overhead of TraceEvent above this threshold will be reported in the
// trace.
const int kOverheadReportThresholdInMicroseconds = 50;

// String options that can be used to initialize TraceOptions.
const char kRecordUntilFull[] = "record-until-full";
const char kRecordContinuously[] = "record-continuously";
const char kRecordAsMuchAsPossible[] = "record-as-much-as-possible";
const char kTraceToConsole[] = "trace-to-console";
const char kEnableSampling[] = "enable-sampling";
const char kEnableSystrace[] = "enable-systrace";

// Controls the number of trace events we will buffer in-memory
// before throwing them away.
const size_t kTraceBufferChunkSize = TraceBufferChunk::kTraceBufferChunkSize;
const size_t kTraceEventVectorBigBufferChunks =
    512000000 / kTraceBufferChunkSize;
const size_t kTraceEventVectorBufferChunks = 256000 / kTraceBufferChunkSize;
const size_t kTraceEventRingBufferChunks = kTraceEventVectorBufferChunks / 4;
const size_t kTraceEventBatchChunks = 1000 / kTraceBufferChunkSize;
// Can store results for 30 seconds with 1 ms sampling interval.
const size_t kMonitorTraceEventBufferChunks = 30000 / kTraceBufferChunkSize;
// ECHO_TO_CONSOLE needs a small buffer to hold the unfinished COMPLETE events.
const size_t kEchoToConsoleTraceEventBufferChunks = 256;

const int kThreadFlushTimeoutMs = 3000;

#if !defined(OS_NACL)
// These categories will cause deadlock when ECHO_TO_CONSOLE. crbug.com/325575.
const char kEchoToConsoleCategoryFilter[] = "-ipc,-task";
#endif

const char kSyntheticDelayCategoryFilterPrefix[] = "DELAY(";

#define MAX_CATEGORY_GROUPS 100

// Parallel arrays g_category_groups and g_category_group_enabled are separate
// so that a pointer to a member of g_category_group_enabled can be easily
// converted to an index into g_category_groups. This allows macros to deal
// only with char enabled pointers from g_category_group_enabled, and we can
// convert internally to determine the category name from the char enabled
// pointer.
const char* g_category_groups[MAX_CATEGORY_GROUPS] = {
  "toplevel",
  "tracing already shutdown",
  "tracing categories exhausted; must increase MAX_CATEGORY_GROUPS",
  "__metadata",
  // For reporting trace_event overhead. For thread local event buffers only.
  "trace_event_overhead"};

// The enabled flag is char instead of bool so that the API can be used from C.
unsigned char g_category_group_enabled[MAX_CATEGORY_GROUPS] = { 0 };
// Indexes here have to match the g_category_groups array indexes above.
const int g_category_already_shutdown = 1;
const int g_category_categories_exhausted = 2;
const int g_category_metadata = 3;
const int g_category_trace_event_overhead = 4;
const int g_num_builtin_categories = 5;
// Skip default categories.
base::subtle::AtomicWord g_category_index = g_num_builtin_categories;

// The name of the current thread. This is used to decide if the current
// thread name has changed. We combine all the seen thread names into the
// output name for the thread.
LazyInstance<ThreadLocalPointer<const char> >::Leaky
    g_current_thread_name = LAZY_INSTANCE_INITIALIZER;

TimeTicks ThreadNow() {
  return TimeTicks::IsThreadNowSupported() ?
      TimeTicks::ThreadNow() : TimeTicks();
}

class TraceBufferRingBuffer : public TraceBuffer {
 public:
  TraceBufferRingBuffer(size_t max_chunks)
      : max_chunks_(max_chunks),
        recyclable_chunks_queue_(new size_t[queue_capacity()]),
        queue_head_(0),
        queue_tail_(max_chunks),
        current_iteration_index_(0),
        current_chunk_seq_(1) {
    chunks_.reserve(max_chunks);
    for (size_t i = 0; i < max_chunks; ++i)
      recyclable_chunks_queue_[i] = i;
  }

  scoped_ptr<TraceBufferChunk> GetChunk(size_t* index) override {
    // Because the number of threads is much less than the number of chunks,
    // the queue should never be empty.
    DCHECK(!QueueIsEmpty());

    *index = recyclable_chunks_queue_[queue_head_];
    queue_head_ = NextQueueIndex(queue_head_);
    current_iteration_index_ = queue_head_;

    if (*index >= chunks_.size())
      chunks_.resize(*index + 1);

    TraceBufferChunk* chunk = chunks_[*index];
    chunks_[*index] = NULL;  // Put NULL in the slot of a in-flight chunk.
    if (chunk)
      chunk->Reset(current_chunk_seq_++);
    else
      chunk = new TraceBufferChunk(current_chunk_seq_++);

    return scoped_ptr<TraceBufferChunk>(chunk);
  }

  void ReturnChunk(size_t index, scoped_ptr<TraceBufferChunk> chunk) override {
    // When this method is called, the queue should not be full because it
    // can contain all chunks including the one to be returned.
    DCHECK(!QueueIsFull());
    DCHECK(chunk);
    DCHECK_LT(index, chunks_.size());
    DCHECK(!chunks_[index]);
    chunks_[index] = chunk.release();
    recyclable_chunks_queue_[queue_tail_] = index;
    queue_tail_ = NextQueueIndex(queue_tail_);
  }

  bool IsFull() const override { return false; }

  size_t Size() const override {
    // This is approximate because not all of the chunks are full.
    return chunks_.size() * kTraceBufferChunkSize;
  }

  size_t Capacity() const override {
    return max_chunks_ * kTraceBufferChunkSize;
  }

  TraceEvent* GetEventByHandle(TraceEventHandle handle) override {
    if (handle.chunk_index >= chunks_.size())
      return NULL;
    TraceBufferChunk* chunk = chunks_[handle.chunk_index];
    if (!chunk || chunk->seq() != handle.chunk_seq)
      return NULL;
    return chunk->GetEventAt(handle.event_index);
  }

  const TraceBufferChunk* NextChunk() override {
    if (chunks_.empty())
      return NULL;

    while (current_iteration_index_ != queue_tail_) {
      size_t chunk_index = recyclable_chunks_queue_[current_iteration_index_];
      current_iteration_index_ = NextQueueIndex(current_iteration_index_);
      if (chunk_index >= chunks_.size()) // Skip uninitialized chunks.
        continue;
      DCHECK(chunks_[chunk_index]);
      return chunks_[chunk_index];
    }
    return NULL;
  }

  scoped_ptr<TraceBuffer> CloneForIteration() const override {
    scoped_ptr<ClonedTraceBuffer> cloned_buffer(new ClonedTraceBuffer());
    for (size_t queue_index = queue_head_; queue_index != queue_tail_;
        queue_index = NextQueueIndex(queue_index)) {
      size_t chunk_index = recyclable_chunks_queue_[queue_index];
      if (chunk_index >= chunks_.size()) // Skip uninitialized chunks.
        continue;
      TraceBufferChunk* chunk = chunks_[chunk_index];
      cloned_buffer->chunks_.push_back(chunk ? chunk->Clone().release() : NULL);
    }
    return cloned_buffer.Pass();
  }

 private:
  class ClonedTraceBuffer : public TraceBuffer {
   public:
    ClonedTraceBuffer() : current_iteration_index_(0) {}

    // The only implemented method.
    const TraceBufferChunk* NextChunk() override {
      return current_iteration_index_ < chunks_.size() ?
          chunks_[current_iteration_index_++] : NULL;
    }

    scoped_ptr<TraceBufferChunk> GetChunk(size_t* index) override {
      NOTIMPLEMENTED();
      return scoped_ptr<TraceBufferChunk>();
    }
    void ReturnChunk(size_t index, scoped_ptr<TraceBufferChunk>) override {
      NOTIMPLEMENTED();
    }
    bool IsFull() const override { return false; }
    size_t Size() const override { return 0; }
    size_t Capacity() const override { return 0; }
    TraceEvent* GetEventByHandle(TraceEventHandle handle) override {
      return NULL;
    }
    scoped_ptr<TraceBuffer> CloneForIteration() const override {
      NOTIMPLEMENTED();
      return scoped_ptr<TraceBuffer>();
    }

    size_t current_iteration_index_;
    ScopedVector<TraceBufferChunk> chunks_;
  };

  bool QueueIsEmpty() const {
    return queue_head_ == queue_tail_;
  }

  size_t QueueSize() const {
    return queue_tail_ > queue_head_ ? queue_tail_ - queue_head_ :
        queue_tail_ + queue_capacity() - queue_head_;
  }

  bool QueueIsFull() const {
    return QueueSize() == queue_capacity() - 1;
  }

  size_t queue_capacity() const {
    // One extra space to help distinguish full state and empty state.
    return max_chunks_ + 1;
  }

  size_t NextQueueIndex(size_t index) const {
    index++;
    if (index >= queue_capacity())
      index = 0;
    return index;
  }

  size_t max_chunks_;
  ScopedVector<TraceBufferChunk> chunks_;

  scoped_ptr<size_t[]> recyclable_chunks_queue_;
  size_t queue_head_;
  size_t queue_tail_;

  size_t current_iteration_index_;
  uint32 current_chunk_seq_;

  DISALLOW_COPY_AND_ASSIGN(TraceBufferRingBuffer);
};

class TraceBufferVector : public TraceBuffer {
 public:
  TraceBufferVector(size_t max_chunks)
      : in_flight_chunk_count_(0),
        current_iteration_index_(0),
        max_chunks_(max_chunks) {
    chunks_.reserve(max_chunks_);
  }

  scoped_ptr<TraceBufferChunk> GetChunk(size_t* index) override {
    // This function may be called when adding normal events or indirectly from
    // AddMetadataEventsWhileLocked(). We can not DECHECK(!IsFull()) because we
    // have to add the metadata events and flush thread-local buffers even if
    // the buffer is full.
    *index = chunks_.size();
    chunks_.push_back(NULL);  // Put NULL in the slot of a in-flight chunk.
    ++in_flight_chunk_count_;
    // + 1 because zero chunk_seq is not allowed.
    return scoped_ptr<TraceBufferChunk>(
        new TraceBufferChunk(static_cast<uint32>(*index) + 1));
  }

  void ReturnChunk(size_t index, scoped_ptr<TraceBufferChunk> chunk) override {
    DCHECK_GT(in_flight_chunk_count_, 0u);
    DCHECK_LT(index, chunks_.size());
    DCHECK(!chunks_[index]);
    --in_flight_chunk_count_;
    chunks_[index] = chunk.release();
  }

  bool IsFull() const override { return chunks_.size() >= max_chunks_; }

  size_t Size() const override {
    // This is approximate because not all of the chunks are full.
    return chunks_.size() * kTraceBufferChunkSize;
  }

  size_t Capacity() const override {
    return max_chunks_ * kTraceBufferChunkSize;
  }

  TraceEvent* GetEventByHandle(TraceEventHandle handle) override {
    if (handle.chunk_index >= chunks_.size())
      return NULL;
    TraceBufferChunk* chunk = chunks_[handle.chunk_index];
    if (!chunk || chunk->seq() != handle.chunk_seq)
      return NULL;
    return chunk->GetEventAt(handle.event_index);
  }

  const TraceBufferChunk* NextChunk() override {
    while (current_iteration_index_ < chunks_.size()) {
      // Skip in-flight chunks.
      const TraceBufferChunk* chunk = chunks_[current_iteration_index_++];
      if (chunk)
        return chunk;
    }
    return NULL;
  }

  scoped_ptr<TraceBuffer> CloneForIteration() const override {
    NOTIMPLEMENTED();
    return scoped_ptr<TraceBuffer>();
  }

 private:
  size_t in_flight_chunk_count_;
  size_t current_iteration_index_;
  size_t max_chunks_;
  ScopedVector<TraceBufferChunk> chunks_;

  DISALLOW_COPY_AND_ASSIGN(TraceBufferVector);
};

template <typename T>
void InitializeMetadataEvent(TraceEvent* trace_event,
                             int thread_id,
                             const char* metadata_name, const char* arg_name,
                             const T& value) {
  if (!trace_event)
    return;

  int num_args = 1;
  unsigned char arg_type;
  unsigned long long arg_value;
  ::trace_event_internal::SetTraceValue(value, &arg_type, &arg_value);
  trace_event->Initialize(thread_id,
                          TimeTicks(), TimeTicks(), TRACE_EVENT_PHASE_METADATA,
                          &g_category_group_enabled[g_category_metadata],
                          metadata_name, ::trace_event_internal::kNoEventId,
                          num_args, &arg_name, &arg_type, &arg_value, NULL,
                          TRACE_EVENT_FLAG_NONE);
}

class AutoThreadLocalBoolean {
 public:
  explicit AutoThreadLocalBoolean(ThreadLocalBoolean* thread_local_boolean)
      : thread_local_boolean_(thread_local_boolean) {
    DCHECK(!thread_local_boolean_->Get());
    thread_local_boolean_->Set(true);
  }
  ~AutoThreadLocalBoolean() {
    thread_local_boolean_->Set(false);
  }

 private:
  ThreadLocalBoolean* thread_local_boolean_;
  DISALLOW_COPY_AND_ASSIGN(AutoThreadLocalBoolean);
};

}  // namespace

void TraceBufferChunk::Reset(uint32 new_seq) {
  for (size_t i = 0; i < next_free_; ++i)
    chunk_[i].Reset();
  next_free_ = 0;
  seq_ = new_seq;
}

TraceEvent* TraceBufferChunk::AddTraceEvent(size_t* event_index) {
  DCHECK(!IsFull());
  *event_index = next_free_++;
  return &chunk_[*event_index];
}

scoped_ptr<TraceBufferChunk> TraceBufferChunk::Clone() const {
  scoped_ptr<TraceBufferChunk> cloned_chunk(new TraceBufferChunk(seq_));
  cloned_chunk->next_free_ = next_free_;
  for (size_t i = 0; i < next_free_; ++i)
    cloned_chunk->chunk_[i].CopyFrom(chunk_[i]);
  return cloned_chunk.Pass();
}

// A helper class that allows the lock to be acquired in the middle of the scope
// and unlocks at the end of scope if locked.
class TraceLog::OptionalAutoLock {
 public:
  explicit OptionalAutoLock(Lock& lock)
      : lock_(lock),
        locked_(false) {
  }

  ~OptionalAutoLock() {
    if (locked_)
      lock_.Release();
  }

  void EnsureAcquired() {
    if (!locked_) {
      lock_.Acquire();
      locked_ = true;
    }
  }

 private:
  Lock& lock_;
  bool locked_;
  DISALLOW_COPY_AND_ASSIGN(OptionalAutoLock);
};

// Use this function instead of TraceEventHandle constructor to keep the
// overhead of ScopedTracer (trace_event.h) constructor minimum.
void MakeHandle(uint32 chunk_seq, size_t chunk_index, size_t event_index,
                TraceEventHandle* handle) {
  DCHECK(chunk_seq);
  DCHECK(chunk_index < (1u << 16));
  DCHECK(event_index < (1u << 16));
  handle->chunk_seq = chunk_seq;
  handle->chunk_index = static_cast<uint16>(chunk_index);
  handle->event_index = static_cast<uint16>(event_index);
}

////////////////////////////////////////////////////////////////////////////////
//
// TraceEvent
//
////////////////////////////////////////////////////////////////////////////////

namespace {

size_t GetAllocLength(const char* str) { return str ? strlen(str) + 1 : 0; }

// Copies |*member| into |*buffer|, sets |*member| to point to this new
// location, and then advances |*buffer| by the amount written.
void CopyTraceEventParameter(char** buffer,
                             const char** member,
                             const char* end) {
  if (*member) {
    size_t written = strlcpy(*buffer, *member, end - *buffer) + 1;
    DCHECK_LE(static_cast<int>(written), end - *buffer);
    *member = *buffer;
    *buffer += written;
  }
}

}  // namespace

TraceEvent::TraceEvent()
    : duration_(TimeDelta::FromInternalValue(-1)),
      id_(0u),
      category_group_enabled_(NULL),
      name_(NULL),
      thread_id_(0),
      phase_(TRACE_EVENT_PHASE_BEGIN),
      flags_(0) {
  for (int i = 0; i < kTraceMaxNumArgs; ++i)
    arg_names_[i] = NULL;
  memset(arg_values_, 0, sizeof(arg_values_));
}

TraceEvent::~TraceEvent() {
}

void TraceEvent::CopyFrom(const TraceEvent& other) {
  timestamp_ = other.timestamp_;
  thread_timestamp_ = other.thread_timestamp_;
  duration_ = other.duration_;
  id_ = other.id_;
  category_group_enabled_ = other.category_group_enabled_;
  name_ = other.name_;
  thread_id_ = other.thread_id_;
  phase_ = other.phase_;
  flags_ = other.flags_;
  parameter_copy_storage_ = other.parameter_copy_storage_;

  for (int i = 0; i < kTraceMaxNumArgs; ++i) {
    arg_names_[i] = other.arg_names_[i];
    arg_types_[i] = other.arg_types_[i];
    arg_values_[i] = other.arg_values_[i];
    convertable_values_[i] = other.convertable_values_[i];
  }
}

void TraceEvent::Initialize(
    int thread_id,
    TimeTicks timestamp,
    TimeTicks thread_timestamp,
    char phase,
    const unsigned char* category_group_enabled,
    const char* name,
    unsigned long long id,
    int num_args,
    const char** arg_names,
    const unsigned char* arg_types,
    const unsigned long long* arg_values,
    const scoped_refptr<ConvertableToTraceFormat>* convertable_values,
    unsigned char flags) {
  timestamp_ = timestamp;
  thread_timestamp_ = thread_timestamp;
  duration_ = TimeDelta::FromInternalValue(-1);
  id_ = id;
  category_group_enabled_ = category_group_enabled;
  name_ = name;
  thread_id_ = thread_id;
  phase_ = phase;
  flags_ = flags;

  // Clamp num_args since it may have been set by a third_party library.
  num_args = (num_args > kTraceMaxNumArgs) ? kTraceMaxNumArgs : num_args;
  int i = 0;
  for (; i < num_args; ++i) {
    arg_names_[i] = arg_names[i];
    arg_types_[i] = arg_types[i];

    if (arg_types[i] == TRACE_VALUE_TYPE_CONVERTABLE)
      convertable_values_[i] = convertable_values[i];
    else
      arg_values_[i].as_uint = arg_values[i];
  }
  for (; i < kTraceMaxNumArgs; ++i) {
    arg_names_[i] = NULL;
    arg_values_[i].as_uint = 0u;
    convertable_values_[i] = NULL;
    arg_types_[i] = TRACE_VALUE_TYPE_UINT;
  }

  bool copy = !!(flags & TRACE_EVENT_FLAG_COPY);
  size_t alloc_size = 0;
  if (copy) {
    alloc_size += GetAllocLength(name);
    for (i = 0; i < num_args; ++i) {
      alloc_size += GetAllocLength(arg_names_[i]);
      if (arg_types_[i] == TRACE_VALUE_TYPE_STRING)
        arg_types_[i] = TRACE_VALUE_TYPE_COPY_STRING;
    }
  }

  bool arg_is_copy[kTraceMaxNumArgs];
  for (i = 0; i < num_args; ++i) {
    // No copying of convertable types, we retain ownership.
    if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
      continue;

    // We only take a copy of arg_vals if they are of type COPY_STRING.
    arg_is_copy[i] = (arg_types_[i] == TRACE_VALUE_TYPE_COPY_STRING);
    if (arg_is_copy[i])
      alloc_size += GetAllocLength(arg_values_[i].as_string);
  }

  if (alloc_size) {
    parameter_copy_storage_ = new RefCountedString;
    parameter_copy_storage_->data().resize(alloc_size);
    char* ptr = string_as_array(&parameter_copy_storage_->data());
    const char* end = ptr + alloc_size;
    if (copy) {
      CopyTraceEventParameter(&ptr, &name_, end);
      for (i = 0; i < num_args; ++i) {
        CopyTraceEventParameter(&ptr, &arg_names_[i], end);
      }
    }
    for (i = 0; i < num_args; ++i) {
      if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
        continue;
      if (arg_is_copy[i])
        CopyTraceEventParameter(&ptr, &arg_values_[i].as_string, end);
    }
    DCHECK_EQ(end, ptr) << "Overrun by " << ptr - end;
  }
}

void TraceEvent::Reset() {
  // Only reset fields that won't be initialized in Initialize(), or that may
  // hold references to other objects.
  duration_ = TimeDelta::FromInternalValue(-1);
  parameter_copy_storage_ = NULL;
  for (int i = 0; i < kTraceMaxNumArgs; ++i)
    convertable_values_[i] = NULL;
}

void TraceEvent::UpdateDuration(const TimeTicks& now,
                                const TimeTicks& thread_now) {
  DCHECK(duration_.ToInternalValue() == -1);
  duration_ = now - timestamp_;
  thread_duration_ = thread_now - thread_timestamp_;
}

// static
void TraceEvent::AppendValueAsJSON(unsigned char type,
                                   TraceEvent::TraceValue value,
                                   std::string* out) {
  switch (type) {
    case TRACE_VALUE_TYPE_BOOL:
      *out += value.as_bool ? "true" : "false";
      break;
    case TRACE_VALUE_TYPE_UINT:
      StringAppendF(out, "%" PRIu64, static_cast<uint64>(value.as_uint));
      break;
    case TRACE_VALUE_TYPE_INT:
      StringAppendF(out, "%" PRId64, static_cast<int64>(value.as_int));
      break;
    case TRACE_VALUE_TYPE_DOUBLE: {
      // FIXME: base/json/json_writer.cc is using the same code,
      //        should be made into a common method.
      std::string real;
      double val = value.as_double;
      if (IsFinite(val)) {
        real = DoubleToString(val);
        // Ensure that the number has a .0 if there's no decimal or 'e'.  This
        // makes sure that when we read the JSON back, it's interpreted as a
        // real rather than an int.
        if (real.find('.') == std::string::npos &&
            real.find('e') == std::string::npos &&
            real.find('E') == std::string::npos) {
          real.append(".0");
        }
        // The JSON spec requires that non-integer values in the range (-1,1)
        // have a zero before the decimal point - ".52" is not valid, "0.52" is.
        if (real[0] == '.') {
          real.insert(0, "0");
        } else if (real.length() > 1 && real[0] == '-' && real[1] == '.') {
          // "-.1" bad "-0.1" good
          real.insert(1, "0");
        }
      } else if (IsNaN(val)){
        // The JSON spec doesn't allow NaN and Infinity (since these are
        // objects in EcmaScript).  Use strings instead.
        real = "\"NaN\"";
      } else if (val < 0) {
        real = "\"-Infinity\"";
      } else {
        real = "\"Infinity\"";
      }
      StringAppendF(out, "%s", real.c_str());
      break;
    }
    case TRACE_VALUE_TYPE_POINTER:
      // JSON only supports double and int numbers.
      // So as not to lose bits from a 64-bit pointer, output as a hex string.
      StringAppendF(out, "\"0x%" PRIx64 "\"", static_cast<uint64>(
                                     reinterpret_cast<intptr_t>(
                                     value.as_pointer)));
      break;
    case TRACE_VALUE_TYPE_STRING:
    case TRACE_VALUE_TYPE_COPY_STRING:
      EscapeJSONString(value.as_string ? value.as_string : "NULL", true, out);
      break;
    default:
      NOTREACHED() << "Don't know how to print this value";
      break;
  }
}

void TraceEvent::AppendAsJSON(std::string* out) const {
  int64 time_int64 = timestamp_.ToInternalValue();
  int process_id = TraceLog::GetInstance()->process_id();
  // Category group checked at category creation time.
  DCHECK(!strchr(name_, '"'));
  StringAppendF(out,
      "{\"pid\":%i,\"tid\":%i,\"ts\":%" PRId64 ","
      "\"ph\":\"%c\",\"cat\":\"%s\",\"name\":\"%s\",\"args\":{",
      process_id,
      thread_id_,
      time_int64,
      phase_,
      TraceLog::GetCategoryGroupName(category_group_enabled_),
      name_);

  // Output argument names and values, stop at first NULL argument name.
  for (int i = 0; i < kTraceMaxNumArgs && arg_names_[i]; ++i) {
    if (i > 0)
      *out += ",";
    *out += "\"";
    *out += arg_names_[i];
    *out += "\":";

    if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
      convertable_values_[i]->AppendAsTraceFormat(out);
    else
      AppendValueAsJSON(arg_types_[i], arg_values_[i], out);
  }
  *out += "}";

  if (phase_ == TRACE_EVENT_PHASE_COMPLETE) {
    int64 duration = duration_.ToInternalValue();
    if (duration != -1)
      StringAppendF(out, ",\"dur\":%" PRId64, duration);
    if (!thread_timestamp_.is_null()) {
      int64 thread_duration = thread_duration_.ToInternalValue();
      if (thread_duration != -1)
        StringAppendF(out, ",\"tdur\":%" PRId64, thread_duration);
    }
  }

  // Output tts if thread_timestamp is valid.
  if (!thread_timestamp_.is_null()) {
    int64 thread_time_int64 = thread_timestamp_.ToInternalValue();
    StringAppendF(out, ",\"tts\":%" PRId64, thread_time_int64);
  }

  // If id_ is set, print it out as a hex string so we don't loose any
  // bits (it might be a 64-bit pointer).
  if (flags_ & TRACE_EVENT_FLAG_HAS_ID)
    StringAppendF(out, ",\"id\":\"0x%" PRIx64 "\"", static_cast<uint64>(id_));

  // Instant events also output their scope.
  if (phase_ == TRACE_EVENT_PHASE_INSTANT) {
    char scope = '?';
    switch (flags_ & TRACE_EVENT_FLAG_SCOPE_MASK) {
      case TRACE_EVENT_SCOPE_GLOBAL:
        scope = TRACE_EVENT_SCOPE_NAME_GLOBAL;
        break;

      case TRACE_EVENT_SCOPE_PROCESS:
        scope = TRACE_EVENT_SCOPE_NAME_PROCESS;
        break;

      case TRACE_EVENT_SCOPE_THREAD:
        scope = TRACE_EVENT_SCOPE_NAME_THREAD;
        break;
    }
    StringAppendF(out, ",\"s\":\"%c\"", scope);
  }

  *out += "}";
}

void TraceEvent::AppendPrettyPrinted(std::ostringstream* out) const {
  *out << name_ << "[";
  *out << TraceLog::GetCategoryGroupName(category_group_enabled_);
  *out << "]";
  if (arg_names_[0]) {
    *out << ", {";
    for (int i = 0; i < kTraceMaxNumArgs && arg_names_[i]; ++i) {
      if (i > 0)
        *out << ", ";
      *out << arg_names_[i] << ":";
      std::string value_as_text;

      if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
        convertable_values_[i]->AppendAsTraceFormat(&value_as_text);
      else
        AppendValueAsJSON(arg_types_[i], arg_values_[i], &value_as_text);

      *out << value_as_text;
    }
    *out << "}";
  }
}

////////////////////////////////////////////////////////////////////////////////
//
// TraceResultBuffer
//
////////////////////////////////////////////////////////////////////////////////

TraceResultBuffer::OutputCallback
    TraceResultBuffer::SimpleOutput::GetCallback() {
  return Bind(&SimpleOutput::Append, Unretained(this));
}

void TraceResultBuffer::SimpleOutput::Append(
    const std::string& json_trace_output) {
  json_output += json_trace_output;
}

TraceResultBuffer::TraceResultBuffer() : append_comma_(false) {
}

TraceResultBuffer::~TraceResultBuffer() {
}

void TraceResultBuffer::SetOutputCallback(
    const OutputCallback& json_chunk_callback) {
  output_callback_ = json_chunk_callback;
}

void TraceResultBuffer::Start() {
  append_comma_ = false;
  output_callback_.Run("[");
}

void TraceResultBuffer::AddFragment(const std::string& trace_fragment) {
  if (append_comma_)
    output_callback_.Run(",");
  append_comma_ = true;
  output_callback_.Run(trace_fragment);
}

void TraceResultBuffer::Finish() {
  output_callback_.Run("]");
}

////////////////////////////////////////////////////////////////////////////////
//
// TraceSamplingThread
//
////////////////////////////////////////////////////////////////////////////////
class TraceBucketData;
typedef base::Callback<void(TraceBucketData*)> TraceSampleCallback;

class TraceBucketData {
 public:
  TraceBucketData(base::subtle::AtomicWord* bucket,
                  const char* name,
                  TraceSampleCallback callback);
  ~TraceBucketData();

  TRACE_EVENT_API_ATOMIC_WORD* bucket;
  const char* bucket_name;
  TraceSampleCallback callback;
};

// This object must be created on the IO thread.
class TraceSamplingThread : public PlatformThread::Delegate {
 public:
  TraceSamplingThread();
  ~TraceSamplingThread() override;

  // Implementation of PlatformThread::Delegate:
  void ThreadMain() override;

  static void DefaultSamplingCallback(TraceBucketData* bucekt_data);

  void Stop();
  void WaitSamplingEventForTesting();

 private:
  friend class TraceLog;

  void GetSamples();
  // Not thread-safe. Once the ThreadMain has been called, this can no longer
  // be called.
  void RegisterSampleBucket(TRACE_EVENT_API_ATOMIC_WORD* bucket,
                            const char* const name,
                            TraceSampleCallback callback);
  // Splits a combined "category\0name" into the two component parts.
  static void ExtractCategoryAndName(const char* combined,
                                     const char** category,
                                     const char** name);
  std::vector<TraceBucketData> sample_buckets_;
  bool thread_running_;
  CancellationFlag cancellation_flag_;
  WaitableEvent waitable_event_for_testing_;
};


TraceSamplingThread::TraceSamplingThread()
    : thread_running_(false),
      waitable_event_for_testing_(false, false) {
}

TraceSamplingThread::~TraceSamplingThread() {
}

void TraceSamplingThread::ThreadMain() {
  PlatformThread::SetName("Sampling Thread");
  thread_running_ = true;
  const int kSamplingFrequencyMicroseconds = 1000;
  while (!cancellation_flag_.IsSet()) {
    PlatformThread::Sleep(
        TimeDelta::FromMicroseconds(kSamplingFrequencyMicroseconds));
    GetSamples();
    waitable_event_for_testing_.Signal();
  }
}

// static
void TraceSamplingThread::DefaultSamplingCallback(
    TraceBucketData* bucket_data) {
  TRACE_EVENT_API_ATOMIC_WORD category_and_name =
      TRACE_EVENT_API_ATOMIC_LOAD(*bucket_data->bucket);
  if (!category_and_name)
    return;
  const char* const combined =
      reinterpret_cast<const char* const>(category_and_name);
  const char* category_group;
  const char* name;
  ExtractCategoryAndName(combined, &category_group, &name);
  TRACE_EVENT_API_ADD_TRACE_EVENT(TRACE_EVENT_PHASE_SAMPLE,
      TraceLog::GetCategoryGroupEnabled(category_group),
      name, 0, 0, NULL, NULL, NULL, NULL, 0);
}

void TraceSamplingThread::GetSamples() {
  for (size_t i = 0; i < sample_buckets_.size(); ++i) {
    TraceBucketData* bucket_data = &sample_buckets_[i];
    bucket_data->callback.Run(bucket_data);
  }
}

void TraceSamplingThread::RegisterSampleBucket(
    TRACE_EVENT_API_ATOMIC_WORD* bucket,
    const char* const name,
    TraceSampleCallback callback) {
  // Access to sample_buckets_ doesn't cause races with the sampling thread
  // that uses the sample_buckets_, because it is guaranteed that
  // RegisterSampleBucket is called before the sampling thread is created.
  DCHECK(!thread_running_);
  sample_buckets_.push_back(TraceBucketData(bucket, name, callback));
}

// static
void TraceSamplingThread::ExtractCategoryAndName(const char* combined,
                                                 const char** category,
                                                 const char** name) {
  *category = combined;
  *name = &combined[strlen(combined) + 1];
}

void TraceSamplingThread::Stop() {
  cancellation_flag_.Set();
}

void TraceSamplingThread::WaitSamplingEventForTesting() {
  waitable_event_for_testing_.Wait();
}

TraceBucketData::TraceBucketData(base::subtle::AtomicWord* bucket,
                                 const char* name,
                                 TraceSampleCallback callback)
    : bucket(bucket),
      bucket_name(name),
      callback(callback) {
}

TraceBucketData::~TraceBucketData() {
}

////////////////////////////////////////////////////////////////////////////////
//
// TraceOptions
//
////////////////////////////////////////////////////////////////////////////////

bool TraceOptions::SetFromString(const std::string& options_string) {
  record_mode = RECORD_UNTIL_FULL;
  enable_sampling = false;
  enable_systrace = false;

  std::vector<std::string> split;
  std::vector<std::string>::iterator iter;
  base::SplitString(options_string, ',', &split);
  for (iter = split.begin(); iter != split.end(); ++iter) {
    if (*iter == kRecordUntilFull) {
      record_mode = RECORD_UNTIL_FULL;
    } else if (*iter == kRecordContinuously) {
      record_mode = RECORD_CONTINUOUSLY;
    } else if (*iter == kTraceToConsole) {
      record_mode = ECHO_TO_CONSOLE;
    } else if (*iter == kRecordAsMuchAsPossible) {
      record_mode = RECORD_AS_MUCH_AS_POSSIBLE;
    } else if (*iter == kEnableSampling) {
      enable_sampling = true;
    } else if (*iter == kEnableSystrace) {
      enable_systrace = true;
    } else {
      return false;
    }
  }
  return true;
}

std::string TraceOptions::ToString() const {
  std::string ret;
  switch (record_mode) {
    case RECORD_UNTIL_FULL:
      ret = kRecordUntilFull;
      break;
    case RECORD_CONTINUOUSLY:
      ret = kRecordContinuously;
      break;
    case ECHO_TO_CONSOLE:
      ret = kTraceToConsole;
      break;
    case RECORD_AS_MUCH_AS_POSSIBLE:
      ret = kRecordAsMuchAsPossible;
      break;
    default:
      NOTREACHED();
  }
  if (enable_sampling)
    ret = ret + "," + kEnableSampling;
  if (enable_systrace)
    ret = ret + "," + kEnableSystrace;
  return ret;
}

////////////////////////////////////////////////////////////////////////////////
//
// TraceLog
//
////////////////////////////////////////////////////////////////////////////////

class TraceLog::ThreadLocalEventBuffer
    : public MessageLoop::DestructionObserver {
 public:
  ThreadLocalEventBuffer(TraceLog* trace_log);
  ~ThreadLocalEventBuffer() override;

  TraceEvent* AddTraceEvent(TraceEventHandle* handle);

  void ReportOverhead(const TimeTicks& event_timestamp,
                      const TimeTicks& event_thread_timestamp);

  TraceEvent* GetEventByHandle(TraceEventHandle handle) {
    if (!chunk_ || handle.chunk_seq != chunk_->seq() ||
        handle.chunk_index != chunk_index_)
      return NULL;

    return chunk_->GetEventAt(handle.event_index);
  }

  int generation() const { return generation_; }

 private:
  // MessageLoop::DestructionObserver
  void WillDestroyCurrentMessageLoop() override;

  void FlushWhileLocked();

  void CheckThisIsCurrentBuffer() const {
    DCHECK(trace_log_->thread_local_event_buffer_.Get() == this);
  }

  // Since TraceLog is a leaky singleton, trace_log_ will always be valid
  // as long as the thread exists.
  TraceLog* trace_log_;
  scoped_ptr<TraceBufferChunk> chunk_;
  size_t chunk_index_;
  int event_count_;
  TimeDelta overhead_;
  int generation_;

  DISALLOW_COPY_AND_ASSIGN(ThreadLocalEventBuffer);
};

TraceLog::ThreadLocalEventBuffer::ThreadLocalEventBuffer(TraceLog* trace_log)
    : trace_log_(trace_log),
      chunk_index_(0),
      event_count_(0),
      generation_(trace_log->generation()) {
  // ThreadLocalEventBuffer is created only if the thread has a message loop, so
  // the following message_loop won't be NULL.
  MessageLoop* message_loop = MessageLoop::current();
  message_loop->AddDestructionObserver(this);

  AutoLock lock(trace_log->lock_);
  trace_log->thread_message_loops_.insert(message_loop);
}

TraceLog::ThreadLocalEventBuffer::~ThreadLocalEventBuffer() {
  CheckThisIsCurrentBuffer();
  MessageLoop::current()->RemoveDestructionObserver(this);

  // Zero event_count_ happens in either of the following cases:
  // - no event generated for the thread;
  // - the thread has no message loop;
  // - trace_event_overhead is disabled.
  if (event_count_) {
    InitializeMetadataEvent(AddTraceEvent(NULL),
                            static_cast<int>(base::PlatformThread::CurrentId()),
                            "overhead", "average_overhead",
                            overhead_.InMillisecondsF() / event_count_);
  }

  {
    AutoLock lock(trace_log_->lock_);
    FlushWhileLocked();
    trace_log_->thread_message_loops_.erase(MessageLoop::current());
  }
  trace_log_->thread_local_event_buffer_.Set(NULL);
}

TraceEvent* TraceLog::ThreadLocalEventBuffer::AddTraceEvent(
    TraceEventHandle* handle) {
  CheckThisIsCurrentBuffer();

  if (chunk_ && chunk_->IsFull()) {
    AutoLock lock(trace_log_->lock_);
    FlushWhileLocked();
    chunk_.reset();
  }
  if (!chunk_) {
    AutoLock lock(trace_log_->lock_);
    chunk_ = trace_log_->logged_events_->GetChunk(&chunk_index_);
    trace_log_->CheckIfBufferIsFullWhileLocked();
  }
  if (!chunk_)
    return NULL;

  size_t event_index;
  TraceEvent* trace_event = chunk_->AddTraceEvent(&event_index);
  if (trace_event && handle)
    MakeHandle(chunk_->seq(), chunk_index_, event_index, handle);

  return trace_event;
}

void TraceLog::ThreadLocalEventBuffer::ReportOverhead(
    const TimeTicks& event_timestamp,
    const TimeTicks& event_thread_timestamp) {
  if (!g_category_group_enabled[g_category_trace_event_overhead])
    return;

  CheckThisIsCurrentBuffer();

  event_count_++;
  TimeTicks thread_now = ThreadNow();
  TimeTicks now = trace_log_->OffsetNow();
  TimeDelta overhead = now - event_timestamp;
  if (overhead.InMicroseconds() >= kOverheadReportThresholdInMicroseconds) {
    TraceEvent* trace_event = AddTraceEvent(NULL);
    if (trace_event) {
      trace_event->Initialize(
          static_cast<int>(PlatformThread::CurrentId()),
          event_timestamp, event_thread_timestamp,
          TRACE_EVENT_PHASE_COMPLETE,
          &g_category_group_enabled[g_category_trace_event_overhead],
          "overhead", 0, 0, NULL, NULL, NULL, NULL, 0);
      trace_event->UpdateDuration(now, thread_now);
    }
  }
  overhead_ += overhead;
}

void TraceLog::ThreadLocalEventBuffer::WillDestroyCurrentMessageLoop() {
  delete this;
}

void TraceLog::ThreadLocalEventBuffer::FlushWhileLocked() {
  if (!chunk_)
    return;

  trace_log_->lock_.AssertAcquired();
  if (trace_log_->CheckGeneration(generation_)) {
    // Return the chunk to the buffer only if the generation matches.
    trace_log_->logged_events_->ReturnChunk(chunk_index_, chunk_.Pass());
  }
  // Otherwise this method may be called from the destructor, or TraceLog will
  // find the generation mismatch and delete this buffer soon.
}

TraceLogStatus::TraceLogStatus() : event_capacity(0), event_count(0) {
}

TraceLogStatus::~TraceLogStatus() {
}

// static
TraceLog* TraceLog::GetInstance() {
  return Singleton<TraceLog, LeakySingletonTraits<TraceLog> >::get();
}

TraceLog::TraceLog()
    : mode_(DISABLED),
      num_traces_recorded_(0),
      event_callback_(0),
      dispatching_to_observer_list_(false),
      process_sort_index_(0),
      process_id_hash_(0),
      process_id_(0),
      watch_category_(0),
      trace_options_(kInternalRecordUntilFull),
      sampling_thread_handle_(0),
      category_filter_(CategoryFilter::kDefaultCategoryFilterString),
      event_callback_category_filter_(
          CategoryFilter::kDefaultCategoryFilterString),
      thread_shared_chunk_index_(0),
      generation_(0) {
  // Trace is enabled or disabled on one thread while other threads are
  // accessing the enabled flag. We don't care whether edge-case events are
  // traced or not, so we allow races on the enabled flag to keep the trace
  // macros fast.
  // TODO(jbates): ANNOTATE_BENIGN_RACE_SIZED crashes windows TSAN bots:
  // ANNOTATE_BENIGN_RACE_SIZED(g_category_group_enabled,
  //                            sizeof(g_category_group_enabled),
  //                           "trace_event category enabled");
  for (int i = 0; i < MAX_CATEGORY_GROUPS; ++i) {
    ANNOTATE_BENIGN_RACE(&g_category_group_enabled[i],
                         "trace_event category enabled");
  }
#if defined(OS_NACL)  // NaCl shouldn't expose the process id.
  SetProcessID(0);
#else
  SetProcessID(static_cast<int>(GetCurrentProcId()));

  // NaCl also shouldn't access the command line.
  if (CommandLine::InitializedForCurrentProcess() &&
      CommandLine::ForCurrentProcess()->HasSwitch(switches::kTraceToConsole)) {
    std::string filter = CommandLine::ForCurrentProcess()->GetSwitchValueASCII(
        switches::kTraceToConsole);
    if (filter.empty()) {
      filter = kEchoToConsoleCategoryFilter;
    } else {
      filter.append(",");
      filter.append(kEchoToConsoleCategoryFilter);
    }

    LOG(ERROR) << "Start " << switches::kTraceToConsole
               << " with CategoryFilter '" << filter << "'.";
    SetEnabled(CategoryFilter(filter),
               RECORDING_MODE,
               TraceOptions(ECHO_TO_CONSOLE));
  }
#endif

  logged_events_.reset(CreateTraceBuffer());
}

TraceLog::~TraceLog() {
}

const unsigned char* TraceLog::GetCategoryGroupEnabled(
    const char* category_group) {
  TraceLog* tracelog = GetInstance();
  if (!tracelog) {
    DCHECK(!g_category_group_enabled[g_category_already_shutdown]);
    return &g_category_group_enabled[g_category_already_shutdown];
  }
  return tracelog->GetCategoryGroupEnabledInternal(category_group);
}

const char* TraceLog::GetCategoryGroupName(
    const unsigned char* category_group_enabled) {
  // Calculate the index of the category group by finding
  // category_group_enabled in g_category_group_enabled array.
  uintptr_t category_begin =
      reinterpret_cast<uintptr_t>(g_category_group_enabled);
  uintptr_t category_ptr = reinterpret_cast<uintptr_t>(category_group_enabled);
  DCHECK(category_ptr >= category_begin &&
         category_ptr < reinterpret_cast<uintptr_t>(
             g_category_group_enabled + MAX_CATEGORY_GROUPS)) <<
      "out of bounds category pointer";
  uintptr_t category_index =
      (category_ptr - category_begin) / sizeof(g_category_group_enabled[0]);
  return g_category_groups[category_index];
}

void TraceLog::UpdateCategoryGroupEnabledFlag(size_t category_index) {
  unsigned char enabled_flag = 0;
  const char* category_group = g_category_groups[category_index];
  if (mode_ == RECORDING_MODE &&
      category_filter_.IsCategoryGroupEnabled(category_group))
    enabled_flag |= ENABLED_FOR_RECORDING;
  else if (mode_ == MONITORING_MODE &&
      category_filter_.IsCategoryGroupEnabled(category_group))
    enabled_flag |= ENABLED_FOR_MONITORING;
  if (event_callback_ &&
      event_callback_category_filter_.IsCategoryGroupEnabled(category_group))
    enabled_flag |= ENABLED_FOR_EVENT_CALLBACK;
  g_category_group_enabled[category_index] = enabled_flag;
}

void TraceLog::UpdateCategoryGroupEnabledFlags() {
  size_t category_index = base::subtle::NoBarrier_Load(&g_category_index);
  for (size_t i = 0; i < category_index; i++)
    UpdateCategoryGroupEnabledFlag(i);
}

void TraceLog::UpdateSyntheticDelaysFromCategoryFilter() {
  ResetTraceEventSyntheticDelays();
  const CategoryFilter::StringList& delays =
      category_filter_.GetSyntheticDelayValues();
  CategoryFilter::StringList::const_iterator ci;
  for (ci = delays.begin(); ci != delays.end(); ++ci) {
    StringTokenizer tokens(*ci, ";");
    if (!tokens.GetNext())
      continue;
    TraceEventSyntheticDelay* delay =
        TraceEventSyntheticDelay::Lookup(tokens.token());
    while (tokens.GetNext()) {
      std::string token = tokens.token();
      char* duration_end;
      double target_duration = strtod(token.c_str(), &duration_end);
      if (duration_end != token.c_str()) {
        delay->SetTargetDuration(TimeDelta::FromMicroseconds(
            static_cast<int64>(target_duration * 1e6)));
      } else if (token == "static") {
        delay->SetMode(TraceEventSyntheticDelay::STATIC);
      } else if (token == "oneshot") {
        delay->SetMode(TraceEventSyntheticDelay::ONE_SHOT);
      } else if (token == "alternating") {
        delay->SetMode(TraceEventSyntheticDelay::ALTERNATING);
      }
    }
  }
}

const unsigned char* TraceLog::GetCategoryGroupEnabledInternal(
    const char* category_group) {
  DCHECK(!strchr(category_group, '"')) <<
      "Category groups may not contain double quote";
  // The g_category_groups is append only, avoid using a lock for the fast path.
  size_t current_category_index = base::subtle::Acquire_Load(&g_category_index);

  // Search for pre-existing category group.
  for (size_t i = 0; i < current_category_index; ++i) {
    if (strcmp(g_category_groups[i], category_group) == 0) {
      return &g_category_group_enabled[i];
    }
  }

  unsigned char* category_group_enabled = NULL;
  // This is the slow path: the lock is not held in the case above, so more
  // than one thread could have reached here trying to add the same category.
  // Only hold to lock when actually appending a new category, and
  // check the categories groups again.
  AutoLock lock(lock_);
  size_t category_index = base::subtle::Acquire_Load(&g_category_index);
  for (size_t i = 0; i < category_index; ++i) {
    if (strcmp(g_category_groups[i], category_group) == 0) {
      return &g_category_group_enabled[i];
    }
  }

  // Create a new category group.
  DCHECK(category_index < MAX_CATEGORY_GROUPS) <<
      "must increase MAX_CATEGORY_GROUPS";
  if (category_index < MAX_CATEGORY_GROUPS) {
    // Don't hold on to the category_group pointer, so that we can create
    // category groups with strings not known at compile time (this is
    // required by SetWatchEvent).
    const char* new_group = strdup(category_group);
    ANNOTATE_LEAKING_OBJECT_PTR(new_group);
    g_category_groups[category_index] = new_group;
    DCHECK(!g_category_group_enabled[category_index]);
    // Note that if both included and excluded patterns in the
    // CategoryFilter are empty, we exclude nothing,
    // thereby enabling this category group.
    UpdateCategoryGroupEnabledFlag(category_index);
    category_group_enabled = &g_category_group_enabled[category_index];
    // Update the max index now.
    base::subtle::Release_Store(&g_category_index, category_index + 1);
  } else {
    category_group_enabled =
        &g_category_group_enabled[g_category_categories_exhausted];
  }
  return category_group_enabled;
}

void TraceLog::GetKnownCategoryGroups(
    std::vector<std::string>* category_groups) {
  AutoLock lock(lock_);
  category_groups->push_back(
      g_category_groups[g_category_trace_event_overhead]);
  size_t category_index = base::subtle::NoBarrier_Load(&g_category_index);
  for (size_t i = g_num_builtin_categories; i < category_index; i++)
    category_groups->push_back(g_category_groups[i]);
}

void TraceLog::SetEnabled(const CategoryFilter& category_filter,
                          Mode mode,
                          const TraceOptions& options) {
  std::vector<EnabledStateObserver*> observer_list;
  {
    AutoLock lock(lock_);

    // Can't enable tracing when Flush() is in progress.
    DCHECK(!flush_message_loop_proxy_.get());

    InternalTraceOptions new_options =
        GetInternalOptionsFromTraceOptions(options);

   InternalTraceOptions old_options = trace_options();

    if (IsEnabled()) {
      if (new_options != old_options) {
        DLOG(ERROR) << "Attempting to re-enable tracing with a different "
                    << "set of options.";
      }

      if (mode != mode_) {
        DLOG(ERROR) << "Attempting to re-enable tracing with a different mode.";
      }

      category_filter_.Merge(category_filter);
      UpdateCategoryGroupEnabledFlags();
      return;
    }

    if (dispatching_to_observer_list_) {
      DLOG(ERROR) <<
          "Cannot manipulate TraceLog::Enabled state from an observer.";
      return;
    }

    mode_ = mode;

    if (new_options != old_options) {
      subtle::NoBarrier_Store(&trace_options_, new_options);
      UseNextTraceBuffer();
    }

    num_traces_recorded_++;

    category_filter_ = CategoryFilter(category_filter);
    UpdateCategoryGroupEnabledFlags();
    UpdateSyntheticDelaysFromCategoryFilter();

    if (new_options & kInternalEnableSampling) {
      sampling_thread_.reset(new TraceSamplingThread);
      sampling_thread_->RegisterSampleBucket(
          &g_trace_state[0],
          "bucket0",
          Bind(&TraceSamplingThread::DefaultSamplingCallback));
      sampling_thread_->RegisterSampleBucket(
          &g_trace_state[1],
          "bucket1",
          Bind(&TraceSamplingThread::DefaultSamplingCallback));
      sampling_thread_->RegisterSampleBucket(
          &g_trace_state[2],
          "bucket2",
          Bind(&TraceSamplingThread::DefaultSamplingCallback));
      if (!PlatformThread::Create(
            0, sampling_thread_.get(), &sampling_thread_handle_)) {
        DCHECK(false) << "failed to create thread";
      }
    }

    dispatching_to_observer_list_ = true;
    observer_list = enabled_state_observer_list_;
  }
  // Notify observers outside the lock in case they trigger trace events.
  for (size_t i = 0; i < observer_list.size(); ++i)
    observer_list[i]->OnTraceLogEnabled();

  {
    AutoLock lock(lock_);
    dispatching_to_observer_list_ = false;
  }
}

TraceLog::InternalTraceOptions TraceLog::GetInternalOptionsFromTraceOptions(
    const TraceOptions& options) {
  InternalTraceOptions ret =
      options.enable_sampling ? kInternalEnableSampling : kInternalNone;
  switch (options.record_mode) {
    case RECORD_UNTIL_FULL:
      return ret | kInternalRecordUntilFull;
    case RECORD_CONTINUOUSLY:
      return ret | kInternalRecordContinuously;
    case ECHO_TO_CONSOLE:
      return ret | kInternalEchoToConsole;
    case RECORD_AS_MUCH_AS_POSSIBLE:
      return ret | kInternalRecordAsMuchAsPossible;
  }
  NOTREACHED();
  return kInternalNone;
}

CategoryFilter TraceLog::GetCurrentCategoryFilter() {
  AutoLock lock(lock_);
  return category_filter_;
}

TraceOptions TraceLog::GetCurrentTraceOptions() const {
  TraceOptions ret;
  InternalTraceOptions option = trace_options();
  ret.enable_sampling = (option & kInternalEnableSampling) != 0;
  if (option & kInternalRecordUntilFull)
    ret.record_mode = RECORD_UNTIL_FULL;
  else if (option & kInternalRecordContinuously)
    ret.record_mode = RECORD_CONTINUOUSLY;
  else if (option & kInternalEchoToConsole)
    ret.record_mode = ECHO_TO_CONSOLE;
  else if (option & kInternalRecordAsMuchAsPossible)
    ret.record_mode = RECORD_AS_MUCH_AS_POSSIBLE;
  else
    NOTREACHED();
  return ret;
}

void TraceLog::SetDisabled() {
  AutoLock lock(lock_);
  SetDisabledWhileLocked();
}

void TraceLog::SetDisabledWhileLocked() {
  lock_.AssertAcquired();

  if (!IsEnabled())
    return;

  if (dispatching_to_observer_list_) {
    DLOG(ERROR)
        << "Cannot manipulate TraceLog::Enabled state from an observer.";
    return;
  }

  mode_ = DISABLED;

  if (sampling_thread_.get()) {
    // Stop the sampling thread.
    sampling_thread_->Stop();
    lock_.Release();
    PlatformThread::Join(sampling_thread_handle_);
    lock_.Acquire();
    sampling_thread_handle_ = PlatformThreadHandle();
    sampling_thread_.reset();
  }

  category_filter_.Clear();
  subtle::NoBarrier_Store(&watch_category_, 0);
  watch_event_name_ = "";
  UpdateCategoryGroupEnabledFlags();
  AddMetadataEventsWhileLocked();

  dispatching_to_observer_list_ = true;
  std::vector<EnabledStateObserver*> observer_list =
      enabled_state_observer_list_;

  {
    // Dispatch to observers outside the lock in case the observer triggers a
    // trace event.
    AutoUnlock unlock(lock_);
    for (size_t i = 0; i < observer_list.size(); ++i)
      observer_list[i]->OnTraceLogDisabled();
  }
  dispatching_to_observer_list_ = false;
}

int TraceLog::GetNumTracesRecorded() {
  AutoLock lock(lock_);
  if (!IsEnabled())
    return -1;
  return num_traces_recorded_;
}

void TraceLog::AddEnabledStateObserver(EnabledStateObserver* listener) {
  enabled_state_observer_list_.push_back(listener);
}

void TraceLog::RemoveEnabledStateObserver(EnabledStateObserver* listener) {
  std::vector<EnabledStateObserver*>::iterator it =
      std::find(enabled_state_observer_list_.begin(),
                enabled_state_observer_list_.end(),
                listener);
  if (it != enabled_state_observer_list_.end())
    enabled_state_observer_list_.erase(it);
}

bool TraceLog::HasEnabledStateObserver(EnabledStateObserver* listener) const {
  std::vector<EnabledStateObserver*>::const_iterator it =
      std::find(enabled_state_observer_list_.begin(),
                enabled_state_observer_list_.end(),
                listener);
  return it != enabled_state_observer_list_.end();
}

TraceLogStatus TraceLog::GetStatus() const {
  AutoLock lock(lock_);
  TraceLogStatus result;
  result.event_capacity = logged_events_->Capacity();
  result.event_count = logged_events_->Size();
  return result;
}

bool TraceLog::BufferIsFull() const {
  AutoLock lock(lock_);
  return logged_events_->IsFull();
}

TraceBuffer* TraceLog::CreateTraceBuffer() {
  InternalTraceOptions options = trace_options();
  if (options & kInternalRecordContinuously)
    return new TraceBufferRingBuffer(kTraceEventRingBufferChunks);
  else if ((options & kInternalEnableSampling) && mode_ == MONITORING_MODE)
    return new TraceBufferRingBuffer(kMonitorTraceEventBufferChunks);
  else if (options & kInternalEchoToConsole)
    return new TraceBufferRingBuffer(kEchoToConsoleTraceEventBufferChunks);
  else if (options & kInternalRecordAsMuchAsPossible)
    return CreateTraceBufferVectorOfSize(kTraceEventVectorBigBufferChunks);
  return CreateTraceBufferVectorOfSize(kTraceEventVectorBufferChunks);
}

TraceBuffer* TraceLog::CreateTraceBufferVectorOfSize(size_t max_chunks) {
  return new TraceBufferVector(max_chunks);
}

TraceEvent* TraceLog::AddEventToThreadSharedChunkWhileLocked(
    TraceEventHandle* handle, bool check_buffer_is_full) {
  lock_.AssertAcquired();

  if (thread_shared_chunk_ && thread_shared_chunk_->IsFull()) {
    logged_events_->ReturnChunk(thread_shared_chunk_index_,
                                thread_shared_chunk_.Pass());
  }

  if (!thread_shared_chunk_) {
    thread_shared_chunk_ = logged_events_->GetChunk(
        &thread_shared_chunk_index_);
    if (check_buffer_is_full)
      CheckIfBufferIsFullWhileLocked();
  }
  if (!thread_shared_chunk_)
    return NULL;

  size_t event_index;
  TraceEvent* trace_event = thread_shared_chunk_->AddTraceEvent(&event_index);
  if (trace_event && handle) {
    MakeHandle(thread_shared_chunk_->seq(), thread_shared_chunk_index_,
               event_index, handle);
  }
  return trace_event;
}

void TraceLog::CheckIfBufferIsFullWhileLocked() {
  lock_.AssertAcquired();
  if (logged_events_->IsFull()) {
    if (buffer_limit_reached_timestamp_.is_null()) {
      buffer_limit_reached_timestamp_ = OffsetNow();
    }
    SetDisabledWhileLocked();
  }
}

void TraceLog::SetEventCallbackEnabled(const CategoryFilter& category_filter,
                                       EventCallback cb) {
  AutoLock lock(lock_);
  subtle::NoBarrier_Store(&event_callback_,
                          reinterpret_cast<subtle::AtomicWord>(cb));
  event_callback_category_filter_ = category_filter;
  UpdateCategoryGroupEnabledFlags();
};

void TraceLog::SetEventCallbackDisabled() {
  AutoLock lock(lock_);
  subtle::NoBarrier_Store(&event_callback_, 0);
  UpdateCategoryGroupEnabledFlags();
}

// Flush() works as the following:
// 1. Flush() is called in threadA whose message loop is saved in
//    flush_message_loop_proxy_;
// 2. If thread_message_loops_ is not empty, threadA posts task to each message
//    loop to flush the thread local buffers; otherwise finish the flush;
// 3. FlushCurrentThread() deletes the thread local event buffer:
//    - The last batch of events of the thread are flushed into the main buffer;
//    - The message loop will be removed from thread_message_loops_;
//    If this is the last message loop, finish the flush;
// 4. If any thread hasn't finish its flush in time, finish the flush.
void TraceLog::Flush(const TraceLog::OutputCallback& cb) {
  if (IsEnabled()) {
    // Can't flush when tracing is enabled because otherwise PostTask would
    // - generate more trace events;
    // - deschedule the calling thread on some platforms causing inaccurate
    //   timing of the trace events.
    scoped_refptr<RefCountedString> empty_result = new RefCountedString;
    if (!cb.is_null())
      cb.Run(empty_result, false);
    LOG(WARNING) << "Ignored TraceLog::Flush called when tracing is enabled";
    return;
  }

  int generation = this->generation();
  // Copy of thread_message_loops_ to be used without locking.
  std::vector<scoped_refptr<SingleThreadTaskRunner> >
      thread_message_loop_task_runners;
  {
    AutoLock lock(lock_);
    DCHECK(!flush_message_loop_proxy_.get());
    flush_message_loop_proxy_ = MessageLoopProxy::current();
    DCHECK(!thread_message_loops_.size() || flush_message_loop_proxy_.get());
    flush_output_callback_ = cb;

    if (thread_shared_chunk_) {
      logged_events_->ReturnChunk(thread_shared_chunk_index_,
                                  thread_shared_chunk_.Pass());
    }

    if (thread_message_loops_.size()) {
      for (hash_set<MessageLoop*>::const_iterator it =
           thread_message_loops_.begin();
           it != thread_message_loops_.end(); ++it) {
        thread_message_loop_task_runners.push_back((*it)->task_runner());
      }
    }
  }

  if (thread_message_loop_task_runners.size()) {
    for (size_t i = 0; i < thread_message_loop_task_runners.size(); ++i) {
      thread_message_loop_task_runners[i]->PostTask(
          FROM_HERE,
          Bind(&TraceLog::FlushCurrentThread, Unretained(this), generation));
    }
    flush_message_loop_proxy_->PostDelayedTask(
        FROM_HERE,
        Bind(&TraceLog::OnFlushTimeout, Unretained(this), generation),
        TimeDelta::FromMilliseconds(kThreadFlushTimeoutMs));
    return;
  }

  FinishFlush(generation);
}

void TraceLog::ConvertTraceEventsToTraceFormat(
    scoped_ptr<TraceBuffer> logged_events,
    const TraceLog::OutputCallback& flush_output_callback) {

  if (flush_output_callback.is_null())
    return;

  // The callback need to be called at least once even if there is no events
  // to let the caller know the completion of flush.
  bool has_more_events = true;
  do {
    scoped_refptr<RefCountedString> json_events_str_ptr =
        new RefCountedString();

    for (size_t i = 0; i < kTraceEventBatchChunks; ++i) {
      const TraceBufferChunk* chunk = logged_events->NextChunk();
      if (!chunk) {
        has_more_events = false;
        break;
      }
      for (size_t j = 0; j < chunk->size(); ++j) {
        if (i > 0 || j > 0)
          json_events_str_ptr->data().append(",\n");
        chunk->GetEventAt(j)->AppendAsJSON(&(json_events_str_ptr->data()));
      }
    }

    flush_output_callback.Run(json_events_str_ptr, has_more_events);
  } while (has_more_events);
}

void TraceLog::FinishFlush(int generation) {
  scoped_ptr<TraceBuffer> previous_logged_events;
  OutputCallback flush_output_callback;

  if (!CheckGeneration(generation))
    return;

  {
    AutoLock lock(lock_);

    previous_logged_events.swap(logged_events_);
    UseNextTraceBuffer();
    thread_message_loops_.clear();

    flush_message_loop_proxy_ = NULL;
    flush_output_callback = flush_output_callback_;
    flush_output_callback_.Reset();
  }

  ConvertTraceEventsToTraceFormat(previous_logged_events.Pass(),
                                  flush_output_callback);
}

// Run in each thread holding a local event buffer.
void TraceLog::FlushCurrentThread(int generation) {
  {
    AutoLock lock(lock_);
    if (!CheckGeneration(generation) || !flush_message_loop_proxy_.get()) {
      // This is late. The corresponding flush has finished.
      return;
    }
  }

  // This will flush the thread local buffer.
  delete thread_local_event_buffer_.Get();

  AutoLock lock(lock_);
  if (!CheckGeneration(generation) || !flush_message_loop_proxy_.get() ||
      thread_message_loops_.size())
    return;

  flush_message_loop_proxy_->PostTask(
      FROM_HERE,
      Bind(&TraceLog::FinishFlush, Unretained(this), generation));
}

void TraceLog::OnFlushTimeout(int generation) {
  {
    AutoLock lock(lock_);
    if (!CheckGeneration(generation) || !flush_message_loop_proxy_.get()) {
      // Flush has finished before timeout.
      return;
    }

    LOG(WARNING) <<
        "The following threads haven't finished flush in time. "
        "If this happens stably for some thread, please call "
        "TraceLog::GetInstance()->SetCurrentThreadBlocksMessageLoop() from "
        "the thread to avoid its trace events from being lost.";
    for (hash_set<MessageLoop*>::const_iterator it =
         thread_message_loops_.begin();
         it != thread_message_loops_.end(); ++it) {
      LOG(WARNING) << "Thread: " << (*it)->thread_name();
    }
  }
  FinishFlush(generation);
}

void TraceLog::FlushButLeaveBufferIntact(
    const TraceLog::OutputCallback& flush_output_callback) {
  scoped_ptr<TraceBuffer> previous_logged_events;
  {
    AutoLock lock(lock_);
    AddMetadataEventsWhileLocked();
    if (thread_shared_chunk_) {
      // Return the chunk to the main buffer to flush the sampling data.
      logged_events_->ReturnChunk(thread_shared_chunk_index_,
                                  thread_shared_chunk_.Pass());
    }
    previous_logged_events = logged_events_->CloneForIteration().Pass();
  }  // release lock

  ConvertTraceEventsToTraceFormat(previous_logged_events.Pass(),
                                  flush_output_callback);
}

void TraceLog::UseNextTraceBuffer() {
  logged_events_.reset(CreateTraceBuffer());
  subtle::NoBarrier_AtomicIncrement(&generation_, 1);
  thread_shared_chunk_.reset();
  thread_shared_chunk_index_ = 0;
}

TraceEventHandle TraceLog::AddTraceEvent(
    char phase,
    const unsigned char* category_group_enabled,
    const char* name,
    unsigned long long id,
    int num_args,
    const char** arg_names,
    const unsigned char* arg_types,
    const unsigned long long* arg_values,
    const scoped_refptr<ConvertableToTraceFormat>* convertable_values,
    unsigned char flags) {
  int thread_id = static_cast<int>(base::PlatformThread::CurrentId());
  base::TimeTicks now = base::TimeTicks::NowFromSystemTraceTime();
  return AddTraceEventWithThreadIdAndTimestamp(phase, category_group_enabled,
                                               name, id, thread_id, now,
                                               num_args, arg_names,
                                               arg_types, arg_values,
                                               convertable_values, flags);
}

TraceEventHandle TraceLog::AddTraceEventWithThreadIdAndTimestamp(
    char phase,
    const unsigned char* category_group_enabled,
    const char* name,
    unsigned long long id,
    int thread_id,
    const TimeTicks& timestamp,
    int num_args,
    const char** arg_names,
    const unsigned char* arg_types,
    const unsigned long long* arg_values,
    const scoped_refptr<ConvertableToTraceFormat>* convertable_values,
    unsigned char flags) {
  TraceEventHandle handle = { 0, 0, 0 };
  if (!*category_group_enabled)
    return handle;

  // Avoid re-entrance of AddTraceEvent. This may happen in GPU process when
  // ECHO_TO_CONSOLE is enabled: AddTraceEvent -> LOG(ERROR) ->
  // GpuProcessLogMessageHandler -> PostPendingTask -> TRACE_EVENT ...
  if (thread_is_in_trace_event_.Get())
    return handle;

  AutoThreadLocalBoolean thread_is_in_trace_event(&thread_is_in_trace_event_);

  DCHECK(name);

  if (flags & TRACE_EVENT_FLAG_MANGLE_ID)
    id ^= process_id_hash_;

  TimeTicks now = OffsetTimestamp(timestamp);
  TimeTicks thread_now = ThreadNow();

  ThreadLocalEventBuffer* thread_local_event_buffer = NULL;
  // A ThreadLocalEventBuffer needs the message loop
  // - to know when the thread exits;
  // - to handle the final flush.
  // For a thread without a message loop or the message loop may be blocked, the
  // trace events will be added into the main buffer directly.
  if (!thread_blocks_message_loop_.Get() && MessageLoop::current()) {
    thread_local_event_buffer = thread_local_event_buffer_.Get();
    if (thread_local_event_buffer &&
        !CheckGeneration(thread_local_event_buffer->generation())) {
      delete thread_local_event_buffer;
      thread_local_event_buffer = NULL;
    }
    if (!thread_local_event_buffer) {
      thread_local_event_buffer = new ThreadLocalEventBuffer(this);
      thread_local_event_buffer_.Set(thread_local_event_buffer);
    }
  }

  // Check and update the current thread name only if the event is for the
  // current thread to avoid locks in most cases.
  if (thread_id == static_cast<int>(PlatformThread::CurrentId())) {
    const char* new_name = ThreadIdNameManager::GetInstance()->
        GetName(thread_id);
    // Check if the thread name has been set or changed since the previous
    // call (if any), but don't bother if the new name is empty. Note this will
    // not detect a thread name change within the same char* buffer address: we
    // favor common case performance over corner case correctness.
    if (new_name != g_current_thread_name.Get().Get() &&
        new_name && *new_name) {
      g_current_thread_name.Get().Set(new_name);

      AutoLock thread_info_lock(thread_info_lock_);

      hash_map<int, std::string>::iterator existing_name =
          thread_names_.find(thread_id);
      if (existing_name == thread_names_.end()) {
        // This is a new thread id, and a new name.
        thread_names_[thread_id] = new_name;
      } else {
        // This is a thread id that we've seen before, but potentially with a
        // new name.
        std::vector<StringPiece> existing_names;
        Tokenize(existing_name->second, ",", &existing_names);
        bool found = std::find(existing_names.begin(),
                               existing_names.end(),
                               new_name) != existing_names.end();
        if (!found) {
          if (existing_names.size())
            existing_name->second.push_back(',');
          existing_name->second.append(new_name);
        }
      }
    }
  }

  std::string console_message;
  if (*category_group_enabled &
      (ENABLED_FOR_RECORDING | ENABLED_FOR_MONITORING)) {
    OptionalAutoLock lock(lock_);

    TraceEvent* trace_event = NULL;
    if (thread_local_event_buffer) {
      trace_event = thread_local_event_buffer->AddTraceEvent(&handle);
    } else {
      lock.EnsureAcquired();
      trace_event = AddEventToThreadSharedChunkWhileLocked(&handle, true);
    }

    if (trace_event) {
      trace_event->Initialize(thread_id, now, thread_now, phase,
                              category_group_enabled, name, id,
                              num_args, arg_names, arg_types, arg_values,
                              convertable_values, flags);

#if defined(OS_ANDROID)
      trace_event->SendToATrace();
#endif
    }

    if (trace_options() & kInternalEchoToConsole) {
      console_message = EventToConsoleMessage(
          phase == TRACE_EVENT_PHASE_COMPLETE ? TRACE_EVENT_PHASE_BEGIN : phase,
          timestamp, trace_event);
    }
  }

  if (console_message.size())
    LOG(ERROR) << console_message;

  if (reinterpret_cast<const unsigned char*>(subtle::NoBarrier_Load(
      &watch_category_)) == category_group_enabled) {
    bool event_name_matches;
    WatchEventCallback watch_event_callback_copy;
    {
      AutoLock lock(lock_);
      event_name_matches = watch_event_name_ == name;
      watch_event_callback_copy = watch_event_callback_;
    }
    if (event_name_matches) {
      if (!watch_event_callback_copy.is_null())
        watch_event_callback_copy.Run();
    }
  }

  if (*category_group_enabled & ENABLED_FOR_EVENT_CALLBACK) {
    EventCallback event_callback = reinterpret_cast<EventCallback>(
        subtle::NoBarrier_Load(&event_callback_));
    if (event_callback) {
      event_callback(now,
                     phase == TRACE_EVENT_PHASE_COMPLETE ?
                         TRACE_EVENT_PHASE_BEGIN : phase,
                     category_group_enabled, name, id,
                     num_args, arg_names, arg_types, arg_values,
                     flags);
    }
  }

  if (thread_local_event_buffer)
    thread_local_event_buffer->ReportOverhead(now, thread_now);

  return handle;
}

// May be called when a COMPELETE event ends and the unfinished event has been
// recycled (phase == TRACE_EVENT_PHASE_END and trace_event == NULL).
std::string TraceLog::EventToConsoleMessage(unsigned char phase,
                                            const TimeTicks& timestamp,
                                            TraceEvent* trace_event) {
  AutoLock thread_info_lock(thread_info_lock_);

  // The caller should translate TRACE_EVENT_PHASE_COMPLETE to
  // TRACE_EVENT_PHASE_BEGIN or TRACE_EVENT_END.
  DCHECK(phase != TRACE_EVENT_PHASE_COMPLETE);

  TimeDelta duration;
  int thread_id = trace_event ?
      trace_event->thread_id() : PlatformThread::CurrentId();
  if (phase == TRACE_EVENT_PHASE_END) {
    duration = timestamp - thread_event_start_times_[thread_id].top();
    thread_event_start_times_[thread_id].pop();
  }

  std::string thread_name = thread_names_[thread_id];
  if (thread_colors_.find(thread_name) == thread_colors_.end())
    thread_colors_[thread_name] = (thread_colors_.size() % 6) + 1;

  std::ostringstream log;
  log << base::StringPrintf("%s: \x1b[0;3%dm",
                            thread_name.c_str(),
                            thread_colors_[thread_name]);

  size_t depth = 0;
  if (thread_event_start_times_.find(thread_id) !=
      thread_event_start_times_.end())
    depth = thread_event_start_times_[thread_id].size();

  for (size_t i = 0; i < depth; ++i)
    log << "| ";

  if (trace_event)
    trace_event->AppendPrettyPrinted(&log);
  if (phase == TRACE_EVENT_PHASE_END)
    log << base::StringPrintf(" (%.3f ms)", duration.InMillisecondsF());

  log << "\x1b[0;m";

  if (phase == TRACE_EVENT_PHASE_BEGIN)
    thread_event_start_times_[thread_id].push(timestamp);

  return log.str();
}

void TraceLog::AddTraceEventEtw(char phase,
                                const char* name,
                                const void* id,
                                const char* extra) {
#if defined(OS_WIN)
  TraceEventETWProvider::Trace(name, phase, id, extra);
#endif
  INTERNAL_TRACE_EVENT_ADD(phase, "ETW Trace Event", name,
                           TRACE_EVENT_FLAG_COPY, "id", id, "extra", extra);
}

void TraceLog::AddTraceEventEtw(char phase,
                                const char* name,
                                const void* id,
                                const std::string& extra) {
#if defined(OS_WIN)
  TraceEventETWProvider::Trace(name, phase, id, extra);
#endif
  INTERNAL_TRACE_EVENT_ADD(phase, "ETW Trace Event", name,
                           TRACE_EVENT_FLAG_COPY, "id", id, "extra", extra);
}

void TraceLog::UpdateTraceEventDuration(
    const unsigned char* category_group_enabled,
    const char* name,
    TraceEventHandle handle) {
  // Avoid re-entrance of AddTraceEvent. This may happen in GPU process when
  // ECHO_TO_CONSOLE is enabled: AddTraceEvent -> LOG(ERROR) ->
  // GpuProcessLogMessageHandler -> PostPendingTask -> TRACE_EVENT ...
  if (thread_is_in_trace_event_.Get())
    return;

  AutoThreadLocalBoolean thread_is_in_trace_event(&thread_is_in_trace_event_);

  TimeTicks thread_now = ThreadNow();
  TimeTicks now = OffsetNow();

  std::string console_message;
  if (*category_group_enabled & ENABLED_FOR_RECORDING) {
    OptionalAutoLock lock(lock_);

    TraceEvent* trace_event = GetEventByHandleInternal(handle, &lock);
    if (trace_event) {
      DCHECK(trace_event->phase() == TRACE_EVENT_PHASE_COMPLETE);
      trace_event->UpdateDuration(now, thread_now);
#if defined(OS_ANDROID)
      trace_event->SendToATrace();
#endif
    }

    if (trace_options() & kInternalEchoToConsole) {
      console_message = EventToConsoleMessage(TRACE_EVENT_PHASE_END,
                                              now, trace_event);
    }
  }

  if (console_message.size())
    LOG(ERROR) << console_message;

  if (*category_group_enabled & ENABLED_FOR_EVENT_CALLBACK) {
    EventCallback event_callback = reinterpret_cast<EventCallback>(
        subtle::NoBarrier_Load(&event_callback_));
    if (event_callback) {
      event_callback(now, TRACE_EVENT_PHASE_END, category_group_enabled, name,
                     trace_event_internal::kNoEventId, 0, NULL, NULL, NULL,
                     TRACE_EVENT_FLAG_NONE);
    }
  }
}

void TraceLog::SetWatchEvent(const std::string& category_name,
                             const std::string& event_name,
                             const WatchEventCallback& callback) {
  const unsigned char* category = GetCategoryGroupEnabled(
      category_name.c_str());
  AutoLock lock(lock_);
  subtle::NoBarrier_Store(&watch_category_,
                          reinterpret_cast<subtle::AtomicWord>(category));
  watch_event_name_ = event_name;
  watch_event_callback_ = callback;
}

void TraceLog::CancelWatchEvent() {
  AutoLock lock(lock_);
  subtle::NoBarrier_Store(&watch_category_, 0);
  watch_event_name_ = "";
  watch_event_callback_.Reset();
}

void TraceLog::AddMetadataEventsWhileLocked() {
  lock_.AssertAcquired();

#if !defined(OS_NACL)  // NaCl shouldn't expose the process id.
  InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
                          0,
                          "num_cpus", "number",
                          base::SysInfo::NumberOfProcessors());
#endif


  int current_thread_id = static_cast<int>(base::PlatformThread::CurrentId());
  if (process_sort_index_ != 0) {
    InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
                            current_thread_id,
                            "process_sort_index", "sort_index",
                            process_sort_index_);
  }

  if (process_name_.size()) {
    InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
                            current_thread_id,
                            "process_name", "name",
                            process_name_);
  }

  if (process_labels_.size() > 0) {
    std::vector<std::string> labels;
    for(base::hash_map<int, std::string>::iterator it = process_labels_.begin();
        it != process_labels_.end();
        it++) {
      labels.push_back(it->second);
    }
    InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
                            current_thread_id,
                            "process_labels", "labels",
                            JoinString(labels, ','));
  }

  // Thread sort indices.
  for(hash_map<int, int>::iterator it = thread_sort_indices_.begin();
      it != thread_sort_indices_.end();
      it++) {
    if (it->second == 0)
      continue;
    InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
                            it->first,
                            "thread_sort_index", "sort_index",
                            it->second);
  }

  // Thread names.
  AutoLock thread_info_lock(thread_info_lock_);
  for(hash_map<int, std::string>::iterator it = thread_names_.begin();
      it != thread_names_.end();
      it++) {
    if (it->second.empty())
      continue;
    InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
                            it->first,
                            "thread_name", "name",
                            it->second);
  }

  // If buffer is full, add a metadata record to report this.
  if (!buffer_limit_reached_timestamp_.is_null()) {
    InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
                            current_thread_id,
                            "trace_buffer_overflowed",
                            "overflowed_at_ts",
                            buffer_limit_reached_timestamp_);
  }
}

void TraceLog::WaitSamplingEventForTesting() {
  if (!sampling_thread_)
    return;
  sampling_thread_->WaitSamplingEventForTesting();
}

void TraceLog::DeleteForTesting() {
  DeleteTraceLogForTesting::Delete();
}

TraceEvent* TraceLog::GetEventByHandle(TraceEventHandle handle) {
  return GetEventByHandleInternal(handle, NULL);
}

TraceEvent* TraceLog::GetEventByHandleInternal(TraceEventHandle handle,
                                               OptionalAutoLock* lock) {
  if (!handle.chunk_seq)
    return NULL;

  if (thread_local_event_buffer_.Get()) {
    TraceEvent* trace_event =
        thread_local_event_buffer_.Get()->GetEventByHandle(handle);
    if (trace_event)
      return trace_event;
  }

  // The event has been out-of-control of the thread local buffer.
  // Try to get the event from the main buffer with a lock.
  if (lock)
    lock->EnsureAcquired();

  if (thread_shared_chunk_ &&
      handle.chunk_index == thread_shared_chunk_index_) {
    return handle.chunk_seq == thread_shared_chunk_->seq() ?
        thread_shared_chunk_->GetEventAt(handle.event_index) : NULL;
  }

  return logged_events_->GetEventByHandle(handle);
}

void TraceLog::SetProcessID(int process_id) {
  process_id_ = process_id;
  // Create a FNV hash from the process ID for XORing.
  // See http://isthe.com/chongo/tech/comp/fnv/ for algorithm details.
  unsigned long long offset_basis = 14695981039346656037ull;
  unsigned long long fnv_prime = 1099511628211ull;
  unsigned long long pid = static_cast<unsigned long long>(process_id_);
  process_id_hash_ = (offset_basis ^ pid) * fnv_prime;
}

void TraceLog::SetProcessSortIndex(int sort_index) {
  AutoLock lock(lock_);
  process_sort_index_ = sort_index;
}

void TraceLog::SetProcessName(const std::string& process_name) {
  AutoLock lock(lock_);
  process_name_ = process_name;
}

void TraceLog::UpdateProcessLabel(
    int label_id, const std::string& current_label) {
  if(!current_label.length())
    return RemoveProcessLabel(label_id);

  AutoLock lock(lock_);
  process_labels_[label_id] = current_label;
}

void TraceLog::RemoveProcessLabel(int label_id) {
  AutoLock lock(lock_);
  base::hash_map<int, std::string>::iterator it = process_labels_.find(
      label_id);
  if (it == process_labels_.end())
    return;

  process_labels_.erase(it);
}

void TraceLog::SetThreadSortIndex(PlatformThreadId thread_id, int sort_index) {
  AutoLock lock(lock_);
  thread_sort_indices_[static_cast<int>(thread_id)] = sort_index;
}

void TraceLog::SetTimeOffset(TimeDelta offset) {
  time_offset_ = offset;
}

size_t TraceLog::GetObserverCountForTest() const {
  return enabled_state_observer_list_.size();
}

void TraceLog::SetCurrentThreadBlocksMessageLoop() {
  thread_blocks_message_loop_.Set(true);
  if (thread_local_event_buffer_.Get()) {
    // This will flush the thread local buffer.
    delete thread_local_event_buffer_.Get();
  }
}

bool CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
    const std::string& str) {
  return  str.empty() ||
          str.at(0) == ' ' ||
          str.at(str.length() - 1) == ' ';
}

CategoryFilter::CategoryFilter(const std::string& filter_string) {
  if (!filter_string.empty())
    Initialize(filter_string);
  else
    Initialize(CategoryFilter::kDefaultCategoryFilterString);
}

CategoryFilter::CategoryFilter() {
    Initialize(CategoryFilter::kDefaultCategoryFilterString);
}

CategoryFilter::CategoryFilter(const CategoryFilter& cf)
    : included_(cf.included_),
      disabled_(cf.disabled_),
      excluded_(cf.excluded_),
      delays_(cf.delays_) {
}

CategoryFilter::~CategoryFilter() {
}

CategoryFilter& CategoryFilter::operator=(const CategoryFilter& rhs) {
  if (this == &rhs)
    return *this;

  included_ = rhs.included_;
  disabled_ = rhs.disabled_;
  excluded_ = rhs.excluded_;
  delays_ = rhs.delays_;
  return *this;
}

void CategoryFilter::Initialize(const std::string& filter_string) {
  // Tokenize list of categories, delimited by ','.
  StringTokenizer tokens(filter_string, ",");
  // Add each token to the appropriate list (included_,excluded_).
  while (tokens.GetNext()) {
    std::string category = tokens.token();
    // Ignore empty categories.
    if (category.empty())
      continue;
    // Synthetic delays are of the form 'DELAY(delay;option;option;...)'.
    if (category.find(kSyntheticDelayCategoryFilterPrefix) == 0 &&
        category.at(category.size() - 1) == ')') {
      category = category.substr(
          strlen(kSyntheticDelayCategoryFilterPrefix),
          category.size() - strlen(kSyntheticDelayCategoryFilterPrefix) - 1);
      size_t name_length = category.find(';');
      if (name_length != std::string::npos && name_length > 0 &&
          name_length != category.size() - 1) {
        delays_.push_back(category);
      }
    } else if (category.at(0) == '-') {
      // Excluded categories start with '-'.
      // Remove '-' from category string.
      category = category.substr(1);
      excluded_.push_back(category);
    } else if (category.compare(0, strlen(TRACE_DISABLED_BY_DEFAULT("")),
                                TRACE_DISABLED_BY_DEFAULT("")) == 0) {
      disabled_.push_back(category);
    } else {
      included_.push_back(category);
    }
  }
}

void CategoryFilter::WriteString(const StringList& values,
                                 std::string* out,
                                 bool included) const {
  bool prepend_comma = !out->empty();
  int token_cnt = 0;
  for (StringList::const_iterator ci = values.begin();
       ci != values.end(); ++ci) {
    if (token_cnt > 0 || prepend_comma)
      StringAppendF(out, ",");
    StringAppendF(out, "%s%s", (included ? "" : "-"), ci->c_str());
    ++token_cnt;
  }
}

void CategoryFilter::WriteString(const StringList& delays,
                                 std::string* out) const {
  bool prepend_comma = !out->empty();
  int token_cnt = 0;
  for (StringList::const_iterator ci = delays.begin();
       ci != delays.end(); ++ci) {
    if (token_cnt > 0 || prepend_comma)
      StringAppendF(out, ",");
    StringAppendF(out, "%s%s)", kSyntheticDelayCategoryFilterPrefix,
                  ci->c_str());
    ++token_cnt;
  }
}

std::string CategoryFilter::ToString() const {
  std::string filter_string;
  WriteString(included_, &filter_string, true);
  WriteString(disabled_, &filter_string, true);
  WriteString(excluded_, &filter_string, false);
  WriteString(delays_, &filter_string);
  return filter_string;
}

bool CategoryFilter::IsCategoryGroupEnabled(
    const char* category_group_name) const {
  // TraceLog should call this method only as  part of enabling/disabling
  // categories.

  bool had_enabled_by_default = false;
  DCHECK(category_group_name);
  CStringTokenizer category_group_tokens(
      category_group_name, category_group_name + strlen(category_group_name),
      ",");
  while (category_group_tokens.GetNext()) {
    std::string category_group_token = category_group_tokens.token();
    // Don't allow empty tokens, nor tokens with leading or trailing space.
    DCHECK(!CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
               category_group_token))
        << "Disallowed category string";
    if (IsCategoryEnabled(category_group_token.c_str())) {
      return true;
    }
    if (!MatchPattern(category_group_token.c_str(),
                      TRACE_DISABLED_BY_DEFAULT("*")))
      had_enabled_by_default = true;
  }
  // Do a second pass to check for explicitly disabled categories
  // (those explicitly enabled have priority due to first pass).
  category_group_tokens.Reset();
  while (category_group_tokens.GetNext()) {
    std::string category_group_token = category_group_tokens.token();
    for (StringList::const_iterator ci = excluded_.begin();
         ci != excluded_.end(); ++ci) {
      if (MatchPattern(category_group_token.c_str(), ci->c_str()))
        return false;
    }
  }
  // If the category group is not excluded, and there are no included patterns
  // we consider this category group enabled, as long as it had categories
  // other than disabled-by-default.
  return included_.empty() && had_enabled_by_default;
}

bool CategoryFilter::IsCategoryEnabled(const char* category_name) const {
  StringList::const_iterator ci;

  // Check the disabled- filters and the disabled-* wildcard first so that a
  // "*" filter does not include the disabled.
  for (ci = disabled_.begin(); ci != disabled_.end(); ++ci) {
    if (MatchPattern(category_name, ci->c_str()))
      return true;
  }

  if (MatchPattern(category_name, TRACE_DISABLED_BY_DEFAULT("*")))
    return false;

  for (ci = included_.begin(); ci != included_.end(); ++ci) {
    if (MatchPattern(category_name, ci->c_str()))
      return true;
  }

  return false;
}

bool CategoryFilter::HasIncludedPatterns() const {
  return !included_.empty();
}

void CategoryFilter::Merge(const CategoryFilter& nested_filter) {
  // Keep included patterns only if both filters have an included entry.
  // Otherwise, one of the filter was specifying "*" and we want to honour the
  // broadest filter.
  if (HasIncludedPatterns() && nested_filter.HasIncludedPatterns()) {
    included_.insert(included_.end(),
                     nested_filter.included_.begin(),
                     nested_filter.included_.end());
  } else {
    included_.clear();
  }

  disabled_.insert(disabled_.end(),
                   nested_filter.disabled_.begin(),
                   nested_filter.disabled_.end());
  excluded_.insert(excluded_.end(),
                   nested_filter.excluded_.begin(),
                   nested_filter.excluded_.end());
  delays_.insert(delays_.end(),
                 nested_filter.delays_.begin(),
                 nested_filter.delays_.end());
}

void CategoryFilter::Clear() {
  included_.clear();
  disabled_.clear();
  excluded_.clear();
}

const CategoryFilter::StringList&
    CategoryFilter::GetSyntheticDelayValues() const {
  return delays_;
}

}  // namespace debug
}  // namespace base

namespace trace_event_internal {

ScopedTraceBinaryEfficient::ScopedTraceBinaryEfficient(
    const char* category_group, const char* name) {
  // The single atom works because for now the category_group can only be "gpu".
  DCHECK(strcmp(category_group, "gpu") == 0);
  static TRACE_EVENT_API_ATOMIC_WORD atomic = 0;
  INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO_CUSTOM_VARIABLES(
      category_group, atomic, category_group_enabled_);
  name_ = name;
  if (*category_group_enabled_) {
    event_handle_ =
        TRACE_EVENT_API_ADD_TRACE_EVENT_WITH_THREAD_ID_AND_TIMESTAMP(
            TRACE_EVENT_PHASE_COMPLETE, category_group_enabled_, name,
            trace_event_internal::kNoEventId,
            static_cast<int>(base::PlatformThread::CurrentId()),
            base::TimeTicks::NowFromSystemTraceTime(),
            0, NULL, NULL, NULL, NULL, TRACE_EVENT_FLAG_NONE);
  }
}

ScopedTraceBinaryEfficient::~ScopedTraceBinaryEfficient() {
  if (*category_group_enabled_) {
    TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION(category_group_enabled_,
                                                name_, event_handle_);
  }
}

}  // namespace trace_event_internal