src: Node Tracing Controller

This commit adds support for trace-event tracing to Node.js. It provides
a mechanism to centralize tracing information generated by V8, Node
core, and userspace code. It includes:

 - A trace writer responsible for serializing traces and cycling the
   output files so that no individual file becomes to large.
 - A buffer for aggregating traces to allow for batched flushes.
 - An agent which initializes the tracing controller and ensures that
   trace serialization is done on a separate thread.
 - A set of macros for generating trace events.
 - Tests and documentation.

Author: Raymond Kang <raymondksi@gmail.com>
Author: Kelvin Jin <kelvinjin@google.com>
Author: Matthew Loring <mattloring@google.com>
Author: Jason Ginchereau <jasongin@microsoft.com>

PR-URL: https://github.com/nodejs/node/pull/9304

Reviewed-By: Trevor Norris <trev.norris@gmail.com>
Reviewed-By: Michael Dawson <michael_dawson@ca.ibm.com>
Reviewed-By: Josh Gavant <josh.gavant@outlook.com>

doc/api/cli.md

@@ -129,6 +129,20 @@ added: v2.1.0
 Prints a stack trace whenever synchronous I/O is detected after the first turn
 of the event loop.
 
+### `--trace-events-enabled`
+<!-- YAML
+added: REPLACEME
+-->
+
+Enables the collection of trace event tracing information.
+
+### `--trace-event-categories`
+<!-- YAML
+added: REPLACEME
+-->
+
+A comma separated list of categories that should be traced when trace event
+tracing is enabled using `--trace-events-enabled`.
 
 ### `--zero-fill-buffers`
 <!-- YAML

doc/api/tracing.md

@@ -0,0 +1,19 @@
+# Tracing
+
+Trace Event provides a mechanism to centralize tracing information generated by
+V8, Node core, and userspace code.
+
+Tracing can be enabled by passing the `--trace-events-enabled` flag when starting a
+Node.js application.
+
+The set of categories for which traces are recorded can be specified using the
+`--trace-event-categories` flag followed by a list of comma separated category names.
+By default the `node` and `v8` categories are enabled.
+
+```txt
+node --trace-events-enabled --trace-event-categories v8,node server.js
+```
+
+Running Node.js with tracing enabled will produce log files that can be opened
+in the [`chrome://tracing`](https://www.chromium.org/developers/how-tos/trace-event-profiling-tool)
+tab of Chrome.

node.gyp

@@ -140,6 +140,10 @@
       ],
 
       'sources': [
+        'src/tracing/agent.cc',
+        'src/tracing/node_trace_buffer.cc',
+        'src/tracing/node_trace_writer.cc',
+        'src/tracing/trace_event.cc',
         'src/debug-agent.cc',
         'src/async-wrap.cc',
         'src/env.cc',
@@ -217,6 +221,7 @@
         'src/stream_base.h',
         'src/stream_base-inl.h',
         'src/stream_wrap.h',
+        'src/tracing/trace_event.h'
         'src/tree.h',
         'src/util.h',
         'src/util-inl.h',

src/node.cc

@@ -38,6 +38,7 @@
 #include "req-wrap.h"
 #include "req-wrap-inl.h"
 #include "string_bytes.h"
+#include "tracing/agent.h"
 #include "util.h"
 #include "uv.h"
 #if NODE_USE_V8_PLATFORM
@@ -150,6 +151,8 @@ static node_module* modpending;
 static node_module* modlist_builtin;
 static node_module* modlist_linked;
 static node_module* modlist_addon;
+static bool trace_enabled = false;
+static const char* trace_enabled_categories = nullptr;
 
 #if defined(NODE_HAVE_I18N_SUPPORT)
 // Path to ICU data (for i18n / Intl)
@@ -186,6 +189,7 @@ static uv_async_t dispatch_debug_messages_async;
 
 static Mutex node_isolate_mutex;
 static v8::Isolate* node_isolate;
+static tracing::Agent* tracing_agent;
 
 static node::DebugOptions debug_options;
 
@@ -194,6 +198,7 @@ static struct {
   void Initialize(int thread_pool_size) {
     platform_ = v8::platform::CreateDefaultPlatform(thread_pool_size);
     V8::InitializePlatform(platform_);
+    tracing::TraceEventHelper::SetCurrentPlatform(platform_);
   }
 
   void PumpMessageLoop(Isolate* isolate) {
@@ -3368,6 +3373,9 @@ void SetupProcessObject(Environment* env,
 
 void SignalExit(int signo) {
   uv_tty_reset_mode();
+  if (trace_enabled) {
+    tracing_agent->Stop();
+  }
 #ifdef __FreeBSD__
   // FreeBSD has a nasty bug, see RegisterSignalHandler for details
   struct sigaction sa;
@@ -3469,7 +3477,8 @@ static void PrintHelp() {
          "  -c, --check              syntax check script without executing\n"
          "  -i, --interactive        always enter the REPL even if stdin\n"
          "                           does not appear to be a terminal\n"
-         "  -r, --require         module to preload (option can be repeated)\n"
+         "  -r, --require            module to preload (option can be "
+         "repeated)\n"
          "  --no-deprecation         silence deprecation warnings\n"
          "  --trace-deprecation      show stack traces on deprecations\n"
          "  --throw-deprecation      throw an exception anytime a deprecated "
@@ -3478,16 +3487,21 @@ static void PrintHelp() {
          "  --trace-warnings         show stack traces on process warnings\n"
          "  --trace-sync-io          show stack trace when use of sync IO\n"
          "                           is detected after the first tick\n"
+         "  --trace-events-enabled   track trace events\n"
+         "  --trace-event-categories comma separated list of trace event\n"
+         "                           categories to record\n"
          "  --track-heap-objects     track heap object allocations for heap "
          "snapshots\n"
          "  --prof-process           process v8 profiler output generated\n"
          "                           using --prof\n"
-         "  --zero-fill-buffers   automatically zero-fill all newly allocated\n"
+         "  --zero-fill-buffers      automatically zero-fill all newly "
+         "allocated\n"
          "                           Buffer and SlowBuffer instances\n"
          "  --v8-options             print v8 command line options\n"
          "  --v8-pool-size=num       set v8's thread pool size\n"
 #if HAVE_OPENSSL
-         "  --tls-cipher-list=val use an alternative default TLS cipher list\n"
+         "  --tls-cipher-list=val    use an alternative default TLS cipher "
+         "list\n"
 #if NODE_FIPS_MODE
          "  --enable-fips            enable FIPS crypto at startup\n"
          "  --force-fips             force FIPS crypto (cannot be disabled)\n"
@@ -3626,6 +3640,16 @@ static void ParseArgs(int* argc,
       trace_deprecation = true;
     } else if (strcmp(arg, "--trace-sync-io") == 0) {
       trace_sync_io = true;
+    } else if (strcmp(arg, "--trace-events-enabled") == 0) {
+      trace_enabled = true;
+    } else if (strcmp(arg, "--trace-event-categories") == 0) {
+      const char* categories = argv[index + 1];
+      if (categories == nullptr) {
+        fprintf(stderr, "%s: %s requires an argument\n", argv[0], arg);
+        exit(9);
+      }
+      args_consumed += 1;
+      trace_enabled_categories = categories;
     } else if (strcmp(arg, "--track-heap-objects") == 0) {
       track_heap_objects = true;
     } else if (strcmp(arg, "--throw-deprecation") == 0) {
@@ -4454,10 +4478,20 @@ int Start(int argc, char** argv) {
 #endif
 
   v8_platform.Initialize(v8_thread_pool_size);
+  // Enable tracing when argv has --trace-events-enabled.
+  if (trace_enabled) {
+    fprintf(stderr, "Warning: Trace event is an experimental feature "
+            "and could change at any time.\n");
+    tracing_agent = new tracing::Agent();
+    tracing_agent->Start(v8_platform.platform_, trace_enabled_categories);
+  }
   V8::Initialize();
   v8_initialized = true;
   const int exit_code =
       Start(uv_default_loop(), argc, argv, exec_argc, exec_argv);
+  if (trace_enabled) {
+    tracing_agent->Stop();
+  }
   v8_initialized = false;
   V8::Dispose();
 

src/node.h

@@ -41,6 +41,7 @@
 
 #include "v8.h"  // NOLINT(build/include_order)
 #include "node_version.h"  // NODE_MODULE_VERSION
+#include "tracing/trace_event.h"
 
 #define NODE_MAKE_VERSION(major, minor, patch)                                \
   ((major) * 0x1000 + (minor) * 0x100 + (patch))

src/tracing/agent.cc

@@ -0,0 +1,72 @@
+#include "tracing/agent.h"
+
+#include <sstream>
+#include <string>
+
+#include "env-inl.h"
+#include "libplatform/libplatform.h"
+
+namespace node {
+namespace tracing {
+
+using v8::platform::tracing::TraceConfig;
+
+Agent::Agent() {}
+
+void Agent::Start(v8::Platform* platform, const char* enabled_categories) {
+  platform_ = platform;
+
+  int err = uv_loop_init(&tracing_loop_);
+  CHECK_EQ(err, 0);
+
+  NodeTraceWriter* trace_writer = new NodeTraceWriter(&tracing_loop_);
+  TraceBuffer* trace_buffer = new NodeTraceBuffer(
+      NodeTraceBuffer::kBufferChunks, trace_writer, &tracing_loop_);
+
+  tracing_controller_ = new TracingController();
+
+  TraceConfig* trace_config = new TraceConfig();
+  if (enabled_categories) {
+    std::stringstream category_list(enabled_categories);
+    while (category_list.good()) {
+      std::string category;
+      getline(category_list, category, ',');
+      trace_config->AddIncludedCategory(category.c_str());
+    }
+  } else {
+    trace_config->AddIncludedCategory("v8");
+    trace_config->AddIncludedCategory("node");
+  }
+
+  // This thread should be created *after* async handles are created
+  // (within NodeTraceWriter and NodeTraceBuffer constructors).
+  // Otherwise the thread could shut down prematurely.
+  err = uv_thread_create(&thread_, ThreadCb, this);
+  CHECK_EQ(err, 0);
+
+  tracing_controller_->Initialize(trace_buffer);
+  tracing_controller_->StartTracing(trace_config);
+  v8::platform::SetTracingController(platform, tracing_controller_);
+}
+
+void Agent::Stop() {
+  if (!IsStarted()) {
+    return;
+  }
+  // Perform final Flush on TraceBuffer. We don't want the tracing controller
+  // to flush the buffer again on destruction of the V8::Platform.
+  tracing_controller_->StopTracing();
+  delete tracing_controller_;
+  // Thread should finish when the tracing loop is stopped.
+  uv_thread_join(&thread_);
+  v8::platform::SetTracingController(platform_, nullptr);
+}
+
+// static
+void Agent::ThreadCb(void* arg) {
+  Agent* agent = static_cast<Agent*>(arg);
+  uv_run(&agent->tracing_loop_, UV_RUN_DEFAULT);
+}
+
+}  // namespace tracing
+}  // namespace node

src/tracing/agent.h

@@ -0,0 +1,31 @@
+#ifndef SRC_TRACING_AGENT_H_
+#define SRC_TRACING_AGENT_H_
+
+#include "tracing/node_trace_buffer.h"
+#include "tracing/node_trace_writer.h"
+#include "uv.h"
+#include "v8.h"
+
+namespace node {
+namespace tracing {
+
+class Agent {
+ public:
+  explicit Agent();
+  void Start(v8::Platform* platform, const char* enabled_categories);
+  void Stop();
+
+ private:
+  bool IsStarted() { return platform_ != nullptr; }
+  static void ThreadCb(void* arg);
+
+  uv_thread_t thread_;
+  uv_loop_t tracing_loop_;
+  v8::Platform* platform_ = nullptr;
+  TracingController* tracing_controller_;
+};
+
+}  // namespace tracing
+}  // namespace node
+
+#endif  // SRC_TRACING_AGENT_H_

src/tracing/node_trace_buffer.cc

@@ -0,0 +1,177 @@
+#include "tracing/node_trace_buffer.h"
+
+namespace node {
+namespace tracing {
+
+InternalTraceBuffer::InternalTraceBuffer(size_t max_chunks, uint32_t id,
+    NodeTraceWriter* trace_writer, NodeTraceBuffer* external_buffer)
+    : id_(id), flushing_(false), max_chunks_(max_chunks),
+      trace_writer_(trace_writer), external_buffer_(external_buffer) {
+  chunks_.resize(max_chunks);
+}
+
+TraceObject* InternalTraceBuffer::AddTraceEvent(uint64_t* handle) {
+  Mutex::ScopedLock scoped_lock(mutex_);
+  // Create new chunk if last chunk is full or there is no chunk.
+  if (total_chunks_ == 0 || chunks_[total_chunks_ - 1]->IsFull()) {
+    auto& chunk = chunks_[total_chunks_++];
+    if (chunk) {
+      chunk->Reset(current_chunk_seq_++);
+    } else {
+      chunk.reset(new TraceBufferChunk(current_chunk_seq_++));
+    }
+  }
+  auto& chunk = chunks_[total_chunks_ - 1];
+  size_t event_index;
+  TraceObject* trace_object = chunk->AddTraceEvent(&event_index);
+  *handle = MakeHandle(total_chunks_ - 1, chunk->seq(), event_index);
+  return trace_object;
+}
+
+TraceObject* InternalTraceBuffer::GetEventByHandle(uint64_t handle) {
+  Mutex::ScopedLock scoped_lock(mutex_);
+  if (handle == 0) {
+    // A handle value of zero never has a trace event associated with it.
+    return NULL;
+  }
+  size_t chunk_index, event_index;
+  uint32_t buffer_id, chunk_seq;
+  ExtractHandle(handle, &buffer_id, &chunk_index, &chunk_seq, &event_index);
+  if (buffer_id != id_ || chunk_index >= total_chunks_) {
+    // Either the chunk belongs to the other buffer, or is outside the current
+    // range of chunks loaded in memory (the latter being true suggests that
+    // the chunk has already been flushed and is no longer in memory.)
+    return NULL;
+  }
+  auto& chunk = chunks_[chunk_index];
+  if (chunk->seq() != chunk_seq) {
+    // Chunk is no longer in memory.
+    return NULL;
+  }
+  return chunk->GetEventAt(event_index);
+}
+
+void InternalTraceBuffer::Flush(bool blocking) {
+  {
+    Mutex::ScopedLock scoped_lock(mutex_);
+    if (total_chunks_ > 0) {
+      flushing_ = true;
+      for (size_t i = 0; i < total_chunks_; ++i) {
+        auto& chunk = chunks_[i];
+        for (size_t j = 0; j < chunk->size(); ++j) {
+          trace_writer_->AppendTraceEvent(chunk->GetEventAt(j));
+        }
+      }
+      total_chunks_ = 0;
+      flushing_ = false;
+    }
+  }
+  trace_writer_->Flush(blocking);
+}
+
+uint64_t InternalTraceBuffer::MakeHandle(
+    size_t chunk_index, uint32_t chunk_seq, size_t event_index) const {
+  return ((static_cast<uint64_t>(chunk_seq) * Capacity() +
+          chunk_index * TraceBufferChunk::kChunkSize + event_index) << 1) + id_;
+}
+
+void InternalTraceBuffer::ExtractHandle(
+    uint64_t handle, uint32_t* buffer_id, size_t* chunk_index,
+    uint32_t* chunk_seq, size_t* event_index) const {
+  *buffer_id = static_cast<uint32_t>(handle & 0x1);
+  handle >>= 1;
+  *chunk_seq = static_cast<uint32_t>(handle / Capacity());
+  size_t indices = handle % Capacity();
+  *chunk_index = indices / TraceBufferChunk::kChunkSize;
+  *event_index = indices % TraceBufferChunk::kChunkSize;
+}
+
+NodeTraceBuffer::NodeTraceBuffer(size_t max_chunks,
+    NodeTraceWriter* trace_writer, uv_loop_t* tracing_loop)
+    : tracing_loop_(tracing_loop), trace_writer_(trace_writer),
+      buffer1_(max_chunks, 0, trace_writer, this),
+      buffer2_(max_chunks, 1, trace_writer, this) {
+  current_buf_.store(&buffer1_);
+
+  flush_signal_.data = this;
+  int err = uv_async_init(tracing_loop_, &flush_signal_, NonBlockingFlushSignalCb);
+  CHECK_EQ(err, 0);
+
+  exit_signal_.data = this;
+  err = uv_async_init(tracing_loop_, &exit_signal_, ExitSignalCb);
+  CHECK_EQ(err, 0);
+}
+
+NodeTraceBuffer::~NodeTraceBuffer() {
+  uv_async_send(&exit_signal_);
+  Mutex::ScopedLock scoped_lock(exit_mutex_);
+  while(!exited_) {
+    exit_cond_.Wait(scoped_lock);
+  }
+}
+
+TraceObject* NodeTraceBuffer::AddTraceEvent(uint64_t* handle) {
+  // If the buffer is full, attempt to perform a flush.
+  if (!TryLoadAvailableBuffer()) {
+    // Assign a value of zero as the trace event handle.
+    // This is equivalent to calling InternalTraceBuffer::MakeHandle(0, 0, 0),
+    // and will cause GetEventByHandle to return NULL if passed as an argument.
+    *handle = 0;
+    return nullptr;
+  }
+  return current_buf_.load()->AddTraceEvent(handle);
+}
+
+TraceObject* NodeTraceBuffer::GetEventByHandle(uint64_t handle) {
+  return current_buf_.load()->GetEventByHandle(handle);
+}
+
+bool NodeTraceBuffer::Flush() {
+  buffer1_.Flush(true);
+  buffer2_.Flush(true);
+  return true;
+}
+
+// Attempts to set current_buf_ such that it references a buffer that can
+// can write at least one trace event. If both buffers are unavailable this
+// method returns false; otherwise it returns true.
+bool NodeTraceBuffer::TryLoadAvailableBuffer() {
+  InternalTraceBuffer* prev_buf = current_buf_.load();
+  if (prev_buf->IsFull()) {
+    uv_async_send(&flush_signal_); // trigger flush on a separate thread
+    InternalTraceBuffer* other_buf = prev_buf == &buffer1_ ?
+      &buffer2_ : &buffer1_;
+    if (!other_buf->IsFull()) {
+      current_buf_.store(other_buf);
+    } else {
+      return false;
+    }
+  }
+  return true;
+}
+
+// static
+void NodeTraceBuffer::NonBlockingFlushSignalCb(uv_async_t* signal) {
+  NodeTraceBuffer* buffer = reinterpret_cast<NodeTraceBuffer*>(signal->data);
+  if (buffer->buffer1_.IsFull() && !buffer->buffer1_.IsFlushing()) {
+    buffer->buffer1_.Flush(false);
+  }
+  if (buffer->buffer2_.IsFull() && !buffer->buffer2_.IsFlushing()) {
+    buffer->buffer2_.Flush(false);
+  }
+}
+
+// static
+void NodeTraceBuffer::ExitSignalCb(uv_async_t* signal) {
+  NodeTraceBuffer* buffer = reinterpret_cast<NodeTraceBuffer*>(signal->data);
+  uv_close(reinterpret_cast<uv_handle_t*>(&buffer->flush_signal_), nullptr);
+  uv_close(reinterpret_cast<uv_handle_t*>(&buffer->exit_signal_), [](uv_handle_t* signal) {
+      NodeTraceBuffer* buffer = reinterpret_cast<NodeTraceBuffer*>(signal->data);
+      Mutex::ScopedLock scoped_lock(buffer->exit_mutex_);
+      buffer->exited_ = true;
+      buffer->exit_cond_.Signal(scoped_lock);
+  });
+}
+
+}  // namespace tracing
+}  // namespace node

src/tracing/node_trace_buffer.h

@@ -0,0 +1,89 @@
+#ifndef SRC_NODE_TRACE_BUFFER_H_
+#define SRC_NODE_TRACE_BUFFER_H_
+
+#include "node_mutex.h"
+#include "tracing/node_trace_writer.h"
+#include "libplatform/v8-tracing.h"
+
+#include <atomic>
+
+namespace node {
+namespace tracing {
+
+using v8::platform::tracing::TraceBuffer;
+using v8::platform::tracing::TraceBufferChunk;
+using v8::platform::tracing::TraceObject;
+
+// forward declaration
+class NodeTraceBuffer;
+
+class InternalTraceBuffer {
+ public:
+  InternalTraceBuffer(size_t max_chunks, uint32_t id,
+                      NodeTraceWriter* trace_writer,
+                      NodeTraceBuffer* external_buffer);
+
+  TraceObject* AddTraceEvent(uint64_t* handle);
+  TraceObject* GetEventByHandle(uint64_t handle);
+  void Flush(bool blocking);
+  bool IsFull() const {
+    return total_chunks_ == max_chunks_ && chunks_[total_chunks_ - 1]->IsFull();
+  }
+  bool IsFlushing() const {
+    return flushing_;
+  }
+
+ private:
+  uint64_t MakeHandle(size_t chunk_index, uint32_t chunk_seq,
+                      size_t event_index) const;
+  void ExtractHandle(uint64_t handle, uint32_t* buffer_id, size_t* chunk_index,
+                     uint32_t* chunk_seq, size_t* event_index) const;
+  size_t Capacity() const { return max_chunks_ * TraceBufferChunk::kChunkSize; }
+
+  Mutex mutex_;
+  bool flushing_;
+  size_t max_chunks_;
+  NodeTraceWriter* trace_writer_;
+  NodeTraceBuffer* external_buffer_;
+  std::vector<std::unique_ptr<TraceBufferChunk>> chunks_;
+  size_t total_chunks_ = 0;
+  uint32_t current_chunk_seq_ = 1;
+  uint32_t id_;
+};
+
+class NodeTraceBuffer : public TraceBuffer {
+ public:
+  NodeTraceBuffer(size_t max_chunks, NodeTraceWriter* trace_writer,
+                  uv_loop_t* tracing_loop);
+  ~NodeTraceBuffer();
+
+  TraceObject* AddTraceEvent(uint64_t* handle) override;
+  TraceObject* GetEventByHandle(uint64_t handle) override;
+  bool Flush() override;
+
+  static const size_t kBufferChunks = 1024;
+
+ private:
+  bool TryLoadAvailableBuffer();
+  static void NonBlockingFlushSignalCb(uv_async_t* signal);
+  static void ExitSignalCb(uv_async_t* signal);
+
+  uv_loop_t* tracing_loop_;
+  uv_async_t flush_signal_;
+  uv_async_t exit_signal_;
+  bool exited_ = false;
+  // Used exclusively for exit logic.
+  Mutex exit_mutex_;
+  // Used to wait until async handles have been closed.
+  ConditionVariable exit_cond_;
+  std::unique_ptr<NodeTraceWriter> trace_writer_;
+  // TODO: Change std::atomic to something less contentious.
+  std::atomic<InternalTraceBuffer*> current_buf_;
+  InternalTraceBuffer buffer1_;
+  InternalTraceBuffer buffer2_;
+};
+
+}  // namespace tracing
+}  // namespace node
+
+#endif  // SRC_NODE_TRACING_CONTROLLER_H_

src/tracing/node_trace_writer.cc

@@ -0,0 +1,185 @@
+#include "tracing/node_trace_writer.h"
+
+#include <string.h>
+#include <fcntl.h>
+
+#include "util.h"
+
+namespace node {
+namespace tracing {
+
+NodeTraceWriter::NodeTraceWriter(uv_loop_t* tracing_loop)
+    : tracing_loop_(tracing_loop) {
+  flush_signal_.data = this;
+  int err = uv_async_init(tracing_loop_, &flush_signal_, FlushSignalCb);
+  CHECK_EQ(err, 0);
+
+  exit_signal_.data = this;
+  err = uv_async_init(tracing_loop_, &exit_signal_, ExitSignalCb);
+  CHECK_EQ(err, 0);
+}
+
+void NodeTraceWriter::WriteSuffix() {
+  // If our final log file has traces, then end the file appropriately.
+  // This means that if no trace events are recorded, then no trace file is
+  // produced.
+  bool should_flush = false;
+  {
+    Mutex::ScopedLock scoped_lock(stream_mutex_);
+    if (total_traces_ > 0) {
+      total_traces_ = 0; // so we don't write it again in FlushPrivate
+      // Appends "]}" to stream_.
+      delete json_trace_writer_;
+      should_flush = true;
+    }
+  }
+  if (should_flush) {
+    Flush(true);
+  }
+}
+
+NodeTraceWriter::~NodeTraceWriter() {
+  WriteSuffix();
+  uv_fs_t req;
+  int err;
+  if (fd_ != -1) {
+    err = uv_fs_close(tracing_loop_, &req, fd_, nullptr);
+    CHECK_EQ(err, 0);
+    uv_fs_req_cleanup(&req);
+  }
+  uv_async_send(&exit_signal_);
+  Mutex::ScopedLock scoped_lock(request_mutex_);
+  while(!exited_) {
+    exit_cond_.Wait(scoped_lock);
+  }
+}
+
+void NodeTraceWriter::OpenNewFileForStreaming() {
+  ++file_num_;
+  uv_fs_t req;
+  std::ostringstream log_file;
+  log_file << "node_trace." << file_num_ << ".log";
+  fd_ = uv_fs_open(tracing_loop_, &req, log_file.str().c_str(),
+      O_CREAT | O_WRONLY | O_TRUNC, 0644, NULL);
+  CHECK_NE(fd_, -1);
+  uv_fs_req_cleanup(&req);
+}
+
+void NodeTraceWriter::AppendTraceEvent(TraceObject* trace_event) {
+  Mutex::ScopedLock scoped_lock(stream_mutex_);
+  // If this is the first trace event, open a new file for streaming.
+  if (total_traces_ == 0) {
+    OpenNewFileForStreaming();
+    // Constructing a new JSONTraceWriter object appends "{\"traceEvents\":["
+    // to stream_.
+    // In other words, the constructor initializes the serialization stream
+    // to a state where we can start writing trace events to it.
+    // Repeatedly constructing and destroying json_trace_writer_ allows
+    // us to use V8's JSON writer instead of implementing our own.
+    json_trace_writer_ = TraceWriter::CreateJSONTraceWriter(stream_);
+  }
+  ++total_traces_;
+  json_trace_writer_->AppendTraceEvent(trace_event);
+}
+
+void NodeTraceWriter::FlushPrivate() {
+  std::string str;
+  int highest_request_id;
+  {
+    Mutex::ScopedLock stream_scoped_lock(stream_mutex_);
+    if (total_traces_ >= kTracesPerFile) {
+      total_traces_ = 0;
+      // Destroying the member JSONTraceWriter object appends "]}" to
+      // stream_ - in other words, ending a JSON file.
+      delete json_trace_writer_;
+    }
+    // str() makes a copy of the contents of the stream.
+    str = stream_.str();
+    stream_.str("");
+    stream_.clear();
+  }
+  {
+    Mutex::ScopedLock request_scoped_lock(request_mutex_);
+    highest_request_id = num_write_requests_;
+  }
+  WriteToFile(std::move(str), highest_request_id);
+}
+
+void NodeTraceWriter::FlushSignalCb(uv_async_t* signal) {
+  NodeTraceWriter* trace_writer = static_cast<NodeTraceWriter*>(signal->data);
+  trace_writer->FlushPrivate();
+}
+
+// TODO: Remove (is it necessary to change the API? Since because of WriteSuffix
+// it no longer matters whether it's true or false)
+void NodeTraceWriter::Flush() {
+  Flush(true);
+}
+
+void NodeTraceWriter::Flush(bool blocking) {
+  Mutex::ScopedLock scoped_lock(request_mutex_);
+  if (!json_trace_writer_) {
+    return;
+  }
+  int request_id = ++num_write_requests_;
+  int err = uv_async_send(&flush_signal_);
+  CHECK_EQ(err, 0);
+  if (blocking) {
+    // Wait until data associated with this request id has been written to disk.
+    // This guarantees that data from all earlier requests have also been
+    // written.
+    while (request_id > highest_request_id_completed_) {
+      request_cond_.Wait(scoped_lock);
+    }
+  }
+}
+
+void NodeTraceWriter::WriteToFile(std::string&& str, int highest_request_id) {
+  WriteRequest* write_req = new WriteRequest();
+  write_req->str = std::move(str);
+  write_req->writer = this;
+  write_req->highest_request_id = highest_request_id;
+  uv_buf_t uv_buf = uv_buf_init(const_cast<char*>(write_req->str.c_str()),
+      write_req->str.length());
+  request_mutex_.Lock();
+  // Manage a queue of WriteRequest objects because the behavior of uv_write is
+  // is undefined if the same WriteRequest object is used more than once
+  // between WriteCb calls. In addition, this allows us to keep track of the id
+  // of the latest write request that actually been completed.
+  write_req_queue_.push(write_req);
+  request_mutex_.Unlock();
+  int err = uv_fs_write(tracing_loop_, reinterpret_cast<uv_fs_t*>(write_req),
+      fd_, &uv_buf, 1, -1, WriteCb);
+  CHECK_EQ(err, 0);
+}
+
+void NodeTraceWriter::WriteCb(uv_fs_t* req) {
+  WriteRequest* write_req = reinterpret_cast<WriteRequest*>(req);
+  CHECK_GE(write_req->req.result, 0);
+
+  NodeTraceWriter* writer = write_req->writer;
+  int highest_request_id = write_req->highest_request_id;
+  {
+    Mutex::ScopedLock scoped_lock(writer->request_mutex_);
+    CHECK_EQ(write_req, writer->write_req_queue_.front());
+    writer->write_req_queue_.pop();
+    writer->highest_request_id_completed_ = highest_request_id;
+    writer->request_cond_.Broadcast(scoped_lock);
+  }
+  delete write_req;
+}
+
+// static
+void NodeTraceWriter::ExitSignalCb(uv_async_t* signal) {
+  NodeTraceWriter* trace_writer = static_cast<NodeTraceWriter*>(signal->data);
+  uv_close(reinterpret_cast<uv_handle_t*>(&trace_writer->flush_signal_), nullptr);
+  uv_close(reinterpret_cast<uv_handle_t*>(&trace_writer->exit_signal_), [](uv_handle_t* signal) {
+      NodeTraceWriter* trace_writer = static_cast<NodeTraceWriter*>(signal->data);
+      Mutex::ScopedLock scoped_lock(trace_writer->request_mutex_);
+      trace_writer->exited_ = true;
+      trace_writer->exit_cond_.Signal(scoped_lock);
+  });
+}
+
+}  // namespace tracing
+}  // namespace node

src/tracing/node_trace_writer.h

@@ -0,0 +1,74 @@
+#ifndef SRC_NODE_TRACE_WRITER_H_
+#define SRC_NODE_TRACE_WRITER_H_
+
+#include <sstream>
+#include <queue>
+
+#include "node_mutex.h"
+#include "libplatform/v8-tracing.h"
+#include "uv.h"
+
+namespace node {
+namespace tracing {
+
+using v8::platform::tracing::TraceObject;
+using v8::platform::tracing::TraceWriter;
+using v8::platform::tracing::TracingController;
+
+class NodeTraceWriter : public TraceWriter {
+ public:
+  NodeTraceWriter(uv_loop_t* tracing_loop);
+  ~NodeTraceWriter();
+
+  void AppendTraceEvent(TraceObject* trace_event) override;
+  void Flush() override;
+  void Flush(bool blocking);
+
+  static const int kTracesPerFile = 1 << 19;
+
+ private:
+  struct WriteRequest {
+    uv_fs_t req;
+    NodeTraceWriter* writer;
+    std::string str;
+    int highest_request_id;
+  };
+
+  static void WriteCb(uv_fs_t* req);
+  void OpenNewFileForStreaming();
+  void WriteToFile(std::string&& str, int highest_request_id);
+  void WriteSuffix();
+  static void FlushSignalCb(uv_async_t* signal);
+  void FlushPrivate();
+  static void ExitSignalCb(uv_async_t* signal);
+
+  uv_loop_t* tracing_loop_;
+  // Triggers callback to initiate writing the contents of stream_ to disk.
+  uv_async_t flush_signal_;
+  // Triggers callback to close async objects, ending the tracing thread.
+  uv_async_t exit_signal_;
+  // Prevents concurrent R/W on state related to serialized trace data
+  // before it's written to disk, namely stream_ and total_traces_.
+  Mutex stream_mutex_;
+  // Prevents concurrent R/W on state related to write requests.
+  Mutex request_mutex_;
+  // Allows blocking calls to Flush() to wait on a condition for
+  // trace events to be written to disk.
+  ConditionVariable request_cond_;
+  // Used to wait until async handles have been closed.
+  ConditionVariable exit_cond_;
+  int fd_ = -1;
+  std::queue<WriteRequest*> write_req_queue_;
+  int num_write_requests_ = 0;
+  int highest_request_id_completed_ = 0;
+  int total_traces_ = 0;
+  int file_num_ = 0;
+  std::ostringstream stream_;
+  TraceWriter* json_trace_writer_ = nullptr;
+  bool exited_ = false;
+};
+
+}  // namespace tracing
+}  // namespace node
+
+#endif  // SRC_NODE_TRACE_WRITER_H_

src/tracing/trace_event.cc

@@ -0,0 +1,17 @@
+#include "tracing/trace_event.h"
+
+namespace node {
+namespace tracing {
+
+v8::Platform* platform_ = nullptr;
+
+void TraceEventHelper::SetCurrentPlatform(v8::Platform* platform) {
+  platform_ = platform;
+}
+
+v8::Platform* TraceEventHelper::GetCurrentPlatform() {
+  return platform_;
+}
+
+}  // namespace tracing
+}  // namespace node

test/parallel/test-trace-event.js

@@ -0,0 +1,35 @@
+'use strict';
+const common = require('../common');
+const assert = require('assert');
+const cp = require('child_process');
+const fs = require('fs');
+
+const CODE = 'for (var i = 0; i < 100000; i++) { "test" + i }';
+const FILE_NAME = 'node_trace.1.log';
+
+common.refreshTmpDir();
+process.chdir(common.tmpDir);
+
+const proc_no_categories = cp.spawn(process.execPath,
+  [ '--trace-events-enabled', '--trace-event-categories', '""', '-e', CODE ]);
+
+proc_no_categories.once('exit', common.mustCall(() => {
+  assert(!common.fileExists(FILE_NAME));
+
+  const proc = cp.spawn(process.execPath,
+  [ '--trace-events-enabled', '-e', CODE ]);
+
+  proc.once('exit', common.mustCall(() => {
+    assert(common.fileExists(FILE_NAME));
+    fs.readFile(FILE_NAME, (err, data) => {
+      const traces = JSON.parse(data.toString()).traceEvents;
+      assert(traces.length > 0);
+      // Values that should be present on all runs to approximate correctness.
+      assert(traces.some((trace) => { return trace.pid === proc.pid; }));
+      assert(traces.some((trace) => { return trace.cat === 'v8'; }));
+      assert(traces.some((trace) => {
+        return trace.name === 'V8.ScriptCompiler';
+      }));
+    });
+  }));
+}));