base/trace_event/trace_log.cc

// Copyright 2015 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_log.h"

#include <algorithm>
#include <cmath>
#include <limits>
#include <memory>
#include <unordered_set>
#include <utility>

#include "base/base_switches.h"
#include "base/bind.h"
#include "base/command_line.h"
#include "base/debug/leak_annotations.h"
#include "base/location.h"
#include "base/macros.h"
#include "base/memory/ptr_util.h"
#include "base/memory/ref_counted_memory.h"
#include "base/message_loop/message_loop_current.h"
#include "base/no_destructor.h"
#include "base/process/process.h"
#include "base/process/process_metrics.h"
#include "base/stl_util.h"
#include "base/strings/string_piece.h"
#include "base/strings/string_split.h"
#include "base/strings/string_tokenizer.h"
#include "base/strings/stringprintf.h"
#include "base/system/sys_info.h"
#include "base/task/post_task.h"
#include "base/task/thread_pool.h"
#include "base/threading/platform_thread.h"
#include "base/threading/sequenced_task_runner_handle.h"
#include "base/threading/thread_id_name_manager.h"
#include "base/threading/thread_task_runner_handle.h"
#include "base/time/time.h"
#include "base/trace_event/event_name_filter.h"
#include "base/trace_event/heap_profiler.h"
#include "base/trace_event/heap_profiler_allocation_context_tracker.h"
#include "base/trace_event/heap_profiler_event_filter.h"
#include "base/trace_event/memory_dump_manager.h"
#include "base/trace_event/memory_dump_provider.h"
#include "base/trace_event/process_memory_dump.h"
#include "base/trace_event/thread_instruction_count.h"
#include "base/trace_event/trace_buffer.h"
#include "base/trace_event/trace_event.h"
#include "build/build_config.h"

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

#if defined(OS_ANDROID)
#include "base/debug/elf_reader.h"

// The linker assigns the virtual address of the start of current library to
// this symbol.
extern char __executable_start;
#endif

namespace base {
namespace trace_event {

namespace {

// 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;
static_assert(
    kTraceEventVectorBigBufferChunks <= TraceBufferChunk::kMaxChunkIndex,
    "Too many big buffer chunks");
const size_t kTraceEventVectorBufferChunks = 256000 / kTraceBufferChunkSize;
static_assert(
    kTraceEventVectorBufferChunks <= TraceBufferChunk::kMaxChunkIndex,
    "Too many vector buffer chunks");
const size_t kTraceEventRingBufferChunks = kTraceEventVectorBufferChunks / 4;

// ECHO_TO_CONSOLE needs a small buffer to hold the unfinished COMPLETE events.
const size_t kEchoToConsoleTraceEventBufferChunks = 256;

const size_t kTraceEventBufferSizeInBytes = 100 * 1024;
const int kThreadFlushTimeoutMs = 3000;

TraceLog* g_trace_log_for_testing = nullptr;

#define MAX_TRACE_EVENT_FILTERS 32

// List of TraceEventFilter objects from the most recent tracing session.
std::vector<std::unique_ptr<TraceEventFilter>>& GetCategoryGroupFilters() {
  static auto* filters = new std::vector<std::unique_ptr<TraceEventFilter>>();
  return *filters;
}

ThreadTicks ThreadNow() {
  return ThreadTicks::IsSupported()
             ? base::subtle::ThreadTicksNowIgnoringOverride()
             : ThreadTicks();
}

ThreadInstructionCount ThreadInstructionNow() {
  return ThreadInstructionCount::IsSupported() ? ThreadInstructionCount::Now()
                                               : ThreadInstructionCount();
}

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;

  TraceArguments args(arg_name, value);
  base::TimeTicks now = TRACE_TIME_TICKS_NOW();
  ThreadTicks thread_now = ThreadNow();
  ThreadInstructionCount thread_instruction_count = ThreadInstructionNow();
  trace_event->Reset(thread_id, now, thread_now, thread_instruction_count,
                     TRACE_EVENT_PHASE_METADATA,
                     CategoryRegistry::kCategoryMetadata->state_ptr(),
                     metadata_name,
                     trace_event_internal::kGlobalScope,  // scope
                     trace_event_internal::kNoId,         // id
                     trace_event_internal::kNoId,         // bind_id
                     &args, 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);
};

// Use this function instead of TraceEventHandle constructor to keep the
// overhead of ScopedTracer (trace_event.h) constructor minimum.
void MakeHandle(uint32_t chunk_seq,
                size_t chunk_index,
                size_t event_index,
                TraceEventHandle* handle) {
  DCHECK(chunk_seq);
  DCHECK(chunk_index <= TraceBufferChunk::kMaxChunkIndex);
  DCHECK(event_index < TraceBufferChunk::kTraceBufferChunkSize);
  DCHECK(chunk_index <= std::numeric_limits<uint16_t>::max());
  handle->chunk_seq = chunk_seq;
  handle->chunk_index = static_cast<uint16_t>(chunk_index);
  handle->event_index = static_cast<uint16_t>(event_index);
}

template <typename Function>
void ForEachCategoryFilter(const unsigned char* category_group_enabled,
                           Function filter_fn) {
  const TraceCategory* category =
      CategoryRegistry::GetCategoryByStatePtr(category_group_enabled);
  uint32_t filter_bitmap = category->enabled_filters();
  for (int index = 0; filter_bitmap != 0; filter_bitmap >>= 1, index++) {
    if (filter_bitmap & 1 && GetCategoryGroupFilters()[index])
      filter_fn(GetCategoryGroupFilters()[index].get());
  }
}

// The fallback arguments filtering function will filter away every argument.
bool DefaultIsTraceEventArgsWhitelisted(
    const char* category_group_name,
    const char* event_name,
    base::trace_event::ArgumentNameFilterPredicate* arg_name_filter) {
  return false;
}

}  // namespace

// 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() EXCLUSIVE_LOCK_FUNCTION(lock_) {
    if (!locked_) {
      lock_->Acquire();
      locked_ = true;
    } else {
      lock_->AssertAcquired();
    }
  }

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

class TraceLog::ThreadLocalEventBuffer
    : public MessageLoopCurrent::DestructionObserver,
      public MemoryDumpProvider {
 public:
  explicit ThreadLocalEventBuffer(TraceLog* trace_log);
  ~ThreadLocalEventBuffer() override;

  TraceEvent* AddTraceEvent(TraceEventHandle* handle);

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

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

  int generation() const { return generation_; }

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

  // MemoryDumpProvider implementation.
  bool OnMemoryDump(const MemoryDumpArgs& args,
                    ProcessMemoryDump* pmd) 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_;
  std::unique_ptr<TraceBufferChunk> chunk_;
  size_t chunk_index_;
  int generation_;

  DISALLOW_COPY_AND_ASSIGN(ThreadLocalEventBuffer);
};

TraceLog::ThreadLocalEventBuffer::ThreadLocalEventBuffer(TraceLog* trace_log)
    : trace_log_(trace_log),
      chunk_index_(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.
  MessageLoopCurrent::Get()->AddDestructionObserver(this);

  // This is to report the local memory usage when memory-infra is enabled.
  MemoryDumpManager::GetInstance()->RegisterDumpProvider(
      this, "ThreadLocalEventBuffer", ThreadTaskRunnerHandle::Get());

  int thread_id = static_cast<int>(PlatformThread::CurrentId());

  AutoLock lock(trace_log->lock_);
  trace_log->thread_task_runners_[thread_id] = ThreadTaskRunnerHandle::Get();
}

TraceLog::ThreadLocalEventBuffer::~ThreadLocalEventBuffer() {
  CheckThisIsCurrentBuffer();
  MessageLoopCurrent::Get()->RemoveDestructionObserver(this);
  MemoryDumpManager::GetInstance()->UnregisterDumpProvider(this);

  {
    AutoLock lock(trace_log_->lock_);
    FlushWhileLocked();

    int thread_id = static_cast<int>(PlatformThread::CurrentId());
    trace_log_->thread_task_runners_.erase(thread_id);
  }
  trace_log_->thread_local_event_buffer_.Set(nullptr);
}

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 nullptr;

  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::WillDestroyCurrentMessageLoop() {
  delete this;
}

bool TraceLog::ThreadLocalEventBuffer::OnMemoryDump(const MemoryDumpArgs& args,
                                                    ProcessMemoryDump* pmd) {
  if (!chunk_)
    return true;
  std::string dump_base_name = StringPrintf(
      "tracing/thread_%d", static_cast<int>(PlatformThread::CurrentId()));
  TraceEventMemoryOverhead overhead;
  chunk_->EstimateTraceMemoryOverhead(&overhead);
  overhead.DumpInto(dump_base_name.c_str(), pmd);
  return true;
}

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_, std::move(chunk_));
  }
  // Otherwise this method may be called from the destructor, or TraceLog will
  // find the generation mismatch and delete this buffer soon.
}

void TraceLog::SetAddTraceEventOverrides(
    const AddTraceEventOverrideFunction& add_event_override,
    const OnFlushFunction& on_flush_override,
    const UpdateDurationFunction& update_duration_override) {
  add_trace_event_override_.store(add_event_override);
  on_flush_override_.store(on_flush_override);
  update_duration_override_.store(update_duration_override);
}

struct TraceLog::RegisteredAsyncObserver {
  explicit RegisteredAsyncObserver(WeakPtr<AsyncEnabledStateObserver> observer)
      : observer(observer), task_runner(ThreadTaskRunnerHandle::Get()) {}
  ~RegisteredAsyncObserver() = default;

  WeakPtr<AsyncEnabledStateObserver> observer;
  scoped_refptr<SequencedTaskRunner> task_runner;
};

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

TraceLogStatus::~TraceLogStatus() = default;

// static
TraceLog* TraceLog::GetInstance() {
  static base::NoDestructor<TraceLog> instance;
  return instance.get();
}

// static
void TraceLog::ResetForTesting() {
  if (!g_trace_log_for_testing)
    return;
  {
    AutoLock lock(g_trace_log_for_testing->lock_);
    CategoryRegistry::ResetForTesting();
  }
  g_trace_log_for_testing->~TraceLog();
  new (g_trace_log_for_testing) TraceLog;
}

TraceLog::TraceLog()
    : enabled_modes_(0),
      num_traces_recorded_(0),
      process_sort_index_(0),
      process_id_hash_(0),
      process_id_(base::kNullProcessId),
      trace_options_(kInternalRecordUntilFull),
      trace_config_(TraceConfig()),
      thread_shared_chunk_index_(0),
      generation_(0),
      use_worker_thread_(false),
      filter_factory_for_testing_(nullptr) {
  CategoryRegistry::Initialize();

#if defined(OS_NACL)  // NaCl shouldn't expose the process id.
  SetProcessID(0);
#else
  SetProcessID(static_cast<int>(GetCurrentProcId()));
#endif

// Linux renderer processes and Android O processes are not allowed to read
// "proc/stat" file, crbug.com/788870.
#if defined(OS_WIN) || (defined(OS_MACOSX) && !defined(OS_IOS))
  process_creation_time_ = Process::Current().CreationTime();
#else
  // Use approximate time when creation time is not available.
  process_creation_time_ = TRACE_TIME_NOW();
#endif

  logged_events_.reset(CreateTraceBuffer());

  MemoryDumpManager::GetInstance()->RegisterDumpProvider(this, "TraceLog",
                                                         nullptr);
  g_trace_log_for_testing = this;
}

TraceLog::~TraceLog() = default;

void TraceLog::InitializeThreadLocalEventBufferIfSupported() {
  // A ThreadLocalEventBuffer needs the message loop with a task runner
  // - to know when the thread exits;
  // - to handle the final flush.
  // For a thread without a message loop or if the message loop may be blocked,
  // the trace events will be added into the main buffer directly.
  if (thread_blocks_message_loop_.Get() || !MessageLoopCurrent::IsSet() ||
      !ThreadTaskRunnerHandle::IsSet()) {
    return;
  }
  HEAP_PROFILER_SCOPED_IGNORE;
  auto* 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 = nullptr;
  }
  if (!thread_local_event_buffer) {
    thread_local_event_buffer = new ThreadLocalEventBuffer(this);
    thread_local_event_buffer_.Set(thread_local_event_buffer);
  }
}

bool TraceLog::OnMemoryDump(const MemoryDumpArgs& args,
                            ProcessMemoryDump* pmd) {
  // TODO(ssid): Use MemoryDumpArgs to create light dumps when requested
  // (crbug.com/499731).
  TraceEventMemoryOverhead overhead;
  overhead.Add(TraceEventMemoryOverhead::kOther, sizeof(*this));
  {
    AutoLock lock(lock_);
    if (logged_events_)
      logged_events_->EstimateTraceMemoryOverhead(&overhead);

    for (auto& metadata_event : metadata_events_)
      metadata_event->EstimateTraceMemoryOverhead(&overhead);
  }
  overhead.AddSelf();
  overhead.DumpInto("tracing/main_trace_log", pmd);
  return true;
}

const unsigned char* TraceLog::GetCategoryGroupEnabled(
    const char* category_group) {
  TraceLog* tracelog = GetInstance();
  if (!tracelog) {
    DCHECK(!CategoryRegistry::kCategoryAlreadyShutdown->is_enabled());
    return CategoryRegistry::kCategoryAlreadyShutdown->state_ptr();
  }
  TraceCategory* category = CategoryRegistry::GetCategoryByName(category_group);
  if (!category) {
    // Slow path: in the case of a new category we have to repeat the check
    // holding the lock, as multiple threads might have reached this point
    // at the same time.
    auto category_initializer = [](TraceCategory* category) {
      TraceLog::GetInstance()->UpdateCategoryState(category);
    };
    AutoLock lock(tracelog->lock_);
    CategoryRegistry::GetOrCreateCategoryLocked(
        category_group, category_initializer, &category);
  }
  DCHECK(category->state_ptr());
  return category->state_ptr();
}

const char* TraceLog::GetCategoryGroupName(
    const unsigned char* category_group_enabled) {
  return CategoryRegistry::GetCategoryByStatePtr(category_group_enabled)
      ->name();
}

void TraceLog::UpdateCategoryState(TraceCategory* category) {
  lock_.AssertAcquired();
  DCHECK(category->is_valid());
  unsigned char state_flags = 0;
  if (enabled_modes_ & RECORDING_MODE &&
      trace_config_.IsCategoryGroupEnabled(category->name())) {
    state_flags |= TraceCategory::ENABLED_FOR_RECORDING;
  }

  // TODO(primiano): this is a temporary workaround for catapult:#2341,
  // to guarantee that metadata events are always added even if the category
  // filter is "-*". See crbug.com/618054 for more details and long-term fix.
  if (enabled_modes_ & RECORDING_MODE &&
      category == CategoryRegistry::kCategoryMetadata) {
    state_flags |= TraceCategory::ENABLED_FOR_RECORDING;
  }

#if defined(OS_WIN)
  if (base::trace_event::TraceEventETWExport::IsCategoryGroupEnabled(
          category->name())) {
    state_flags |= TraceCategory::ENABLED_FOR_ETW_EXPORT;
  }
#endif

  uint32_t enabled_filters_bitmap = 0;
  int index = 0;
  for (const auto& event_filter : enabled_event_filters_) {
    if (event_filter.IsCategoryGroupEnabled(category->name())) {
      state_flags |= TraceCategory::ENABLED_FOR_FILTERING;
      DCHECK(GetCategoryGroupFilters()[index]);
      enabled_filters_bitmap |= 1 << index;
    }
    if (index++ >= MAX_TRACE_EVENT_FILTERS) {
      NOTREACHED();
      break;
    }
  }
  category->set_enabled_filters(enabled_filters_bitmap);
  category->set_state(state_flags);
}

void TraceLog::UpdateCategoryRegistry() {
  lock_.AssertAcquired();
  CreateFiltersForTraceConfig();
  for (TraceCategory& category : CategoryRegistry::GetAllCategories()) {
    UpdateCategoryState(&category);
  }
}

void TraceLog::CreateFiltersForTraceConfig() {
  if (!(enabled_modes_ & FILTERING_MODE))
    return;

  // Filters were already added and tracing could be enabled. Filters list
  // cannot be changed when trace events are using them.
  if (GetCategoryGroupFilters().size())
    return;

  for (auto& filter_config : enabled_event_filters_) {
    if (GetCategoryGroupFilters().size() >= MAX_TRACE_EVENT_FILTERS) {
      NOTREACHED()
          << "Too many trace event filters installed in the current session";
      break;
    }

    std::unique_ptr<TraceEventFilter> new_filter;
    const std::string& predicate_name = filter_config.predicate_name();
    if (predicate_name == EventNameFilter::kName) {
      auto whitelist = std::make_unique<std::unordered_set<std::string>>();
      CHECK(filter_config.GetArgAsSet("event_name_whitelist", &*whitelist));
      new_filter = std::make_unique<EventNameFilter>(std::move(whitelist));
    } else if (predicate_name == HeapProfilerEventFilter::kName) {
      new_filter = std::make_unique<HeapProfilerEventFilter>();
    } else {
      if (filter_factory_for_testing_)
        new_filter = filter_factory_for_testing_(predicate_name);
      CHECK(new_filter) << "Unknown trace filter " << predicate_name;
    }
    GetCategoryGroupFilters().push_back(std::move(new_filter));
  }
}

void TraceLog::SetEnabled(const TraceConfig& trace_config,
                          uint8_t modes_to_enable) {
  DCHECK(trace_config.process_filter_config().IsEnabled(process_id_));

  AutoLock lock(lock_);

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

  InternalTraceOptions new_options =
      GetInternalOptionsFromTraceConfig(trace_config);

  InternalTraceOptions old_options = trace_options();

  if (dispatching_to_observers_) {
    // TODO(ssid): Change to NOTREACHED after fixing crbug.com/625170.
    DLOG(ERROR)
        << "Cannot manipulate TraceLog::Enabled state from an observer.";
    return;
  }

  // Clear all filters from previous tracing session. These filters are not
  // cleared at the end of tracing because some threads which hit trace event
  // when disabling, could try to use the filters.
  if (!enabled_modes_)
    GetCategoryGroupFilters().clear();

  // Update trace config for recording.
  const bool already_recording = enabled_modes_ & RECORDING_MODE;
  if (modes_to_enable & RECORDING_MODE) {
    if (already_recording) {
      trace_config_.Merge(trace_config);
    } else {
      trace_config_ = trace_config;
    }
  }

  // Update event filters only if filtering was not enabled.
  if (modes_to_enable & FILTERING_MODE && enabled_event_filters_.empty()) {
    DCHECK(!trace_config.event_filters().empty());
    enabled_event_filters_ = trace_config.event_filters();
  }
  // Keep the |trace_config_| updated with only enabled filters in case anyone
  // tries to read it using |GetCurrentTraceConfig| (even if filters are
  // empty).
  trace_config_.SetEventFilters(enabled_event_filters_);

  enabled_modes_ |= modes_to_enable;
  UpdateCategoryRegistry();

  // Do not notify observers or create trace buffer if only enabled for
  // filtering or if recording was already enabled.
  if (!(modes_to_enable & RECORDING_MODE) || already_recording)
    return;

  // Discard events if new trace options are different. Reducing trace buffer
  // size is not supported while already recording, so only replace trace
  // buffer if we were not already recording.
  if (new_options != old_options ||
      (trace_config_.GetTraceBufferSizeInEvents() && !already_recording)) {
    subtle::NoBarrier_Store(&trace_options_, new_options);
    UseNextTraceBuffer();
  }

  num_traces_recorded_++;

  UpdateCategoryRegistry();

  dispatching_to_observers_ = true;
  {
    // Notify observers outside of the thread events lock, so they can trigger
    // trace events.
    AutoUnlock unlock(lock_);
    AutoLock lock2(observers_lock_);
    for (EnabledStateObserver* observer : enabled_state_observers_)
      observer->OnTraceLogEnabled();
    for (const auto& it : async_observers_) {
      it.second.task_runner->PostTask(
          FROM_HERE, BindOnce(&AsyncEnabledStateObserver::OnTraceLogEnabled,
                              it.second.observer));
    }
  }
  dispatching_to_observers_ = false;
}

void TraceLog::SetArgumentFilterPredicate(
    const ArgumentFilterPredicate& argument_filter_predicate) {
  AutoLock lock(lock_);
  DCHECK(!argument_filter_predicate.is_null());
  // Replace the existing argument filter.
  argument_filter_predicate_ = argument_filter_predicate;
}

ArgumentFilterPredicate TraceLog::GetArgumentFilterPredicate() const {
  AutoLock lock(lock_);
  return argument_filter_predicate_;
}

void TraceLog::SetMetadataFilterPredicate(
    const MetadataFilterPredicate& metadata_filter_predicate) {
  AutoLock lock(lock_);
  DCHECK(!metadata_filter_predicate.is_null());
  // Replace the existing argument filter.
  metadata_filter_predicate_ = metadata_filter_predicate;
}

MetadataFilterPredicate TraceLog::GetMetadataFilterPredicate() const {
  AutoLock lock(lock_);
  return metadata_filter_predicate_;
}

TraceLog::InternalTraceOptions TraceLog::GetInternalOptionsFromTraceConfig(
    const TraceConfig& config) {
  InternalTraceOptions ret = config.IsArgumentFilterEnabled()
                                 ? kInternalEnableArgumentFilter
                                 : kInternalNone;
  switch (config.GetTraceRecordMode()) {
    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;
}

TraceConfig TraceLog::GetCurrentTraceConfig() const {
  AutoLock lock(lock_);
  return trace_config_;
}

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

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

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

  if (!(enabled_modes_ & modes_to_disable))
    return;

  if (dispatching_to_observers_) {
    // TODO(ssid): Change to NOTREACHED after fixing crbug.com/625170.
    DLOG(ERROR)
        << "Cannot manipulate TraceLog::Enabled state from an observer.";
    return;
  }

  bool is_recording_mode_disabled =
      (enabled_modes_ & RECORDING_MODE) && (modes_to_disable & RECORDING_MODE);
  enabled_modes_ &= ~modes_to_disable;

  if (modes_to_disable & FILTERING_MODE)
    enabled_event_filters_.clear();

  if (modes_to_disable & RECORDING_MODE)
    trace_config_.Clear();

  UpdateCategoryRegistry();

  // Add metadata events and notify observers only if recording mode was
  // disabled now.
  if (!is_recording_mode_disabled)
    return;

  AddMetadataEventsWhileLocked();

  // Remove metadata events so they will not get added to a subsequent trace.
  metadata_events_.clear();

  dispatching_to_observers_ = true;
  {
    // Release trace events lock, so observers can trigger trace events.
    AutoUnlock unlock(lock_);
    AutoLock lock2(observers_lock_);
    for (auto* it : enabled_state_observers_)
      it->OnTraceLogDisabled();
    for (const auto& it : async_observers_) {
      it.second.task_runner->PostTask(
          FROM_HERE, BindOnce(&AsyncEnabledStateObserver::OnTraceLogDisabled,
                              it.second.observer));
    }
  }
  dispatching_to_observers_ = false;
}

int TraceLog::GetNumTracesRecorded() {
  AutoLock lock(lock_);
  return (enabled_modes_ & RECORDING_MODE) ? num_traces_recorded_ : -1;
}

void TraceLog::AddEnabledStateObserver(EnabledStateObserver* listener) {
  AutoLock lock(observers_lock_);
  enabled_state_observers_.push_back(listener);
}

void TraceLog::RemoveEnabledStateObserver(EnabledStateObserver* listener) {
  AutoLock lock(observers_lock_);
  enabled_state_observers_.erase(
      std::remove(enabled_state_observers_.begin(),
                  enabled_state_observers_.end(), listener),
      enabled_state_observers_.end());
}

void TraceLog::AddOwnedEnabledStateObserver(
    std::unique_ptr<EnabledStateObserver> listener) {
  AutoLock lock(observers_lock_);
  enabled_state_observers_.push_back(listener.get());
  owned_enabled_state_observer_copy_.push_back(std::move(listener));
}

bool TraceLog::HasEnabledStateObserver(EnabledStateObserver* listener) const {
  AutoLock lock(observers_lock_);
  return Contains(enabled_state_observers_, listener);
}

void TraceLog::AddAsyncEnabledStateObserver(
    WeakPtr<AsyncEnabledStateObserver> listener) {
  AutoLock lock(observers_lock_);
  async_observers_.emplace(listener.get(), RegisteredAsyncObserver(listener));
}

void TraceLog::RemoveAsyncEnabledStateObserver(
    AsyncEnabledStateObserver* listener) {
  AutoLock lock(observers_lock_);
  async_observers_.erase(listener);
}

bool TraceLog::HasAsyncEnabledStateObserver(
    AsyncEnabledStateObserver* listener) const {
  AutoLock lock(observers_lock_);
  return Contains(async_observers_, listener);
}

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

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

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_,
                                std::move(thread_shared_chunk_));
  }

  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 nullptr;

  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(RECORDING_MODE);
  }
}

// Flush() works as the following:
// 1. Flush() is called in thread A whose task runner is saved in
//    flush_task_runner_;
// 2. If thread_message_loops_ is not empty, thread A 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,
                     bool use_worker_thread) {
  FlushInternal(cb, use_worker_thread, false);
}

void TraceLog::CancelTracing(const OutputCallback& cb) {
  SetDisabled();
  FlushInternal(cb, false, true);
}

void TraceLog::FlushInternal(const TraceLog::OutputCallback& cb,
                             bool use_worker_thread,
                             bool discard_events) {
  use_worker_thread_ = use_worker_thread;
  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 gen = generation();
  // Copy of thread_task_runners_ to be used without locking.
  std::vector<scoped_refptr<SingleThreadTaskRunner>> task_runners;
  {
    AutoLock lock(lock_);
    DCHECK(!flush_task_runner_);
    flush_task_runner_ = SequencedTaskRunnerHandle::IsSet()
                             ? SequencedTaskRunnerHandle::Get()
                             : nullptr;
    DCHECK(thread_task_runners_.empty() || flush_task_runner_);
    flush_output_callback_ = cb;

    if (thread_shared_chunk_) {
      logged_events_->ReturnChunk(thread_shared_chunk_index_,
                                  std::move(thread_shared_chunk_));
    }

    for (const auto& it : thread_task_runners_)
      task_runners.push_back(it.second);
  }

  if (!task_runners.empty()) {
    for (auto& task_runner : task_runners) {
      task_runner->PostTask(
          FROM_HERE, BindOnce(&TraceLog::FlushCurrentThread, Unretained(this),
                              gen, discard_events));
    }
    flush_task_runner_->PostDelayedTask(
        FROM_HERE,
        BindOnce(&TraceLog::OnFlushTimeout, Unretained(this), gen,
                 discard_events),
        TimeDelta::FromMilliseconds(kThreadFlushTimeoutMs));
    return;
  }

  FinishFlush(gen, discard_events);
}

// Usually it runs on a different thread.
void TraceLog::ConvertTraceEventsToTraceFormat(
    std::unique_ptr<TraceBuffer> logged_events,
    const OutputCallback& flush_output_callback,
    const ArgumentFilterPredicate& argument_filter_predicate) {
  if (flush_output_callback.is_null())
    return;

  HEAP_PROFILER_SCOPED_IGNORE;
  // The callback need to be called at least once even if there is no events
  // to let the caller know the completion of flush.
  scoped_refptr<RefCountedString> json_events_str_ptr = new RefCountedString();
  const size_t kReserveCapacity = kTraceEventBufferSizeInBytes * 5 / 4;
  json_events_str_ptr->data().reserve(kReserveCapacity);
  while (const TraceBufferChunk* chunk = logged_events->NextChunk()) {
    for (size_t j = 0; j < chunk->size(); ++j) {
      size_t size = json_events_str_ptr->size();
      if (size > kTraceEventBufferSizeInBytes) {
        flush_output_callback.Run(json_events_str_ptr, true);
        json_events_str_ptr = new RefCountedString();
        json_events_str_ptr->data().reserve(kReserveCapacity);
      } else if (size) {
        json_events_str_ptr->data().append(",\n");
      }
      chunk->GetEventAt(j)->AppendAsJSON(&(json_events_str_ptr->data()),
                                         argument_filter_predicate);
    }
  }
  flush_output_callback.Run(json_events_str_ptr, false);
}

void TraceLog::FinishFlush(int generation, bool discard_events) {
  std::unique_ptr<TraceBuffer> previous_logged_events;
  OutputCallback flush_output_callback;
  ArgumentFilterPredicate argument_filter_predicate;

  if (!CheckGeneration(generation))
    return;

  {
    AutoLock lock(lock_);

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

    flush_task_runner_ = nullptr;
    flush_output_callback = flush_output_callback_;
    flush_output_callback_.Reset();

    if (trace_options() & kInternalEnableArgumentFilter) {
      // If argument filtering is activated and there is no filtering predicate,
      // use the safe default filtering predicate.
      if (argument_filter_predicate_.is_null()) {
        argument_filter_predicate =
            base::BindRepeating(&DefaultIsTraceEventArgsWhitelisted);
      } else {
        argument_filter_predicate = argument_filter_predicate_;
      }
    }
  }

  if (discard_events) {
    if (!flush_output_callback.is_null()) {
      scoped_refptr<RefCountedString> empty_result = new RefCountedString;
      flush_output_callback.Run(empty_result, false);
    }
    return;
  }

  if (use_worker_thread_) {
    base::ThreadPool::PostTask(
        FROM_HERE,
        {MayBlock(), TaskPriority::BEST_EFFORT,
         TaskShutdownBehavior::CONTINUE_ON_SHUTDOWN},
        BindOnce(&TraceLog::ConvertTraceEventsToTraceFormat,
                 std::move(previous_logged_events), flush_output_callback,
                 argument_filter_predicate));
    return;
  }

  ConvertTraceEventsToTraceFormat(std::move(previous_logged_events),
                                  flush_output_callback,
                                  argument_filter_predicate);
}

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

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

  auto on_flush_override = on_flush_override_.load(std::memory_order_relaxed);
  if (on_flush_override) {
    on_flush_override();
  }

  // Scheduler uses TRACE_EVENT macros when posting a task, which can lead
  // to acquiring a tracing lock. Given that posting a task requires grabbing
  // a scheduler lock, we need to post this task outside tracing lock to avoid
  // deadlocks.
  scoped_refptr<SequencedTaskRunner> cached_flush_task_runner;
  {
    AutoLock lock(lock_);
    cached_flush_task_runner = flush_task_runner_;
    if (!CheckGeneration(generation) || !flush_task_runner_ ||
        !thread_task_runners_.empty())
      return;
  }
  cached_flush_task_runner->PostTask(
      FROM_HERE, BindOnce(&TraceLog::FinishFlush, Unretained(this), generation,
                          discard_events));
}

void TraceLog::OnFlushTimeout(int generation, bool discard_events) {
  {
    AutoLock lock(lock_);
    if (!CheckGeneration(generation) || !flush_task_runner_) {
      // 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 (const auto& it : thread_task_runners_) {
      LOG(WARNING) << "Thread: "
                   << ThreadIdNameManager::GetInstance()->GetName(it.first);
    }
  }
  FinishFlush(generation, discard_events);
}

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

bool TraceLog::ShouldAddAfterUpdatingState(
    char phase,
    const unsigned char* category_group_enabled,
    const char* name,
    unsigned long long id,
    int thread_id,
    TraceArguments* args) {
  if (!*category_group_enabled)
    return false;

  // 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 false;

  DCHECK(name);

  // 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()->GetNameForCurrentThread();
    // 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.
    static auto* current_thread_name = new ThreadLocalPointer<const char>();
    if (new_name != current_thread_name->Get() && new_name && *new_name) {
      current_thread_name->Set(new_name);

      AutoLock thread_info_lock(thread_info_lock_);

      auto 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 = base::SplitStringPiece(
            existing_name->second, ",", base::KEEP_WHITESPACE,
            base::SPLIT_WANT_NONEMPTY);
        if (!Contains(existing_names, new_name)) {
          if (!existing_names.empty())
            existing_name->second.push_back(',');
          existing_name->second.append(new_name);
        }
      }
    }
  }

#if defined(OS_WIN)
  // This is done sooner rather than later, to avoid creating the event and
  // acquiring the lock, which is not needed for ETW as it's already threadsafe.
  if (*category_group_enabled & TraceCategory::ENABLED_FOR_ETW_EXPORT) {
    TraceEventETWExport::AddEvent(phase, category_group_enabled, name, id,
                                  args);
  }
#endif  // OS_WIN
  return true;
}

TraceEventHandle TraceLog::AddTraceEvent(
    char phase,
    const unsigned char* category_group_enabled,
    const char* name,
    const char* scope,
    unsigned long long id,
    TraceArguments* args,
    unsigned int flags) {
  int thread_id = static_cast<int>(base::PlatformThread::CurrentId());
  base::TimeTicks now = TRACE_TIME_TICKS_NOW();
  return AddTraceEventWithThreadIdAndTimestamp(
      phase, category_group_enabled, name, scope, id,
      trace_event_internal::kNoId,  // bind_id
      thread_id, now, args, flags);
}

TraceEventHandle TraceLog::AddTraceEventWithBindId(
    char phase,
    const unsigned char* category_group_enabled,
    const char* name,
    const char* scope,
    unsigned long long id,
    unsigned long long bind_id,
    TraceArguments* args,
    unsigned int flags) {
  int thread_id = static_cast<int>(base::PlatformThread::CurrentId());
  base::TimeTicks now = TRACE_TIME_TICKS_NOW();
  return AddTraceEventWithThreadIdAndTimestamp(
      phase, category_group_enabled, name, scope, id, bind_id, thread_id, now,
      args, flags | TRACE_EVENT_FLAG_HAS_CONTEXT_ID);
}

TraceEventHandle TraceLog::AddTraceEventWithProcessId(
    char phase,
    const unsigned char* category_group_enabled,
    const char* name,
    const char* scope,
    unsigned long long id,
    int process_id,
    TraceArguments* args,
    unsigned int flags) {
  base::TimeTicks now = TRACE_TIME_TICKS_NOW();
  return AddTraceEventWithThreadIdAndTimestamp(
      phase, category_group_enabled, name, scope, id,
      trace_event_internal::kNoId,  // bind_id
      process_id, now, args, flags | TRACE_EVENT_FLAG_HAS_PROCESS_ID);
}

// Handle legacy calls to AddTraceEventWithThreadIdAndTimestamp
// with kNoId as bind_id
TraceEventHandle TraceLog::AddTraceEventWithThreadIdAndTimestamp(
    char phase,
    const unsigned char* category_group_enabled,
    const char* name,
    const char* scope,
    unsigned long long id,
    int thread_id,
    const TimeTicks& timestamp,
    TraceArguments* args,
    unsigned int flags) {
  return AddTraceEventWithThreadIdAndTimestamp(
      phase, category_group_enabled, name, scope, id,
      trace_event_internal::kNoId,  // bind_id
      thread_id, timestamp, args, flags);
}

TraceEventHandle TraceLog::AddTraceEventWithThreadIdAndTimestamp(
    char phase,
    const unsigned char* category_group_enabled,
    const char* name,
    const char* scope,
    unsigned long long id,
    unsigned long long bind_id,
    int thread_id,
    const TimeTicks& timestamp,
    TraceArguments* args,
    unsigned int flags) NO_THREAD_SAFETY_ANALYSIS {
  TraceEventHandle handle = {0, 0, 0};
  if (!ShouldAddAfterUpdatingState(phase, category_group_enabled, name, id,
                                   thread_id, args)) {
    return handle;
  }
  DCHECK(!timestamp.is_null());

  AutoThreadLocalBoolean thread_is_in_trace_event(&thread_is_in_trace_event_);

  // Flow bind_ids don't have scopes, so we need to mangle in-process ones to
  // avoid collisions.
  bool has_flow =
      flags & (TRACE_EVENT_FLAG_FLOW_OUT | TRACE_EVENT_FLAG_FLOW_IN);
  if (has_flow && (flags & TRACE_EVENT_FLAG_HAS_LOCAL_ID))
    bind_id = MangleEventId(bind_id);

  TimeTicks offset_event_timestamp = OffsetTimestamp(timestamp);
  ThreadTicks thread_now = ThreadNow();
  ThreadInstructionCount thread_instruction_now = ThreadInstructionNow();

  ThreadLocalEventBuffer* thread_local_event_buffer = nullptr;
  if (*category_group_enabled & RECORDING_MODE) {
    // |thread_local_event_buffer_| can be null if the current thread doesn't
    // have a message loop or the message loop is blocked.
    InitializeThreadLocalEventBufferIfSupported();
    thread_local_event_buffer = thread_local_event_buffer_.Get();
  }

  if (*category_group_enabled & RECORDING_MODE) {
    auto trace_event_override =
        add_trace_event_override_.load(std::memory_order_relaxed);
    if (trace_event_override) {
      TraceEvent new_trace_event(
          thread_id, offset_event_timestamp, thread_now, thread_instruction_now,
          phase, category_group_enabled, name, scope, id, bind_id, args, flags);

      trace_event_override(
          &new_trace_event,
          /*thread_will_flush=*/thread_local_event_buffer != nullptr, &handle);
      return handle;
    }
  }

  std::string console_message;
  std::unique_ptr<TraceEvent> filtered_trace_event;
  bool disabled_by_filters = false;
  if (*category_group_enabled & TraceCategory::ENABLED_FOR_FILTERING) {
    auto new_trace_event = std::make_unique<TraceEvent>(
        thread_id, offset_event_timestamp, thread_now, thread_instruction_now,
        phase, category_group_enabled, name, scope, id, bind_id, args, flags);

    disabled_by_filters = true;
    ForEachCategoryFilter(
        category_group_enabled, [&new_trace_event, &disabled_by_filters](
                                    TraceEventFilter* trace_event_filter) {
          if (trace_event_filter->FilterTraceEvent(*new_trace_event))
            disabled_by_filters = false;
        });
    if (!disabled_by_filters)
      filtered_trace_event = std::move(new_trace_event);
  }

  // If enabled for recording, the event should be added only if one of the
  // filters indicates or category is not enabled for filtering.
  if ((*category_group_enabled & TraceCategory::ENABLED_FOR_RECORDING) &&
      !disabled_by_filters) {
    OptionalAutoLock lock(&lock_);

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

    // NO_THREAD_SAFETY_ANALYSIS: Conditional locking above.
    if (trace_event) {
      if (filtered_trace_event) {
        *trace_event = std::move(*filtered_trace_event);
      } else {
        trace_event->Reset(thread_id, offset_event_timestamp, thread_now,
                           thread_instruction_now, phase,
                           category_group_enabled, name, scope, id, bind_id,
                           args, 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.empty())
    LOG(ERROR) << console_message;

  return handle;
}

void TraceLog::AddMetadataEvent(const unsigned char* category_group_enabled,
                                const char* name,
                                TraceArguments* args,
                                unsigned int flags) {
  HEAP_PROFILER_SCOPED_IGNORE;
  int thread_id = static_cast<int>(base::PlatformThread::CurrentId());
  ThreadTicks thread_now = ThreadNow();
  TimeTicks now = OffsetNow();
  ThreadInstructionCount thread_instruction_now = ThreadInstructionNow();
  AutoLock lock(lock_);
  auto trace_event = std::make_unique<TraceEvent>(
      thread_id, now, thread_now, thread_instruction_now,
      TRACE_EVENT_PHASE_METADATA, category_group_enabled, name,
      trace_event_internal::kGlobalScope,  // scope
      trace_event_internal::kNoId,         // id
      trace_event_internal::kNoId,         // bind_id
      args, flags);
  metadata_events_.push_back(std::move(trace_event));
}

// 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) {
  HEAP_PROFILER_SCOPED_IGNORE;
  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()) {
    size_t next_color = (thread_colors_.size() % 6) + 1;
    thread_colors_[thread_name] = next_color;
  }

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

  size_t depth = 0;
  auto it = thread_event_start_times_.find(thread_id);
  if (it != thread_event_start_times_.end())
    depth = it->second.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::EndFilteredEvent(const unsigned char* category_group_enabled,
                                const char* name,
                                TraceEventHandle handle) {
  const char* category_name = GetCategoryGroupName(category_group_enabled);
  ForEachCategoryFilter(
      category_group_enabled,
      [name, category_name](TraceEventFilter* trace_event_filter) {
        trace_event_filter->EndEvent(category_name, name);
      });
}

void TraceLog::UpdateTraceEventDuration(
    const unsigned char* category_group_enabled,
    const char* name,
    TraceEventHandle handle) {
  char category_group_enabled_local = *category_group_enabled;
  if (!category_group_enabled_local)
    return;

  UpdateTraceEventDurationExplicit(
      category_group_enabled, name, handle,
      static_cast<int>(base::PlatformThread::CurrentId()),
      /*explicit_timestamps=*/false, OffsetNow(), ThreadNow(),
      ThreadInstructionNow());
}

void TraceLog::UpdateTraceEventDurationExplicit(
    const unsigned char* category_group_enabled,
    const char* name,
    TraceEventHandle handle,
    int thread_id,
    bool explicit_timestamps,
    const TimeTicks& now,
    const ThreadTicks& thread_now,
    ThreadInstructionCount thread_instruction_now) {
  char category_group_enabled_local = *category_group_enabled;
  if (!category_group_enabled_local)
    return;

  // 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_);

#if defined(OS_WIN)
  // Generate an ETW event that marks the end of a complete event.
  if (category_group_enabled_local & TraceCategory::ENABLED_FOR_ETW_EXPORT)
    TraceEventETWExport::AddCompleteEndEvent(name);
#endif  // OS_WIN

  if (category_group_enabled_local & TraceCategory::ENABLED_FOR_RECORDING) {
    auto update_duration_override =
        update_duration_override_.load(std::memory_order_relaxed);
    if (update_duration_override) {
      update_duration_override(category_group_enabled, name, handle, thread_id,
                               explicit_timestamps, now, thread_now,
                               thread_instruction_now);
      return;
    }
  }

  std::string console_message;
  if (category_group_enabled_local & TraceCategory::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, thread_instruction_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.empty())
    LOG(ERROR) << console_message;

  if (category_group_enabled_local & TraceCategory::ENABLED_FOR_FILTERING)
    EndFilteredEvent(category_group_enabled, name, handle);
}

uint64_t TraceLog::MangleEventId(uint64_t id) {
  return id ^ process_id_hash_;
}

template <typename T>
void TraceLog::AddMetadataEventWhileLocked(int thread_id,
                                           const char* metadata_name,
                                           const char* arg_name,
                                           const T& value) {
  auto trace_event_override =
      add_trace_event_override_.load(std::memory_order_relaxed);
  if (trace_event_override) {
    TraceEvent trace_event;
    InitializeMetadataEvent(&trace_event, thread_id, metadata_name, arg_name,
                            value);
    trace_event_override(&trace_event, /*thread_will_flush=*/true, nullptr);
  } else {
    InitializeMetadataEvent(
        AddEventToThreadSharedChunkWhileLocked(nullptr, false), thread_id,
        metadata_name, arg_name, value);
  }
}

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

  auto trace_event_override =
      add_trace_event_override_.load(std::memory_order_relaxed);

  // Move metadata added by |AddMetadataEvent| into the trace log.
  if (trace_event_override) {
    while (!metadata_events_.empty()) {
      trace_event_override(metadata_events_.back().get(),
                           /*thread_will_flush=*/true, nullptr);
      metadata_events_.pop_back();
    }
  } else {
    while (!metadata_events_.empty()) {
      TraceEvent* event =
          AddEventToThreadSharedChunkWhileLocked(nullptr, false);
      *event = std::move(*metadata_events_.back());
      metadata_events_.pop_back();
    }
  }

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

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

  if (!process_name_.empty()) {
    AddMetadataEventWhileLocked(current_thread_id, "process_name", "name",
                                process_name_);
  }

  TimeDelta process_uptime = TRACE_TIME_NOW() - process_creation_time_;
  AddMetadataEventWhileLocked(current_thread_id, "process_uptime_seconds",
                              "uptime", process_uptime.InSeconds());

#if defined(OS_ANDROID)
  AddMetadataEventWhileLocked(current_thread_id, "chrome_library_address",
                              "start_address",
                              base::StringPrintf("%p", &__executable_start));
  base::debug::ElfBuildIdBuffer build_id;
  size_t build_id_length =
      base::debug::ReadElfBuildId(&__executable_start, true, build_id);
  if (build_id_length > 0) {
    AddMetadataEventWhileLocked(current_thread_id, "chrome_library_module",
                                "id", std::string(build_id));
  }
#endif

  if (!process_labels_.empty()) {
    std::vector<base::StringPiece> labels;
    for (const auto& it : process_labels_)
      labels.push_back(it.second);
    AddMetadataEventWhileLocked(current_thread_id, "process_labels", "labels",
                                base::JoinString(labels, ","));
  }

  // Thread sort indices.
  for (const auto& it : thread_sort_indices_) {
    if (it.second == 0)
      continue;
    AddMetadataEventWhileLocked(it.first, "thread_sort_index", "sort_index",
                                it.second);
  }

  // TODO(ssid): Stop emitting and tracking thread names when perfetto is
  // enabled and after crbug/978093 if fixed. The JSON exporter will emit thread
  // names from thread descriptors.
  AutoLock thread_info_lock(thread_info_lock_);
  for (const auto& it : thread_names_) {
    if (it.second.empty())
      continue;
    AddMetadataEventWhileLocked(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()) {
    AddMetadataEventWhileLocked(current_thread_id, "trace_buffer_overflowed",
                                "overflowed_at_ts",
                                buffer_limit_reached_timestamp_);
  }
}

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

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

  DCHECK(handle.chunk_seq);
  DCHECK(handle.chunk_index <= TraceBufferChunk::kMaxChunkIndex);
  DCHECK(handle.event_index <= TraceBufferChunk::kTraceBufferChunkSize - 1);

  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.
  // NO_THREAD_SAFETY_ANALYSIS: runtime-dependent locking here.
  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)
               : nullptr;
  }

  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.
  const unsigned long long kOffsetBasis = 14695981039346656037ull;
  const unsigned long long kFnvPrime = 1099511628211ull;
  const unsigned long long pid = static_cast<unsigned long long>(process_id_);
  process_id_hash_ = (kOffsetBasis ^ pid) * kFnvPrime;
}

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

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_);
  process_labels_.erase(label_id);
}

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_observers_.size();
}

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

TraceBuffer* TraceLog::CreateTraceBuffer() {
  HEAP_PROFILER_SCOPED_IGNORE;
  InternalTraceOptions options = trace_options();
  const size_t config_buffer_chunks =
      trace_config_.GetTraceBufferSizeInEvents() / kTraceBufferChunkSize;
  if (options & kInternalRecordContinuously) {
    return TraceBuffer::CreateTraceBufferRingBuffer(
        config_buffer_chunks > 0 ? config_buffer_chunks
                                 : kTraceEventRingBufferChunks);
  }
  if (options & kInternalEchoToConsole) {
    return TraceBuffer::CreateTraceBufferRingBuffer(
        config_buffer_chunks > 0 ? config_buffer_chunks
                                 : kEchoToConsoleTraceEventBufferChunks);
  }
  if (options & kInternalRecordAsMuchAsPossible) {
    return TraceBuffer::CreateTraceBufferVectorOfSize(
        config_buffer_chunks > 0 ? config_buffer_chunks
                                 : kTraceEventVectorBigBufferChunks);
  }
  return TraceBuffer::CreateTraceBufferVectorOfSize(
      config_buffer_chunks > 0 ? config_buffer_chunks
                               : kTraceEventVectorBufferChunks);
}

#if defined(OS_WIN)
void TraceLog::UpdateETWCategoryGroupEnabledFlags() {
  // Go through each category and set/clear the ETW bit depending on whether the
  // category is enabled.
  for (TraceCategory& category : CategoryRegistry::GetAllCategories()) {
    if (base::trace_event::TraceEventETWExport::IsCategoryGroupEnabled(
            category.name())) {
      category.set_state_flag(TraceCategory::ENABLED_FOR_ETW_EXPORT);
    } else {
      category.clear_state_flag(TraceCategory::ENABLED_FOR_ETW_EXPORT);
    }
  }
}
#endif  // defined(OS_WIN)

void TraceLog::SetTraceBufferForTesting(
    std::unique_ptr<TraceBuffer> trace_buffer) {
  AutoLock lock(lock_);
  logged_events_ = std::move(trace_buffer);
}

void ConvertableToTraceFormat::EstimateTraceMemoryOverhead(
    TraceEventMemoryOverhead* overhead) {
  overhead->Add(TraceEventMemoryOverhead::kConvertableToTraceFormat,
                sizeof(*this));
}

}  // namespace trace_event
}  // namespace base

namespace trace_event_internal {

base::trace_event::TraceEventHandle AddTraceEvent(
    char phase,
    const unsigned char* category_group_enabled,
    const char* name,
    const char* scope,
    unsigned long long id,
    base::trace_event::TraceArguments* args,
    unsigned int flags) {
  return base::trace_event::TraceLog::GetInstance()->AddTraceEvent(
      phase, category_group_enabled, name, scope, id, args, flags);
}

base::trace_event::TraceEventHandle AddTraceEventWithBindId(
    char phase,
    const unsigned char* category_group_enabled,
    const char* name,
    const char* scope,
    unsigned long long id,
    unsigned long long bind_id,
    base::trace_event::TraceArguments* args,
    unsigned int flags) {
  return base::trace_event::TraceLog::GetInstance()->AddTraceEventWithBindId(
      phase, category_group_enabled, name, scope, id, bind_id, args, flags);
}

base::trace_event::TraceEventHandle AddTraceEventWithProcessId(
    char phase,
    const unsigned char* category_group_enabled,
    const char* name,
    const char* scope,
    unsigned long long id,
    int process_id,
    base::trace_event::TraceArguments* args,
    unsigned int flags) {
  return base::trace_event::TraceLog::GetInstance()->AddTraceEventWithProcessId(
      phase, category_group_enabled, name, scope, id, process_id, args, flags);
}

base::trace_event::TraceEventHandle AddTraceEventWithThreadIdAndTimestamp(
    char phase,
    const unsigned char* category_group_enabled,
    const char* name,
    const char* scope,
    unsigned long long id,
    int thread_id,
    const base::TimeTicks& timestamp,
    base::trace_event::TraceArguments* args,
    unsigned int flags) {
  return base::trace_event::TraceLog::GetInstance()
      ->AddTraceEventWithThreadIdAndTimestamp(phase, category_group_enabled,
                                              name, scope, id, thread_id,
                                              timestamp, args, flags);
}

base::trace_event::TraceEventHandle AddTraceEventWithThreadIdAndTimestamp(
    char phase,
    const unsigned char* category_group_enabled,
    const char* name,
    const char* scope,
    unsigned long long id,
    unsigned long long bind_id,
    int thread_id,
    const base::TimeTicks& timestamp,
    base::trace_event::TraceArguments* args,
    unsigned int flags) {
  return base::trace_event::TraceLog::GetInstance()
      ->AddTraceEventWithThreadIdAndTimestamp(
          phase, category_group_enabled, name, scope, id, bind_id, thread_id,
          timestamp, args, flags);
}

void AddMetadataEvent(const unsigned char* category_group_enabled,
                      const char* name,
                      base::trace_event::TraceArguments* args,
                      unsigned int flags) {
  return base::trace_event::TraceLog::GetInstance()->AddMetadataEvent(
      category_group_enabled, name, args, flags);
}

int GetNumTracesRecorded() {
  return base::trace_event::TraceLog::GetInstance()->GetNumTracesRecorded();
}

void UpdateTraceEventDuration(const unsigned char* category_group_enabled,
                              const char* name,
                              base::trace_event::TraceEventHandle handle) {
  return base::trace_event::TraceLog::GetInstance()->UpdateTraceEventDuration(
      category_group_enabled, name, handle);
}

void UpdateTraceEventDurationExplicit(
    const unsigned char* category_group_enabled,
    const char* name,
    base::trace_event::TraceEventHandle handle,
    int thread_id,
    bool explicit_timestamps,
    const base::TimeTicks& now,
    const base::ThreadTicks& thread_now,
    base::trace_event::ThreadInstructionCount thread_instruction_now) {
  return base::trace_event::TraceLog::GetInstance()
      ->UpdateTraceEventDurationExplicit(category_group_enabled, name, handle,
                                         thread_id, explicit_timestamps, now,
                                         thread_now, thread_instruction_now);
}

ScopedTraceBinaryEfficient::ScopedTraceBinaryEfficient(
    const char* category_group,
    const char* name) {
  // The single atom works because for now the category_group can only be "gpu".
  DCHECK_EQ(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::kGlobalScope,                   // scope
            trace_event_internal::kNoId,                          // id
            static_cast<int>(base::PlatformThread::CurrentId()),  // thread_id
            TRACE_TIME_TICKS_NOW(), nullptr, 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