async_hooks: add trace events to async_hooks

This will allow trace event to record timing information for all
asynchronous operations that are observed by async_hooks.

PR-URL: https://github.com/nodejs/node/pull/15538
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: Anna Henningsen <anna@addaleax.net>

doc/api/tracing.md

@@ -8,10 +8,10 @@ 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.
+By default the `node`, `node.async_hooks`, and `v8` categories are enabled.
 
 ```txt
-node --trace-events-enabled --trace-event-categories v8,node server.js
+node --trace-events-enabled --trace-event-categories v8,node,node.async_hooks server.js
 ```
 
 Running Node.js with tracing enabled will produce log files that can be opened

lib/_http_common.js

@@ -27,7 +27,6 @@ const { methods, HTTPParser } = binding;
 const FreeList = require('internal/freelist');
 const { ondrain } = require('internal/http');
 const incoming = require('_http_incoming');
-const { emitDestroy } = require('async_hooks');
 const {
   IncomingMessage,
   readStart,
@@ -218,7 +217,7 @@ function freeParser(parser, req, socket) {
     } else {
       // Since the Parser destructor isn't going to run the destroy() callbacks
       // it needs to be triggered manually.
-      emitDestroy(parser.getAsyncId());
+      parser.free();
     }
   }
   if (req) {

lib/internal/bootstrap_node.js

@@ -59,6 +59,7 @@
     if (global.__coverage__)
       NativeModule.require('internal/process/write-coverage').setup();
 
+    NativeModule.require('internal/trace_events_async_hooks').setup();
     NativeModule.require('internal/inspector_async_hook').setup();
 
     // Do not initialize channel in debugger agent, it deletes env variable

lib/internal/trace_events_async_hooks.js

@@ -0,0 +1,67 @@
+'use strict';
+
+const trace_events = process.binding('trace_events');
+const async_wrap = process.binding('async_wrap');
+const async_hooks = require('async_hooks');
+
+// Use small letters such that chrome://traceing groups by the name.
+// The behaviour is not only useful but the same as the events emitted using
+// the specific C++ macros.
+const BEFORE_EVENT = 'b'.charCodeAt(0);
+const END_EVENT = 'e'.charCodeAt(0);
+
+// In trace_events it is not only the id but also the name that needs to be
+// repeated. Since async_hooks doesn't expose the provider type in the
+// non-init events, use a map to manually map the asyncId to the type name.
+const typeMemory = new Map();
+
+// It is faster to emit trace_events directly from C++. Thus, this happens in
+// async_wrap.cc. However, events emitted from the JavaScript API or the
+// Embedder C++ API can't be emitted from async_wrap.cc. Thus they are
+// emitted using the JavaScript API. To prevent emitting the same event
+// twice the async_wrap.Providers list is used to filter the events.
+const nativeProviders = new Set(Object.keys(async_wrap.Providers));
+
+const hook = async_hooks.createHook({
+  init(asyncId, type, triggerAsyncId, resource) {
+    if (nativeProviders.has(type)) return;
+
+    typeMemory.set(asyncId, type);
+    trace_events.emit(BEFORE_EVENT, 'node.async_hooks',
+                      type, asyncId, 'triggerAsyncId', triggerAsyncId);
+  },
+
+  before(asyncId) {
+    const type = typeMemory.get(asyncId);
+    if (type === undefined) return;
+
+    trace_events.emit(BEFORE_EVENT, 'node.async_hooks',
+                      type + '_CALLBACK', asyncId);
+  },
+
+  after(asyncId) {
+    const type = typeMemory.get(asyncId);
+    if (type === undefined) return;
+
+    trace_events.emit(END_EVENT, 'node.async_hooks',
+                      type + '_CALLBACK', asyncId);
+  },
+
+  destroy(asyncId) {
+    const type = typeMemory.get(asyncId);
+    if (type === undefined) return;
+
+    trace_events.emit(END_EVENT, 'node.async_hooks',
+                      type, asyncId);
+
+    // cleanup asyncId to type map
+    typeMemory.delete(asyncId);
+  }
+});
+
+
+exports.setup = function() {
+  if (trace_events.categoryGroupEnabled('node.async_hooks')) {
+    hook.enable();
+  }
+};

node.gyp

@@ -121,6 +121,7 @@
       'lib/internal/socket_list.js',
       'lib/internal/test/unicode.js',
       'lib/internal/tls.js',
+      'lib/internal/trace_events_async_hooks.js',
       'lib/internal/url.js',
       'lib/internal/util.js',
       'lib/internal/util/comparisons.js',
@@ -213,6 +214,7 @@
         'src/node_platform.cc',
         'src/node_perf.cc',
         'src/node_serdes.cc',
+        'src/node_trace_events.cc',
         'src/node_url.cc',
         'src/node_util.cc',
         'src/node_v8.cc',

src/async-wrap.cc

@@ -167,18 +167,6 @@ static void DestroyAsyncIdsCallback(uv_timer_t* handle) {
 }
 
 
-static void PushBackDestroyAsyncId(Environment* env, double id) {
-  if (env->async_hooks()->fields()[AsyncHooks::kDestroy] == 0)
-    return;
-
-  if (env->destroy_async_id_list()->empty())
-    uv_timer_start(env->destroy_async_ids_timer_handle(),
-                   DestroyAsyncIdsCallback, 0, 0);
-
-  env->destroy_async_id_list()->push_back(id);
-}
-
-
 void AsyncWrap::EmitPromiseResolve(Environment* env, double async_id) {
   AsyncHooks* async_hooks = env->async_hooks();
 
@@ -198,6 +186,21 @@ void AsyncWrap::EmitPromiseResolve(Environment* env, double async_id) {
 }
 
 
+void AsyncWrap::EmitTraceEventBefore() {
+  switch (provider_type()) {
+#define V(PROVIDER)                                                           \
+    case PROVIDER_ ## PROVIDER:                                               \
+      TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("node.async_hooks",                   \
+        #PROVIDER "_CALLBACK", static_cast<int64_t>(get_async_id()));         \
+      break;
+    NODE_ASYNC_PROVIDER_TYPES(V)
+#undef V
+    default:
+      UNREACHABLE();
+  }
+}
+
+
 void AsyncWrap::EmitBefore(Environment* env, double async_id) {
   AsyncHooks* async_hooks = env->async_hooks();
 
@@ -217,6 +220,21 @@ void AsyncWrap::EmitBefore(Environment* env, double async_id) {
 }
 
 
+void AsyncWrap::EmitTraceEventAfter() {
+  switch (provider_type()) {
+#define V(PROVIDER)                                                           \
+    case PROVIDER_ ## PROVIDER:                                               \
+      TRACE_EVENT_NESTABLE_ASYNC_END0("node.async_hooks",                     \
+        #PROVIDER "_CALLBACK", static_cast<int64_t>(get_async_id()));         \
+      break;
+    NODE_ASYNC_PROVIDER_TYPES(V)
+#undef V
+    default:
+      UNREACHABLE();
+  }
+}
+
+
 void AsyncWrap::EmitAfter(Environment* env, double async_id) {
   AsyncHooks* async_hooks = env->async_hooks();
 
@@ -327,8 +345,10 @@ static void PromiseHook(PromiseHookType type, Local<Promise> promise,
   if (type == PromiseHookType::kBefore) {
     env->async_hooks()->push_async_ids(
       wrap->get_async_id(), wrap->get_trigger_async_id());
+      wrap->EmitTraceEventBefore();
     AsyncWrap::EmitBefore(wrap->env(), wrap->get_async_id());
   } else if (type == PromiseHookType::kAfter) {
+    wrap->EmitTraceEventAfter();
     AsyncWrap::EmitAfter(wrap->env(), wrap->get_async_id());
     if (env->execution_async_id() == wrap->get_async_id()) {
       // This condition might not be true if async_hooks was enabled during
@@ -455,7 +475,8 @@ void AsyncWrap::AsyncReset(const FunctionCallbackInfo<Value>& args) {
 
 void AsyncWrap::QueueDestroyAsyncId(const FunctionCallbackInfo<Value>& args) {
   CHECK(args[0]->IsNumber());
-  PushBackDestroyAsyncId(Environment::GetCurrent(args), args[0]->NumberValue());
+  AsyncWrap::EmitDestroy(
+      Environment::GetCurrent(args), args[0]->NumberValue());
 }
 
 void AsyncWrap::AddWrapMethods(Environment* env,
@@ -604,7 +625,34 @@ AsyncWrap::AsyncWrap(Environment* env,
 
 
 AsyncWrap::~AsyncWrap() {
-  PushBackDestroyAsyncId(env(), get_async_id());
+  EmitTraceEventDestroy();
+  EmitDestroy(env(), get_async_id());
+}
+
+void AsyncWrap::EmitTraceEventDestroy() {
+  switch (provider_type()) {
+  #define V(PROVIDER)                                                         \
+    case PROVIDER_ ## PROVIDER:                                               \
+      TRACE_EVENT_NESTABLE_ASYNC_END0("node.async_hooks",                     \
+        #PROVIDER, static_cast<int64_t>(get_async_id()));                     \
+      break;
+    NODE_ASYNC_PROVIDER_TYPES(V)
+  #undef V
+    default:
+      UNREACHABLE();
+  }
+}
+
+void AsyncWrap::EmitDestroy(Environment* env, double async_id) {
+  if (env->async_hooks()->fields()[AsyncHooks::kDestroy] == 0)
+    return;
+
+  if (env->destroy_async_id_list()->empty()) {
+    uv_timer_start(env->destroy_async_ids_timer_handle(),
+                   DestroyAsyncIdsCallback, 0, 0);
+  }
+
+  env->destroy_async_id_list()->push_back(async_id);
 }
 
 
@@ -616,6 +664,19 @@ void AsyncWrap::AsyncReset(double execution_async_id, bool silent) {
     execution_async_id == -1 ? env()->new_async_id() : execution_async_id;
   trigger_async_id_ = env()->get_init_trigger_async_id();
 
+  switch (provider_type()) {
+#define V(PROVIDER)                                                           \
+    case PROVIDER_ ## PROVIDER:                                               \
+      TRACE_EVENT_NESTABLE_ASYNC_BEGIN1("node.async_hooks",                   \
+        #PROVIDER, static_cast<int64_t>(get_async_id()),                      \
+        "triggerAsyncId", static_cast<int64_t>(get_trigger_async_id()));      \
+      break;
+    NODE_ASYNC_PROVIDER_TYPES(V)
+#undef V
+    default:
+      UNREACHABLE();
+  }
+
   if (silent) return;
 
   EmitAsyncInit(env(), object(),
@@ -662,8 +723,15 @@ void AsyncWrap::EmitAsyncInit(Environment* env,
 MaybeLocal<Value> AsyncWrap::MakeCallback(const Local<Function> cb,
                                           int argc,
                                           Local<Value>* argv) {
+  EmitTraceEventBefore();
+
   async_context context { get_async_id(), get_trigger_async_id() };
-  return InternalMakeCallback(env(), object(), cb, argc, argv, context);
+  MaybeLocal<Value> ret = InternalMakeCallback(
+      env(), object(), cb, argc, argv, context);
+
+  EmitTraceEventAfter();
+
+  return ret;
 }
 
 
@@ -713,8 +781,8 @@ async_context EmitAsyncInit(Isolate* isolate,
 }
 
 void EmitAsyncDestroy(Isolate* isolate, async_context asyncContext) {
-  PushBackDestroyAsyncId(Environment::GetCurrent(isolate),
-                         asyncContext.async_id);
+  AsyncWrap::EmitDestroy(
+      Environment::GetCurrent(isolate), asyncContext.async_id);
 }
 
 }  // namespace node

src/async-wrap.h

@@ -128,12 +128,18 @@ class AsyncWrap : public BaseObject {
   static void EmitAsyncInit(Environment* env,
                             v8::Local<v8::Object> object,
                             v8::Local<v8::String> type,
-                            double id,
+                            double async_id,
                             double trigger_async_id);
 
-  static void EmitBefore(Environment* env, double id);
-  static void EmitAfter(Environment* env, double id);
-  static void EmitPromiseResolve(Environment* env, double id);
+  static void EmitDestroy(Environment* env, double async_id);
+  static void EmitBefore(Environment* env, double async_id);
+  static void EmitAfter(Environment* env, double async_id);
+  static void EmitPromiseResolve(Environment* env, double async_id);
+
+  void EmitTraceEventBefore();
+  void EmitTraceEventAfter();
+  void EmitTraceEventDestroy();
+
 
   inline ProviderType provider_type() const;
 

src/node.cc

@@ -273,13 +273,20 @@ node::DebugOptions debug_options;
 static struct {
 #if NODE_USE_V8_PLATFORM
   void Initialize(int thread_pool_size) {
-    tracing_agent_.reset(
-        trace_enabled ? new tracing::Agent() : nullptr);
+    if (trace_enabled) {
+      tracing_agent_.reset(new tracing::Agent());
       platform_ = new NodePlatform(thread_pool_size,
-        trace_enabled ? tracing_agent_->GetTracingController() : nullptr);
+        tracing_agent_->GetTracingController());
       V8::InitializePlatform(platform_);
       tracing::TraceEventHelper::SetTracingController(
-        trace_enabled ? tracing_agent_->GetTracingController() : nullptr);
+        tracing_agent_->GetTracingController());
+    } else {
+      tracing_agent_.reset(nullptr);
+      platform_ = new NodePlatform(thread_pool_size, nullptr);
+      V8::InitializePlatform(platform_);
+      tracing::TraceEventHelper::SetTracingController(
+        new v8::TracingController());
+    }
   }
 
   void Dispose() {

src/node_http_parser.cc

@@ -397,6 +397,18 @@ class Parser : public AsyncWrap {
   }
 
 
+  static void Free(const FunctionCallbackInfo<Value>& args) {
+    Environment* env = Environment::GetCurrent(args);
+    Parser* parser;
+    ASSIGN_OR_RETURN_UNWRAP(&parser, args.Holder());
+
+    // Since the Parser destructor isn't going to run the destroy() callbacks
+    // it needs to be triggered manually.
+    parser->EmitTraceEventDestroy();
+    parser->EmitDestroy(env, parser->get_async_id());
+  }
+
+
   void Save() {
     url_.Save();
     status_message_.Save();
@@ -792,6 +804,7 @@ void InitHttpParser(Local<Object> target,
 
   AsyncWrap::AddWrapMethods(env, t);
   env->SetProtoMethod(t, "close", Parser::Close);
+  env->SetProtoMethod(t, "free", Parser::Free);
   env->SetProtoMethod(t, "execute", Parser::Execute);
   env->SetProtoMethod(t, "finish", Parser::Finish);
   env->SetProtoMethod(t, "reinitialize", Parser::Reinitialize);

src/node_trace_events.cc

@@ -0,0 +1,136 @@
+#include "node_internals.h"
+#include "tracing/agent.h"
+
+namespace node {
+
+using v8::Context;
+using v8::FunctionCallbackInfo;
+using v8::Int32;
+using v8::Local;
+using v8::Object;
+using v8::Value;
+
+// The tracing APIs require category groups to be pointers to long-lived
+// strings. Those strings are stored here.
+static std::unordered_set<std::string> categoryGroups;
+
+// Gets a pointer to the category-enabled flags for a tracing category group,
+// if tracing is enabled for it.
+static const uint8_t* GetCategoryGroupEnabled(const char* category_group) {
+    if (category_group == nullptr) return nullptr;
+
+    return TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED(category_group);
+}
+
+static const char* GetCategoryGroup(Environment* env,
+                                    const Local<Value> categoryValue) {
+  CHECK(categoryValue->IsString());
+
+  Utf8Value category(env->isolate(), categoryValue);
+  // If the value already exists in the set, insertion.first will point
+  // to the existing value. Thus, this will maintain a long lived pointer
+  // to the category c-string.
+  auto insertion = categoryGroups.insert(category.out());
+
+  // The returned insertion is a pair whose first item is the object that was
+  // inserted or that blocked the insertion and second item is a boolean
+  // indicating whether it was inserted.
+  return insertion.first->c_str();
+}
+
+static void Emit(const FunctionCallbackInfo<Value>& args) {
+  Environment* env = Environment::GetCurrent(args);
+  Local<Context> context = env->context();
+
+  // Args: [type, category, name, id, argName, argValue]
+  CHECK_GE(args.Length(), 3);
+
+  // Check the category group first, to avoid doing more work if it's not
+  // enabled.
+  const char* category_group = GetCategoryGroup(env, args[1]);
+  const uint8_t* category_group_enabled =
+    GetCategoryGroupEnabled(category_group);
+  if (*category_group_enabled == 0) return;
+
+  // get trace_event phase
+  CHECK(args[0]->IsNumber());
+  char phase = static_cast<char>(args[0]->Int32Value(context).ToChecked());
+
+  // get trace_event name
+  CHECK(args[2]->IsString());
+  Utf8Value nameValue(env->isolate(), args[2]);
+  const char* name = nameValue.out();
+
+  // get trace_event id
+  int64_t id = 0;
+  bool has_id = false;
+  if (args.Length() >= 4 && !args[3]->IsUndefined() && !args[3]->IsNull()) {
+    has_id = true;
+    CHECK(args[3]->IsNumber());
+    id = args[3]->IntegerValue(context).ToChecked();
+  }
+
+  // TODO(AndreasMadsen): Two extra arguments are not supported.
+  // TODO(AndreasMadsen): String values are not supported.
+  int32_t num_args = 0;
+  const char* arg_names[1];
+  uint8_t arg_types[1];
+  uint64_t arg_values[1];
+
+  // Create Utf8Value in the function scope to prevent deallocation.
+  // The c-string will be copied by TRACE_EVENT_API_ADD_TRACE_EVENT at the end.
+  Utf8Value arg1NameValue(env->isolate(), args[4]);
+
+  if (args.Length() < 6 || (args[4]->IsUndefined() && args[5]->IsUndefined())) {
+    num_args = 0;
+  } else {
+    num_args = 1;
+    arg_types[0] = TRACE_VALUE_TYPE_INT;
+
+    CHECK(args[4]->IsString());
+    arg_names[0] = arg1NameValue.out();
+
+    CHECK(args[5]->IsNumber());
+    arg_values[0] = args[5]->IntegerValue(context).ToChecked();
+  }
+
+  // The TRACE_EVENT_FLAG_COPY flag indicates that the name and argument
+  // name should be copied thus they don't need to long-lived pointers.
+  // The category name still won't be copied and thus need to be a long-lived
+  // pointer.
+  uint32_t flags = TRACE_EVENT_FLAG_COPY;
+  if (has_id) {
+    flags |= TRACE_EVENT_FLAG_HAS_ID;
+  }
+
+  const char* scope = node::tracing::kGlobalScope;
+  uint64_t bind_id = node::tracing::kNoId;
+
+  TRACE_EVENT_API_ADD_TRACE_EVENT(
+    phase, category_group_enabled, name, scope, id, bind_id,
+    num_args, arg_names, arg_types, arg_values,
+    flags);
+}
+
+static void CategoryGroupEnabled(const FunctionCallbackInfo<Value>& args) {
+  Environment* env = Environment::GetCurrent(args);
+
+  const char* category_group = GetCategoryGroup(env, args[0]);
+  const uint8_t* category_group_enabled =
+    GetCategoryGroupEnabled(category_group);
+  args.GetReturnValue().Set(*category_group_enabled > 0);
+}
+
+void InitializeTraceEvents(Local<Object> target,
+                           Local<Value> unused,
+                           Local<Context> context,
+                           void* priv) {
+  Environment* env = Environment::GetCurrent(context);
+
+  env->SetMethod(target, "emit", Emit);
+  env->SetMethod(target, "categoryGroupEnabled", CategoryGroupEnabled);
+}
+
+}  // namespace node
+
+NODE_MODULE_CONTEXT_AWARE_BUILTIN(trace_events, node::InitializeTraceEvents)

src/tracing/agent.cc

@@ -36,6 +36,7 @@ void Agent::Start(const string& enabled_categories) {
   } else {
     trace_config->AddIncludedCategory("v8");
     trace_config->AddIncludedCategory("node");
+    trace_config->AddIncludedCategory("node.async_hooks");
   }
 
   // This thread should be created *after* async handles are created

test/parallel/test-trace-event.js

@@ -1,41 +0,0 @@
-'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, common.mustCall((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) => {
-        if (trace.pid !== proc.pid)
-          return false;
-        if (trace.cat !== 'v8')
-          return false;
-        if (trace.name !== 'V8.ScriptCompiler')
-          return false;
-        return true;
-      }));
-    }));
-  }));
-}));

test/parallel/test-trace-events-all.js

@@ -0,0 +1,56 @@
+'use strict';
+const common = require('../common');
+const assert = require('assert');
+const cp = require('child_process');
+const fs = require('fs');
+
+const CODE =
+  'setTimeout(() => { for (var i = 0; i < 100000; i++) { "test" + i } }, 1)';
+const FILE_NAME = 'node_trace.1.log';
+
+common.refreshTmpDir();
+process.chdir(common.tmpDir);
+
+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, common.mustCall((err, data) => {
+    const traces = JSON.parse(data.toString()).traceEvents;
+    assert(traces.length > 0);
+    // V8 trace events should be generated.
+    assert(traces.some((trace) => {
+      if (trace.pid !== proc.pid)
+        return false;
+      if (trace.cat !== 'v8')
+        return false;
+      if (trace.name !== 'V8.ScriptCompiler')
+        return false;
+      return true;
+    }));
+
+    // C++ async_hooks trace events should be generated.
+    assert(traces.some((trace) => {
+      if (trace.pid !== proc.pid)
+        return false;
+      if (trace.cat !== 'node.async_hooks')
+        return false;
+      if (trace.name !== 'TIMERWRAP')
+        return false;
+      return true;
+    }));
+
+
+    // JavaScript async_hooks trace events should be generated.
+    assert(traces.some((trace) => {
+      if (trace.pid !== proc.pid)
+        return false;
+      if (trace.cat !== 'node.async_hooks')
+        return false;
+      if (trace.name !== 'Timeout')
+        return false;
+      return true;
+    }));
+  }));
+}));

test/parallel/test-trace-events-async-hooks.js

@@ -0,0 +1,58 @@
+'use strict';
+const common = require('../common');
+const assert = require('assert');
+const cp = require('child_process');
+const fs = require('fs');
+
+const CODE =
+  'setTimeout(() => { for (var i = 0; i < 100000; i++) { "test" + i } }, 1)';
+const FILE_NAME = 'node_trace.1.log';
+
+common.refreshTmpDir();
+process.chdir(common.tmpDir);
+
+const proc = cp.spawn(process.execPath,
+                      [ '--trace-events-enabled',
+                        '--trace-event-categories', 'node.async_hooks',
+                        '-e', CODE ]);
+
+proc.once('exit', common.mustCall(() => {
+  assert(common.fileExists(FILE_NAME));
+  fs.readFile(FILE_NAME, common.mustCall((err, data) => {
+    const traces = JSON.parse(data.toString()).traceEvents;
+    assert(traces.length > 0);
+    // V8 trace events should be generated.
+    assert(!traces.some((trace) => {
+      if (trace.pid !== proc.pid)
+        return false;
+      if (trace.cat !== 'v8')
+        return false;
+      if (trace.name !== 'V8.ScriptCompiler')
+        return false;
+      return true;
+    }));
+
+    // C++ async_hooks trace events should be generated.
+    assert(traces.some((trace) => {
+      if (trace.pid !== proc.pid)
+        return false;
+      if (trace.cat !== 'node.async_hooks')
+        return false;
+      if (trace.name !== 'TIMERWRAP')
+        return false;
+      return true;
+    }));
+
+
+    // JavaScript async_hooks trace events should be generated.
+    assert(traces.some((trace) => {
+      if (trace.pid !== proc.pid)
+        return false;
+      if (trace.cat !== 'node.async_hooks')
+        return false;
+      if (trace.name !== 'Timeout')
+        return false;
+      return true;
+    }));
+  }));
+}));

test/parallel/test-trace-events-binding.js

@@ -0,0 +1,48 @@
+'use strict';
+const common = require('../common');
+const assert = require('assert');
+const cp = require('child_process');
+const fs = require('fs');
+
+const CODE = `
+  process.binding("trace_events").emit(
+    'b'.charCodeAt(0), 'custom',
+    'type-value', 10, 'extra-value', 20);
+  process.binding("trace_events").emit(
+    'b'.charCodeAt(0), 'custom',
+    'type-value', 20);
+  process.binding("trace_events").emit(
+    'b'.charCodeAt(0), 'missing',
+    'type-value', 10, 'extra-value', 20);
+`;
+const FILE_NAME = 'node_trace.1.log';
+
+common.refreshTmpDir();
+process.chdir(common.tmpDir);
+
+const proc = cp.spawn(process.execPath,
+                      [ '--trace-events-enabled',
+                        '--trace-event-categories', 'custom',
+                        '-e', CODE ]);
+
+proc.once('exit', common.mustCall(() => {
+  assert(common.fileExists(FILE_NAME));
+  fs.readFile(FILE_NAME, common.mustCall((err, data) => {
+    const traces = JSON.parse(data.toString()).traceEvents;
+    assert.strictEqual(traces.length, 2);
+
+    assert.strictEqual(traces[0].pid, proc.pid);
+    assert.strictEqual(traces[0].ph, 'b');
+    assert.strictEqual(traces[0].cat, 'custom');
+    assert.strictEqual(traces[0].name, 'type-value');
+    assert.strictEqual(traces[0].id, '0xa');
+    assert.deepStrictEqual(traces[0].args, { 'extra-value': 20 });
+
+    assert.strictEqual(traces[1].pid, proc.pid);
+    assert.strictEqual(traces[1].ph, 'b');
+    assert.strictEqual(traces[1].cat, 'custom');
+    assert.strictEqual(traces[1].name, 'type-value');
+    assert.strictEqual(traces[1].id, '0x14');
+    assert.deepStrictEqual(traces[1].args, { });
+  }));
+}));

test/parallel/test-trace-events-category-used.js

@@ -0,0 +1,35 @@
+'use strict';
+const common = require('../common');
+const assert = require('assert');
+const cp = require('child_process');
+
+const CODE = `console.log(
+  process.binding("trace_events").categoryGroupEnabled("custom")
+);`;
+
+common.refreshTmpDir();
+process.chdir(common.tmpDir);
+
+const procEnabled = cp.spawn(
+  process.execPath,
+  [ '--trace-events-enabled', '--trace-event-categories', 'custom', '-e', CODE ]
+);
+let procEnabledOutput = '';
+
+procEnabled.stdout.on('data', (data) => procEnabledOutput += data);
+procEnabled.stderr.pipe(process.stderr);
+procEnabled.once('exit', common.mustCall(() => {
+  assert.strictEqual(procEnabledOutput, 'true\n');
+}));
+
+const procDisabled = cp.spawn(
+  process.execPath,
+  [ '--trace-events-enabled', '--trace-event-categories', 'other', '-e', CODE ]
+);
+let procDisabledOutput = '';
+
+procDisabled.stdout.on('data', (data) => procDisabledOutput += data);
+procDisabled.stderr.pipe(process.stderr);
+procDisabled.once('exit', common.mustCall(() => {
+  assert.strictEqual(procDisabledOutput, 'false\n');
+}));

test/parallel/test-trace-events-none.js

@@ -0,0 +1,20 @@
+'use strict';
+const common = require('../common');
+const assert = require('assert');
+const cp = require('child_process');
+
+const CODE =
+  'setTimeout(() => { for (var i = 0; i < 100000; i++) { "test" + i } }, 1)';
+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));
+}));

test/parallel/test-trace-events-v8.js

@@ -0,0 +1,58 @@
+'use strict';
+const common = require('../common');
+const assert = require('assert');
+const cp = require('child_process');
+const fs = require('fs');
+
+const CODE =
+  'setTimeout(() => { for (var i = 0; i < 100000; i++) { "test" + i } }, 1)';
+const FILE_NAME = 'node_trace.1.log';
+
+common.refreshTmpDir();
+process.chdir(common.tmpDir);
+
+const proc = cp.spawn(process.execPath,
+                      [ '--trace-events-enabled',
+                        '--trace-event-categories', 'v8',
+                        '-e', CODE ]);
+
+proc.once('exit', common.mustCall(() => {
+  assert(common.fileExists(FILE_NAME));
+  fs.readFile(FILE_NAME, common.mustCall((err, data) => {
+    const traces = JSON.parse(data.toString()).traceEvents;
+    assert(traces.length > 0);
+    // V8 trace events should be generated.
+    assert(traces.some((trace) => {
+      if (trace.pid !== proc.pid)
+        return false;
+      if (trace.cat !== 'v8')
+        return false;
+      if (trace.name !== 'V8.ScriptCompiler')
+        return false;
+      return true;
+    }));
+
+    // C++ async_hooks trace events should be generated.
+    assert(!traces.some((trace) => {
+      if (trace.pid !== proc.pid)
+        return false;
+      if (trace.cat !== 'node.async_hooks')
+        return false;
+      if (trace.name !== 'TIMERWRAP')
+        return false;
+      return true;
+    }));
+
+
+    // JavaScript async_hooks trace events should be generated.
+    assert(!traces.some((trace) => {
+      if (trace.pid !== proc.pid)
+        return false;
+      if (trace.cat !== 'node.async_hooks')
+        return false;
+      if (trace.name !== 'Timeout')
+        return false;
+      return true;
+    }));
+  }));
+}));