diff --git a/doc/api/errors.md b/doc/api/errors.md index 7d6e238f93bdaa..fc205a71e91ee7 100644 --- a/doc/api/errors.md +++ b/doc/api/errors.md @@ -1510,6 +1510,14 @@ 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_UNAVAILABLE + +The trace events mechanism is not available for use in the Node.js binary. + +This is the case when 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 ef58eb72bac217..207fb020c77e22 100644 --- a/doc/api/tracing.md +++ b/doc/api/tracing.md @@ -5,12 +5,9 @@ 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 either by using the `--trace-event-categories` flag +followed by a list of comma separated category names, or by using the +`trace_events.setTracingCategories()` method. The available categories are: @@ -23,15 +20,17 @@ The available categories are: measurements. * `v8` -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 +``` + +```js +const trace_events = require('trace_events'); +trace_events.enableTracingCategories('v8', 'node,node.async_hooks'); ``` Running Node.js with tracing enabled will produce log files that can be opened -in the [`chrome://tracing`](https://www.chromium.org/developers/how-tos/trace-event-profiling-tool) -tab of Chrome. +in the [`chrome://tracing`][] tab of Chrome. The logging file is by default called `node_trace.${rotation}.log`, where `${rotation}` is an incrementing log-rotation id. The filepath pattern can @@ -39,7 +38,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-file-pattern '${pid}-${rotation}.log' server.js ``` Starting with Node.js 10.0.0, the tracing system uses the same time source @@ -47,4 +46,65 @@ as the one used by `process.hrtime()` however the trace-event timestamps are expressed in microseconds, unlike `process.hrtime()` which returns nanoseconds. +Previous versions of Node.js required use of the `--trace-events-enabled` +command line flag to enable trace event capture. This flag is no longer +required to enable trace events. If it is used, however, trace events are +enabled using the default categories: `v8`, `node`, and `node.async_hooks`. + +## The `trace_events` module + +The `trace_events` module may be used to turn trace event reporting on and off. + +It is accessible using `require('trace_events')`. + +### trace_events.disableTracingCategories(...categories) + +* `...categories` {string} One or more category names. + +Disables trace event capture for the given set of category names. + +An error will be thrown if trace event support is not enabled in the Node.js +binary. + +```js +const trace_events = require('trace_events'); +trace_events.disableTracingCategories('v8', 'node.async_hooks'); +``` + +To disable all currently enabled trace event categories, the +`trace_events.getTracingCategories()` method may be used together with +`trace_events.disableTracingCategories()`: + +```js +const trace_events = require('trace_events'); +trace_events.disableTracingCategories( + ...trace_events.getTracingCategories()); +``` + +### trace_events.enableTracingCategories(...categories) + +* `...categories` {string} One or more category names. + +Enables trace event capture for the given set of category names. + +An error will be thrown if trace event support is not enabled in the Node.js +binary. + +```js +const trace_events = require('trace_events'); +trace_events.enableTracingCategories('v8', 'node.async_hooks'); +``` + +### trace_events.getTracingCategories() + +* Returns: {string[]} + +Returns an Array of the currently enabled trace event categories. + +```js +const trace_events = require('trace_events'); +console.log(trace_events.getTracingCategories()); +``` + +[`chrome://tracing`]: https://www.chromium.org/developers/how-tos/trace-event-profiling-tool [Performance API]: perf_hooks.html diff --git a/lib/internal/errors.js b/lib/internal/errors.js index 8ec72dd647b1b2..58a821059fff2f 100644 --- a/lib/internal/errors.js +++ b/lib/internal/errors.js @@ -866,6 +866,7 @@ 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_UNAVAILABLE', 'Trace events are not available', Error); E('ERR_TRANSFORM_ALREADY_TRANSFORMING', 'Calling transform done when still transforming', Error); diff --git a/lib/trace_events.js b/lib/trace_events.js new file mode 100644 index 00000000000000..22ae4d2deb8f3a --- /dev/null +++ b/lib/trace_events.js @@ -0,0 +1,46 @@ +'use strict'; + +const { + enableTracingCategories: _enableTracingCategories, + disableTracingCategories: _disableTracingCategories, + getTracingCategories +} = process.binding('trace_events'); + +const { trace_events_enabled } = process.binding('config'); + +const { + codes: { + ERR_INVALID_ARG_TYPE, + ERR_TRACE_EVENTS_UNAVAILABLE + } +} = require('internal/errors'); + +function enableTracingCategories(...categories) { + if (!trace_events_enabled) + throw new ERR_TRACE_EVENTS_UNAVAILABLE(); + + for (var n = 0; n < categories.length; n++) { + if (typeof categories[n] !== 'string') + throw new ERR_INVALID_ARG_TYPE('category', 'string'); + } + + _enableTracingCategories(categories); +} + +function disableTracingCategories(...categories) { + if (!trace_events_enabled) + throw new ERR_TRACE_EVENTS_UNAVAILABLE(); + + for (var n = 0; n < categories.length; n++) { + if (typeof categories[n] !== 'string') + throw new ERR_INVALID_ARG_TYPE('category', 'string'); + } + + _disableTracingCategories(categories); +} + +module.exports = { + enableTracingCategories, + disableTracingCategories, + getTracingCategories +}; diff --git a/node.gyp b/node.gyp index ce8125ecc39d39..373e373aa29b58 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/node.cc b/src/node.cc index 2e44e249a0d5fd..c1a1ae25597081 100644 --- a/src/node.cc +++ b/src/node.cc @@ -82,6 +82,7 @@ #include #include +#include #if defined(NODE_HAVE_I18N_SUPPORT) #include @@ -190,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"; @@ -276,20 +276,11 @@ 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_->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()); - } + tracing_agent_.reset(new tracing::Agent(trace_file_pattern)); + v8::TracingController* controller = tracing_agent_->GetTracingController(); + platform_ = new NodePlatform(thread_pool_size, controller); + tracing::TraceEventHelper::SetTracingController(controller); + V8::InitializePlatform(platform_); } void Dispose() { @@ -321,8 +312,24 @@ static struct { } #endif // HAVE_INSPECTOR - void StartTracingAgent() { - tracing_agent_->Start(trace_enabled_categories); + void EnableTracingCategories(const std::string& categories) { + tracing_agent_->EnableCategories(categories); + } + + void EnableTracingCategories(const std::vector& categories) { + tracing_agent_->EnableCategories(categories); + } + + void DisableTracingCategories(const std::vector& categories) { + tracing_agent_->DisableCategories(categories); + } + + const std::unordered_set& GetEnabledTracingCategories() { + return tracing_agent_->GetEnabledCategories(); + } + + void StopTracing() { + tracing_agent_->StopTracing(); } void StopTracingAgent() { @@ -346,15 +353,20 @@ static struct { return true; } - void StartTracingAgent() { - fprintf(stderr, "Node compiled with NODE_USE_V8_PLATFORM=0, " - "so event tracing is not available.\n"); + void EnableTracingCategories(const std::string& categories) {} + void EnableTracingCategories(const std::vector categories) {} + void DisableTracingCategories(const std::vector categories) {} + const std::unordered_set& GetEnabledTracingCategories() { + return categories_; } + void StopTracing() {} void StopTracingAgent() {} NodePlatform* Platform() { return nullptr; } + + std::unordered_set categories_; #endif // !NODE_USE_V8_PLATFORM #if !NODE_USE_V8_PLATFORM || !HAVE_INSPECTOR @@ -364,6 +376,20 @@ static struct { #endif // !NODE_USE_V8_PLATFORM || !HAVE_INSPECTOR } v8_platform; +void EnableTracingCategories(const std::vector& categories) { + v8_platform.EnableTracingCategories(categories); +} + +void DisableTracingCategories(const std::vector& categories) { + v8_platform.DisableTracingCategories(categories); +} + +const std::unordered_set& GetEnabledTracingCategories() { + return v8_platform.GetEnabledTracingCategories(); +} + +void StopTracing() { v8_platform.StopTracing(); } + #ifdef __POSIX__ static const unsigned kMaxSignal = 32; #endif @@ -1987,9 +2013,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 +3311,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; @@ -3491,6 +3513,7 @@ static void PrintHelp() { " is detected after the first tick\n" " --no-force-async-hooks-checks\n" " disable checks for async_hooks\n" +#if NODE_USE_V8_PLATFORM " --trace-events-enabled track trace events\n" " --trace-event-categories comma separated list of trace event\n" " categories to record\n" @@ -3498,6 +3521,7 @@ static void PrintHelp() { " filepath for the trace-events data, it\n" " supports ${rotation} and ${pid}\n" " log-rotation id. %%2$u is the pid.\n" +#endif " --track-heap-objects track heap object allocations for heap " "snapshots\n" " --prof-process process v8 profiler output generated\n" @@ -3624,9 +3648,11 @@ static void CheckIfAllowedInEnv(const char* exe, bool is_env, "--redirect-warnings", "--trace-sync-io", "--no-force-async-hooks-checks", +#if NODE_USE_V8_PLATFORM "--trace-events-enabled", "--trace-event-categories", "--trace-event-file-pattern", +#endif "--track-heap-objects", "--zero-fill-buffers", "--v8-pool-size", @@ -3768,8 +3794,11 @@ static void ParseArgs(int* argc, trace_sync_io = true; } else if (strcmp(arg, "--no-force-async-hooks-checks") == 0) { no_force_async_hooks_checks = true; +#if NODE_USE_V8_PLATFORM } 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) { @@ -3786,6 +3815,7 @@ static void ParseArgs(int* argc, } args_consumed += 1; trace_file_pattern = file_pattern; +#endif } else if (strcmp(arg, "--track-heap-objects") == 0) { track_heap_objects = true; } else if (strcmp(arg, "--throw-deprecation") == 0) { @@ -4595,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.EnableTracingCategories(trace_enabled_categories); 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 cac551ad2c410a..47667a2521e32d 100644 --- a/src/node_config.cc +++ b/src/node_config.cc @@ -82,6 +82,10 @@ static void InitConfig(Local target, } } +#if NODE_USE_V8_PLATFORM + READONLY_BOOLEAN_PROPERTY("trace_events_enabled"); +#endif + if (config_experimental_vm_modules) READONLY_BOOLEAN_PROPERTY("experimentalVMModules"); diff --git a/src/node_internals.h b/src/node_internals.h index 2faa6f93475ad7..4b2d1415aafe96 100644 --- a/src/node_internals.h +++ b/src/node_internals.h @@ -38,6 +38,7 @@ #include #include +#include // Custom constants used by both node_constants.cc and node_zlib.cc #define Z_MIN_WINDOWBITS 8 @@ -785,6 +786,11 @@ static inline const char *errno_string(int errorno) { TRACING_CATEGORY_NODE "." #one "," \ TRACING_CATEGORY_NODE "." #one "." #two +void EnableTracingCategories(const std::vector& categories); +void DisableTracingCategories(const std::vector& categories); +const std::unordered_set& GetEnabledTracingCategories(); +void StopTracing(); + } // namespace node diff --git a/src/node_trace_events.cc b/src/node_trace_events.cc index f269b32fbef869..adbc39003d6cb8 100644 --- a/src/node_trace_events.cc +++ b/src/node_trace_events.cc @@ -3,11 +3,13 @@ namespace node { +using v8::Array; using v8::Context; using v8::FunctionCallbackInfo; using v8::Int32; using v8::Local; using v8::Object; +using v8::String; using v8::Value; // The tracing APIs require category groups to be pointers to long-lived @@ -132,6 +134,62 @@ static void CategoryGroupEnabled(const FunctionCallbackInfo& args) { args.GetReturnValue().Set(*category_group_enabled > 0); } +static void EnableTracingCategories(const FunctionCallbackInfo& args) { +#if NODE_USE_V8_PLATFORM + Environment* env = Environment::GetCurrent(args); + CHECK(args[0]->IsArray()); + Local categories = args[0].As(); + size_t length = categories->Length(); + if (length == 0) + return; + std::vector cats; + for (size_t n = 0; n < length; n++) { + Utf8Value val(env->isolate(), + categories->Get(env->context(), n).ToLocalChecked()); + cats.push_back(*val); + } + EnableTracingCategories(cats); +#else + UNREACHABLE(); +#endif +} + +static void DisableTracingCategories(const FunctionCallbackInfo& args) { +#if NODE_USE_V8_PLATFORM + Environment* env = Environment::GetCurrent(args); + CHECK(args[0]->IsArray()); + Local categories = args[0].As(); + size_t length = categories->Length(); + if (length == 0) + return; + std::vector cats; + for (size_t n = 0; n < length; n++) { + Utf8Value val(env->isolate(), + categories->Get(env->context(), n).ToLocalChecked()); + cats.push_back(*val); + } + DisableTracingCategories(cats); +#else + UNREACHABLE(); +#endif +} + +static void GetTracingCategories(const FunctionCallbackInfo& args) { +#if NODE_USE_V8_PLATFORM + Environment* env = Environment::GetCurrent(args); + const auto& categories = GetEnabledTracingCategories(); + Local ret = Array::New(env->isolate(), categories.size()); + size_t n = 0; + for (const std::string& category : categories) { + ret->Set(env->context(), n++, + String::NewFromUtf8(env->isolate(), category.c_str(), + v8::NewStringType::kNormal).ToLocalChecked()) + .FromJust(); + } + args.GetReturnValue().Set(ret); +#endif +} + void InitializeTraceEvents(Local target, Local unused, Local context, @@ -140,6 +198,10 @@ void InitializeTraceEvents(Local target, env->SetMethod(target, "emit", Emit); env->SetMethod(target, "categoryGroupEnabled", CategoryGroupEnabled); + + env->SetMethod(target, "enableTracingCategories", EnableTracingCategories); + env->SetMethod(target, "disableTracingCategories", DisableTracingCategories); + env->SetMethod(target, "getTracingCategories", GetTracingCategories); } } // namespace node diff --git a/src/tracing/agent.cc b/src/tracing/agent.cc index 71e53e787a464e..5eafbfd6b1bc21 100644 --- a/src/tracing/agent.cc +++ b/src/tracing/agent.cc @@ -1,67 +1,98 @@ #include "tracing/agent.h" - -#include -#include #include "tracing/node_trace_buffer.h" #include "tracing/node_trace_writer.h" - #include "env-inl.h" +#include +#include +#include + namespace node { namespace tracing { using v8::platform::tracing::TraceConfig; -using std::string; -Agent::Agent(const std::string& log_file_pattern) { +Agent::Agent(const std::string& log_file_pattern) : + log_file_pattern_(log_file_pattern) { + tracing_controller_ = new TracingController(); + tracing_controller_->Initialize(nullptr); +} + +void Agent::InitializeOnce() { + if (initialized_) + return; int err = uv_loop_init(&tracing_loop_); CHECK_EQ(err, 0); NodeTraceWriter* trace_writer = new NodeTraceWriter( - log_file_pattern, &tracing_loop_); + 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); +void Agent::StartTracing() { + tracing_controller_->StopTracing(); + if (!categories_.empty()) { + if (!started_) { + InitializeOnce(); + // 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); + started_ = true; + } + TraceConfig* trace_config = new TraceConfig(); + for (const std::string& category : categories_) { + trace_config->AddIncludedCategory(category.c_str()); + } + tracing_controller_->StartTracing(trace_config); + } +} + +void Agent::EnableCategories(const std::string& categories) { + if (!categories.empty()) { + std::stringstream category_list(categories); while (category_list.good()) { std::string category; getline(category_list, category, ','); - trace_config->AddIncludedCategory(category.c_str()); + categories_.insert(category); } - } else { - trace_config->AddIncludedCategory("v8"); - trace_config->AddIncludedCategory("node"); - trace_config->AddIncludedCategory("node.async_hooks"); + StartTracing(); } +} - // 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); +void Agent::EnableCategories(const std::vector& categories) { + if (!categories.empty()) { + categories_.insert(categories.begin(), categories.end()); + StartTracing(); + } +} + +void Agent::DisableCategories(const std::vector& categories) { + if (!categories.empty()) { + for (const std::string& category : categories) + categories_.erase(category); + StartTracing(); + } +} - tracing_controller_->StartTracing(trace_config); - started_ = true; +void Agent::StopTracing() { + tracing_controller_->StopTracing(); } void Agent::Stop() { - 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(); tracing_controller_->Initialize(nullptr); - started_ = false; // Thread should finish when the tracing loop is stopped. - uv_thread_join(&thread_); + if (started_) { + uv_thread_join(&thread_); + started_ = false; + } } // static diff --git a/src/tracing/agent.h b/src/tracing/agent.h index 9d6bc4e90a35af..20d57c52456221 100644 --- a/src/tracing/agent.h +++ b/src/tracing/agent.h @@ -5,6 +5,10 @@ #include "uv.h" #include "v8.h" +#include +#include +#include + namespace node { namespace tracing { @@ -20,7 +24,15 @@ 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 EnableCategories(const std::string& categories); + void EnableCategories(const std::vector& categories); + void DisableCategories(const std::vector& categories); + const std::unordered_set& GetEnabledCategories() const { + return categories_; + } + + void StopTracing(); void Stop(); TracingController* GetTracingController() { return tracing_controller_; } @@ -28,8 +40,15 @@ class Agent { private: static void ThreadCb(void* arg); + void InitializeOnce(); + void StartTracing(); + + const std::string& log_file_pattern_; + std::unordered_set categories_; + uv_thread_t thread_; uv_loop_t tracing_loop_; + bool initialized_ = false; bool started_ = false; TracingController* tracing_controller_ = nullptr; }; diff --git a/test/parallel/test-trace-events-module.js b/test/parallel/test-trace-events-module.js new file mode 100644 index 00000000000000..3accd8ec701306 --- /dev/null +++ b/test/parallel/test-trace-events-module.js @@ -0,0 +1,77 @@ +'use strict'; +const common = require('../common'); +const assert = require('assert'); +const cp = require('child_process'); +const path = require('path'); +const fs = require('fs'); +const tmpdir = require('../common/tmpdir'); + +if (process.argv[2] === 'child') { + const trace_events = require('trace_events'); + // Note: this test is leveraging the fact that perf_hooks + // will emit a very limited number of predictable trace events + // that we can use to quickly verify that trace events are + // enabled. Using the v8 and node.async_hooks targets tend + // to be less predictable in terms of what is actually output + // to the file. That said, if necessary, this test could + // be modified to use any trace event output. + const { performance } = require('perf_hooks'); + assert.deepStrictEqual(trace_events.getTracingCategories(), []); + trace_events.enableTracingCategories('node.perf.usertiming'); + assert.deepStrictEqual(trace_events.getTracingCategories(), + ['node.perf.usertiming']); + performance.mark('A'); + performance.mark('B'); + performance.measure('A to B', 'A', 'B'); + trace_events.disableTracingCategories('node.perf.usertiming'); + assert.deepStrictEqual(trace_events.getTracingCategories(), []); +} else { + tmpdir.refresh(); + process.chdir(tmpdir.path); + + const expectedMarks = ['A', 'B']; + const expectedBegins = [ + { cat: 'node,node.perf,node.perf.usertiming', name: 'A to B' } + ]; + const expectedEnds = [ + { cat: 'node,node.perf,node.perf.usertiming', name: 'A to B' } + ]; + + const proc = cp.fork(__filename, [ 'child' ]); + + 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'); + } + }); + })); + })); +}