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 <[email protected]>
Author: Kelvin Jin <[email protected]>
Author: Matthew Loring <[email protected]>
Author: Jason Ginchereau <[email protected]>

PR-URL: #9304

Reviewed-By: Trevor Norris <[email protected]>
Reviewed-By: Michael Dawson <[email protected]>
Reviewed-By: Josh Gavant <[email protected]>

Author: misterpoe

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/debugger.md

@@ -201,4 +201,4 @@ To start debugging, open the following URL in Chrome:
     chrome-devtools://devtools/remote/serve_file/@60cd6e859b9f557d2312f5bf532f6aec5f284980/inspector.html?experiments=true&v8only=true&ws=localhost:9229/node
 ```
 
-[TCP-based protocol]: https://github.com/v8/v8/wiki/Debugging-Protocol
+[TCP-based protocol]: https://github.com/v8/v8/wiki/Debugging-Protocol

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;
@@ -3463,64 +3471,70 @@ static void PrintHelp() {
          "       node debug script.js [arguments] \n"
          "\n"
          "Options:\n"
-         "  -v, --version         print Node.js version\n"
-         "  -e, --eval script     evaluate script\n"
-         "  -p, --print           evaluate script and print result\n"
-         "  -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"
-         "  --no-deprecation      silence deprecation warnings\n"
-         "  --trace-deprecation   show stack traces on deprecations\n"
-         "  --throw-deprecation   throw an exception anytime a deprecated "
+         "  -v, --version            print Node.js version\n"
+         "  -e, --eval script        evaluate script\n"
+         "  -p, --print              evaluate script and print result\n"
+         "  -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"
+         "  --no-deprecation         silence deprecation warnings\n"
+         "  --trace-deprecation      show stack traces on deprecations\n"
+         "  --throw-deprecation      throw an exception anytime a deprecated "
          "function is used\n"
-         "  --no-warnings         silence all process warnings\n"
-         "  --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"
-         "  --track-heap-objects  track heap object allocations for heap "
+         "  --no-warnings            silence all process warnings\n"
+         "  --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"
-         "                        Buffer and SlowBuffer instances\n"
-         "  --v8-options          print v8 command line options\n"
-         "  --v8-pool-size=num    set v8's thread pool size\n"
+         "  --prof-process           process v8 profiler output generated\n"
+         "                           using --prof\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"
+         "  --enable-fips            enable FIPS crypto at startup\n"
+         "  --force-fips             force FIPS crypto (cannot be disabled)\n"
 #endif  /* NODE_FIPS_MODE */
-         "  --openssl-config=path load OpenSSL configuration file from the\n"
-         "                        specified path\n"
+         "  --openssl-config=path    load OpenSSL configuration file from the\n"
+         "                           specified path\n"
 #endif /* HAVE_OPENSSL */
 #if defined(NODE_HAVE_I18N_SUPPORT)
-         "  --icu-data-dir=dir    set ICU data load path to dir\n"
-         "                        (overrides NODE_ICU_DATA)\n"
+         "  --icu-data-dir=dir       set ICU data load path to dir\n"
+         "                           (overrides NODE_ICU_DATA)\n"
 #if !defined(NODE_HAVE_SMALL_ICU)
-         "                        note: linked-in ICU data is\n"
-         "                        present.\n"
+         "                           note: linked-in ICU data is\n"
+         "                           present.\n"
 #endif
-         "  --preserve-symlinks   preserve symbolic links when resolving\n"
-         "                        and caching modules.\n"
+         "  --preserve-symlinks      preserve symbolic links when resolving\n"
+         "                           and caching modules.\n"
 #endif
          "\n"
          "Environment variables:\n"
 #ifdef _WIN32
-         "NODE_PATH                ';'-separated list of directories\n"
+         "NODE_PATH                  ';'-separated list of directories\n"
 #else
-         "NODE_PATH                ':'-separated list of directories\n"
+         "NODE_PATH                  ':'-separated list of directories\n"
 #endif
-         "                         prefixed to the module search path.\n"
-         "NODE_DISABLE_COLORS      set to 1 to disable colors in the REPL\n"
+         "                           prefixed to the module search path.\n"
+         "NODE_DISABLE_COLORS        set to 1 to disable colors in the REPL\n"
 #if defined(NODE_HAVE_I18N_SUPPORT)
-         "NODE_ICU_DATA            data path for ICU (Intl object) data\n"
+         "NODE_ICU_DATA              data path for ICU (Intl object) data\n"
 #if !defined(NODE_HAVE_SMALL_ICU)
-         "                         (will extend linked-in data)\n"
+         "                           (will extend linked-in data)\n"
 #endif
 #endif
-         "NODE_REPL_HISTORY        path to the persistent REPL history file\n"
+         "NODE_REPL_HISTORY          path to the persistent REPL history file\n"
          "\n"
          "Documentation can be found at https://nodejs.org/\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_