From cf7e15cf784ebcc3e81b4c0756ade5162fc9c776 Mon Sep 17 00:00:00 2001 From: Andreas Madsen Date: Mon, 17 Jul 2017 16:47:12 -0700 Subject: [PATCH] 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 Reviewed-By: James M Snell Reviewed-By: Anna Henningsen --- doc/api/tracing.md | 4 +- lib/_http_common.js | 3 +- lib/internal/bootstrap_node.js | 1 + lib/internal/trace_events_async_hooks.js | 67 +++++++++ node.gyp | 2 + src/async-wrap.cc | 102 ++++++++++--- src/async-wrap.h | 14 +- src/node.cc | 21 ++- src/node_http_parser.cc | 13 ++ src/node_trace_events.cc | 136 ++++++++++++++++++ src/tracing/agent.cc | 1 + test/parallel/test-trace-event.js | 41 ------ test/parallel/test-trace-events-all.js | 56 ++++++++ .../parallel/test-trace-events-async-hooks.js | 58 ++++++++ test/parallel/test-trace-events-binding.js | 48 +++++++ .../test-trace-events-category-used.js | 35 +++++ test/parallel/test-trace-events-none.js | 20 +++ test/parallel/test-trace-events-v8.js | 58 ++++++++ 18 files changed, 607 insertions(+), 73 deletions(-) create mode 100644 lib/internal/trace_events_async_hooks.js create mode 100644 src/node_trace_events.cc delete mode 100644 test/parallel/test-trace-event.js create mode 100644 test/parallel/test-trace-events-all.js create mode 100644 test/parallel/test-trace-events-async-hooks.js create mode 100644 test/parallel/test-trace-events-binding.js create mode 100644 test/parallel/test-trace-events-category-used.js create mode 100644 test/parallel/test-trace-events-none.js create mode 100644 test/parallel/test-trace-events-v8.js diff --git a/doc/api/tracing.md b/doc/api/tracing.md index 28e488201ec2d8..53c6dac55dac05 100644 --- a/doc/api/tracing.md +++ b/doc/api/tracing.md @@ -8,10 +8,10 @@ Node.js application. The set of categories for which traces are recorded can be specified using the `--trace-event-categories` flag followed by a list of comma separated category names. -By default the `node` and `v8` categories are enabled. +By default the `node`, `node.async_hooks`, and `v8` categories are enabled. ```txt -node --trace-events-enabled --trace-event-categories v8,node server.js +node --trace-events-enabled --trace-event-categories v8,node,node.async_hooks server.js ``` Running Node.js with tracing enabled will produce log files that can be opened diff --git a/lib/_http_common.js b/lib/_http_common.js index 4c8d3c3850b2fa..6f5378fbe275e8 100644 --- a/lib/_http_common.js +++ b/lib/_http_common.js @@ -27,7 +27,6 @@ const { methods, HTTPParser } = binding; const FreeList = require('internal/freelist'); const { ondrain } = require('internal/http'); const incoming = require('_http_incoming'); -const { emitDestroy } = require('async_hooks'); const { IncomingMessage, readStart, @@ -218,7 +217,7 @@ function freeParser(parser, req, socket) { } else { // Since the Parser destructor isn't going to run the destroy() callbacks // it needs to be triggered manually. - emitDestroy(parser.getAsyncId()); + parser.free(); } } if (req) { diff --git a/lib/internal/bootstrap_node.js b/lib/internal/bootstrap_node.js index 9a2990fd473bed..dfb8b88ee440bb 100644 --- a/lib/internal/bootstrap_node.js +++ b/lib/internal/bootstrap_node.js @@ -59,6 +59,7 @@ if (global.__coverage__) NativeModule.require('internal/process/write-coverage').setup(); + NativeModule.require('internal/trace_events_async_hooks').setup(); NativeModule.require('internal/inspector_async_hook').setup(); // Do not initialize channel in debugger agent, it deletes env variable diff --git a/lib/internal/trace_events_async_hooks.js b/lib/internal/trace_events_async_hooks.js new file mode 100644 index 00000000000000..9f47f2aa5fd658 --- /dev/null +++ b/lib/internal/trace_events_async_hooks.js @@ -0,0 +1,67 @@ +'use strict'; + +const trace_events = process.binding('trace_events'); +const async_wrap = process.binding('async_wrap'); +const async_hooks = require('async_hooks'); + +// Use small letters such that chrome://traceing groups by the name. +// The behaviour is not only useful but the same as the events emitted using +// the specific C++ macros. +const BEFORE_EVENT = 'b'.charCodeAt(0); +const END_EVENT = 'e'.charCodeAt(0); + +// In trace_events it is not only the id but also the name that needs to be +// repeated. Since async_hooks doesn't expose the provider type in the +// non-init events, use a map to manually map the asyncId to the type name. +const typeMemory = new Map(); + +// It is faster to emit trace_events directly from C++. Thus, this happens in +// async_wrap.cc. However, events emitted from the JavaScript API or the +// Embedder C++ API can't be emitted from async_wrap.cc. Thus they are +// emitted using the JavaScript API. To prevent emitting the same event +// twice the async_wrap.Providers list is used to filter the events. +const nativeProviders = new Set(Object.keys(async_wrap.Providers)); + +const hook = async_hooks.createHook({ + init(asyncId, type, triggerAsyncId, resource) { + if (nativeProviders.has(type)) return; + + typeMemory.set(asyncId, type); + trace_events.emit(BEFORE_EVENT, 'node.async_hooks', + type, asyncId, 'triggerAsyncId', triggerAsyncId); + }, + + before(asyncId) { + const type = typeMemory.get(asyncId); + if (type === undefined) return; + + trace_events.emit(BEFORE_EVENT, 'node.async_hooks', + type + '_CALLBACK', asyncId); + }, + + after(asyncId) { + const type = typeMemory.get(asyncId); + if (type === undefined) return; + + trace_events.emit(END_EVENT, 'node.async_hooks', + type + '_CALLBACK', asyncId); + }, + + destroy(asyncId) { + const type = typeMemory.get(asyncId); + if (type === undefined) return; + + trace_events.emit(END_EVENT, 'node.async_hooks', + type, asyncId); + + // cleanup asyncId to type map + typeMemory.delete(asyncId); + } +}); + + +exports.setup = function() { + if (trace_events.categoryGroupEnabled('node.async_hooks')) { + hook.enable(); + } +}; diff --git a/node.gyp b/node.gyp index a210f74eeaeb69..1e8121e0385159 100644 --- a/node.gyp +++ b/node.gyp @@ -121,6 +121,7 @@ 'lib/internal/socket_list.js', 'lib/internal/test/unicode.js', 'lib/internal/tls.js', + 'lib/internal/trace_events_async_hooks.js', 'lib/internal/url.js', 'lib/internal/util.js', 'lib/internal/util/comparisons.js', @@ -213,6 +214,7 @@ 'src/node_platform.cc', 'src/node_perf.cc', 'src/node_serdes.cc', + 'src/node_trace_events.cc', 'src/node_url.cc', 'src/node_util.cc', 'src/node_v8.cc', diff --git a/src/async-wrap.cc b/src/async-wrap.cc index 8f2b8f377f4d1f..9be77c2e9443c4 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(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(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, 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& args) { void AsyncWrap::QueueDestroyAsyncId(const FunctionCallbackInfo& 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(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(get_async_id()), \ + "triggerAsyncId", static_cast(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 AsyncWrap::MakeCallback(const Local cb, int argc, Local* argv) { + EmitTraceEventBefore(); + async_context context { get_async_id(), get_trigger_async_id() }; - return InternalMakeCallback(env(), object(), cb, argc, argv, context); + MaybeLocal 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 22761fa65f7796..df2eae5233d534 100644 --- a/src/async-wrap.h +++ b/src/async-wrap.h @@ -129,12 +129,18 @@ class AsyncWrap : public BaseObject { static void EmitAsyncInit(Environment* env, v8::Local object, v8::Local 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 35a7f6582ef7d3..37fdd47ec176cc 100644 --- a/src/node.cc +++ b/src/node.cc @@ -263,13 +263,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 9102f9f886c3ae..972982a4260ba4 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& 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 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 00000000000000..20edb66cd66ed4 --- /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 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 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& args) { + Environment* env = Environment::GetCurrent(args); + Local 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(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& 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 target, + Local unused, + Local 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 bc04b0b5e60d17..4514a0fce1f0a2 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 diff --git a/test/parallel/test-trace-event.js b/test/parallel/test-trace-event.js deleted file mode 100644 index 434c7db4d263cd..00000000000000 --- a/test/parallel/test-trace-event.js +++ /dev/null @@ -1,41 +0,0 @@ -'use strict'; -const common = require('../common'); -const assert = require('assert'); -const cp = require('child_process'); -const fs = require('fs'); - -const CODE = 'for (var i = 0; i < 100000; i++) { "test" + i }'; -const FILE_NAME = 'node_trace.1.log'; - -common.refreshTmpDir(); -process.chdir(common.tmpDir); - -const proc_no_categories = cp.spawn( - process.execPath, - [ '--trace-events-enabled', '--trace-event-categories', '""', '-e', CODE ] -); - -proc_no_categories.once('exit', common.mustCall(() => { - assert(!common.fileExists(FILE_NAME)); - - const proc = cp.spawn(process.execPath, - [ '--trace-events-enabled', '-e', CODE ]); - - proc.once('exit', common.mustCall(() => { - assert(common.fileExists(FILE_NAME)); - fs.readFile(FILE_NAME, common.mustCall((err, data) => { - const traces = JSON.parse(data.toString()).traceEvents; - assert(traces.length > 0); - // Values that should be present on all runs to approximate correctness. - 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; - })); - })); - })); -})); diff --git a/test/parallel/test-trace-events-all.js b/test/parallel/test-trace-events-all.js new file mode 100644 index 00000000000000..329f99f591244d --- /dev/null +++ b/test/parallel/test-trace-events-all.js @@ -0,0 +1,56 @@ +'use strict'; +const common = require('../common'); +const assert = require('assert'); +const cp = require('child_process'); +const fs = require('fs'); + +const CODE = + 'setTimeout(() => { for (var i = 0; i < 100000; i++) { "test" + i } }, 1)'; +const FILE_NAME = 'node_trace.1.log'; + +common.refreshTmpDir(); +process.chdir(common.tmpDir); + +const proc = cp.spawn(process.execPath, + [ '--trace-events-enabled', '-e', CODE ]); + +proc.once('exit', common.mustCall(() => { + assert(common.fileExists(FILE_NAME)); + fs.readFile(FILE_NAME, common.mustCall((err, data) => { + const traces = JSON.parse(data.toString()).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.async_hooks') + return false; + if (trace.name !== 'TIMERWRAP') + 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.async_hooks') + return false; + if (trace.name !== 'Timeout') + return false; + return true; + })); + })); +})); diff --git a/test/parallel/test-trace-events-async-hooks.js b/test/parallel/test-trace-events-async-hooks.js new file mode 100644 index 00000000000000..7f8fb106200b1a --- /dev/null +++ b/test/parallel/test-trace-events-async-hooks.js @@ -0,0 +1,58 @@ +'use strict'; +const common = require('../common'); +const assert = require('assert'); +const cp = require('child_process'); +const fs = require('fs'); + +const CODE = + 'setTimeout(() => { for (var i = 0; i < 100000; i++) { "test" + i } }, 1)'; +const FILE_NAME = 'node_trace.1.log'; + +common.refreshTmpDir(); +process.chdir(common.tmpDir); + +const proc = cp.spawn(process.execPath, + [ '--trace-events-enabled', + '--trace-event-categories', 'node.async_hooks', + '-e', CODE ]); + +proc.once('exit', common.mustCall(() => { + assert(common.fileExists(FILE_NAME)); + fs.readFile(FILE_NAME, common.mustCall((err, data) => { + const traces = JSON.parse(data.toString()).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.async_hooks') + return false; + if (trace.name !== 'TIMERWRAP') + 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.async_hooks') + return false; + if (trace.name !== 'Timeout') + return false; + return true; + })); + })); +})); diff --git a/test/parallel/test-trace-events-binding.js b/test/parallel/test-trace-events-binding.js new file mode 100644 index 00000000000000..628c9cace71973 --- /dev/null +++ b/test/parallel/test-trace-events-binding.js @@ -0,0 +1,48 @@ +'use strict'; +const common = require('../common'); +const assert = require('assert'); +const cp = require('child_process'); +const fs = require('fs'); + +const CODE = ` + process.binding("trace_events").emit( + 'b'.charCodeAt(0), 'custom', + 'type-value', 10, 'extra-value', 20); + process.binding("trace_events").emit( + 'b'.charCodeAt(0), 'custom', + 'type-value', 20); + process.binding("trace_events").emit( + 'b'.charCodeAt(0), 'missing', + 'type-value', 10, 'extra-value', 20); +`; +const FILE_NAME = 'node_trace.1.log'; + +common.refreshTmpDir(); +process.chdir(common.tmpDir); + +const proc = cp.spawn(process.execPath, + [ '--trace-events-enabled', + '--trace-event-categories', 'custom', + '-e', CODE ]); + +proc.once('exit', common.mustCall(() => { + assert(common.fileExists(FILE_NAME)); + fs.readFile(FILE_NAME, common.mustCall((err, data) => { + const traces = JSON.parse(data.toString()).traceEvents; + assert.strictEqual(traces.length, 2); + + assert.strictEqual(traces[0].pid, proc.pid); + assert.strictEqual(traces[0].ph, 'b'); + assert.strictEqual(traces[0].cat, 'custom'); + assert.strictEqual(traces[0].name, 'type-value'); + assert.strictEqual(traces[0].id, '0xa'); + assert.deepStrictEqual(traces[0].args, { 'extra-value': 20 }); + + assert.strictEqual(traces[1].pid, proc.pid); + assert.strictEqual(traces[1].ph, 'b'); + assert.strictEqual(traces[1].cat, 'custom'); + assert.strictEqual(traces[1].name, 'type-value'); + assert.strictEqual(traces[1].id, '0x14'); + assert.deepStrictEqual(traces[1].args, { }); + })); +})); diff --git a/test/parallel/test-trace-events-category-used.js b/test/parallel/test-trace-events-category-used.js new file mode 100644 index 00000000000000..39d09ad862d787 --- /dev/null +++ b/test/parallel/test-trace-events-category-used.js @@ -0,0 +1,35 @@ +'use strict'; +const common = require('../common'); +const assert = require('assert'); +const cp = require('child_process'); + +const CODE = `console.log( + process.binding("trace_events").categoryGroupEnabled("custom") +);`; + +common.refreshTmpDir(); +process.chdir(common.tmpDir); + +const procEnabled = cp.spawn( + process.execPath, + [ '--trace-events-enabled', '--trace-event-categories', 'custom', '-e', CODE ] +); +let procEnabledOutput = ''; + +procEnabled.stdout.on('data', (data) => procEnabledOutput += data); +procEnabled.stderr.pipe(process.stderr); +procEnabled.once('exit', common.mustCall(() => { + assert.strictEqual(procEnabledOutput, 'true\n'); +})); + +const procDisabled = cp.spawn( + process.execPath, + [ '--trace-events-enabled', '--trace-event-categories', 'other', '-e', CODE ] +); +let procDisabledOutput = ''; + +procDisabled.stdout.on('data', (data) => procDisabledOutput += data); +procDisabled.stderr.pipe(process.stderr); +procDisabled.once('exit', common.mustCall(() => { + assert.strictEqual(procDisabledOutput, 'false\n'); +})); diff --git a/test/parallel/test-trace-events-none.js b/test/parallel/test-trace-events-none.js new file mode 100644 index 00000000000000..9a4d587f2db0e1 --- /dev/null +++ b/test/parallel/test-trace-events-none.js @@ -0,0 +1,20 @@ +'use strict'; +const common = require('../common'); +const assert = require('assert'); +const cp = require('child_process'); + +const CODE = + 'setTimeout(() => { for (var i = 0; i < 100000; i++) { "test" + i } }, 1)'; +const FILE_NAME = 'node_trace.1.log'; + +common.refreshTmpDir(); +process.chdir(common.tmpDir); + +const proc_no_categories = cp.spawn( + process.execPath, + [ '--trace-events-enabled', '--trace-event-categories', '""', '-e', CODE ] +); + +proc_no_categories.once('exit', common.mustCall(() => { + assert(!common.fileExists(FILE_NAME)); +})); diff --git a/test/parallel/test-trace-events-v8.js b/test/parallel/test-trace-events-v8.js new file mode 100644 index 00000000000000..b17b1473ecaf0c --- /dev/null +++ b/test/parallel/test-trace-events-v8.js @@ -0,0 +1,58 @@ +'use strict'; +const common = require('../common'); +const assert = require('assert'); +const cp = require('child_process'); +const fs = require('fs'); + +const CODE = + 'setTimeout(() => { for (var i = 0; i < 100000; i++) { "test" + i } }, 1)'; +const FILE_NAME = 'node_trace.1.log'; + +common.refreshTmpDir(); +process.chdir(common.tmpDir); + +const proc = cp.spawn(process.execPath, + [ '--trace-events-enabled', + '--trace-event-categories', 'v8', + '-e', CODE ]); + +proc.once('exit', common.mustCall(() => { + assert(common.fileExists(FILE_NAME)); + fs.readFile(FILE_NAME, common.mustCall((err, data) => { + const traces = JSON.parse(data.toString()).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.async_hooks') + return false; + if (trace.name !== 'TIMERWRAP') + 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.async_hooks') + return false; + if (trace.name !== 'Timeout') + return false; + return true; + })); + })); +}));