log.cc

// Copyright 2011 the V8 project 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 "src/log.h"

#include <cstdarg>
#include <memory>
#include <sstream>

#include "src/bailout-reason.h"
#include "src/base/platform/platform.h"
#include "src/bootstrapper.h"
#include "src/code-stubs.h"
#include "src/counters.h"
#include "src/deoptimizer.h"
#include "src/global-handles.h"
#include "src/interpreter/bytecodes.h"
#include "src/interpreter/interpreter.h"
#include "src/libsampler/sampler.h"
#include "src/log-inl.h"
#include "src/log-utils.h"
#include "src/macro-assembler.h"
#include "src/perf-jit.h"
#include "src/profiler/tick-sample.h"
#include "src/runtime-profiler.h"
#include "src/source-position-table.h"
#include "src/string-stream.h"
#include "src/tracing/tracing-category-observer.h"
#include "src/vm-state-inl.h"

namespace v8 {
namespace internal {

#define DECLARE_EVENT(ignore1, name) name,
static const char* kLogEventsNames[CodeEventListener::NUMBER_OF_LOG_EVENTS] = {
    LOG_EVENTS_AND_TAGS_LIST(DECLARE_EVENT)};
#undef DECLARE_EVENT

static const char* ComputeMarker(SharedFunctionInfo* shared,
                                 AbstractCode* code) {
  switch (code->kind()) {
    case AbstractCode::FUNCTION:
    case AbstractCode::INTERPRETED_FUNCTION:
      return shared->optimization_disabled() ? "" : "~";
    case AbstractCode::OPTIMIZED_FUNCTION:
      return "*";
    default:
      return "";
  }
}


class CodeEventLogger::NameBuffer {
 public:
  NameBuffer() { Reset(); }

  void Reset() {
    utf8_pos_ = 0;
  }

  void Init(CodeEventListener::LogEventsAndTags tag) {
    Reset();
    AppendBytes(kLogEventsNames[tag]);
    AppendByte(':');
  }

  void AppendName(Name* name) {
    if (name->IsString()) {
      AppendString(String::cast(name));
    } else {
      Symbol* symbol = Symbol::cast(name);
      AppendBytes("symbol(");
      if (!symbol->name()->IsUndefined(symbol->GetIsolate())) {
        AppendBytes("\"");
        AppendString(String::cast(symbol->name()));
        AppendBytes("\" ");
      }
      AppendBytes("hash ");
      AppendHex(symbol->Hash());
      AppendByte(')');
    }
  }

  void AppendString(String* str) {
    if (str == NULL) return;
    int uc16_length = Min(str->length(), kUtf16BufferSize);
    String::WriteToFlat(str, utf16_buffer, 0, uc16_length);
    int previous = unibrow::Utf16::kNoPreviousCharacter;
    for (int i = 0; i < uc16_length && utf8_pos_ < kUtf8BufferSize; ++i) {
      uc16 c = utf16_buffer[i];
      if (c <= unibrow::Utf8::kMaxOneByteChar) {
        utf8_buffer_[utf8_pos_++] = static_cast<char>(c);
      } else {
        int char_length = unibrow::Utf8::Length(c, previous);
        if (utf8_pos_ + char_length > kUtf8BufferSize) break;
        unibrow::Utf8::Encode(utf8_buffer_ + utf8_pos_, c, previous);
        utf8_pos_ += char_length;
      }
      previous = c;
    }
  }

  void AppendBytes(const char* bytes, int size) {
    size = Min(size, kUtf8BufferSize - utf8_pos_);
    MemCopy(utf8_buffer_ + utf8_pos_, bytes, size);
    utf8_pos_ += size;
  }

  void AppendBytes(const char* bytes) {
    AppendBytes(bytes, StrLength(bytes));
  }

  void AppendByte(char c) {
    if (utf8_pos_ >= kUtf8BufferSize) return;
    utf8_buffer_[utf8_pos_++] = c;
  }

  void AppendInt(int n) {
    int space = kUtf8BufferSize - utf8_pos_;
    if (space <= 0) return;
    Vector<char> buffer(utf8_buffer_ + utf8_pos_, space);
    int size = SNPrintF(buffer, "%d", n);
    if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) {
      utf8_pos_ += size;
    }
  }

  void AppendHex(uint32_t n) {
    int space = kUtf8BufferSize - utf8_pos_;
    if (space <= 0) return;
    Vector<char> buffer(utf8_buffer_ + utf8_pos_, space);
    int size = SNPrintF(buffer, "%x", n);
    if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) {
      utf8_pos_ += size;
    }
  }

  const char* get() { return utf8_buffer_; }
  int size() const { return utf8_pos_; }

 private:
  static const int kUtf8BufferSize = 512;
  static const int kUtf16BufferSize = kUtf8BufferSize;

  int utf8_pos_;
  char utf8_buffer_[kUtf8BufferSize];
  uc16 utf16_buffer[kUtf16BufferSize];
};


CodeEventLogger::CodeEventLogger() : name_buffer_(new NameBuffer) { }

CodeEventLogger::~CodeEventLogger() { delete name_buffer_; }

void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
                                      AbstractCode* code, const char* comment) {
  name_buffer_->Init(tag);
  name_buffer_->AppendBytes(comment);
  LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
}

void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
                                      AbstractCode* code, Name* name) {
  name_buffer_->Init(tag);
  name_buffer_->AppendName(name);
  LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
}

void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
                                      AbstractCode* code,
                                      SharedFunctionInfo* shared, Name* name) {
  name_buffer_->Init(tag);
  name_buffer_->AppendBytes(ComputeMarker(shared, code));
  name_buffer_->AppendName(name);
  LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size());
}

void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
                                      AbstractCode* code,
                                      SharedFunctionInfo* shared, Name* source,
                                      int line, int column) {
  name_buffer_->Init(tag);
  name_buffer_->AppendBytes(ComputeMarker(shared, code));
  name_buffer_->AppendString(shared->DebugName());
  name_buffer_->AppendByte(' ');
  if (source->IsString()) {
    name_buffer_->AppendString(String::cast(source));
  } else {
    name_buffer_->AppendBytes("symbol(hash ");
    name_buffer_->AppendHex(Name::cast(source)->Hash());
    name_buffer_->AppendByte(')');
  }
  name_buffer_->AppendByte(':');
  name_buffer_->AppendInt(line);
  LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size());
}

void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
                                      AbstractCode* code, int args_count) {
  name_buffer_->Init(tag);
  name_buffer_->AppendInt(args_count);
  LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
}

void CodeEventLogger::RegExpCodeCreateEvent(AbstractCode* code,
                                            String* source) {
  name_buffer_->Init(CodeEventListener::REG_EXP_TAG);
  name_buffer_->AppendString(source);
  LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
}


// Linux perf tool logging support
class PerfBasicLogger : public CodeEventLogger {
 public:
  PerfBasicLogger();
  ~PerfBasicLogger() override;

  void CodeMoveEvent(AbstractCode* from, AbstractCode* to) override {}
  void CodeDisableOptEvent(AbstractCode* code,
                           SharedFunctionInfo* shared) override {}

 private:
  void LogRecordedBuffer(AbstractCode* code, SharedFunctionInfo* shared,
                         const char* name, int length) override;

  // Extension added to V8 log file name to get the low-level log name.
  static const char kFilenameFormatString[];
  static const int kFilenameBufferPadding;

  FILE* perf_output_handle_;
};

const char PerfBasicLogger::kFilenameFormatString[] = "/tmp/perf-%d.map";
// Extra space for the PID in the filename
const int PerfBasicLogger::kFilenameBufferPadding = 16;

PerfBasicLogger::PerfBasicLogger()
    : perf_output_handle_(NULL) {
  // Open the perf JIT dump file.
  int bufferSize = sizeof(kFilenameFormatString) + kFilenameBufferPadding;
  ScopedVector<char> perf_dump_name(bufferSize);
  int size = SNPrintF(
      perf_dump_name,
      kFilenameFormatString,
      base::OS::GetCurrentProcessId());
  CHECK_NE(size, -1);
  perf_output_handle_ =
      base::OS::FOpen(perf_dump_name.start(), base::OS::LogFileOpenMode);
  CHECK_NOT_NULL(perf_output_handle_);
  setvbuf(perf_output_handle_, NULL, _IOLBF, 0);
}


PerfBasicLogger::~PerfBasicLogger() {
  fclose(perf_output_handle_);
  perf_output_handle_ = NULL;
}

void PerfBasicLogger::LogRecordedBuffer(AbstractCode* code, SharedFunctionInfo*,
                                        const char* name, int length) {
  if (FLAG_perf_basic_prof_only_functions &&
      (code->kind() != AbstractCode::FUNCTION &&
       code->kind() != AbstractCode::INTERPRETED_FUNCTION &&
       code->kind() != AbstractCode::OPTIMIZED_FUNCTION)) {
    return;
  }

  // Linux perf expects hex literals without a leading 0x, while some
  // implementations of printf might prepend one when using the %p format
  // for pointers, leading to wrongly formatted JIT symbols maps.
  //
  // Instead, we use V8PRIxPTR format string and cast pointer to uintpr_t,
  // so that we have control over the exact output format.
  base::OS::FPrint(perf_output_handle_, "%" V8PRIxPTR " %x %.*s\n",
                   reinterpret_cast<uintptr_t>(code->instruction_start()),
                   code->instruction_size(), length, name);
}

// Low-level logging support.
#define LL_LOG(Call) if (ll_logger_) ll_logger_->Call;

class LowLevelLogger : public CodeEventLogger {
 public:
  explicit LowLevelLogger(const char* file_name);
  ~LowLevelLogger() override;

  void CodeMoveEvent(AbstractCode* from, AbstractCode* to) override;
  void CodeDisableOptEvent(AbstractCode* code,
                           SharedFunctionInfo* shared) override {}
  void SnapshotPositionEvent(HeapObject* obj, int pos);
  void CodeMovingGCEvent() override;

 private:
  void LogRecordedBuffer(AbstractCode* code, SharedFunctionInfo* shared,
                         const char* name, int length) override;

  // Low-level profiling event structures.
  struct CodeCreateStruct {
    static const char kTag = 'C';

    int32_t name_size;
    Address code_address;
    int32_t code_size;
  };


  struct CodeMoveStruct {
    static const char kTag = 'M';

    Address from_address;
    Address to_address;
  };


  static const char kCodeMovingGCTag = 'G';


  // Extension added to V8 log file name to get the low-level log name.
  static const char kLogExt[];

  void LogCodeInfo();
  void LogWriteBytes(const char* bytes, int size);

  template <typename T>
  void LogWriteStruct(const T& s) {
    char tag = T::kTag;
    LogWriteBytes(reinterpret_cast<const char*>(&tag), sizeof(tag));
    LogWriteBytes(reinterpret_cast<const char*>(&s), sizeof(s));
  }

  FILE* ll_output_handle_;
};

const char LowLevelLogger::kLogExt[] = ".ll";

LowLevelLogger::LowLevelLogger(const char* name)
    : ll_output_handle_(NULL) {
  // Open the low-level log file.
  size_t len = strlen(name);
  ScopedVector<char> ll_name(static_cast<int>(len + sizeof(kLogExt)));
  MemCopy(ll_name.start(), name, len);
  MemCopy(ll_name.start() + len, kLogExt, sizeof(kLogExt));
  ll_output_handle_ =
      base::OS::FOpen(ll_name.start(), base::OS::LogFileOpenMode);
  setvbuf(ll_output_handle_, NULL, _IOLBF, 0);

  LogCodeInfo();
}


LowLevelLogger::~LowLevelLogger() {
  fclose(ll_output_handle_);
  ll_output_handle_ = NULL;
}


void LowLevelLogger::LogCodeInfo() {
#if V8_TARGET_ARCH_IA32
  const char arch[] = "ia32";
#elif V8_TARGET_ARCH_X64 && V8_TARGET_ARCH_64_BIT
  const char arch[] = "x64";
#elif V8_TARGET_ARCH_X64 && V8_TARGET_ARCH_32_BIT
  const char arch[] = "x32";
#elif V8_TARGET_ARCH_ARM
  const char arch[] = "arm";
#elif V8_TARGET_ARCH_PPC
  const char arch[] = "ppc";
#elif V8_TARGET_ARCH_MIPS
  const char arch[] = "mips";
#elif V8_TARGET_ARCH_ARM64
  const char arch[] = "arm64";
#elif V8_TARGET_ARCH_S390
  const char arch[] = "s390";
#else
  const char arch[] = "unknown";
#endif
  LogWriteBytes(arch, sizeof(arch));
}

void LowLevelLogger::LogRecordedBuffer(AbstractCode* code, SharedFunctionInfo*,
                                       const char* name, int length) {
  CodeCreateStruct event;
  event.name_size = length;
  event.code_address = code->instruction_start();
  event.code_size = code->instruction_size();
  LogWriteStruct(event);
  LogWriteBytes(name, length);
  LogWriteBytes(
      reinterpret_cast<const char*>(code->instruction_start()),
      code->instruction_size());
}

void LowLevelLogger::CodeMoveEvent(AbstractCode* from, AbstractCode* to) {
  CodeMoveStruct event;
  event.from_address = from->instruction_start();
  event.to_address = to->instruction_start();
  LogWriteStruct(event);
}


void LowLevelLogger::LogWriteBytes(const char* bytes, int size) {
  size_t rv = fwrite(bytes, 1, size, ll_output_handle_);
  DCHECK(static_cast<size_t>(size) == rv);
  USE(rv);
}


void LowLevelLogger::CodeMovingGCEvent() {
  const char tag = kCodeMovingGCTag;

  LogWriteBytes(&tag, sizeof(tag));
}

class JitLogger : public CodeEventLogger {
 public:
  explicit JitLogger(JitCodeEventHandler code_event_handler);

  void CodeMoveEvent(AbstractCode* from, AbstractCode* to) override;
  void CodeDisableOptEvent(AbstractCode* code,
                           SharedFunctionInfo* shared) override {}
  void AddCodeLinePosInfoEvent(void* jit_handler_data, int pc_offset,
                               int position,
                               JitCodeEvent::PositionType position_type);

  void* StartCodePosInfoEvent();
  void EndCodePosInfoEvent(AbstractCode* code, void* jit_handler_data);

 private:
  void LogRecordedBuffer(AbstractCode* code, SharedFunctionInfo* shared,
                         const char* name, int length) override;

  JitCodeEventHandler code_event_handler_;
  base::Mutex logger_mutex_;
};


JitLogger::JitLogger(JitCodeEventHandler code_event_handler)
    : code_event_handler_(code_event_handler) {
}

void JitLogger::LogRecordedBuffer(AbstractCode* code,
                                  SharedFunctionInfo* shared, const char* name,
                                  int length) {
  JitCodeEvent event;
  memset(&event, 0, sizeof(event));
  event.type = JitCodeEvent::CODE_ADDED;
  event.code_start = code->instruction_start();
  event.code_len = code->instruction_size();
  Handle<SharedFunctionInfo> shared_function_handle;
  if (shared && shared->script()->IsScript()) {
    shared_function_handle = Handle<SharedFunctionInfo>(shared);
  }
  event.script = ToApiHandle<v8::UnboundScript>(shared_function_handle);
  event.name.str = name;
  event.name.len = length;
  code_event_handler_(&event);
}

void JitLogger::CodeMoveEvent(AbstractCode* from, AbstractCode* to) {
  base::LockGuard<base::Mutex> guard(&logger_mutex_);

  JitCodeEvent event;
  event.type = JitCodeEvent::CODE_MOVED;
  event.code_start = reinterpret_cast<void*>(from->instruction_start());
  event.code_len = from->instruction_size();
  event.new_code_start = reinterpret_cast<void*>(to->instruction_start());

  code_event_handler_(&event);
}

void JitLogger::AddCodeLinePosInfoEvent(
    void* jit_handler_data,
    int pc_offset,
    int position,
    JitCodeEvent::PositionType position_type) {
  JitCodeEvent event;
  memset(&event, 0, sizeof(event));
  event.type = JitCodeEvent::CODE_ADD_LINE_POS_INFO;
  event.user_data = jit_handler_data;
  event.line_info.offset = pc_offset;
  event.line_info.pos = position;
  event.line_info.position_type = position_type;

  code_event_handler_(&event);
}


void* JitLogger::StartCodePosInfoEvent() {
  JitCodeEvent event;
  memset(&event, 0, sizeof(event));
  event.type = JitCodeEvent::CODE_START_LINE_INFO_RECORDING;

  code_event_handler_(&event);
  return event.user_data;
}

void JitLogger::EndCodePosInfoEvent(AbstractCode* code,
                                    void* jit_handler_data) {
  JitCodeEvent event;
  memset(&event, 0, sizeof(event));
  event.type = JitCodeEvent::CODE_END_LINE_INFO_RECORDING;
  event.code_start = code->instruction_start();
  event.user_data = jit_handler_data;

  code_event_handler_(&event);
}


// TODO(lpy): Keeping sampling thread inside V8 is a workaround currently,
// the reason is to reduce code duplication during migration to sampler library,
// sampling thread, as well as the sampler, will be moved to D8 eventually.
class SamplingThread : public base::Thread {
 public:
  static const int kSamplingThreadStackSize = 64 * KB;

  SamplingThread(sampler::Sampler* sampler, int interval_microseconds)
      : base::Thread(
            base::Thread::Options("SamplingThread", kSamplingThreadStackSize)),
        sampler_(sampler),
        interval_microseconds_(interval_microseconds) {}
  void Run() override {
    while (sampler_->IsProfiling()) {
      sampler_->DoSample();
      base::OS::Sleep(
          base::TimeDelta::FromMicroseconds(interval_microseconds_));
    }
  }

 private:
  sampler::Sampler* sampler_;
  const int interval_microseconds_;
};


// The Profiler samples pc and sp values for the main thread.
// Each sample is appended to a circular buffer.
// An independent thread removes data and writes it to the log.
// This design minimizes the time spent in the sampler.
//
class Profiler: public base::Thread {
 public:
  explicit Profiler(Isolate* isolate);
  void Engage();
  void Disengage();

  // Inserts collected profiling data into buffer.
  void Insert(v8::TickSample* sample) {
    if (paused_)
      return;

    if (Succ(head_) == static_cast<int>(base::Relaxed_Load(&tail_))) {
      overflow_ = true;
    } else {
      buffer_[head_] = *sample;
      head_ = Succ(head_);
      buffer_semaphore_.Signal();  // Tell we have an element.
    }
  }

  virtual void Run();

  // Pause and Resume TickSample data collection.
  void pause() { paused_ = true; }
  void resume() { paused_ = false; }

 private:
  // Waits for a signal and removes profiling data.
  bool Remove(v8::TickSample* sample) {
    buffer_semaphore_.Wait();  // Wait for an element.
    *sample = buffer_[base::Relaxed_Load(&tail_)];
    bool result = overflow_;
    base::Relaxed_Store(
        &tail_, static_cast<base::Atomic32>(Succ(base::Relaxed_Load(&tail_))));
    overflow_ = false;
    return result;
  }

  // Returns the next index in the cyclic buffer.
  int Succ(int index) { return (index + 1) % kBufferSize; }

  Isolate* isolate_;
  // Cyclic buffer for communicating profiling samples
  // between the signal handler and the worker thread.
  static const int kBufferSize = 128;
  v8::TickSample buffer_[kBufferSize];  // Buffer storage.
  int head_;  // Index to the buffer head.
  base::Atomic32 tail_;             // Index to the buffer tail.
  bool overflow_;  // Tell whether a buffer overflow has occurred.
  // Sempahore used for buffer synchronization.
  base::Semaphore buffer_semaphore_;

  // Tells whether profiler is engaged, that is, processing thread is stated.
  bool engaged_;

  // Tells whether worker thread should continue running.
  base::Atomic32 running_;

  // Tells whether we are currently recording tick samples.
  bool paused_;
};


//
// Ticker used to provide ticks to the profiler and the sliding state
// window.
//
class Ticker: public sampler::Sampler {
 public:
  Ticker(Isolate* isolate, int interval_microseconds)
      : sampler::Sampler(reinterpret_cast<v8::Isolate*>(isolate)),
        profiler_(nullptr),
        sampling_thread_(new SamplingThread(this, interval_microseconds)) {}

  ~Ticker() {
    if (IsActive()) Stop();
    delete sampling_thread_;
  }

  void SetProfiler(Profiler* profiler) {
    DCHECK(profiler_ == nullptr);
    profiler_ = profiler;
    IncreaseProfilingDepth();
    if (!IsActive()) Start();
    sampling_thread_->StartSynchronously();
  }

  void ClearProfiler() {
    profiler_ = nullptr;
    if (IsActive()) Stop();
    DecreaseProfilingDepth();
    sampling_thread_->Join();
  }

  void SampleStack(const v8::RegisterState& state) override {
    if (!profiler_) return;
    Isolate* isolate = reinterpret_cast<Isolate*>(this->isolate());
    TickSample sample;
    sample.Init(isolate, state, TickSample::kIncludeCEntryFrame, true);
    profiler_->Insert(&sample);
  }

 private:
  Profiler* profiler_;
  SamplingThread* sampling_thread_;
};


//
// Profiler implementation.
//
Profiler::Profiler(Isolate* isolate)
    : base::Thread(Options("v8:Profiler")),
      isolate_(isolate),
      head_(0),
      overflow_(false),
      buffer_semaphore_(0),
      engaged_(false),
      paused_(false) {
  base::Relaxed_Store(&tail_, 0);
  base::Relaxed_Store(&running_, 0);
}


void Profiler::Engage() {
  if (engaged_) return;
  engaged_ = true;

  std::vector<base::OS::SharedLibraryAddress> addresses =
      base::OS::GetSharedLibraryAddresses();
  for (size_t i = 0; i < addresses.size(); ++i) {
    LOG(isolate_,
        SharedLibraryEvent(addresses[i].library_path, addresses[i].start,
                           addresses[i].end, addresses[i].aslr_slide));
  }

  // Start thread processing the profiler buffer.
  base::Relaxed_Store(&running_, 1);
  Start();

  // Register to get ticks.
  Logger* logger = isolate_->logger();
  logger->ticker_->SetProfiler(this);

  logger->ProfilerBeginEvent();
}


void Profiler::Disengage() {
  if (!engaged_) return;

  // Stop receiving ticks.
  isolate_->logger()->ticker_->ClearProfiler();

  // Terminate the worker thread by setting running_ to false,
  // inserting a fake element in the queue and then wait for
  // the thread to terminate.
  base::Relaxed_Store(&running_, 0);
  v8::TickSample sample;
  // Reset 'paused_' flag, otherwise semaphore may not be signalled.
  resume();
  Insert(&sample);
  Join();

  LOG(isolate_, UncheckedStringEvent("profiler", "end"));
}


void Profiler::Run() {
  v8::TickSample sample;
  bool overflow = Remove(&sample);
  while (base::Relaxed_Load(&running_)) {
    LOG(isolate_, TickEvent(&sample, overflow));
    overflow = Remove(&sample);
  }
}


//
// Logger class implementation.
//

Logger::Logger(Isolate* isolate)
    : isolate_(isolate),
      ticker_(NULL),
      profiler_(NULL),
      log_events_(NULL),
      is_logging_(false),
      log_(new Log(this)),
      perf_basic_logger_(NULL),
      perf_jit_logger_(NULL),
      ll_logger_(NULL),
      jit_logger_(NULL),
      is_initialized_(false) {}

Logger::~Logger() {
  delete log_;
}

void Logger::addCodeEventListener(CodeEventListener* listener) {
  bool result = isolate_->code_event_dispatcher()->AddListener(listener);
  USE(result);
  DCHECK(result);
}

void Logger::removeCodeEventListener(CodeEventListener* listener) {
  isolate_->code_event_dispatcher()->RemoveListener(listener);
}

void Logger::ProfilerBeginEvent() {
  if (!log_->IsEnabled()) return;
  Log::MessageBuilder msg(log_);
  msg.Append("profiler,\"begin\",%d", FLAG_prof_sampling_interval);
  msg.WriteToLogFile();
}


void Logger::StringEvent(const char* name, const char* value) {
  if (FLAG_log) UncheckedStringEvent(name, value);
}


void Logger::UncheckedStringEvent(const char* name, const char* value) {
  if (!log_->IsEnabled()) return;
  Log::MessageBuilder msg(log_);
  msg.Append("%s,\"%s\"", name, value);
  msg.WriteToLogFile();
}


void Logger::IntEvent(const char* name, int value) {
  if (FLAG_log) UncheckedIntEvent(name, value);
}


void Logger::IntPtrTEvent(const char* name, intptr_t value) {
  if (FLAG_log) UncheckedIntPtrTEvent(name, value);
}


void Logger::UncheckedIntEvent(const char* name, int value) {
  if (!log_->IsEnabled()) return;
  Log::MessageBuilder msg(log_);
  msg.Append("%s,%d", name, value);
  msg.WriteToLogFile();
}


void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) {
  if (!log_->IsEnabled()) return;
  Log::MessageBuilder msg(log_);
  msg.Append("%s,%" V8PRIdPTR, name, value);
  msg.WriteToLogFile();
}


void Logger::HandleEvent(const char* name, Object** location) {
  if (!log_->IsEnabled() || !FLAG_log_handles) return;
  Log::MessageBuilder msg(log_);
  msg.Append("%s,%p", name, static_cast<void*>(location));
  msg.WriteToLogFile();
}


// ApiEvent is private so all the calls come from the Logger class.  It is the
// caller's responsibility to ensure that log is enabled and that
// FLAG_log_api is true.
void Logger::ApiEvent(const char* format, ...) {
  DCHECK(log_->IsEnabled() && FLAG_log_api);
  Log::MessageBuilder msg(log_);
  va_list ap;
  va_start(ap, format);
  msg.AppendVA(format, ap);
  va_end(ap);
  msg.WriteToLogFile();
}


void Logger::ApiSecurityCheck() {
  if (!log_->IsEnabled() || !FLAG_log_api) return;
  ApiEvent("api,check-security");
}

void Logger::SharedLibraryEvent(const std::string& library_path,
                                uintptr_t start, uintptr_t end,
                                intptr_t aslr_slide) {
  if (!log_->IsEnabled() || !FLAG_prof_cpp) return;
  Log::MessageBuilder msg(log_);
  msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR
             ",%" V8PRIdPTR,
             library_path.c_str(), start, end, aslr_slide);
  msg.WriteToLogFile();
}

void Logger::CodeDeoptEvent(Code* code, DeoptKind kind, Address pc,
                            int fp_to_sp_delta) {
  if (!log_->IsEnabled()) return;
  Deoptimizer::DeoptInfo info = Deoptimizer::GetDeoptInfo(code, pc);
  Log::MessageBuilder msg(log_);
  int since_epoch = timer_.IsStarted()
                        ? static_cast<int>(timer_.Elapsed().InMicroseconds())
                        : -1;
  msg.Append("code-deopt,%d,%d,", since_epoch, code->CodeSize());
  msg.AppendAddress(code->instruction_start());

  // Deoptimization position.
  std::ostringstream deopt_location;
  int inlining_id = -1;
  int script_offset = -1;
  if (info.position.IsKnown()) {
    info.position.Print(deopt_location, code);
    inlining_id = info.position.InliningId();
    script_offset = info.position.ScriptOffset();
  } else {
    deopt_location << "<unknown>";
  }
  msg.Append(",%d,%d,", inlining_id, script_offset);
  switch (kind) {
    case kLazy:
      msg.Append("\"lazy\",");
      break;
    case kSoft:
      msg.Append("\"soft\",");
      break;
    case kEager:
      msg.Append("\"eager\",");
      break;
  }
  msg.AppendDoubleQuotedString(deopt_location.str().c_str());
  msg.Append(",");
  msg.AppendDoubleQuotedString(DeoptimizeReasonToString(info.deopt_reason));
  msg.WriteToLogFile();
}


void Logger::CurrentTimeEvent() {
  if (!log_->IsEnabled()) return;
  DCHECK(FLAG_log_internal_timer_events);
  Log::MessageBuilder msg(log_);
  int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds());
  msg.Append("current-time,%d", since_epoch);
  msg.WriteToLogFile();
}


void Logger::TimerEvent(Logger::StartEnd se, const char* name) {
  if (!log_->IsEnabled()) return;
  DCHECK(FLAG_log_internal_timer_events);
  Log::MessageBuilder msg(log_);
  int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds());
  const char* format = (se == START) ? "timer-event-start,\"%s\",%ld"
                                     : "timer-event-end,\"%s\",%ld";
  msg.Append(format, name, since_epoch);
  msg.WriteToLogFile();
}


void Logger::EnterExternal(Isolate* isolate) {
  LOG(isolate, TimerEvent(START, TimerEventExternal::name()));
  DCHECK(isolate->current_vm_state() == JS);
  isolate->set_current_vm_state(EXTERNAL);
}


void Logger::LeaveExternal(Isolate* isolate) {
  LOG(isolate, TimerEvent(END, TimerEventExternal::name()));
  DCHECK(isolate->current_vm_state() == EXTERNAL);
  isolate->set_current_vm_state(JS);
}

// Instantiate template methods.
#define V(TimerName, expose)                                           \
  template void TimerEventScope<TimerEvent##TimerName>::LogTimerEvent( \
      Logger::StartEnd se);
TIMER_EVENTS_LIST(V)
#undef V

void Logger::ApiNamedPropertyAccess(const char* tag,
                                    JSObject* holder,
                                    Object* name) {
  DCHECK(name->IsName());
  if (!log_->IsEnabled() || !FLAG_log_api) return;
  String* class_name_obj = holder->class_name();
  std::unique_ptr<char[]> class_name =
      class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
  if (name->IsString()) {
    std::unique_ptr<char[]> property_name =
        String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
    ApiEvent("api,%s,\"%s\",\"%s\"", tag, class_name.get(),
             property_name.get());
  } else {
    Symbol* symbol = Symbol::cast(name);
    uint32_t hash = symbol->Hash();
    if (symbol->name()->IsUndefined(symbol->GetIsolate())) {
      ApiEvent("api,%s,\"%s\",symbol(hash %x)", tag, class_name.get(), hash);
    } else {
      std::unique_ptr<char[]> str =
          String::cast(symbol->name())
              ->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
      ApiEvent("api,%s,\"%s\",symbol(\"%s\" hash %x)", tag, class_name.get(),
               str.get(), hash);
    }
  }
}

void Logger::ApiIndexedPropertyAccess(const char* tag,
                                      JSObject* holder,
                                      uint32_t index) {
  if (!log_->IsEnabled() || !FLAG_log_api) return;
  String* class_name_obj = holder->class_name();
  std::unique_ptr<char[]> class_name =
      class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
  ApiEvent("api,%s,\"%s\",%u", tag, class_name.get(), index);
}


void Logger::ApiObjectAccess(const char* tag, JSObject* object) {
  if (!log_->IsEnabled() || !FLAG_log_api) return;
  String* class_name_obj = object->class_name();
  std::unique_ptr<char[]> class_name =
      class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
  ApiEvent("api,%s,\"%s\"", tag, class_name.get());
}


void Logger::ApiEntryCall(const char* name) {
  if (!log_->IsEnabled() || !FLAG_log_api) return;
  ApiEvent("api,%s", name);
}


void Logger::NewEvent(const char* name, void* object, size_t size) {
  if (!log_->IsEnabled() || !FLAG_log) return;
  Log::MessageBuilder msg(log_);
  msg.Append("new,%s,%p,%u", name, object, static_cast<unsigned int>(size));
  msg.WriteToLogFile();
}


void Logger::DeleteEvent(const char* name, void* object) {
  if (!log_->IsEnabled() || !FLAG_log) return;
  Log::MessageBuilder msg(log_);
  msg.Append("delete,%s,%p", name, object);
  msg.WriteToLogFile();
}


void Logger::CallbackEventInternal(const char* prefix, Name* name,
                                   Address entry_point) {
  if (!FLAG_log_code || !log_->IsEnabled()) return;
  Log::MessageBuilder msg(log_);
  msg.Append("%s,%s,-2,",
             kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT],
             kLogEventsNames[CodeEventListener::CALLBACK_TAG]);
  int timestamp = timer_.IsStarted()
                      ? static_cast<int>(timer_.Elapsed().InMicroseconds())
                      : -1;
  msg.Append("%d,", timestamp);
  msg.AppendAddress(entry_point);
  if (name->IsString()) {
    std::unique_ptr<char[]> str =
        String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
    msg.Append(",1,\"%s%s\"", prefix, str.get());
  } else {
    Symbol* symbol = Symbol::cast(name);
    if (symbol->name()->IsUndefined(symbol->GetIsolate())) {
      msg.Append(",1,symbol(hash %x)", symbol->Hash());
    } else {
      std::unique_ptr<char[]> str =
          String::cast(symbol->name())
              ->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
      msg.Append(",1,symbol(\"%s%s\" hash %x)", prefix, str.get(),
                 symbol->Hash());
    }
  }
  msg.WriteToLogFile();
}


void Logger::CallbackEvent(Name* name, Address entry_point) {
  CallbackEventInternal("", name, entry_point);
}


void Logger::GetterCallbackEvent(Name* name, Address entry_point) {
  CallbackEventInternal("get ", name, entry_point);
}


void Logger::SetterCallbackEvent(Name* name, Address entry_point) {
  CallbackEventInternal("set ", name, entry_point);
}

namespace {

void AppendCodeCreateHeader(Log::MessageBuilder* msg,
                            CodeEventListener::LogEventsAndTags tag,
                            AbstractCode* code, base::ElapsedTimer* timer) {
  DCHECK(msg);
  msg->Append("%s,%s,%d,",
              kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT],
              kLogEventsNames[tag], code->kind());
  int timestamp = timer->IsStarted()
                      ? static_cast<int>(timer->Elapsed().InMicroseconds())
                      : -1;
  msg->Append("%d,", timestamp);
  msg->AppendAddress(code->instruction_start());
  msg->Append(",%d,", code->instruction_size());
}

}  // namespace

void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
                             AbstractCode* code, const char* comment) {
  if (!is_logging_code_events()) return;
  if (!FLAG_log_code || !log_->IsEnabled()) return;
  Log::MessageBuilder msg(log_);
  AppendCodeCreateHeader(&msg, tag, code, &timer_);
  msg.AppendDoubleQuotedString(comment);
  msg.WriteToLogFile();
}

void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
                             AbstractCode* code, Name* name) {
  if (!is_logging_code_events()) return;
  if (!FLAG_log_code || !log_->IsEnabled()) return;
  Log::MessageBuilder msg(log_);
  AppendCodeCreateHeader(&msg, tag, code, &timer_);
  if (name->IsString()) {
    msg.Append('"');
    msg.AppendDetailed(String::cast(name), false);
    msg.Append('"');
  } else {
    msg.AppendSymbolName(Symbol::cast(name));
  }
  msg.WriteToLogFile();
}

void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
                             AbstractCode* code, SharedFunctionInfo* shared,
                             Name* name) {
  if (!is_logging_code_events()) return;
  if (!FLAG_log_code || !log_->IsEnabled()) return;
  if (code == AbstractCode::cast(
                  isolate_->builtins()->builtin(Builtins::kCompileLazy))) {
    return;
  }

  Log::MessageBuilder msg(log_);
  AppendCodeCreateHeader(&msg, tag, code, &timer_);
  if (name->IsString()) {
    std::unique_ptr<char[]> str =
        String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
    msg.Append("\"%s\"", str.get());
  } else {
    msg.AppendSymbolName(Symbol::cast(name));
  }
  msg.Append(',');
  msg.AppendAddress(shared->address());
  msg.Append(",%s", ComputeMarker(shared, code));
  msg.WriteToLogFile();
}


// Although, it is possible to extract source and line from
// the SharedFunctionInfo object, we left it to caller
// to leave logging functions free from heap allocations.
void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
                             AbstractCode* code, SharedFunctionInfo* shared,
                             Name* source, int line, int column) {
  if (!is_logging_code_events()) return;
  if (!FLAG_log_code || !log_->IsEnabled()) return;

  {
    Log::MessageBuilder msg(log_);
    AppendCodeCreateHeader(&msg, tag, code, &timer_);
    std::unique_ptr<char[]> name =
        shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
    msg.Append("\"%s ", name.get());
    if (source->IsString()) {
      std::unique_ptr<char[]> sourcestr = String::cast(source)->ToCString(
          DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
      msg.Append("%s", sourcestr.get());
    } else {
      msg.AppendSymbolName(Symbol::cast(source));
    }
    msg.Append(":%d:%d\",", line, column);
    msg.AppendAddress(shared->address());
    msg.Append(",%s", ComputeMarker(shared, code));
    msg.WriteToLogFile();
  }

  if (FLAG_log_source_code) {
    Object* script_object = shared->script();
    if (script_object->IsScript()) {
      // Make sure the script is written to the log file.
      std::ostringstream os;
      Script* script = Script::cast(script_object);
      int script_id = script->id();
      if (logged_source_code_.find(script_id) == logged_source_code_.end()) {
        // This script has not been logged yet.
        logged_source_code_.insert(script_id);
        Object* source_object = script->source();
        if (source_object->IsString()) {
          Log::MessageBuilder msg(log_);
          String* source_code = String::cast(source_object);
          os << "script," << script_id << ",\"";
          msg.AppendUnbufferedCString(os.str().c_str());

          // Log the script name.
          if (script->name()->IsString()) {
            msg.AppendUnbufferedHeapString(String::cast(script->name()));
            msg.AppendUnbufferedCString("\",\"");
          } else {
            msg.AppendUnbufferedCString("<unknown>\",\"");
          }

          // Log the source code.
          msg.AppendUnbufferedHeapString(source_code);
          os.str("");
          os << "\"" << std::endl;
          msg.AppendUnbufferedCString(os.str().c_str());
          os.str("");
        }
      }

      // We log source code information in the form:
      //
      // code-source-info <addr>,<script>,<start>,<end>,<pos>,<inline-pos>,<fns>
      //
      // where
      //   <addr> is code object address
      //   <script> is script id
      //   <start> is the starting position inside the script
      //   <end> is the end position inside the script
      //   <pos> is source position table encoded in the string,
      //      it is a sequence of C<code-offset>O<script-offset>[I<inlining-id>]
      //      where
      //        <code-offset> is the offset within the code object
      //        <script-offset> is the position within the script
      //        <inlining-id> is the offset in the <inlining> table
      //   <inlining> table is a sequence of strings of the form
      //      F<function-id>O<script-offset>[I<inlining-id>
      //      where
      //         <function-id> is an index into the <fns> function table
      //   <fns> is the function table encoded as a sequence of strings
      //      S<shared-function-info-address>
      os << "code-source-info," << static_cast<void*>(code->instruction_start())
         << "," << script_id << "," << shared->start_position() << ","
         << shared->end_position() << ",";

      SourcePositionTableIterator iterator(code->source_position_table());
      bool is_first = true;
      bool hasInlined = false;
      for (; !iterator.done(); iterator.Advance()) {
        if (is_first) {
          is_first = false;
        }
        SourcePosition pos = iterator.source_position();
        os << "C" << iterator.code_offset();
        os << "O" << pos.ScriptOffset();
        if (pos.isInlined()) {
          os << "I" << pos.InliningId();
          hasInlined = true;
        }
      }
      os << ",";
      int maxInlinedId = -1;
      if (hasInlined) {
        PodArray<InliningPosition>* inlining_positions =
            DeoptimizationInputData::cast(
                Code::cast(code)->deoptimization_data())
                ->InliningPositions();
        for (int i = 0; i < inlining_positions->length(); i++) {
          InliningPosition inlining_pos = inlining_positions->get(i);
          os << "F";
          if (inlining_pos.inlined_function_id != -1) {
            os << inlining_pos.inlined_function_id;
            if (inlining_pos.inlined_function_id > maxInlinedId) {
              maxInlinedId = inlining_pos.inlined_function_id;
            }
          }
          SourcePosition pos = inlining_pos.position;
          os << "O" << pos.ScriptOffset();
          if (pos.isInlined()) {
            os << "I" << pos.InliningId();
          }
        }
      }
      os << ",";
      if (hasInlined) {
        DeoptimizationInputData* deopt_data = DeoptimizationInputData::cast(
            Code::cast(code)->deoptimization_data());

        os << std::hex;
        for (int i = 0; i <= maxInlinedId; i++) {
          os << "S"
             << static_cast<void*>(
                    deopt_data->GetInlinedFunction(i)->address());
        }
        os << std::dec;
      }
      os << std::endl;
      Log::MessageBuilder msg(log_);
      msg.AppendUnbufferedCString(os.str().c_str());
    }
  }
}

void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
                             AbstractCode* code, int args_count) {
  if (!is_logging_code_events()) return;
  if (!FLAG_log_code || !log_->IsEnabled()) return;
  Log::MessageBuilder msg(log_);
  AppendCodeCreateHeader(&msg, tag, code, &timer_);
  msg.Append("\"args_count: %d\"", args_count);
  msg.WriteToLogFile();
}

void Logger::CodeDisableOptEvent(AbstractCode* code,
                                 SharedFunctionInfo* shared) {
  if (!is_logging_code_events()) return;
  if (!FLAG_log_code || !log_->IsEnabled()) return;
  Log::MessageBuilder msg(log_);
  msg.Append("%s,", kLogEventsNames[CodeEventListener::CODE_DISABLE_OPT_EVENT]);
  std::unique_ptr<char[]> name =
      shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
  msg.Append("\"%s\",", name.get());
  msg.Append("\"%s\"", GetBailoutReason(shared->disable_optimization_reason()));
  msg.WriteToLogFile();
}


void Logger::CodeMovingGCEvent() {
  if (!is_logging_code_events()) return;
  if (!log_->IsEnabled() || !FLAG_ll_prof) return;
  base::OS::SignalCodeMovingGC();
}

void Logger::RegExpCodeCreateEvent(AbstractCode* code, String* source) {
  if (!is_logging_code_events()) return;
  if (!FLAG_log_code || !log_->IsEnabled()) return;
  Log::MessageBuilder msg(log_);
  AppendCodeCreateHeader(&msg, CodeEventListener::REG_EXP_TAG, code, &timer_);
  msg.Append('"');
  msg.AppendDetailed(source, false);
  msg.Append('"');
  msg.WriteToLogFile();
}

void Logger::CodeMoveEvent(AbstractCode* from, AbstractCode* to) {
  if (!is_logging_code_events()) return;
  MoveEventInternal(CodeEventListener::CODE_MOVE_EVENT, from->address(),
                    to->address());
}

void Logger::CodeLinePosInfoRecordEvent(AbstractCode* code,
                                        ByteArray* source_position_table) {
  if (jit_logger_) {
    void* jit_handler_data = jit_logger_->StartCodePosInfoEvent();
    for (SourcePositionTableIterator iter(source_position_table); !iter.done();
         iter.Advance()) {
      if (iter.is_statement()) {
        jit_logger_->AddCodeLinePosInfoEvent(
            jit_handler_data, iter.code_offset(),
            iter.source_position().ScriptOffset(),
            JitCodeEvent::STATEMENT_POSITION);
      }
      jit_logger_->AddCodeLinePosInfoEvent(
          jit_handler_data, iter.code_offset(),
          iter.source_position().ScriptOffset(), JitCodeEvent::POSITION);
    }
    jit_logger_->EndCodePosInfoEvent(code, jit_handler_data);
  }
}

void Logger::CodeNameEvent(Address addr, int pos, const char* code_name) {
  if (code_name == NULL) return;  // Not a code object.
  Log::MessageBuilder msg(log_);
  msg.Append("%s,%d,",
             kLogEventsNames[CodeEventListener::SNAPSHOT_CODE_NAME_EVENT], pos);
  msg.AppendDoubleQuotedString(code_name);
  msg.WriteToLogFile();
}


void Logger::SharedFunctionInfoMoveEvent(Address from, Address to) {
  if (!is_logging_code_events()) return;
  MoveEventInternal(CodeEventListener::SHARED_FUNC_MOVE_EVENT, from, to);
}

void Logger::MoveEventInternal(CodeEventListener::LogEventsAndTags event,
                               Address from, Address to) {
  if (!FLAG_log_code || !log_->IsEnabled()) return;
  Log::MessageBuilder msg(log_);
  msg.Append("%s,", kLogEventsNames[event]);
  msg.AppendAddress(from);
  msg.Append(',');
  msg.AppendAddress(to);
  msg.WriteToLogFile();
}


void Logger::ResourceEvent(const char* name, const char* tag) {
  if (!log_->IsEnabled() || !FLAG_log) return;
  Log::MessageBuilder msg(log_);
  msg.Append("%s,%s,", name, tag);

  uint32_t sec, usec;
  if (base::OS::GetUserTime(&sec, &usec) != -1) {
    msg.Append("%d,%d,", sec, usec);
  }
  msg.Append("%.0f", base::OS::TimeCurrentMillis());
  msg.WriteToLogFile();
}


void Logger::SuspectReadEvent(Name* name, Object* obj) {
  if (!log_->IsEnabled() || !FLAG_log_suspect) return;
  Log::MessageBuilder msg(log_);
  String* class_name = obj->IsJSObject()
                       ? JSObject::cast(obj)->class_name()
                       : isolate_->heap()->empty_string();
  msg.Append("suspect-read,");
  msg.Append(class_name);
  msg.Append(',');
  if (name->IsString()) {
    msg.Append('"');
    msg.Append(String::cast(name));
    msg.Append('"');
  } else {
    msg.AppendSymbolName(Symbol::cast(name));
  }
  msg.WriteToLogFile();
}


void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
  if (!log_->IsEnabled() || !FLAG_log_gc) return;
  Log::MessageBuilder msg(log_);
  // Using non-relative system time in order to be able to synchronize with
  // external memory profiling events (e.g. DOM memory size).
  msg.Append("heap-sample-begin,\"%s\",\"%s\",%.0f", space, kind,
             base::OS::TimeCurrentMillis());
  msg.WriteToLogFile();
}


void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
  if (!log_->IsEnabled() || !FLAG_log_gc) return;
  Log::MessageBuilder msg(log_);
  msg.Append("heap-sample-end,\"%s\",\"%s\"", space, kind);
  msg.WriteToLogFile();
}


void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) {
  if (!log_->IsEnabled() || !FLAG_log_gc) return;
  Log::MessageBuilder msg(log_);
  msg.Append("heap-sample-item,%s,%d,%d", type, number, bytes);
  msg.WriteToLogFile();
}


void Logger::RuntimeCallTimerEvent() {
  RuntimeCallStats* stats = isolate_->counters()->runtime_call_stats();
  RuntimeCallCounter* counter = stats->current_counter();
  if (counter == nullptr) return;
  Log::MessageBuilder msg(log_);
  msg.Append("active-runtime-timer,");
  msg.AppendDoubleQuotedString(counter->name());
  msg.WriteToLogFile();
}

void Logger::TickEvent(v8::TickSample* sample, bool overflow) {
  if (!log_->IsEnabled() || !FLAG_prof_cpp) return;
  if (V8_UNLIKELY(FLAG_runtime_stats ==
                  v8::tracing::TracingCategoryObserver::ENABLED_BY_NATIVE)) {
    RuntimeCallTimerEvent();
  }
  Log::MessageBuilder msg(log_);
  msg.Append("%s,", kLogEventsNames[CodeEventListener::TICK_EVENT]);
  msg.AppendAddress(reinterpret_cast<Address>(sample->pc));
  msg.Append(",%d", static_cast<int>(timer_.Elapsed().InMicroseconds()));
  if (sample->has_external_callback) {
    msg.Append(",1,");
    msg.AppendAddress(
        reinterpret_cast<Address>(sample->external_callback_entry));
  } else {
    msg.Append(",0,");
    msg.AppendAddress(reinterpret_cast<Address>(sample->tos));
  }
  msg.Append(",%d", static_cast<int>(sample->state));
  if (overflow) {
    msg.Append(",overflow");
  }
  for (unsigned i = 0; i < sample->frames_count; ++i) {
    msg.Append(',');
    msg.AppendAddress(reinterpret_cast<Address>(sample->stack[i]));
  }
  msg.WriteToLogFile();
}

void Logger::ICEvent(const char* type, bool keyed, const Address pc, int line,
                     int column, Map* map, Object* key, char old_state,
                     char new_state, const char* modifier,
                     const char* slow_stub_reason) {
  if (!log_->IsEnabled() || !FLAG_trace_ic) return;
  Log::MessageBuilder msg(log_);
  if (keyed) msg.Append("Keyed");
  msg.Append("%s,", type);
  msg.AppendAddress(pc);
  msg.Append(",%d,%d,", line, column);
  msg.Append(old_state);
  msg.Append(",");
  msg.Append(new_state);
  msg.Append(",");
  msg.AppendAddress(reinterpret_cast<Address>(map));
  msg.Append(",");
  if (key->IsSmi()) {
    msg.Append("%d", Smi::ToInt(key));
  } else if (key->IsNumber()) {
    msg.Append("%lf", key->Number());
  } else if (key->IsString()) {
    msg.AppendDetailed(String::cast(key), false);
  } else if (key->IsSymbol()) {
    msg.AppendSymbolName(Symbol::cast(key));
  }
  msg.Append(",%s,", modifier);
  if (slow_stub_reason != nullptr) {
    msg.AppendDoubleQuotedString(slow_stub_reason);
  }
  msg.WriteToLogFile();
}

void Logger::StopProfiler() {
  if (!log_->IsEnabled()) return;
  if (profiler_ != NULL) {
    profiler_->pause();
    is_logging_ = false;
    removeCodeEventListener(this);
  }
}


// This function can be called when Log's mutex is acquired,
// either from main or Profiler's thread.
void Logger::LogFailure() {
  StopProfiler();
}

static void AddFunctionAndCode(SharedFunctionInfo* sfi,
                               AbstractCode* code_object,
                               Handle<SharedFunctionInfo>* sfis,
                               Handle<AbstractCode>* code_objects, int offset) {
  if (sfis != NULL) {
    sfis[offset] = Handle<SharedFunctionInfo>(sfi);
  }
  if (code_objects != NULL) {
    code_objects[offset] = Handle<AbstractCode>(code_object);
  }
}

class EnumerateOptimizedFunctionsVisitor: public OptimizedFunctionVisitor {
 public:
  EnumerateOptimizedFunctionsVisitor(Handle<SharedFunctionInfo>* sfis,
                                     Handle<AbstractCode>* code_objects,
                                     int* count)
      : sfis_(sfis), code_objects_(code_objects), count_(count) {}

  virtual void VisitFunction(JSFunction* function) {
    SharedFunctionInfo* sfi = SharedFunctionInfo::cast(function->shared());
    Object* maybe_script = sfi->script();
    if (maybe_script->IsScript()
        && !Script::cast(maybe_script)->HasValidSource()) return;

    DCHECK(function->abstract_code()->kind() ==
           AbstractCode::OPTIMIZED_FUNCTION);
    AddFunctionAndCode(sfi, function->abstract_code(), sfis_, code_objects_,
                       *count_);
    *count_ = *count_ + 1;
  }

 private:
  Handle<SharedFunctionInfo>* sfis_;
  Handle<AbstractCode>* code_objects_;
  int* count_;
};

static int EnumerateCompiledFunctions(Heap* heap,
                                      Handle<SharedFunctionInfo>* sfis,
                                      Handle<AbstractCode>* code_objects) {
  HeapIterator iterator(heap);
  DisallowHeapAllocation no_gc;
  int compiled_funcs_count = 0;

  // Iterate the heap to find shared function info objects and record
  // the unoptimized code for them.
  for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
    if (!obj->IsSharedFunctionInfo()) continue;
    SharedFunctionInfo* sfi = SharedFunctionInfo::cast(obj);
    if (sfi->is_compiled()
        && (!sfi->script()->IsScript()
            || Script::cast(sfi->script())->HasValidSource())) {
      // In some cases, an SFI might have (and have executing!) both bytecode
      // and baseline code, so check for both and add them both if needed.
      if (sfi->HasBytecodeArray()) {
        AddFunctionAndCode(sfi, AbstractCode::cast(sfi->bytecode_array()), sfis,
                           code_objects, compiled_funcs_count);
        ++compiled_funcs_count;
      }

      if (!sfi->IsInterpreted()) {
        AddFunctionAndCode(sfi, AbstractCode::cast(sfi->code()), sfis,
                           code_objects, compiled_funcs_count);
        ++compiled_funcs_count;
      }
    }
  }

  // Iterate all optimized functions in all contexts.
  EnumerateOptimizedFunctionsVisitor visitor(sfis,
                                             code_objects,
                                             &compiled_funcs_count);
  Deoptimizer::VisitAllOptimizedFunctions(heap->isolate(), &visitor);

  return compiled_funcs_count;
}


void Logger::LogCodeObject(Object* object) {
  AbstractCode* code_object = AbstractCode::cast(object);
  CodeEventListener::LogEventsAndTags tag = CodeEventListener::STUB_TAG;
  const char* description = "Unknown code from the snapshot";
  switch (code_object->kind()) {
    case AbstractCode::FUNCTION:
    case AbstractCode::INTERPRETED_FUNCTION:
    case AbstractCode::OPTIMIZED_FUNCTION:
      return;  // We log this later using LogCompiledFunctions.
    case AbstractCode::BYTECODE_HANDLER:
      return;  // We log it later by walking the dispatch table.
    case AbstractCode::STUB:
      description =
          CodeStub::MajorName(CodeStub::GetMajorKey(code_object->GetCode()));
      if (description == NULL)
        description = "A stub from the snapshot";
      tag = CodeEventListener::STUB_TAG;
      break;
    case AbstractCode::REGEXP:
      description = "Regular expression code";
      tag = CodeEventListener::REG_EXP_TAG;
      break;
    case AbstractCode::BUILTIN:
      description =
          isolate_->builtins()->name(code_object->GetCode()->builtin_index());
      tag = CodeEventListener::BUILTIN_TAG;
      break;
    case AbstractCode::HANDLER:
      description = "An IC handler from the snapshot";
      tag = CodeEventListener::HANDLER_TAG;
      break;
    case AbstractCode::KEYED_LOAD_IC:
      description = "A keyed load IC from the snapshot";
      tag = CodeEventListener::KEYED_LOAD_IC_TAG;
      break;
    case AbstractCode::LOAD_IC:
      description = "A load IC from the snapshot";
      tag = CodeEventListener::LOAD_IC_TAG;
      break;
    case AbstractCode::LOAD_GLOBAL_IC:
      description = "A load global IC from the snapshot";
      tag = Logger::LOAD_GLOBAL_IC_TAG;
      break;
    case AbstractCode::STORE_IC:
      description = "A store IC from the snapshot";
      tag = CodeEventListener::STORE_IC_TAG;
      break;
    case AbstractCode::STORE_GLOBAL_IC:
      description = "A store global IC from the snapshot";
      tag = CodeEventListener::STORE_GLOBAL_IC_TAG;
      break;
    case AbstractCode::KEYED_STORE_IC:
      description = "A keyed store IC from the snapshot";
      tag = CodeEventListener::KEYED_STORE_IC_TAG;
      break;
    case AbstractCode::WASM_FUNCTION:
      description = "A Wasm function";
      tag = CodeEventListener::STUB_TAG;
      break;
    case AbstractCode::JS_TO_WASM_FUNCTION:
      description = "A JavaScript to Wasm adapter";
      tag = CodeEventListener::STUB_TAG;
      break;
    case AbstractCode::WASM_TO_JS_FUNCTION:
      description = "A Wasm to JavaScript adapter";
      tag = CodeEventListener::STUB_TAG;
      break;
    case AbstractCode::WASM_INTERPRETER_ENTRY:
      description = "A Wasm to Interpreter adapter";
      tag = CodeEventListener::STUB_TAG;
      break;
    case AbstractCode::C_WASM_ENTRY:
      description = "A C to Wasm entry stub";
      tag = CodeEventListener::STUB_TAG;
      break;
    case AbstractCode::NUMBER_OF_KINDS:
      UNIMPLEMENTED();
  }
  PROFILE(isolate_, CodeCreateEvent(tag, code_object, description));
}


void Logger::LogCodeObjects() {
  Heap* heap = isolate_->heap();
  HeapIterator iterator(heap);
  DisallowHeapAllocation no_gc;
  for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
    if (obj->IsCode()) LogCodeObject(obj);
    if (obj->IsBytecodeArray()) LogCodeObject(obj);
  }
}

void Logger::LogBytecodeHandlers() {
  const interpreter::OperandScale kOperandScales[] = {
#define VALUE(Name, _) interpreter::OperandScale::k##Name,
      OPERAND_SCALE_LIST(VALUE)
#undef VALUE
  };

  const int last_index = static_cast<int>(interpreter::Bytecode::kLast);
  interpreter::Interpreter* interpreter = isolate_->interpreter();
  for (auto operand_scale : kOperandScales) {
    for (int index = 0; index <= last_index; ++index) {
      interpreter::Bytecode bytecode = interpreter::Bytecodes::FromByte(index);
      if (interpreter::Bytecodes::BytecodeHasHandler(bytecode, operand_scale)) {
        Code* code = interpreter->GetBytecodeHandler(bytecode, operand_scale);
        std::string bytecode_name =
            interpreter::Bytecodes::ToString(bytecode, operand_scale);
        PROFILE(isolate_, CodeCreateEvent(
                              CodeEventListener::BYTECODE_HANDLER_TAG,
                              AbstractCode::cast(code), bytecode_name.c_str()));
      }
    }
  }
}

void Logger::LogExistingFunction(Handle<SharedFunctionInfo> shared,
                                 Handle<AbstractCode> code) {
  if (shared->script()->IsScript()) {
    Handle<Script> script(Script::cast(shared->script()));
    int line_num = Script::GetLineNumber(script, shared->start_position()) + 1;
    int column_num =
        Script::GetColumnNumber(script, shared->start_position()) + 1;
    if (script->name()->IsString()) {
      Handle<String> script_name(String::cast(script->name()));
      if (line_num > 0) {
        PROFILE(isolate_,
                CodeCreateEvent(
                    Logger::ToNativeByScript(
                        CodeEventListener::LAZY_COMPILE_TAG, *script),
                    *code, *shared, *script_name, line_num, column_num));
      } else {
        // Can't distinguish eval and script here, so always use Script.
        PROFILE(isolate_,
                CodeCreateEvent(Logger::ToNativeByScript(
                                    CodeEventListener::SCRIPT_TAG, *script),
                                *code, *shared, *script_name));
      }
    } else {
      PROFILE(isolate_,
              CodeCreateEvent(Logger::ToNativeByScript(
                                  CodeEventListener::LAZY_COMPILE_TAG, *script),
                              *code, *shared, isolate_->heap()->empty_string(),
                              line_num, column_num));
    }
  } else if (shared->IsApiFunction()) {
    // API function.
    FunctionTemplateInfo* fun_data = shared->get_api_func_data();
    Object* raw_call_data = fun_data->call_code();
    if (!raw_call_data->IsUndefined(isolate_)) {
      CallHandlerInfo* call_data = CallHandlerInfo::cast(raw_call_data);
      Object* callback_obj = call_data->callback();
      Address entry_point = v8::ToCData<Address>(callback_obj);
#if USES_FUNCTION_DESCRIPTORS
      entry_point = *FUNCTION_ENTRYPOINT_ADDRESS(entry_point);
#endif
      PROFILE(isolate_, CallbackEvent(shared->DebugName(), entry_point));
    }
  } else {
    PROFILE(isolate_,
            CodeCreateEvent(CodeEventListener::LAZY_COMPILE_TAG, *code, *shared,
                            isolate_->heap()->empty_string()));
  }
}


void Logger::LogCompiledFunctions() {
  Heap* heap = isolate_->heap();
  HandleScope scope(isolate_);
  const int compiled_funcs_count = EnumerateCompiledFunctions(heap, NULL, NULL);
  ScopedVector< Handle<SharedFunctionInfo> > sfis(compiled_funcs_count);
  ScopedVector<Handle<AbstractCode> > code_objects(compiled_funcs_count);
  EnumerateCompiledFunctions(heap, sfis.start(), code_objects.start());

  // During iteration, there can be heap allocation due to
  // GetScriptLineNumber call.
  for (int i = 0; i < compiled_funcs_count; ++i) {
    if (code_objects[i].is_identical_to(BUILTIN_CODE(isolate_, CompileLazy)))
      continue;
    LogExistingFunction(sfis[i], code_objects[i]);
  }
}


void Logger::LogAccessorCallbacks() {
  Heap* heap = isolate_->heap();
  HeapIterator iterator(heap);
  DisallowHeapAllocation no_gc;
  for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
    if (!obj->IsAccessorInfo()) continue;
    AccessorInfo* ai = AccessorInfo::cast(obj);
    if (!ai->name()->IsName()) continue;
    Address getter_entry = v8::ToCData<Address>(ai->getter());
    Name* name = Name::cast(ai->name());
    if (getter_entry != 0) {
#if USES_FUNCTION_DESCRIPTORS
      getter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(getter_entry);
#endif
      PROFILE(isolate_, GetterCallbackEvent(name, getter_entry));
    }
    Address setter_entry = v8::ToCData<Address>(ai->setter());
    if (setter_entry != 0) {
#if USES_FUNCTION_DESCRIPTORS
      setter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(setter_entry);
#endif
      PROFILE(isolate_, SetterCallbackEvent(name, setter_entry));
    }
  }
}


static void AddIsolateIdIfNeeded(std::ostream& os,  // NOLINT
                                 Isolate* isolate) {
  if (FLAG_logfile_per_isolate) os << "isolate-" << isolate << "-";
}


static void PrepareLogFileName(std::ostream& os,  // NOLINT
                               Isolate* isolate, const char* file_name) {
  int dir_separator_count = 0;
  for (const char* p = file_name; *p; p++) {
    if (base::OS::isDirectorySeparator(*p)) dir_separator_count++;
  }

  for (const char* p = file_name; *p; p++) {
    if (dir_separator_count == 0) {
      AddIsolateIdIfNeeded(os, isolate);
      dir_separator_count--;
    }
    if (*p == '%') {
      p++;
      switch (*p) {
        case '\0':
          // If there's a % at the end of the string we back up
          // one character so we can escape the loop properly.
          p--;
          break;
        case 'p':
          os << base::OS::GetCurrentProcessId();
          break;
        case 't':
          // %t expands to the current time in milliseconds.
          os << static_cast<int64_t>(base::OS::TimeCurrentMillis());
          break;
        case '%':
          // %% expands (contracts really) to %.
          os << '%';
          break;
        default:
          // All other %'s expand to themselves.
          os << '%' << *p;
          break;
      }
    } else {
      if (base::OS::isDirectorySeparator(*p)) dir_separator_count--;
      os << *p;
    }
  }
}


bool Logger::SetUp(Isolate* isolate) {
  // Tests and EnsureInitialize() can call this twice in a row. It's harmless.
  if (is_initialized_) return true;
  is_initialized_ = true;

  std::ostringstream log_file_name;
  std::ostringstream source_log_file_name;
  PrepareLogFileName(log_file_name, isolate, FLAG_logfile);
  log_->Initialize(log_file_name.str().c_str());

  if (FLAG_perf_basic_prof) {
    perf_basic_logger_ = new PerfBasicLogger();
    addCodeEventListener(perf_basic_logger_);
  }

  if (FLAG_perf_prof) {
    perf_jit_logger_ = new PerfJitLogger();
    addCodeEventListener(perf_jit_logger_);
  }

  if (FLAG_ll_prof) {
    ll_logger_ = new LowLevelLogger(log_file_name.str().c_str());
    addCodeEventListener(ll_logger_);
  }

  ticker_ = new Ticker(isolate, FLAG_prof_sampling_interval);

  if (Log::InitLogAtStart()) {
    is_logging_ = true;
  }

  if (FLAG_log_internal_timer_events || FLAG_prof_cpp) timer_.Start();

  if (FLAG_prof_cpp) {
    profiler_ = new Profiler(isolate);
    is_logging_ = true;
    profiler_->Engage();
  }

  if (is_logging_) {
    addCodeEventListener(this);
  }

  return true;
}


void Logger::SetCodeEventHandler(uint32_t options,
                                 JitCodeEventHandler event_handler) {
  if (jit_logger_) {
      removeCodeEventListener(jit_logger_);
      delete jit_logger_;
      jit_logger_ = NULL;
  }

  if (event_handler) {
    jit_logger_ = new JitLogger(event_handler);
    addCodeEventListener(jit_logger_);
    if (options & kJitCodeEventEnumExisting) {
      HandleScope scope(isolate_);
      LogCodeObjects();
      LogCompiledFunctions();
    }
  }
}

sampler::Sampler* Logger::sampler() {
  return ticker_;
}


FILE* Logger::TearDown() {
  if (!is_initialized_) return NULL;
  is_initialized_ = false;

  // Stop the profiler before closing the file.
  if (profiler_ != NULL) {
    profiler_->Disengage();
    delete profiler_;
    profiler_ = NULL;
  }

  delete ticker_;
  ticker_ = NULL;

  if (perf_basic_logger_) {
    removeCodeEventListener(perf_basic_logger_);
    delete perf_basic_logger_;
    perf_basic_logger_ = NULL;
  }

  if (perf_jit_logger_) {
    removeCodeEventListener(perf_jit_logger_);
    delete perf_jit_logger_;
    perf_jit_logger_ = NULL;
  }

  if (ll_logger_) {
    removeCodeEventListener(ll_logger_);
    delete ll_logger_;
    ll_logger_ = NULL;
  }

  if (jit_logger_) {
    removeCodeEventListener(jit_logger_);
    delete jit_logger_;
    jit_logger_ = NULL;
  }

  return log_->Close();
}

}  // namespace internal
}  // namespace v8