process: set the trace category update handler during bootstrap

lib/internal/bootstrap/node.js

@@ -214,6 +214,16 @@ if (!config.noBrowserGlobals) {
   defineOperation(global, 'setImmediate', timers.setImmediate);
 }
 
+// Set the per-Environment callback that will be called
+// when the TrackingTraceStateObserver updates trace state.
+// Note that when NODE_USE_V8_PLATFORM is true, the observer is
+// attached to the per-process TracingController.
+const { setTraceCategoryStateUpdateHandler } = internalBinding('trace_events');
+const {
+  toggleTraceCategoryState
+} = NativeModule.require('internal/process/per_thread');
+setTraceCategoryStateUpdateHandler(toggleTraceCategoryState);
+
 // process.allowedNodeEnvironmentFlags
 Object.defineProperty(process, 'allowedNodeEnvironmentFlags', {
   get() {

lib/internal/bootstrap/pre_execution.js

@@ -1,9 +1,6 @@
 '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() {
   // Patch the process object with legacy properties and normalizations
@@ -162,26 +159,9 @@ function initializeReportSignalHandlers() {
 }
 
 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();
-  }
+  const { isTraceCategoryEnabled } = internalBinding('trace_events');
+  const { toggleTraceCategoryState } = require('internal/process/per_thread');
+  toggleTraceCategoryState(isTraceCategoryEnabled('node.async_hooks'));
 }
 
 // In general deprecations are intialized wherever the APIs are implemented,

lib/internal/process/per_thread.js

@@ -304,7 +304,24 @@ function buildAllowedFlags() {
   ));
 }
 
+// Lazy load internal/trace_events_async_hooks only if the async_hooks
+// trace event category is enabled.
+let traceEventsAsyncHook;
+// 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();
+  }
+}
+
 module.exports = {
+  toggleTraceCategoryState,
   assert,
   buildAllowedFlags,
   wrapProcessMethods

src/node_trace_events.cc

@@ -11,7 +11,6 @@
 namespace node {
 
 using v8::Array;
-using v8::Boolean;
 using v8::Context;
 using v8::Function;
 using v8::FunctionCallbackInfo;
@@ -149,15 +148,6 @@ void NodeCategorySet::Initialize(Local<Object> target,
                   .FromJust();
   target->Set(context, trace,
               binding->Get(context, trace).ToLocalChecked()).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

@@ -1,5 +1,8 @@
 'use strict';
 
+// This tests that tracing can be enabled dynamically with the
+// trace_events module.
+
 const common = require('../common');
 try {
   require('trace_events');
@@ -11,7 +14,6 @@ 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();`;
@@ -32,55 +34,31 @@ const proc = cp.spawnSync(
       'NODE_DEBUG': 'tracing'
     })
   });
-console.log(proc.signal);
-console.log(proc.stderr.toString());
-assert.strictEqual(proc.status, 0);
 
+console.log('process exit with signal:', proc.signal);
+console.log('process stderr:', 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) => {
+function filterTimeoutTraces(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;
+{
+  const timeoutTraces = traces.filter(filterTimeoutTraces);
+  assert.notDeepStrictEqual(timeoutTraces, []);
+  const threads = new Set();
+  for (const trace of timeoutTraces) {
+    threads.add(trace.tid);
   }
-  assert.fail('Unexpected initEvent: ',
-              util.inspect(trace, { depth: Infinity }));
+  assert.notDeepStrictEqual(timeoutTraces, []);
 }

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

@@ -1,5 +1,8 @@
 'use strict';
 
+// This tests that enabling node.async_hooks in main threads also
+// affects the workers.
+
 const common = require('../common');
 try {
   require('trace_events');
@@ -11,17 +14,18 @@ const assert = require('assert');
 const cp = require('child_process');
 const fs = require('fs');
 const path = require('path');
-const util = require('util');
 
 const code =
   'setTimeout(() => { for (var i = 0; i < 100000; i++) { "test" + i } }, 1)';
-const worker = `const { Worker } = require('worker_threads');
-  const worker = new Worker('${code}',
-  { eval: true, stdout: true, stderr: true });
-  worker.stdout.on('data',
-    (chunk) => console.log('worker', chunk.toString()));
-  worker.stderr.on('data',
-    (chunk) => console.error('worker', chunk.toString()));`;
+const worker =
+`const { Worker } = require('worker_threads');
+const worker = new Worker('${code}',
+{ eval: true, stdout: true, stderr: true });
+worker.stdout.on('data',
+  (chunk) => console.log('worker', chunk.toString()));
+worker.stderr.on('data',
+  (chunk) => console.error('worker', chunk.toString()));
+worker.on('exit', () => { ${code} })`;
 
 const tmpdir = require('../common/tmpdir');
 const filename = path.join(tmpdir.path, 'node_trace.1.log');
@@ -38,60 +42,32 @@ const proc = cp.spawnSync(
     })
   });
 
-console.log(proc.signal);
-console.log(proc.stderr.toString());
-assert.strictEqual(proc.status, 0);
+console.log('process exit with signal:', proc.signal);
+console.log('process stderr:', 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) => {
+function filterTimeoutTraces(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) {
-  if (trace.name === 'MESSAGEPORT' &&
-    trace.args.data.executionAsyncId === 0 &&
-    trace.args.data.triggerAsyncId === 0) {
-    continue;
-  }
-  if (trace.args.data.executionAsyncId > 0 &&
-    trace.args.data.triggerAsyncId > 0) {
-    continue;
+{
+  const timeoutTraces = traces.filter(filterTimeoutTraces);
+  assert.notDeepStrictEqual(timeoutTraces, []);
+  const threads = new Set();
+  for (const trace of timeoutTraces) {
+    threads.add(trace.tid);
   }
-  assert.fail('Unexpected initEvent: ',
-              util.inspect(trace, { depth: Infinity }));
+  assert.notDeepStrictEqual(timeoutTraces, []);
+  console.log('Threads with Timeout traces:', threads);
+  assert.strictEqual(threads.size, 2);
 }