diff --git a/lib/internal/bootstrap/node.js b/lib/internal/bootstrap/node.js index 2cd13a2891068c..aa0a6b282e138a 100644 --- a/lib/internal/bootstrap/node.js +++ b/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); diff --git a/lib/internal/bootstrap/pre_execution.js b/lib/internal/bootstrap/pre_execution.js index ce4af115badaab..556c6ba39e51f6 100644 --- a/lib/internal/bootstrap/pre_execution.js +++ b/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 }; diff --git a/lib/internal/main/check_syntax.js b/lib/internal/main/check_syntax.js index 392fadb99ff668..7df70b272091ff 100644 --- a/lib/internal/main/check_syntax.js +++ b/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); diff --git a/lib/internal/main/worker_thread.js b/lib/internal/main/worker_thread.js index ac161b7588f04c..13c1b136edaf43 100644 --- a/lib/internal/main/worker_thread.js +++ b/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); } diff --git a/lib/internal/trace_events_async_hooks.js b/lib/internal/trace_events_async_hooks.js index b947cbb6152b4b..05bb7b85644915 100644 --- a/lib/internal/trace_events_async_hooks.js +++ b/lib/internal/trace_events_async_hooks.js @@ -83,4 +83,4 @@ function createHook() { }; } -module.exports = createHook(); +exports.createHook = createHook; diff --git a/src/env-inl.h b/src/env-inl.h index 60dafc04e16516..72c32a39de1f1d 100644 --- a/src/env-inl.h +++ b/src/env-inl.h @@ -443,11 +443,6 @@ Environment::should_abort_on_uncaught_toggle() { return should_abort_on_uncaught_toggle_; } -inline AliasedBuffer& -Environment::trace_category_state() { - return trace_category_state_; -} - inline AliasedBuffer& Environment::stream_base_state() { return stream_base_state_; diff --git a/src/env.cc b/src/env.cc index 94fe595ac596ca..6801fee415094f 100644 --- a/src/env.cc +++ b/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 args[] = {Boolean::New(isolate, async_hooks_enabled)}; + cb->Call(env_->context(), Undefined(isolate), arraysize(args), args) + .ToLocalChecked(); } static std::atomic 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), diff --git a/src/env.h b/src/env.h index 5cf2ee2c8b493e..2a413c72da8a0c 100644 --- a/src/env.h +++ b/src/env.h @@ -697,7 +697,6 @@ class Environment { inline AliasedBuffer& should_abort_on_uncaught_toggle(); - inline AliasedBuffer& trace_category_state(); inline AliasedBuffer& stream_base_state(); // The necessary API for async_hooks. @@ -1006,8 +1005,6 @@ class Environment { AliasedBuffer should_abort_on_uncaught_toggle_; int should_not_abort_scope_counter_ = 0; - // Attached to a Uint8Array that tracks the state of trace category - AliasedBuffer trace_category_state_; std::unique_ptr trace_state_observer_; AliasedBuffer stream_base_state_; diff --git a/src/node_trace_events.cc b/src/node_trace_events.cc index 6a0d4f037a76c4..5e30df41c4f4fa 100644 --- a/src/node_trace_events.cc +++ b/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 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 diff --git a/test/parallel/test-trace-events-async-hooks-dynamic.js b/test/parallel/test-trace-events-async-hooks-dynamic.js new file mode 100644 index 00000000000000..884909b2a380fb --- /dev/null +++ b/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 })); +} diff --git a/test/parallel/test-trace-events-async-hooks-worker.js b/test/parallel/test-trace-events-async-hooks-worker.js new file mode 100644 index 00000000000000..6d7bf91c11e6c4 --- /dev/null +++ b/test/parallel/test-trace-events-async-hooks-worker.js @@ -0,0 +1,94 @@ +'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 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 tmpdir = require('../common/tmpdir'); +const filename = path.join(tmpdir.path, 'node_trace.1.log'); + +tmpdir.refresh(); +const proc = cp.spawnSync( + process.execPath, + [ '--trace-event-categories', 'node.async_hooks', '-e', worker ], + { + 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) { + 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; + } + assert.fail('Unexpected initEvent: ', + util.inspect(trace, { depth: Infinity })); +}