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: nodejs#15538
Backport-PR-URL: nodejs#18179
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: Anna Henningsen <anna@addaleax.net>

Author: AndreasMadsen

doc/api/tracing.md

@@ -10,10 +10,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

@@ -26,7 +26,6 @@ const { methods, HTTPParser } = process.binding('http_parser');
 const FreeList = require('internal/freelist');
 const { ondrain } = require('internal/http');
 const incoming = require('_http_incoming');
-const { emitDestroy } = require('async_hooks');
 const {
   IncomingMessage,
   readStart,
@@ -217,7 +216,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

@@ -55,6 +55,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

@@ -113,6 +113,7 @@
       'lib/internal/repl.js',
       'lib/internal/socket_list.js',
       'lib/internal/test/unicode.js',
+      'lib/internal/trace_events_async_hooks.js',
       'lib/internal/url.js',
       'lib/internal/util.js',
       'lib/internal/util/types.js',
@@ -202,6 +203,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

@@ -168,18 +168,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();
 
@@ -199,6 +187,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();
 
@@ -218,6 +221,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();
 
@@ -328,8 +346,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
@@ -456,7 +476,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,
@@ -605,7 +626,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);
 }
 
 
@@ -617,6 +665,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;
 
   AsyncWrap::EmitAsyncInit(
@@ -664,8 +725,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;
 }
 
 
@@ -723,8 +791,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

@@ -130,12 +130,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

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

src/node_http_parser.cc

@@ -399,6 +399,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();
@@ -794,6 +806,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);