From cf1f5f0e141640ac5085accfad987413eb7b9b40 Mon Sep 17 00:00:00 2001 From: James M Snell Date: Sun, 14 Oct 2018 16:51:35 -0700 Subject: [PATCH 1/5] src: add trace events for env.cc --- src/env.cc | 54 +++++++++++++++++++++++++++++++++++++++++++++++++++++- 1 file changed, 53 insertions(+), 1 deletion(-) diff --git a/src/env.cc b/src/env.cc index 14a8b23a8441e9..3bdd3176fd839d 100644 --- a/src/env.cc +++ b/src/env.cc @@ -7,6 +7,7 @@ #include "node_context_data.h" #include "node_worker.h" #include "tracing/agent.h" +#include "tracing/traced_value.h" #include #include @@ -33,6 +34,24 @@ using worker::Worker; #define kTraceCategoryCount 1 +// TODO(@jasnell): Likely useful to move this to util or node_internal to +// allow reuse. But since we're not reusing it yet... +class TraceEventScope { + public: + TraceEventScope(const char* category, + const char* name, + void* id) : category_(category), name_(name), id_(id) { + TRACE_EVENT_NESTABLE_ASYNC_BEGIN0(category_, name_, id); + } + ~TraceEventScope() { + TRACE_EVENT_NESTABLE_ASYNC_END0(category_, name_, id_); + } + private: + const char* category_; + const char* name_; + void* id_; +}; + int const Environment::kNodeContextTag = 0x6e6f64; void* Environment::kNodeContextTagPtr = const_cast( static_cast(&Environment::kNodeContextTag)); @@ -223,6 +242,9 @@ Environment::~Environment() { delete[] heap_statistics_buffer_; delete[] heap_space_statistics_buffer_; delete[] http_parser_buffer_; + + TRACE_EVENT_NESTABLE_ASYNC_END0( + TRACING_CATEGORY_NODE1(environment), "Environment", this); } void Environment::Start(const std::vector& args, @@ -231,6 +253,23 @@ void Environment::Start(const std::vector& args, HandleScope handle_scope(isolate()); Context::Scope context_scope(context()); + if (*TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED( + TRACING_CATEGORY_NODE1(environment))) { + auto traced_value = tracing::TracedValue::Create(); + traced_value->BeginArray("args"); + for (std::string arg : args) + traced_value->AppendString(arg); + traced_value->EndArray(); + traced_value->BeginArray("exec_args"); + for (std::string arg : exec_args) + traced_value->AppendString(arg); + traced_value->EndArray(); + TRACE_EVENT_NESTABLE_ASYNC_BEGIN1( + TRACING_CATEGORY_NODE1(environment), + "Environment", this, + "args", std::move(traced_value)); + } + CHECK_EQ(0, uv_timer_init(event_loop(), timer_handle())); uv_unref(reinterpret_cast(timer_handle())); @@ -400,6 +439,8 @@ void Environment::PrintSyncTrace() const { } void Environment::RunCleanup() { + TraceEventScope trace_scope(TRACING_CATEGORY_NODE1(environment), + "RunCleanup", this); CleanupHandles(); while (!cleanup_hooks_.empty()) { @@ -431,6 +472,8 @@ void Environment::RunCleanup() { } void Environment::RunBeforeExitCallbacks() { + TraceEventScope trace_scope(TRACING_CATEGORY_NODE1(environment), + "BeforeExit", this); for (ExitCallback before_exit : before_exit_functions_) { before_exit.cb_(before_exit.arg_); } @@ -442,6 +485,8 @@ void Environment::BeforeExit(void (*cb)(void* arg), void* arg) { } void Environment::RunAtExitCallbacks() { + TraceEventScope trace_scope(TRACING_CATEGORY_NODE1(environment), + "AtExit", this); for (ExitCallback at_exit : at_exit_functions_) { at_exit.cb_(at_exit.arg_); } @@ -495,13 +540,16 @@ void Environment::EnvPromiseHook(v8::PromiseHookType type, Environment* env = Environment::GetCurrent(context); if (env == nullptr) return; - + TraceEventScope trace_scope(TRACING_CATEGORY_NODE1(environment), + "EnvPromiseHook", env); for (const PromiseHookCallback& hook : env->promise_hooks_) { hook.cb_(type, promise, parent, hook.arg_); } } void Environment::RunAndClearNativeImmediates() { + TraceEventScope trace_scope(TRACING_CATEGORY_NODE1(environment), + "RunAndClearNativeImmediates", this); size_t count = native_immediate_callbacks_.size(); if (count > 0) { size_t ref_count = 0; @@ -554,6 +602,8 @@ void Environment::ToggleTimerRef(bool ref) { void Environment::RunTimers(uv_timer_t* handle) { Environment* env = Environment::from_timer_handle(handle); + TraceEventScope trace_scope(TRACING_CATEGORY_NODE1(environment), + "RunTimers", env); if (!env->can_call_into_js()) return; @@ -614,6 +664,8 @@ void Environment::RunTimers(uv_timer_t* handle) { void Environment::CheckImmediate(uv_check_t* handle) { Environment* env = Environment::from_immediate_check_handle(handle); + TraceEventScope trace_scope(TRACING_CATEGORY_NODE1(environment), + "CheckImmediate", env); if (env->immediate_info()->count() == 0) return; From b32b136171f85f6f155abe5b823c7bb8c2295bdf Mon Sep 17 00:00:00 2001 From: James M Snell Date: Mon, 15 Oct 2018 10:53:08 -0700 Subject: [PATCH 2/5] [Squash] nits, docs, and a test (oh my) --- doc/api/tracing.md | 1 + src/env.cc | 3 +- .../parallel/test-trace-events-environment.js | 49 +++++++++++++++++++ 3 files changed, 52 insertions(+), 1 deletion(-) create mode 100644 test/parallel/test-trace-events-environment.js diff --git a/doc/api/tracing.md b/doc/api/tracing.md index fb855084022a6c..d58079360a0056 100644 --- a/doc/api/tracing.md +++ b/doc/api/tracing.md @@ -18,6 +18,7 @@ The available categories are: The [`async_hooks`] events have a unique `asyncId` and a special `triggerId` `triggerAsyncId` property. * `node.bootstrap` - Enables capture of Node.js bootstrap milestones. +* `node.environment` - Enables capture of Node.js Environment milestones. * `node.fs.sync` - Enables capture of trace data for file system sync methods. * `node.perf` - Enables capture of [Performance API] measurements. * `node.perf.usertiming` - Enables capture of only Performance API User Timing diff --git a/src/env.cc b/src/env.cc index 3bdd3176fd839d..dca05b36c1f8f0 100644 --- a/src/env.cc +++ b/src/env.cc @@ -46,6 +46,7 @@ class TraceEventScope { ~TraceEventScope() { TRACE_EVENT_NESTABLE_ASYNC_END0(category_, name_, id_); } + private: const char* category_; const char* name_; @@ -257,7 +258,7 @@ void Environment::Start(const std::vector& args, TRACING_CATEGORY_NODE1(environment))) { auto traced_value = tracing::TracedValue::Create(); traced_value->BeginArray("args"); - for (std::string arg : args) + for (const std::string& arg : args) traced_value->AppendString(arg); traced_value->EndArray(); traced_value->BeginArray("exec_args"); diff --git a/test/parallel/test-trace-events-environment.js b/test/parallel/test-trace-events-environment.js new file mode 100644 index 00000000000000..bcc2680f8f0416 --- /dev/null +++ b/test/parallel/test-trace-events-environment.js @@ -0,0 +1,49 @@ +'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 (!common.isMainThread) + common.skip('process.chdir is not available in Workers'); + +const names = [ + 'Environment', + 'RunAndClearNativeImmediates', + 'CheckImmediate', + 'RunTimers', + 'BeforeExit', + 'RunCleanup', + 'AtExit' +]; + +if (process.argv[2] === 'child') { + 1 + 1; +} else { + tmpdir.refresh(); + process.chdir(tmpdir.path); + + const proc = cp.fork(__filename, + [ 'child' ], { + execArgv: [ + '--trace-event-categories', + 'node.environment' + ] + }); + + proc.once('exit', common.mustCall(() => { + const file = path.join(tmpdir.path, 'node_trace.1.log'); + + assert(fs.existsSync(file)); + fs.readFile(file, common.mustCall((err, data) => { + const traces = JSON.parse(data.toString()).traceEvents + .filter((trace) => trace.cat !== '__metadata'); + traces.forEach((trace) => { + assert.strictEqual(trace.pid, proc.pid); + assert(names.includes(trace.name)); + }); + })); + })); +} From 065495fb3958219744eea5470b9565345833e05e Mon Sep 17 00:00:00 2001 From: James M Snell Date: Mon, 15 Oct 2018 10:56:29 -0700 Subject: [PATCH 3/5] [Squash] nit --- src/env.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/env.cc b/src/env.cc index dca05b36c1f8f0..d6cc040cdad8b1 100644 --- a/src/env.cc +++ b/src/env.cc @@ -262,7 +262,7 @@ void Environment::Start(const std::vector& args, traced_value->AppendString(arg); traced_value->EndArray(); traced_value->BeginArray("exec_args"); - for (std::string arg : exec_args) + for (const std::string& arg : exec_args) traced_value->AppendString(arg); traced_value->EndArray(); TRACE_EVENT_NESTABLE_ASYNC_BEGIN1( From c2df5c892a535f4da800302089d3391fa63fe99e Mon Sep 17 00:00:00 2001 From: James M Snell Date: Mon, 15 Oct 2018 15:24:29 -0700 Subject: [PATCH 4/5] [Squash] nits and updates --- src/env.cc | 4 +-- .../parallel/test-trace-events-environment.js | 26 ++++++++++++++----- 2 files changed, 22 insertions(+), 8 deletions(-) diff --git a/src/env.cc b/src/env.cc index d6cc040cdad8b1..78c1bad0012217 100644 --- a/src/env.cc +++ b/src/env.cc @@ -41,7 +41,7 @@ class TraceEventScope { TraceEventScope(const char* category, const char* name, void* id) : category_(category), name_(name), id_(id) { - TRACE_EVENT_NESTABLE_ASYNC_BEGIN0(category_, name_, id); + TRACE_EVENT_NESTABLE_ASYNC_BEGIN0(category_, name_, id_); } ~TraceEventScope() { TRACE_EVENT_NESTABLE_ASYNC_END0(category_, name_, id_); @@ -255,7 +255,7 @@ void Environment::Start(const std::vector& args, Context::Scope context_scope(context()); if (*TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED( - TRACING_CATEGORY_NODE1(environment))) { + TRACING_CATEGORY_NODE1(environment)) != 0) { auto traced_value = tracing::TracedValue::Create(); traced_value->BeginArray("args"); for (const std::string& arg : args) diff --git a/test/parallel/test-trace-events-environment.js b/test/parallel/test-trace-events-environment.js index bcc2680f8f0416..447025c9862d20 100644 --- a/test/parallel/test-trace-events-environment.js +++ b/test/parallel/test-trace-events-environment.js @@ -1,3 +1,5 @@ +// Flags: --no-warnings + 'use strict'; const common = require('../common'); const assert = require('assert'); @@ -6,6 +8,8 @@ const path = require('path'); const fs = require('fs'); const tmpdir = require('../common/tmpdir'); +// This tests the emission of node.environment trace events + if (!common.isMainThread) common.skip('process.chdir is not available in Workers'); @@ -20,7 +24,12 @@ const names = [ ]; if (process.argv[2] === 'child') { + // This is just so that the child has something to do. 1 + 1; + // These ensure that the RunTimers, CheckImmediate, and + // RunAndClearNativeImmediates appear in the list. + setImmediate(() => { 1 + 1; }); + setTimeout(() => { 1 + 1; }, 1); } else { tmpdir.refresh(); process.chdir(tmpdir.path); @@ -33,17 +42,22 @@ if (process.argv[2] === 'child') { ] }); - proc.once('exit', common.mustCall(() => { + proc.once('exit', common.mustCall(async () => { const file = path.join(tmpdir.path, 'node_trace.1.log'); + const checkSet = new Set(); assert(fs.existsSync(file)); - fs.readFile(file, common.mustCall((err, data) => { - const traces = JSON.parse(data.toString()).traceEvents - .filter((trace) => trace.cat !== '__metadata'); - traces.forEach((trace) => { + const data = await fs.promises.readFile(file); + JSON.parse(data.toString()).traceEvents + .filter((trace) => trace.cat !== '__metadata') + .forEach((trace) => { assert.strictEqual(trace.pid, proc.pid); assert(names.includes(trace.name)); + checkSet.add(trace.name); }); - })); + + let name; + while (name = names.shift()) + assert(checkSet.has(name)); })); } From 472f9473d951497943bb5a7dde4122969df98a22 Mon Sep 17 00:00:00 2001 From: James M Snell Date: Tue, 16 Oct 2018 07:44:09 -0700 Subject: [PATCH 5/5] [Squash] nit --- test/parallel/test-trace-events-environment.js | 10 ++++------ 1 file changed, 4 insertions(+), 6 deletions(-) diff --git a/test/parallel/test-trace-events-environment.js b/test/parallel/test-trace-events-environment.js index 447025c9862d20..39218d0aac225e 100644 --- a/test/parallel/test-trace-events-environment.js +++ b/test/parallel/test-trace-events-environment.js @@ -13,7 +13,7 @@ const tmpdir = require('../common/tmpdir'); if (!common.isMainThread) common.skip('process.chdir is not available in Workers'); -const names = [ +const names = new Set([ 'Environment', 'RunAndClearNativeImmediates', 'CheckImmediate', @@ -21,7 +21,7 @@ const names = [ 'BeforeExit', 'RunCleanup', 'AtExit' -]; +]); if (process.argv[2] === 'child') { // This is just so that the child has something to do. @@ -52,12 +52,10 @@ if (process.argv[2] === 'child') { .filter((trace) => trace.cat !== '__metadata') .forEach((trace) => { assert.strictEqual(trace.pid, proc.pid); - assert(names.includes(trace.name)); + assert(names.has(trace.name)); checkSet.add(trace.name); }); - let name; - while (name = names.shift()) - assert(checkSet.has(name)); + assert.deepStrictEqual(names, checkSet); })); }