process: delay and simplify the setup of async hooks trace events

lib/internal/bootstrap/node.js

@@ -42,8 +42,6 @@ const { getOptionValue } = NativeModule.require('internal/options');
 const config = internalBinding('config');
 const { deprecate } = NativeModule.require('internal/util');
 
-setupTraceCategoryState();
-
 setupProcessObject();
 
 setupGlobalProxy();
@@ -316,35 +314,6 @@ if (getOptionValue('--experimental-report')) {
   }
 }
 
-function setupTraceCategoryState() {
-  const {
-    traceCategoryState,
-    setTraceCategoryStateUpdateHandler
-  } = internalBinding('trace_events');
-  const kCategoryAsyncHooks = 0;
-  let traceEventsAsyncHook;
-
-  function toggleTraceCategoryState() {
-    // Dynamically enable/disable the traceEventsAsyncHook
-    const asyncHooksEnabled = !!traceCategoryState[kCategoryAsyncHooks];
-
-    if (asyncHooksEnabled) {
-      // Lazy load internal/trace_events_async_hooks only if the async_hooks
-      // trace event category is enabled.
-      if (!traceEventsAsyncHook) {
-        traceEventsAsyncHook =
-          NativeModule.require('internal/trace_events_async_hooks');
-      }
-      traceEventsAsyncHook.enable();
-    } else if (traceEventsAsyncHook) {
-      traceEventsAsyncHook.disable();
-    }
-  }
-
-  toggleTraceCategoryState();
-  setTraceCategoryStateUpdateHandler(toggleTraceCategoryState);
-}
-
 function setupProcessObject() {
   const EventEmitter = NativeModule.require('events');
   const origProcProto = Object.getPrototypeOf(process);

lib/internal/bootstrap/pre_execution.js

@@ -1,8 +1,13 @@
 'use strict';
 
 const { getOptionValue } = require('internal/options');
+// Lazy load internal/trace_events_async_hooks only if the async_hooks
+// trace event category is enabled.
+let traceEventsAsyncHook;
 
 function prepareMainThreadExecution() {
+  setupTraceCategoryState();
+
   // If the process is spawned with env NODE_CHANNEL_FD, it's probably
   // spawned by our child_process module, then initialize IPC.
   // This attaches some internal event listeners and creates:
@@ -23,6 +28,29 @@ function prepareMainThreadExecution() {
   loadPreloadModules();
 }
 
+function setupTraceCategoryState() {
+  const {
+    asyncHooksEnabledInitial,
+    setTraceCategoryStateUpdateHandler
+  } = internalBinding('trace_events');
+
+  toggleTraceCategoryState(asyncHooksEnabledInitial);
+  setTraceCategoryStateUpdateHandler(toggleTraceCategoryState);
+}
+
+// Dynamically enable/disable the traceEventsAsyncHook
+function toggleTraceCategoryState(asyncHooksEnabled) {
+  if (asyncHooksEnabled) {
+    if (!traceEventsAsyncHook) {
+      traceEventsAsyncHook =
+        require('internal/trace_events_async_hooks').createHook();
+    }
+    traceEventsAsyncHook.enable();
+  } else if (traceEventsAsyncHook) {
+    traceEventsAsyncHook.disable();
+  }
+}
+
 // In general deprecations are intialized wherever the APIs are implemented,
 // this is used to deprecate APIs implemented in C++ where the deprecation
 // utitlities are not easily accessible.
@@ -150,5 +178,6 @@ module.exports = {
   prepareMainThreadExecution,
   initializeDeprecations,
   initializeESMLoader,
-  loadPreloadModules
+  loadPreloadModules,
+  setupTraceCategoryState
 };

lib/internal/main/check_syntax.js

@@ -22,14 +22,16 @@ if (process.argv[1] && process.argv[1] !== '-') {
   // Expand process.argv[1] into a full path.
   const path = require('path');
   process.argv[1] = path.resolve(process.argv[1]);
+
+  // TODO(joyeecheung): not every one of these are necessary
+  prepareMainThreadExecution();
+
   // Read the source.
   const filename = CJSModule._resolveFilename(process.argv[1]);
 
   const fs = require('fs');
   const source = fs.readFileSync(filename, 'utf-8');
 
-  // TODO(joyeecheung): not every one of these are necessary
-  prepareMainThreadExecution();
   markBootstrapComplete();
 
   checkScriptSyntax(source, filename);

lib/internal/main/worker_thread.js

@@ -6,7 +6,8 @@
 const {
   initializeDeprecations,
   initializeESMLoader,
-  loadPreloadModules
+  loadPreloadModules,
+  setupTraceCategoryState
 } = require('internal/bootstrap/pre_execution');
 
 const {
@@ -72,6 +73,8 @@ port.on('message', (message) => {
       manifestURL,
       hasStdin
     } = message;
+
+    setupTraceCategoryState();
     if (manifestSrc) {
       require('internal/process/policy').setup(manifestSrc, manifestURL);
     }

lib/internal/trace_events_async_hooks.js

@@ -83,4 +83,4 @@ function createHook() {
   };
 }
 
-module.exports = createHook();
+exports.createHook = createHook;

src/env-inl.h

@@ -443,11 +443,6 @@ Environment::should_abort_on_uncaught_toggle() {
   return should_abort_on_uncaught_toggle_;
 }
 
-inline AliasedBuffer<uint8_t, v8::Uint8Array>&
-Environment::trace_category_state() {
-  return trace_category_state_;
-}
-
 inline AliasedBuffer<int32_t, v8::Int32Array>&
 Environment::stream_base_state() {
   return stream_base_state_;

src/env.cc

@@ -21,6 +21,7 @@
 namespace node {
 
 using errors::TryCatchScope;
+using v8::Boolean;
 using v8::Context;
 using v8::EmbedderGraph;
 using v8::External;
@@ -152,9 +153,8 @@ void Environment::TrackingTraceStateObserver::UpdateTraceCategoryState() {
     return;
   }
 
-  env_->trace_category_state()[0] =
-      *TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED(
-          TRACING_CATEGORY_NODE1(async_hooks));
+  bool async_hooks_enabled = (*(TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED(
+                                 TRACING_CATEGORY_NODE1(async_hooks)))) != 0;
 
   Isolate* isolate = env_->isolate();
   HandleScope handle_scope(isolate);
@@ -163,8 +163,9 @@ void Environment::TrackingTraceStateObserver::UpdateTraceCategoryState() {
     return;
   TryCatchScope try_catch(env_);
   try_catch.SetVerbose(true);
-  cb->Call(env_->context(), Undefined(isolate),
-           0, nullptr).ToLocalChecked();
+  Local<Value> args[] = {Boolean::New(isolate, async_hooks_enabled)};
+  cb->Call(env_->context(), Undefined(isolate), arraysize(args), args)
+      .ToLocalChecked();
 }
 
 static std::atomic<uint64_t> next_thread_id{0};
@@ -183,7 +184,6 @@ Environment::Environment(IsolateData* isolate_data,
       tick_info_(context->GetIsolate()),
       timer_base_(uv_now(isolate_data->event_loop())),
       should_abort_on_uncaught_toggle_(isolate_, 1),
-      trace_category_state_(isolate_, kTraceCategoryCount),
       stream_base_state_(isolate_, StreamBase::kNumStreamBaseStateFields),
       flags_(flags),
       thread_id_(thread_id == kNoThreadId ? AllocateThreadId() : thread_id),

src/env.h

@@ -697,7 +697,6 @@ class Environment {
   inline AliasedBuffer<uint32_t, v8::Uint32Array>&
   should_abort_on_uncaught_toggle();
 
-  inline AliasedBuffer<uint8_t, v8::Uint8Array>& trace_category_state();
   inline AliasedBuffer<int32_t, v8::Int32Array>& stream_base_state();
 
   // The necessary API for async_hooks.
@@ -1006,8 +1005,6 @@ class Environment {
   AliasedBuffer<uint32_t, v8::Uint32Array> should_abort_on_uncaught_toggle_;
   int should_not_abort_scope_counter_ = 0;
 
-  // Attached to a Uint8Array that tracks the state of trace category
-  AliasedBuffer<uint8_t, v8::Uint8Array> trace_category_state_;
   std::unique_ptr<TrackingTraceStateObserver> trace_state_observer_;
 
   AliasedBuffer<int32_t, v8::Int32Array> stream_base_state_;

src/node_trace_events.cc

@@ -1,6 +1,7 @@
 #include "base_object-inl.h"
 #include "env.h"
 #include "node.h"
+#include "node_internals.h"
 #include "node_v8_platform-inl.h"
 #include "tracing/agent.h"
 
@@ -10,6 +11,7 @@
 namespace node {
 
 using v8::Array;
+using v8::Boolean;
 using v8::Context;
 using v8::Function;
 using v8::FunctionCallbackInfo;
@@ -148,9 +150,14 @@ void NodeCategorySet::Initialize(Local<Object> target,
   target->Set(context, trace,
               binding->Get(context, trace).ToLocalChecked()).FromJust();
 
-  target->Set(context,
-              FIXED_ONE_BYTE_STRING(env->isolate(), "traceCategoryState"),
-              env->trace_category_state().GetJSArray()).FromJust();
+  // Initial value of async hook trace events
+  bool async_hooks_enabled = (*(TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED(
+                                 TRACING_CATEGORY_NODE1(async_hooks)))) != 0;
+  target
+      ->Set(context,
+            FIXED_ONE_BYTE_STRING(env->isolate(), "asyncHooksEnabledInitial"),
+            Boolean::New(env->isolate(), async_hooks_enabled))
+      .FromJust();
 }
 
 }  // namespace node

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

@@ -0,0 +1,83 @@
+'use strict';
+
+const common = require('../common');
+if (!process.binding('config').hasTracing)
+  common.skip('missing trace events');
+
+const assert = require('assert');
+const cp = require('child_process');
+const fs = require('fs');
+const path = require('path');
+const util = require('util');
+
+const enable = `require("trace_events").createTracing(
+{ categories: ["node.async_hooks"] }).enable();`;
+const code =
+  'setTimeout(() => { for (var i = 0; i < 100000; i++) { "test" + i } }, 1)';
+
+const tmpdir = require('../common/tmpdir');
+const filename = path.join(tmpdir.path, 'node_trace.1.log');
+
+tmpdir.refresh();
+const proc = cp.spawnSync(
+  process.execPath,
+  ['-e', enable + code ],
+  {
+    cwd: tmpdir.path,
+    env: Object.assign({}, process.env, {
+      'NODE_DEBUG_NATIVE': 'tracing',
+      'NODE_DEBUG': 'tracing'
+    })
+  });
+console.log(proc.signal);
+console.log(proc.stderr.toString());
+assert.strictEqual(proc.status, 0);
+
+assert(fs.existsSync(filename));
+const data = fs.readFileSync(filename, 'utf-8');
+const traces = JSON.parse(data).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,node.async_hooks')
+    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,node.async_hooks')
+    return false;
+  if (trace.name !== 'Timeout')
+    return false;
+  return true;
+}));
+
+// Check args in init events
+const initEvents = traces.filter((trace) => {
+  return (trace.ph === 'b' && !trace.name.includes('_CALLBACK'));
+});
+for (const trace of initEvents) {
+  console.log(trace);
+  if (trace.args.data.executionAsyncId > 0 &&
+    trace.args.data.triggerAsyncId > 0) {
+    continue;
+  }
+  assert.fail('Unexpected initEvent: ',
+              util.inspect(trace, { depth: Infinity }));
+}