diff --git a/lib/internal/bootstrap/node.js b/lib/internal/bootstrap/node.js index f8cddb3153ed20..30b32c9c9c1581 100644 --- a/lib/internal/bootstrap/node.js +++ b/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() { diff --git a/lib/internal/bootstrap/pre_execution.js b/lib/internal/bootstrap/pre_execution.js index 04083b53a2315d..c38822bd8967e5 100644 --- a/lib/internal/bootstrap/pre_execution.js +++ b/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, diff --git a/lib/internal/process/per_thread.js b/lib/internal/process/per_thread.js index a0d6b325960bd6..7a3bee3098e8e9 100644 --- a/lib/internal/process/per_thread.js +++ b/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 diff --git a/src/node_trace_events.cc b/src/node_trace_events.cc index 5e30df41c4f4fa..1fad37743fb418 100644 --- a/src/node_trace_events.cc +++ b/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 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 diff --git a/test/parallel/test-trace-events-async-hooks-dynamic.js b/test/parallel/test-trace-events-async-hooks-dynamic.js index 4ad1c10bcf8859..318f94b182c5c1 100644 --- a/test/parallel/test-trace-events-async-hooks-dynamic.js +++ b/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,36 +34,16 @@ 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') @@ -69,18 +51,14 @@ assert(traces.some((trace) => { 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, []); } diff --git a/test/parallel/test-trace-events-async-hooks-worker.js b/test/parallel/test-trace-events-async-hooks-worker.js index 94183e311a76bc..338f0f9c09e534 100644 --- a/test/parallel/test-trace-events-async-hooks-worker.js +++ b/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,36 +42,15 @@ 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') @@ -75,23 +58,16 @@ assert(traces.some((trace) => { 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); }