From da5d818a54ab28df632e29204896a74c855b3430 Mon Sep 17 00:00:00 2001 From: James M Snell Date: Tue, 3 Apr 2018 18:05:33 -0700 Subject: [PATCH] trace_events: adds a new trace_events api Removes the requirement to use `--trace-events-enabled` to enable trace events. Tracing is enabled automatically if there are any enabled categories. Adds a new `trace_events` module with an API for enabling/disabling trace events at runtime without a command line flag. ```js const trace_events = require('trace_events'); const categories = [ 'node.perf', 'node.async_hooks' ]; const tracing = trace_events.createTracing({ categories }); tracing.enable(); // do stuff tracing.disable(); ``` Multiple `Tracing` objects may exist and be enabled at any point in time. The enabled trace event categories is the union of all enabled `Tracing` objects and the `--trace-event-categories` flag. PR-URL: https://github.com/nodejs/node/pull/19803 Reviewed-By: Matteo Collina Reviewed-By: Ali Ijaz Sheikh Reviewed-By: Franziska Hinkelmann --- doc/api/_toc.md | 2 +- doc/api/errors.md | 12 ++ doc/api/tracing.md | 162 ++++++++++++++++- lib/internal/errors.js | 3 + lib/internal/modules/cjs/helpers.js | 3 +- lib/trace_events.js | 89 ++++++++++ node.gyp | 1 + src/env-inl.h | 5 + src/env.cc | 5 +- src/env.h | 7 +- src/node.cc | 57 +++--- src/node_config.cc | 4 + src/node_trace_events.cc | 93 ++++++++++ src/tracing/agent.cc | 113 ++++++++---- src/tracing/agent.h | 19 +- test/common/index.js | 7 + test/parallel/test-module-cjs-helpers.js | 2 +- test/parallel/test-trace-events-api.js | 164 ++++++++++++++++++ .../parallel/test-trace-events-async-hooks.js | 3 +- test/parallel/test-trace-events-binding.js | 3 +- test/parallel/test-trace-events-bootstrap.js | 1 - .../test-trace-events-category-used.js | 4 +- test/parallel/test-trace-events-none.js | 2 +- test/parallel/test-trace-events-perf.js | 1 - tools/doc/type-parser.js | 2 + 25 files changed, 677 insertions(+), 87 deletions(-) create mode 100644 lib/trace_events.js create mode 100644 test/parallel/test-trace-events-api.js diff --git a/doc/api/_toc.md b/doc/api/_toc.md index 29b264e77b3c63..9b487b50a55031 100644 --- a/doc/api/_toc.md +++ b/doc/api/_toc.md @@ -46,7 +46,7 @@ * [String Decoder](string_decoder.html) * [Timers](timers.html) * [TLS/SSL](tls.html) -* [Tracing](tracing.html) +* [Trace Events](tracing.html) * [TTY](tty.html) * [UDP/Datagram](dgram.html) * [URL](url.html) diff --git a/doc/api/errors.md b/doc/api/errors.md index 0ba9b992fd8e2e..84a74c51e05093 100644 --- a/doc/api/errors.md +++ b/doc/api/errors.md @@ -1550,6 +1550,18 @@ socket, which is only valid from a client. An attempt was made to renegotiate TLS on a socket instance with TLS disabled. + +### ERR_TRACE_EVENTS_CATEGORY_REQUIRED + +The `trace_events.createTracing()` method requires at least one trace event +category. + + +### ERR_TRACE_EVENTS_UNAVAILABLE + +The `trace_events` module could not be loaded because Node.js was compiled with +the `--without-v8-platform` flag. + ### ERR_TRANSFORM_ALREADY_TRANSFORMING diff --git a/doc/api/tracing.md b/doc/api/tracing.md index b53197b8109c83..e07320a0163284 100644 --- a/doc/api/tracing.md +++ b/doc/api/tracing.md @@ -1,16 +1,15 @@ -# Tracing +# Trace Events +> Stability: 1 - Experimental + Trace Event provides a mechanism to centralize tracing information generated by V8, Node.js core, and userspace code. -Tracing can be enabled by passing the `--trace-events-enabled` flag when -starting a 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. +Tracing can be enabled with the `--trace-event-categories` command-line flag +or by using the trace_events module. The `--trace-event-categories` flag accepts +a list of comma-separated category names. The available categories are: @@ -27,7 +26,32 @@ The available categories are: By default the `node`, `node.async_hooks`, and `v8` categories are enabled. ```txt -node --trace-events-enabled --trace-event-categories v8,node,node.async_hooks server.js +node --trace-event-categories v8,node,node.async_hooks server.js +``` + +Prior versions of Node.js required the use of the `--trace-events-enabled` +flag to enable trace events. This requirement has been removed. However, the +`--trace-events-enabled` flag *may* still be used and will enable the +`node`, `node.async_hooks`, and `v8` trace event categories by default. + +```txt +node --trace-events-enabled + +// is equivalent to + +node --trace-event-categories v8,node,node.async_hooks +``` + +Alternatively, trace events may be enabled using the `trace_events` module: + +```js +const trace_events = require('trace_events'); +const tracing = trace_events.createTracing({ categories: ['node.perf'] }); +tracing.enable(); // Enable trace event capture for the 'node.perf' category + +// do work + +tracing.disable(); // Disable trace event capture for the 'node.perf' category ``` Running Node.js with tracing enabled will produce log files that can be opened @@ -40,7 +64,7 @@ be specified with `--trace-event-file-pattern` that accepts a template string that supports `${rotation}` and `${pid}`. For example: ```txt -node --trace-events-enabled --trace-event-file-pattern '${pid}-${rotation}.log' server.js +node --trace-event-categories v8 --trace-event-file-pattern '${pid}-${rotation}.log' server.js ``` Starting with Node.js 10.0.0, the tracing system uses the same time source @@ -48,4 +72,124 @@ as the one used by `process.hrtime()` however the trace-event timestamps are expressed in microseconds, unlike `process.hrtime()` which returns nanoseconds. +## The `trace_events` module + + +### `Tracing` object + + +The `Tracing` object is used to enable or disable tracing for sets of +categories. Instances are created using the `trace_events.createTracing()` +method. + +When created, the `Tracing` object is disabled. Calling the +`tracing.enable()` method adds the categories to the set of enabled trace event +categories. Calling `tracing.disable()` will remove the categories from the +set of enabled trace event categories. + +#### `tracing.categories` + + +* {string} + +A comma-separated list of the trace event categories covered by this +`Tracing` object. + +#### `tracing.disable()` + + +Disables this `Tracing` object. + +Only trace event categories *not* covered by other enabled `Tracing` objects +and *not* specified by the `--trace-event-categories` flag will be disabled. + +```js +const trace_events = require('trace_events'); +const t1 = trace_events.createTracing({ categories: ['node', 'v8'] }); +const t2 = trace_events.createTracing({ categories: ['node.perf', 'node'] }); +t1.enable(); +t2.enable(); + +// Prints 'node,node.perf,v8' +console.log(trace_events.getEnabledCategories()); + +t2.disable(); // will only disable emission of the 'node.perf' category + +// Prints 'node,v8' +console.log(trace_events.getEnabledCategories()); +``` + +#### `tracing.enable()` + + +Enables this `Tracing` object for the set of categories covered by the +`Tracing` object. + +#### `tracing.enabled` + + +* {boolean} `true` only if the `Tracing` object has been enabled. + +### `trace_events.createTracing(options)` + + +* `options` {Object} + * `categories` {string[]} An array of trace category names. Values included + in the array are coerced to a string when possible. An error will be + thrown if the value cannot be coerced. +* Returns: {Tracing}. + +Creates and returns a `Tracing` object for the given set of `categories`. + +```js +const trace_events = require('trace_events'); +const categories = ['node.perf', 'node.async_hooks']; +const tracing = trace_events.createTracing({ categories }); +tracing.enable(); +// do stuff +tracing.disable(); +``` + +### `trace_events.getEnabledCategories()` + + +* Returns: {string} + +Returns a comma-separated list of all currently-enabled trace event +categories. The current set of enabled trace event categories is determined +by the *union* of all currently-enabled `Tracing` objects and any categories +enabled using the `--trace-event-categories` flag. + +Given the file `test.js` below, the command +`node --trace-event-categories node.perf test.js` will print +`'node.async_hooks,node.perf'` to the console. + +```js +const trace_events = require('trace_events'); +const t1 = trace_events.createTracing({ categories: ['node.async_hooks'] }); +const t2 = trace_events.createTracing({ categories: ['node.perf'] }); +const t3 = trace_events.createTracing({ categories: ['v8'] }); + +t1.enable(); +t2.enable(); + +console.log(trace_events.getEnabledCategories()); +``` + [Performance API]: perf_hooks.html diff --git a/lib/internal/errors.js b/lib/internal/errors.js index a91f5f6dcfd040..4823f0b65cb6ea 100644 --- a/lib/internal/errors.js +++ b/lib/internal/errors.js @@ -984,6 +984,9 @@ E('ERR_TLS_REQUIRED_SERVER_NAME', E('ERR_TLS_SESSION_ATTACK', 'TLS session renegotiation attack detected', Error); E('ERR_TLS_SNI_FROM_SERVER', 'Cannot issue SNI from a TLS server-side socket', Error); +E('ERR_TRACE_EVENTS_CATEGORY_REQUIRED', + 'At least one category is required', TypeError); +E('ERR_TRACE_EVENTS_UNAVAILABLE', 'Trace events are unavailable', Error); E('ERR_TRANSFORM_ALREADY_TRANSFORMING', 'Calling transform done when still transforming', Error); diff --git a/lib/internal/modules/cjs/helpers.js b/lib/internal/modules/cjs/helpers.js index fdad580b3b6158..60346c5841c7df 100644 --- a/lib/internal/modules/cjs/helpers.js +++ b/lib/internal/modules/cjs/helpers.js @@ -101,7 +101,8 @@ const builtinLibs = [ 'assert', 'async_hooks', 'buffer', 'child_process', 'cluster', 'crypto', 'dgram', 'dns', 'domain', 'events', 'fs', 'http', 'http2', 'https', 'net', 'os', 'path', 'perf_hooks', 'punycode', 'querystring', 'readline', 'repl', - 'stream', 'string_decoder', 'tls', 'tty', 'url', 'util', 'v8', 'vm', 'zlib' + 'stream', 'string_decoder', 'tls', 'trace_events', 'tty', 'url', 'util', + 'v8', 'vm', 'zlib' ]; if (typeof process.binding('inspector').open === 'function') { diff --git a/lib/trace_events.js b/lib/trace_events.js new file mode 100644 index 00000000000000..45015c8a63add0 --- /dev/null +++ b/lib/trace_events.js @@ -0,0 +1,89 @@ +'use strict'; + +const { hasTracing } = process.binding('config'); +const kHandle = Symbol('handle'); +const kEnabled = Symbol('enabled'); +const kCategories = Symbol('categories'); + +const kMaxTracingCount = 10; + +const { + ERR_TRACE_EVENTS_CATEGORY_REQUIRED, + ERR_TRACE_EVENTS_UNAVAILABLE, + ERR_INVALID_ARG_TYPE +} = require('internal/errors').codes; + +if (!hasTracing) + throw new ERR_TRACE_EVENTS_UNAVAILABLE(); + +const { CategorySet, getEnabledCategories } = process.binding('trace_events'); +const { customInspectSymbol } = require('internal/util'); +const { format } = require('util'); + +const enabledTracingObjects = new Set(); + +class Tracing { + constructor(categories) { + this[kHandle] = new CategorySet(categories); + this[kCategories] = categories; + this[kEnabled] = false; + } + + enable() { + if (!this[kEnabled]) { + this[kEnabled] = true; + this[kHandle].enable(); + enabledTracingObjects.add(this); + if (enabledTracingObjects.size > kMaxTracingCount) { + process.emitWarning( + 'Possible trace_events memory leak detected. There are more than ' + + `${kMaxTracingCount} enabled Tracing objects.` + ); + } + } + } + + disable() { + if (this[kEnabled]) { + this[kEnabled] = false; + this[kHandle].disable(); + enabledTracingObjects.delete(this); + } + } + + get enabled() { + return this[kEnabled]; + } + + get categories() { + return this[kCategories].join(','); + } + + [customInspectSymbol](depth, opts) { + const obj = { + enabled: this.enabled, + categories: this.categories + }; + return `Tracing ${format(obj)}`; + } +} + +function createTracing(options) { + if (typeof options !== 'object' || options == null) + throw new ERR_INVALID_ARG_TYPE('options', 'object', options); + + if (!Array.isArray(options.categories)) { + throw new ERR_INVALID_ARG_TYPE('options.categories', 'string[]', + options.categories); + } + + if (options.categories.length <= 0) + throw new ERR_TRACE_EVENTS_CATEGORY_REQUIRED(); + + return new Tracing(options.categories); +} + +module.exports = { + createTracing, + getEnabledCategories +}; diff --git a/node.gyp b/node.gyp index 7ca158c25f04c8..15475f689e3295 100644 --- a/node.gyp +++ b/node.gyp @@ -73,6 +73,7 @@ 'lib/tls.js', 'lib/_tls_common.js', 'lib/_tls_wrap.js', + 'lib/trace_events.js', 'lib/tty.js', 'lib/url.js', 'lib/util.js', diff --git a/src/env-inl.h b/src/env-inl.h index 96e88b5c116adb..fa241f9706ec65 100644 --- a/src/env-inl.h +++ b/src/env-inl.h @@ -32,6 +32,7 @@ #include "v8.h" #include "node_perf_common.h" #include "node_context_data.h" +#include "tracing/agent.h" #include #include @@ -325,6 +326,10 @@ inline v8::Isolate* Environment::isolate() const { return isolate_; } +inline tracing::Agent* Environment::tracing_agent() const { + return tracing_agent_; +} + inline Environment* Environment::from_immediate_check_handle( uv_check_t* handle) { return ContainerOf(&Environment::immediate_check_handle_, handle); diff --git a/src/env.cc b/src/env.cc index 4be70036e313cf..1f47ea21af21b8 100644 --- a/src/env.cc +++ b/src/env.cc @@ -3,6 +3,7 @@ #include "node_buffer.h" #include "node_platform.h" #include "node_file.h" +#include "tracing/agent.h" #include #include @@ -87,9 +88,11 @@ void InitThreadLocalOnce() { } Environment::Environment(IsolateData* isolate_data, - Local context) + Local context, + tracing::Agent* tracing_agent) : isolate_(context->GetIsolate()), isolate_data_(isolate_data), + tracing_agent_(tracing_agent), immediate_info_(context->GetIsolate()), tick_info_(context->GetIsolate()), timer_base_(uv_now(isolate_data->event_loop())), diff --git a/src/env.h b/src/env.h index 23758c8d123ea6..af4470ad8632fe 100644 --- a/src/env.h +++ b/src/env.h @@ -36,6 +36,7 @@ #include "v8.h" #include "node.h" #include "node_http2_state.h" +#include "tracing/agent.h" #include #include @@ -553,7 +554,9 @@ class Environment { static uv_key_t thread_local_env; static inline Environment* GetThreadLocalEnv(); - Environment(IsolateData* isolate_data, v8::Local context); + Environment(IsolateData* isolate_data, + v8::Local context, + tracing::Agent* tracing_agent); ~Environment(); void Start(int argc, @@ -585,6 +588,7 @@ class Environment { void StopProfilerIdleNotifier(); inline v8::Isolate* isolate() const; + inline tracing::Agent* tracing_agent() const; inline uv_loop_t* event_loop() const; inline uint32_t watched_providers() const; @@ -780,6 +784,7 @@ class Environment { v8::Isolate* const isolate_; IsolateData* const isolate_data_; + tracing::Agent* const tracing_agent_; uv_check_t immediate_check_handle_; uv_idle_t immediate_idle_handle_; uv_prepare_t idle_prepare_handle_; diff --git a/src/node.cc b/src/node.cc index 6f946ab3ad1cc7..099fba35a872d5 100644 --- a/src/node.cc +++ b/src/node.cc @@ -191,7 +191,6 @@ static node_module* modlist_builtin; static node_module* modlist_internal; static node_module* modlist_linked; static node_module* modlist_addon; -static bool trace_enabled = false; static std::string trace_enabled_categories; // NOLINT(runtime/string) static std::string trace_file_pattern = // NOLINT(runtime/string) "node_trace.${rotation}.log"; @@ -277,20 +276,12 @@ DebugOptions debug_options; static struct { #if NODE_USE_V8_PLATFORM void Initialize(int thread_pool_size) { - if (trace_enabled) { - tracing_agent_.reset(new tracing::Agent(trace_file_pattern)); - platform_ = new NodePlatform(thread_pool_size, + tracing_agent_.reset(new tracing::Agent(trace_file_pattern)); + platform_ = new NodePlatform(thread_pool_size, tracing_agent_->GetTracingController()); - V8::InitializePlatform(platform_); - tracing::TraceEventHelper::SetTracingController( + 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() { @@ -323,13 +314,17 @@ static struct { #endif // HAVE_INSPECTOR void StartTracingAgent() { - tracing_agent_->Start(trace_enabled_categories); + tracing_agent_->Enable(trace_enabled_categories); } void StopTracingAgent() { tracing_agent_->Stop(); } + tracing::Agent* GetTracingAgent() const { + return tracing_agent_.get(); + } + NodePlatform* Platform() { return platform_; } @@ -348,11 +343,15 @@ static struct { } void StartTracingAgent() { - fprintf(stderr, "Node compiled with NODE_USE_V8_PLATFORM=0, " - "so event tracing is not available.\n"); + if (!trace_enabled_categories.empty()) { + fprintf(stderr, "Node compiled with NODE_USE_V8_PLATFORM=0, " + "so event tracing is not available.\n"); + } } void StopTracingAgent() {} + tracing::Agent* GetTracingAgent() const { return nullptr; } + NodePlatform* Platform() { return nullptr; } @@ -1990,9 +1989,7 @@ static void WaitForInspectorDisconnect(Environment* env) { static void Exit(const FunctionCallbackInfo& args) { WaitForInspectorDisconnect(Environment::GetCurrent(args)); - if (trace_enabled) { - v8_platform.StopTracingAgent(); - } + v8_platform.StopTracingAgent(); exit(args[0]->Int32Value()); } @@ -3287,9 +3284,7 @@ void SetupProcessObject(Environment* env, void SignalExit(int signo) { uv_tty_reset_mode(); - if (trace_enabled) { - v8_platform.StopTracingAgent(); - } + v8_platform.StopTracingAgent(); #ifdef __FreeBSD__ // FreeBSD has a nasty bug, see RegisterSignalHandler for details struct sigaction sa; @@ -3789,7 +3784,8 @@ static void ParseArgs(int* argc, } else if (strcmp(arg, "--no-force-async-hooks-checks") == 0) { no_force_async_hooks_checks = true; } else if (strcmp(arg, "--trace-events-enabled") == 0) { - trace_enabled = true; + if (trace_enabled_categories.empty()) + trace_enabled_categories = "v8,node,node.async_hooks"; } else if (strcmp(arg, "--trace-event-categories") == 0) { const char* categories = argv[index + 1]; if (categories == nullptr) { @@ -4422,7 +4418,8 @@ Environment* CreateEnvironment(IsolateData* isolate_data, Isolate* isolate = context->GetIsolate(); HandleScope handle_scope(isolate); Context::Scope context_scope(context); - auto env = new Environment(isolate_data, context); + auto env = new Environment(isolate_data, context, + v8_platform.GetTracingAgent()); env->Start(argc, argv, exec_argc, exec_argv, v8_is_profiling); return env; } @@ -4471,7 +4468,7 @@ inline int Start(Isolate* isolate, IsolateData* isolate_data, HandleScope handle_scope(isolate); Local context = NewContext(isolate); Context::Scope context_scope(context); - Environment env(isolate_data, context); + Environment env(isolate_data, context, v8_platform.GetTracingAgent()); env.Start(argc, argv, exec_argc, exec_argv, v8_is_profiling); const char* path = argc > 1 ? argv[1] : nullptr; @@ -4628,19 +4625,13 @@ int Start(int argc, char** argv) { v8_platform.Initialize(v8_thread_pool_size); // Enable tracing when argv has --trace-events-enabled. - if (trace_enabled) { - fprintf(stderr, "Warning: Trace event is an experimental feature " - "and could change at any time.\n"); - v8_platform.StartTracingAgent(); - } + v8_platform.StartTracingAgent(); V8::Initialize(); performance::performance_v8_start = PERFORMANCE_NOW(); v8_initialized = true; const int exit_code = Start(uv_default_loop(), argc, argv, exec_argc, exec_argv); - if (trace_enabled) { - v8_platform.StopTracingAgent(); - } + v8_platform.StopTracingAgent(); v8_initialized = false; V8::Dispose(); diff --git a/src/node_config.cc b/src/node_config.cc index 0542bff1d65186..055a9b0ae46887 100644 --- a/src/node_config.cc +++ b/src/node_config.cc @@ -56,6 +56,10 @@ static void Initialize(Local target, READONLY_BOOLEAN_PROPERTY("hasSmallICU"); #endif // NODE_HAVE_SMALL_ICU +#if NODE_USE_V8_PLATFORM + READONLY_BOOLEAN_PROPERTY("hasTracing"); +#endif + target->DefineOwnProperty( context, FIXED_ONE_BYTE_STRING(isolate, "icuDataDir"), diff --git a/src/node_trace_events.cc b/src/node_trace_events.cc index 96d00115feee74..1e02048d1f0843 100644 --- a/src/node_trace_events.cc +++ b/src/node_trace_events.cc @@ -1,15 +1,98 @@ +#include "node.h" #include "node_internals.h" #include "tracing/agent.h" +#include "env.h" +#include "base_object-inl.h" + +#include +#include namespace node { +using v8::Array; using v8::Context; using v8::FunctionCallbackInfo; +using v8::FunctionTemplate; using v8::Int32; using v8::Local; using v8::Object; +using v8::String; using v8::Value; +class NodeCategorySet : public BaseObject { + public: + ~NodeCategorySet() override { + // Verify that the thing was properly disabled before gc + CHECK_NE(enabled_, true); + } + + static void New(const FunctionCallbackInfo& args); + static void Enable(const FunctionCallbackInfo& args); + static void Disable(const FunctionCallbackInfo& args); + + const std::set& GetCategories() { return categories_; } + + private: + NodeCategorySet(Environment* env, + Local wrap, + std::set categories) : + BaseObject(env, wrap), categories_(categories) { + MakeWeak(this); + } + + bool enabled_ = false; + const std::set categories_; +}; + +void NodeCategorySet::New(const FunctionCallbackInfo& args) { + Environment* env = Environment::GetCurrent(args); + std::set categories; + CHECK(args[0]->IsArray()); + Local cats = args[0].As(); + for (size_t n = 0; n < cats->Length(); n++) { + Local category = cats->Get(env->context(), n).ToLocalChecked(); + Utf8Value val(env->isolate(), category); + categories.emplace(*val); + } + CHECK_NE(env->tracing_agent(), nullptr); + new NodeCategorySet(env, args.This(), categories); +} + +void NodeCategorySet::Enable(const FunctionCallbackInfo& args) { + Environment* env = Environment::GetCurrent(args); + NodeCategorySet* category_set; + ASSIGN_OR_RETURN_UNWRAP(&category_set, args.Holder()); + CHECK_NE(category_set, nullptr); + auto categories = category_set->GetCategories(); + if (!category_set->enabled_ && !categories.empty()) { + env->tracing_agent()->Enable(categories); + category_set->enabled_ = true; + } +} + +void NodeCategorySet::Disable(const FunctionCallbackInfo& args) { + Environment* env = Environment::GetCurrent(args); + NodeCategorySet* category_set; + ASSIGN_OR_RETURN_UNWRAP(&category_set, args.Holder()); + CHECK_NE(category_set, nullptr); + auto categories = category_set->GetCategories(); + if (category_set->enabled_ && !categories.empty()) { + env->tracing_agent()->Disable(categories); + category_set->enabled_ = false; + } +} + +void GetEnabledCategories(const FunctionCallbackInfo& args) { + Environment* env = Environment::GetCurrent(args); + std::string categories = env->tracing_agent()->GetEnabledCategories(); + if (!categories.empty()) { + args.GetReturnValue().Set( + String::NewFromUtf8(env->isolate(), + categories.c_str(), + v8::NewStringType::kNormal).ToLocalChecked()); + } +} + // The tracing APIs require category groups to be pointers to long-lived // strings. Those strings are stored here. static std::unordered_set categoryGroups; @@ -140,6 +223,16 @@ void Initialize(Local target, env->SetMethod(target, "emit", Emit); env->SetMethod(target, "categoryGroupEnabled", CategoryGroupEnabled); + env->SetMethod(target, "getEnabledCategories", GetEnabledCategories); + + Local category_set = + env->NewFunctionTemplate(NodeCategorySet::New); + category_set->InstanceTemplate()->SetInternalFieldCount(1); + env->SetProtoMethod(category_set, "enable", NodeCategorySet::Enable); + env->SetProtoMethod(category_set, "disable", NodeCategorySet::Disable); + + target->Set(FIXED_ONE_BYTE_STRING(env->isolate(), "CategorySet"), + category_set->GetFunction()); } } // namespace node diff --git a/src/tracing/agent.cc b/src/tracing/agent.cc index 71e53e787a464e..cd4c3c0df9398e 100644 --- a/src/tracing/agent.cc +++ b/src/tracing/agent.cc @@ -5,55 +5,40 @@ #include "tracing/node_trace_buffer.h" #include "tracing/node_trace_writer.h" -#include "env-inl.h" - namespace node { namespace tracing { using v8::platform::tracing::TraceConfig; using std::string; -Agent::Agent(const std::string& log_file_pattern) { - int err = uv_loop_init(&tracing_loop_); - CHECK_EQ(err, 0); +Agent::Agent(const std::string& log_file_pattern) + : log_file_pattern_(log_file_pattern) { + tracing_controller_ = new TracingController(); + tracing_controller_->Initialize(nullptr); +} + +void Agent::Start() { + if (started_) + return; - NodeTraceWriter* trace_writer = new NodeTraceWriter( - log_file_pattern, &tracing_loop_); + CHECK_EQ(uv_loop_init(&tracing_loop_), 0); + + NodeTraceWriter* trace_writer = + new NodeTraceWriter(log_file_pattern_, &tracing_loop_); TraceBuffer* trace_buffer = new NodeTraceBuffer( NodeTraceBuffer::kBufferChunks, trace_writer, &tracing_loop_); - tracing_controller_ = new TracingController(); tracing_controller_->Initialize(trace_buffer); -} - -void Agent::Start(const string& enabled_categories) { - TraceConfig* trace_config = new TraceConfig(); - if (!enabled_categories.empty()) { - std::stringstream category_list(enabled_categories); - while (category_list.good()) { - std::string category; - getline(category_list, category, ','); - trace_config->AddIncludedCategory(category.c_str()); - } - } 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 // (within NodeTraceWriter and NodeTraceBuffer constructors). // Otherwise the thread could shut down prematurely. - int err = uv_thread_create(&thread_, ThreadCb, this); - CHECK_EQ(err, 0); - - tracing_controller_->StartTracing(trace_config); + CHECK_EQ(0, uv_thread_create(&thread_, ThreadCb, this)); started_ = true; } void Agent::Stop() { - if (!started_) { + if (!started_) return; - } // Perform final Flush on TraceBuffer. We don't want the tracing controller // to flush the buffer again on destruction of the V8::Platform. tracing_controller_->StopTracing(); @@ -70,5 +55,73 @@ void Agent::ThreadCb(void* arg) { uv_run(&agent->tracing_loop_, UV_RUN_DEFAULT); } +void Agent::Enable(const std::string& categories) { + if (!categories.empty()) { + std::stringstream category_list(categories); + while (category_list.good()) { + std::string category; + getline(category_list, category, ','); + categories_.insert(category.c_str()); + } + RestartTracing(); + } +} + +void Agent::Enable(const std::set& categories) { + if (!categories.empty()) { + categories_.insert(categories.begin(), categories.end()); + RestartTracing(); + } +} + +void Agent::Disable(const std::set& categories) { + if (!categories.empty()) { + for (auto category : categories) { + auto pos = categories_.lower_bound(category); + if (pos != categories_.end()) + categories_.erase(pos); + } + RestartTracing(); + } +} + +void Agent::RestartTracing() { + static bool warned; + if (!warned) { + warned = true; + fprintf(stderr, "Warning: Trace event is an experimental feature " + "and could change at any time.\n"); + } + Start(); // Start the agent if it hasn't already been started + tracing_controller_->StopTracing(); + auto config = CreateTraceConfig(); + if (config != nullptr) + tracing_controller_->StartTracing(config); +} + +TraceConfig* Agent::CreateTraceConfig() { + if (categories_.empty()) + return nullptr; + TraceConfig* trace_config = new TraceConfig(); + for (auto category = categories_.begin(); + category != categories_.end(); + category = categories_.upper_bound(*category)) { + trace_config->AddIncludedCategory(category->c_str()); + } + return trace_config; +} + +std::string Agent::GetEnabledCategories() { + std::string categories; + for (auto category = categories_.begin(); + category != categories_.end(); + category = categories_.upper_bound(*category)) { + if (!categories.empty()) + categories += ','; + categories += *category; + } + return categories; +} + } // namespace tracing } // namespace node diff --git a/src/tracing/agent.h b/src/tracing/agent.h index 9d6bc4e90a35af..ca5fd35417fd0f 100644 --- a/src/tracing/agent.h +++ b/src/tracing/agent.h @@ -5,9 +5,14 @@ #include "uv.h" #include "v8.h" +#include +#include + namespace node { namespace tracing { +using v8::platform::tracing::TraceConfig; + class TracingController : public v8::platform::tracing::TracingController { public: TracingController() : v8::platform::tracing::TracingController() {} @@ -20,17 +25,29 @@ class TracingController : public v8::platform::tracing::TracingController { class Agent { public: explicit Agent(const std::string& log_file_pattern); - void Start(const std::string& enabled_categories); void Stop(); TracingController* GetTracingController() { return tracing_controller_; } + void Enable(const std::string& categories); + void Enable(const std::set& categories); + void Disable(const std::set& categories); + std::string GetEnabledCategories(); + private: static void ThreadCb(void* arg); + void Start(); + void RestartTracing(); + + TraceConfig* CreateTraceConfig(); + + const std::string& log_file_pattern_; uv_thread_t thread_; uv_loop_t tracing_loop_; bool started_ = false; + + std::multiset categories_; TracingController* tracing_controller_ = nullptr; }; diff --git a/test/common/index.js b/test/common/index.js index eaae0b53acb17a..7df3907f0e7174 100644 --- a/test/common/index.js +++ b/test/common/index.js @@ -30,6 +30,7 @@ const { exec, execSync, spawn, spawnSync } = require('child_process'); const stream = require('stream'); const util = require('util'); const Timer = process.binding('timer_wrap').Timer; +const { hasTracing } = process.binding('config'); const { fixturesDir } = require('./fixtures'); const tmpdir = require('./tmpdir'); @@ -201,6 +202,12 @@ Object.defineProperty(exports, 'hasCrypto', { } }); +Object.defineProperty(exports, 'hasTracing', { + get: function() { + return Boolean(hasTracing); + } +}); + Object.defineProperty(exports, 'hasFipsCrypto', { get: function() { return exports.hasCrypto && require('crypto').fips; diff --git a/test/parallel/test-module-cjs-helpers.js b/test/parallel/test-module-cjs-helpers.js index 1ed9746198a606..f6e80af032a2cd 100644 --- a/test/parallel/test-module-cjs-helpers.js +++ b/test/parallel/test-module-cjs-helpers.js @@ -7,5 +7,5 @@ const { builtinLibs } = require('internal/modules/cjs/helpers'); const hasInspector = process.config.variables.v8_enable_inspector === 1; -const expectedLibs = hasInspector ? 32 : 31; +const expectedLibs = hasInspector ? 33 : 32; assert.strictEqual(builtinLibs.length, expectedLibs); diff --git a/test/parallel/test-trace-events-api.js b/test/parallel/test-trace-events-api.js new file mode 100644 index 00000000000000..b4f7112d07ac77 --- /dev/null +++ b/test/parallel/test-trace-events-api.js @@ -0,0 +1,164 @@ +// Flags: --expose-gc --no-warnings +'use strict'; + +const common = require('../common'); + +if (!common.hasTracing) + common.skip('missing trace events'); + +const assert = require('assert'); +const cp = require('child_process'); +const path = require('path'); +const fs = require('fs'); +const tmpdir = require('../common/tmpdir'); +const { + createTracing, + getEnabledCategories +} = require('trace_events'); + +const isChild = process.argv[2] === 'child'; +const enabledCategories = isChild ? 'foo' : undefined; + +assert.strictEqual(getEnabledCategories(), enabledCategories); +[1, 'foo', true, false, null, undefined].forEach((i) => { + common.expectsError(() => createTracing(i), { + code: 'ERR_INVALID_ARG_TYPE', + type: TypeError + }); + common.expectsError(() => createTracing({ categories: i }), { + code: 'ERR_INVALID_ARG_TYPE', + type: TypeError + }); +}); + +common.expectsError( + () => createTracing({ categories: [] }), + { + code: 'ERR_TRACE_EVENTS_CATEGORY_REQUIRED', + type: TypeError + } +); + +const tracing = createTracing({ categories: [ 'node.perf' ] }); + +assert.strictEqual(tracing.categories, 'node.perf'); +assert.strictEqual(tracing.enabled, false); + +assert.strictEqual(getEnabledCategories(), enabledCategories); +tracing.enable(); +tracing.enable(); // purposefully enable twice to test calling twice +assert.strictEqual(tracing.enabled, true); + +assert.strictEqual(getEnabledCategories(), + isChild ? 'foo,node.perf' : 'node.perf'); + +tracing.disable(); +assert.strictEqual(tracing.enabled, false); + +const tracing2 = createTracing({ categories: [ 'foo' ] }); +tracing2.enable(); +assert.strictEqual(getEnabledCategories(), 'foo'); + +tracing2.disable(); +tracing2.disable(); // purposefully disable twice to test calling twice +assert.strictEqual(getEnabledCategories(), enabledCategories); + +if (isChild) { + tracing.enable(); + const { performance } = require('perf_hooks'); + + // Will emit mark and measure trace events + performance.mark('A'); + setTimeout(() => { + performance.mark('B'); + performance.measure('A to B', 'A', 'B'); + }, 1); + + // Intentional non-op, part of the test + function f() {} + const ff = performance.timerify(f); + ff(); // Will emit a timerify trace event +} else { + + // Test that enabled tracing references do not get garbage collected + // until after they are disabled. + { + { + let tracing3 = createTracing({ categories: [ 'abc' ] }); + tracing3.enable(); + assert.strictEqual(getEnabledCategories(), 'abc'); + tracing3 = undefined; + } + global.gc(); + assert.strictEqual(getEnabledCategories(), 'abc'); + // Not able to disable the thing after this point, however. + } + + { + common.expectWarning( + 'Warning', + 'Possible trace_events memory leak detected. There are more than ' + + '10 enabled Tracing objects.', + common.noWarnCode); + for (let n = 0; n < 10; n++) { + const tracing = createTracing({ categories: [ `a${n}` ] }); + tracing.enable(); + } + } + + tmpdir.refresh(); + process.chdir(tmpdir.path); + + const expectedMarks = ['A', 'B']; + const expectedBegins = [ + { cat: 'node,node.perf,node.perf.timerify', name: 'f' }, + { cat: 'node,node.perf,node.perf.usertiming', name: 'A to B' } + ]; + const expectedEnds = [ + { cat: 'node,node.perf,node.perf.timerify', name: 'f' }, + { cat: 'node,node.perf,node.perf.usertiming', name: 'A to B' } + ]; + + const proc = cp.fork(__filename, + ['child'], + { execArgv: [ '--expose-gc', + '--trace-event-categories', + 'foo' ] }); + + proc.once('exit', common.mustCall(() => { + const file = path.join(tmpdir.path, 'node_trace.1.log'); + + assert(common.fileExists(file)); + fs.readFile(file, common.mustCall((err, data) => { + const traces = JSON.parse(data.toString()).traceEvents; + assert.strictEqual(traces.length, + expectedMarks.length + + expectedBegins.length + + expectedEnds.length); + + traces.forEach((trace) => { + assert.strictEqual(trace.pid, proc.pid); + switch (trace.ph) { + case 'R': + assert.strictEqual(trace.cat, + 'node,node.perf,node.perf.usertiming'); + assert.strictEqual(trace.name, + expectedMarks.shift()); + break; + case 'b': + const expectedBegin = expectedBegins.shift(); + assert.strictEqual(trace.cat, expectedBegin.cat); + assert.strictEqual(trace.name, expectedBegin.name); + break; + case 'e': + const expectedEnd = expectedEnds.shift(); + assert.strictEqual(trace.cat, expectedEnd.cat); + assert.strictEqual(trace.name, expectedEnd.name); + break; + default: + assert.fail('Unexpected trace event phase'); + } + }); + })); + })); +} diff --git a/test/parallel/test-trace-events-async-hooks.js b/test/parallel/test-trace-events-async-hooks.js index 7fb11223c3141d..d3c5a0af5b8e50 100644 --- a/test/parallel/test-trace-events-async-hooks.js +++ b/test/parallel/test-trace-events-async-hooks.js @@ -13,8 +13,7 @@ tmpdir.refresh(); process.chdir(tmpdir.path); const proc = cp.spawn(process.execPath, - [ '--trace-events-enabled', - '--trace-event-categories', 'node.async_hooks', + [ '--trace-event-categories', 'node.async_hooks', '-e', CODE ]); proc.once('exit', common.mustCall(() => { diff --git a/test/parallel/test-trace-events-binding.js b/test/parallel/test-trace-events-binding.js index fc4e7f99f87c1b..35fbfc3692a5d3 100644 --- a/test/parallel/test-trace-events-binding.js +++ b/test/parallel/test-trace-events-binding.js @@ -25,8 +25,7 @@ tmpdir.refresh(); process.chdir(tmpdir.path); const proc = cp.spawn(process.execPath, - [ '--trace-events-enabled', - '--trace-event-categories', 'custom', + [ '--trace-event-categories', 'custom', '-e', CODE ]); proc.once('exit', common.mustCall(() => { diff --git a/test/parallel/test-trace-events-bootstrap.js b/test/parallel/test-trace-events-bootstrap.js index 6693291664ef67..a0bfcf123e7233 100644 --- a/test/parallel/test-trace-events-bootstrap.js +++ b/test/parallel/test-trace-events-bootstrap.js @@ -32,7 +32,6 @@ if (process.argv[2] === 'child') { const proc = cp.fork(__filename, [ 'child' ], { execArgv: [ - '--trace-events-enabled', '--trace-event-categories', 'node.bootstrap' ] diff --git a/test/parallel/test-trace-events-category-used.js b/test/parallel/test-trace-events-category-used.js index aa0662b7493568..a98cb350371da9 100644 --- a/test/parallel/test-trace-events-category-used.js +++ b/test/parallel/test-trace-events-category-used.js @@ -13,7 +13,7 @@ process.chdir(tmpdir.path); const procEnabled = cp.spawn( process.execPath, - [ '--trace-events-enabled', '--trace-event-categories', 'custom', '-e', CODE ] + [ '--trace-event-categories', 'custom', '-e', CODE ] ); let procEnabledOutput = ''; @@ -25,7 +25,7 @@ procEnabled.once('exit', common.mustCall(() => { const procDisabled = cp.spawn( process.execPath, - [ '--trace-events-enabled', '--trace-event-categories', 'other', '-e', CODE ] + [ '--trace-event-categories', 'other', '-e', CODE ] ); let procDisabledOutput = ''; diff --git a/test/parallel/test-trace-events-none.js b/test/parallel/test-trace-events-none.js index 7a87fc5cbd3a8d..6b60ce999ac118 100644 --- a/test/parallel/test-trace-events-none.js +++ b/test/parallel/test-trace-events-none.js @@ -13,7 +13,7 @@ process.chdir(tmpdir.path); const proc_no_categories = cp.spawn( process.execPath, - [ '--trace-events-enabled', '--trace-event-categories', '""', '-e', CODE ] + [ '--trace-event-categories', '""', '-e', CODE ] ); proc_no_categories.once('exit', common.mustCall(() => { diff --git a/test/parallel/test-trace-events-perf.js b/test/parallel/test-trace-events-perf.js index 57f886d272447a..5758082b6efa43 100644 --- a/test/parallel/test-trace-events-perf.js +++ b/test/parallel/test-trace-events-perf.js @@ -39,7 +39,6 @@ if (process.argv[2] === 'child') { 'child' ], { execArgv: [ - '--trace-events-enabled', '--trace-event-categories', 'node.perf' ] diff --git a/tools/doc/type-parser.js b/tools/doc/type-parser.js index 55998d1c229d3d..6314a4889f06e6 100644 --- a/tools/doc/type-parser.js +++ b/tools/doc/type-parser.js @@ -114,6 +114,8 @@ const customTypesMap = { 'tls.Server': 'tls.html#tls_class_tls_server', 'tls.TLSSocket': 'tls.html#tls_class_tls_tlssocket', + 'Tracing': 'tracing.html#tracing_tracing_object', + 'URL': 'url.html#url_the_whatwg_url_api', 'URLSearchParams': 'url.html#url_class_urlsearchparams' };