[WIP]Create a V8 sampler library and tracing controller.

src/v8-tracing-controller.cc

+// Copyright 2016 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 "include/v8-tracing-controller.h"
+#include "src/base/platform/platform.h"
+#include "src/log.h"
+#include "src/version.h"
+#include <iostream>
+
+namespace v8 {
+
+// Functions and data for performing output of log messages.
+class TracingLogger {
+ public:
+  // Performs process-wide initialization.
+  void Initialize(const char* log_file_name);
+
+  // Disables logging, but preserves acquired resources.
+  void stop() { is_stopped_ = true; }
+
+  // Frees all resources acquired in Initialize and Open... functions.
+  // When a temporary file is used for the log, returns its stream descriptor,
+  // leaving the file open.
+  FILE* Close();
+
+  // Returns whether logging is enabled.
+  bool IsEnabled() {
+    return !is_stopped_ && output_handle_ != NULL;
+  }
+
+  // Size of buffer used for formatting log messages.
+  static const int kMessageBufferSize = 8192;
+
+  void SharedLibraryEvent(const std::string& library_path,
+                          uintptr_t start,
+                          uintptr_t end);
+  void BeginEvent(const char* event_name);
+  void EndEvent(const char* event_name);
+
+  // Utility class for formatting log messages. It fills the message into the
+  // static buffer in TracingLogger.
+  class MessageBuilder {
+   public:
+    // Create a message builder starting from position 0.
+    // This acquires the mutex in the log as well.
+    explicit MessageBuilder(TracingLogger* logger);
+    ~MessageBuilder() { }
+
+    // Append string data to the log message.
+    void Append(const char* format, ...);
+
+    // Append string data to the log message.
+    void AppendVA(const char* format, va_list args);
+
+    // Append a character to the log message.
+    void Append(const char c);
+
+    // Append double quoted string to the log message.
+    void AppendDoubleQuotedString(const char* string);
+
+    // Append a portion of a string.
+    void AppendStringPart(const char* str, int len);
+
+    // Write the log message to the log file currently opened.
+    void WriteToLogFile();
+
+   private:
+    TracingLogger* logger_;
+    base::LockGuard<base::Mutex> lock_guard_;
+    int pos_;
+  };
+
+ private:
+  friend class TracingController;
+
+  explicit TracingLogger();
+  // Opens file for logging.
+  void OpenFile(const char* name);
+
+  // Implementation of writing to a log file.
+  int WriteToFile(const char* msg, int length) {
+    DCHECK(output_handle_ != NULL);
+    size_t rv = fwrite(msg, 1, length, output_handle_);
+    DCHECK(static_cast<size_t>(length) == rv);
+    USE(rv);
+    fflush(output_handle_);
+    return length;
+  }
+
+  // Whether logging is stopped (e.g. due to insufficient resources).
+  bool is_stopped_;
+
+  // When logging is active output_handle_ is used to store a pointer to log
+  // destination.  mutex_ should be acquired before using output_handle_.
+  FILE* output_handle_;
+
+  // mutex_ is a Mutex used for enforcing exclusive
+  // access to the formatting buffer and the log file or log memory buffer.
+  base::Mutex mutex_;
+
+  // Buffer used for formatting log messages. This is a singleton buffer and
+  // mutex_ should be acquired before using it.
+  char* message_buffer_;
+};
+
+TracingLogger::TracingLogger()
+    : is_stopped_(false),
+      output_handle_(NULL),
+      message_buffer_(NULL) {}
+
+void TracingLogger::Initialize(const char* log_file_name) {
+  message_buffer_ = i::NewArray<char>(kMessageBufferSize);
+  // If we're logging anything, we need to open the log file.
+  OpenFile(log_file_name);
+  if (output_handle_ != nullptr) {
+    TracingLogger::MessageBuilder msg(this);
+    msg.Append("v8-version,%d,%d,%d,%d,%d", i::Version::GetMajor(),
+               i::Version::GetMinor(), i::Version::GetBuild(),
+               i::Version::GetPatch(), i::Version::IsCandidate());
+    msg.WriteToLogFile();
+  }
+}
+
+void TracingLogger::OpenFile(const char* name) {
+  DCHECK(!IsEnabled());
+  output_handle_ = base::OS::FOpen(name, base::OS::LogFileOpenMode);
+}
+
+FILE* TracingLogger::Close() {
+  FILE* result = NULL;
+  if (output_handle_ != NULL) {
+    fclose(output_handle_);
+  }
+  output_handle_ = NULL;
+  i::DeleteArray(message_buffer_);
+  message_buffer_ = NULL;
+  is_stopped_ = false;
+  return result;
+}
+
+void TracingLogger::SharedLibraryEvent(const std::string& library_path,
+                                       uintptr_t start,
+                                       uintptr_t end) {
+  TracingLogger::MessageBuilder msg(this);
+  msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR,
+             library_path.c_str(), start, end);
+  msg.WriteToLogFile();
+}
+
+void TracingLogger::BeginEvent(const char* event_name) {
+  TracingLogger::MessageBuilder msg(this);
+  msg.Append("%s,\"begin\"", event_name);
+  msg.WriteToLogFile();
+}
+
+void TracingLogger::EndEvent(const char* event_name) {
+  TracingLogger::MessageBuilder msg(this);
+  msg.Append("%s,\"end\"", event_name);
+  msg.WriteToLogFile();
+}
+
+
+TracingLogger::MessageBuilder::MessageBuilder(TracingLogger* logger)
+  : logger_(logger),
+    lock_guard_(&logger_->mutex_),
+    pos_(0) {
+  DCHECK(logger_->message_buffer_ != NULL);
+}
+
+void TracingLogger::MessageBuilder::Append(const char* format, ...) {
+  i::Vector<char> buf(logger_->message_buffer_ + pos_,
+                      TracingLogger::kMessageBufferSize - pos_);
+  va_list args;
+  va_start(args, format);
+  AppendVA(format, args);
+  va_end(args);
+  DCHECK(pos_ <= TracingLogger::kMessageBufferSize);
+}
+
+void TracingLogger::MessageBuilder::AppendVA(const char* format, va_list args) {
+  i::Vector<char> buf(logger_->message_buffer_ + pos_,
+                      TracingLogger::kMessageBufferSize - pos_);
+  int result = v8::internal::VSNPrintF(buf, format, args);
+
+  // Result is -1 if output was truncated.
+  if (result >= 0) {
+    pos_ += result;
+  } else {
+    pos_ = TracingLogger::kMessageBufferSize;
+  }
+  DCHECK(pos_ <= TracingLogger::kMessageBufferSize);
+}
+
+void TracingLogger::MessageBuilder::Append(const char c) {
+  if (pos_ < TracingLogger::kMessageBufferSize) {
+    logger_->message_buffer_[pos_++] = c;
+  }
+  DCHECK(pos_ <= TracingLogger::kMessageBufferSize);
+}
+
+void TracingLogger::MessageBuilder::AppendDoubleQuotedString(const char* string) {
+  Append('"');
+  for (const char* p = string; *p != '\0'; p++) {
+    if (*p == '"') {
+      Append('\\');
+    }
+    Append(*p);
+  }
+  Append('"');
+}
+
+void TracingLogger::MessageBuilder::AppendStringPart(const char* str, int len) {
+  if (pos_ + len > TracingLogger::kMessageBufferSize) {
+    len = TracingLogger::kMessageBufferSize - pos_;
+    DCHECK(len >= 0);
+    if (len == 0) return;
+  }
+  i::Vector<char> buf(logger_->message_buffer_ + pos_,
+                      TracingLogger::kMessageBufferSize - pos_);
+  StrNCpy(buf, str, len);
+  pos_ += len;
+  DCHECK(pos_ <= TracingLogger::kMessageBufferSize);
+}
+
+void TracingLogger::MessageBuilder::WriteToLogFile() {
+  DCHECK(pos_ <= TracingLogger::kMessageBufferSize);
+  // Assert that we do not already have a new line at the end.
+  DCHECK(pos_ == 0 || logger_->message_buffer_[pos_ - 1] != '\n');
+  if (pos_ == TracingLogger::kMessageBufferSize) pos_--;
+  logger_->message_buffer_[pos_++] = '\n';
+  const int written = logger_->WriteToFile(logger_->message_buffer_, pos_);
+  if (written != pos_) {
+    logger_->stop();
+  }
+}
+
+
+// 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();
+  void Engage();
+  void Disengage();
+
+  // Inserts collected profiling data into buffer.
+  void Insert(i::TickSample* sample) {
+    if (paused_)
+      return;
+
+    if (Succ(head_) == static_cast<int>(base::NoBarrier_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(i::TickSample* sample) {
+    buffer_semaphore_.Wait();  // Wait for an element.
+    *sample = buffer_[base::NoBarrier_Load(&tail_)];
+    bool result = overflow_;
+    base::NoBarrier_Store(&tail_, static_cast<base::Atomic32>(
+                                      Succ(base::NoBarrier_Load(&tail_))));
+    overflow_ = false;
+    return result;
+  }
+
+  // Returns the next index in the cyclic buffer.
+  int Succ(int index) { return (index + 1) % kBufferSize; }
+
+  // Cyclic buffer for communicating profiling samples
+  // between the signal handler and the worker thread.
+  static const int kBufferSize = 128;
+  i::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 samples to the tracing controller.
+//
+class Ticker: public V8Sampler {
+ public:
+  Ticker(Isolate* isolate):
+      V8Sampler(isolate),
+      profiler_(NULL) {}
+
+  ~Ticker() { if (IsActive()) Stop(); }
+
+  void SetProfiler(Profiler* profiler) {
+    DCHECK(profiler_ == NULL);
+    profiler_ = profiler;
+    IncreaseProfilingDepth();
+    if (!IsActive())
+      Start();
+  }
+
+  void ClearProfiler() {
+    profiler_ = NULL;
+    if (IsActive()) Stop();
+    DecreaseProfilingDepth();
+  }
+
+  void Tick(i::TickSample* sample) override {
+    if (profiler_) profiler_->Insert(sample);
+  }
+
+ private:
+  Profiler* profiler_;
+};
+
+
+//
+// Profiler implementation.
+//
+Profiler::Profiler()
+    : base::Thread(Options("v8:Profiler")),
+      head_(0),
+      overflow_(false),
+      buffer_semaphore_(0),
+      engaged_(false),
+      paused_(false) {
+  base::NoBarrier_Store(&tail_, 0);
+  base::NoBarrier_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) {
+    TracingController::tracing_controller_->logger_->SharedLibraryEvent(
+        addresses[i].library_path, addresses[i].start, addresses[i].end);
+  }
+
+  // Start thread processing the profiler buffer.
+  base::NoBarrier_Store(&running_, 1);
+  Start();
+
+  TracingLogger::MessageBuilder msg(
+      TracingController::tracing_controller_->logger_);
+}
+
+void Profiler::Disengage() {
+  if (!engaged_) return;
+
+  // Stop receiving ticks.
+  TracingController::tracing_controller_->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::NoBarrier_Store(&running_, 0);
+  i::TickSample sample;
+  // Reset 'paused_' flag, otherwise semaphore may not be signalled.
+  resume();
+  Insert(&sample);
+  Join();
+
+  TracingLogger::MessageBuilder msg(TracingController::tracing_controller_->logger_);
+}
+
+void Profiler::Run() {
+  i::TickSample sample;
+  bool overflow = Remove(&sample);
+  while (base::NoBarrier_Load(&running_)) {
+    TracingController::tracing_controller_->LogSample(&sample, overflow);
+    overflow = Remove(&sample);
+  }
+}
+
+
+base::Mutex* TracingController::mutex_ = NULL;
+TracingController* TracingController::tracing_controller_ = NULL;
+
+void TracingController::StartTracing(Isolate* isolate) {
+  base::LockGuard<base::Mutex> lock_guard(mutex_);
+  if (TracingController::tracing_controller_ == NULL) {
+    TracingController::tracing_controller_ = new TracingController(isolate);
+  }
+  TracingController::tracing_controller_->Start();
+}
+
+void TracingController::StopTracing() {
+  base::LockGuard<base::Mutex> lock_guard(mutex_);
+  if (TracingController::tracing_controller_ != NULL) {
+    TracingController::tracing_controller_->Stop();
+  }
+}
+
+void TracingController::InstallJitCodeEventHandler(Isolate* isolate, void* data) {
+  TracingController::tracing_controller_->ticker_->SetJitCodeEventHandler(
+      v8::JitCodeEventOptions::kJitCodeEventEnumExisting, data);
+}
+
+void TracingController::HandleJitCodeEvent(const JitCodeEvent* event) {
+}
+
+void TracingController::SetInterval(int interval) {
+  V8Sampler::SetInterval(interval);
+}
+
+TracingController::TracingController(Isolate* isolate)
+    : is_tracing_(false),
+      profiler_(NULL),
+      ticker_(NULL),
+      logger_(new TracingLogger()) {
+  isolate_ = isolate;
+}
+
+void TracingController::Start() {
+  if (is_tracing_)
+    return;
+  is_tracing_ = true;
+  logger_->Initialize("d8.log");
+  timer_.Start();
+  profiler_ = new Profiler();
+  profiler_->Engage();
+  ticker_ = new Ticker(isolate_);
+  v8::JitCodeEventHandler handler = &HandleJitCodeEvent;
+  isolate_->RequestInterrupt(&InstallJitCodeEventHandler,
+                             reinterpret_cast<void*>(handler));
+  ticker_->SetProfiler(profiler_);
+}
+
+void TracingController::Stop() {
+  if (!is_tracing_)
+    return;
+  is_tracing_ = false;
+  // Stop the profiler before closing the file.
+  if (profiler_ != NULL) {
+    profiler_->Disengage();
+    delete profiler_;
+    profiler_ = NULL;
+  }
+
+  ticker_->ClearProfiler();
+  delete ticker_;
+  ticker_ = NULL;
+
+  logger_->Close();
+  logger_ = NULL;
+
+  delete tracing_controller_;
+  tracing_controller_ = NULL;
+}
+
+void TracingController::LogSample(i::TickSample* sample, bool overflow) {
+  /*
+  TracingLogger::MessageBuilder msg(logger_);
+  msg.Append("%s,", "tick");
+  msg.Append("0x%x", sample->pc);
+  msg.Append(",%ld", static_cast<int>(timer_.Elapsed().InMicroseconds()));
+  if (sample->has_external_callback) {
+    msg.Append(",1,");
+#if USES_FUNCTION_DESCRIPTORS
+    msg.Append("0x%x", *FUNCTION_ENTRYPOINT_ADDRESS(sample->external_callback));
+#else
+    msg.Append("0x%x", sample->external_callback);
+#endif
+  } else {
+    msg.Append(",0,");
+    msg.Append("0x%x", 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.Append("0x%x", sample->stack[i]);
+  }
+  msg.WriteToLogFile();
+  */
+}
+
+}