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>

6 files changed, 259 insertions, 28 deletions

diff --git a/src/async-wrap.cc b/src/async-wrap.cc
index af0336d492..c53929d11b 100644
--- a/src/async-wrap.cc
+++ b/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
diff --git a/src/async-wrap.h b/src/async-wrap.h
index 2702cfa2b7..39b6f287c9 100644
--- a/src/async-wrap.h
+++ b/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;
 
diff --git a/src/node.cc b/src/node.cc
index eeab7df11f..85fc23bbd9 100644
--- a/src/node.cc
+++ b/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);
-    platform_ = new NodePlatform(thread_pool_size,
-        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,
+        tracing_agent_->GetTracingController());
+      V8::InitializePlatform(platform_);
+      tracing::TraceEventHelper::SetTracingController(
+        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() {
diff --git a/src/node_http_parser.cc b/src/node_http_parser.cc
index ccb0942609..9974f566a8 100644
--- a/src/node_http_parser.cc
+++ b/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);
diff --git a/src/node_trace_events.cc b/src/node_trace_events.cc
new file mode 100644
index 0000000000..20edb66cd6
--- /dev/null
+++ b/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)
diff --git a/src/tracing/agent.cc b/src/tracing/agent.cc
index bc04b0b5e6..4514a0fce1 100644
--- a/src/tracing/agent.cc
+++ b/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