From 74ddae783d91acc35528cd431eb3cf3f58deff95 Mon Sep 17 00:00:00 2001 From: James M Snell Date: Sun, 14 Oct 2018 16:51:35 -0700 Subject: [PATCH] src: add trace events for env.cc PR-URL: https://github.com/nodejs/node/pull/23674 Reviewed-By: Anna Henningsen Reviewed-By: Denys Otrishko Reviewed-By: Refael Ackermann Reviewed-By: Ali Ijaz Sheikh Reviewed-By: Matheus Marchini --- doc/api/tracing.md | 1 + src/env.cc | 55 ++++++++++++++++- .../parallel/test-trace-events-environment.js | 61 +++++++++++++++++++ 3 files changed, 116 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 4f98b5590cf941..f77bcbf1699912 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,25 @@ 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)); @@ -224,6 +244,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, @@ -232,6 +255,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)) != 0) { + auto traced_value = tracing::TracedValue::Create(); + traced_value->BeginArray("args"); + for (const std::string& arg : args) + traced_value->AppendString(arg); + traced_value->EndArray(); + traced_value->BeginArray("exec_args"); + for (const 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())); @@ -401,6 +441,8 @@ void Environment::PrintSyncTrace() const { } void Environment::RunCleanup() { + TraceEventScope trace_scope(TRACING_CATEGORY_NODE1(environment), + "RunCleanup", this); CleanupHandles(); while (!cleanup_hooks_.empty()) { @@ -432,6 +474,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_); } @@ -443,6 +487,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_); } @@ -496,13 +542,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; @@ -555,6 +604,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; @@ -615,6 +666,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; diff --git a/test/parallel/test-trace-events-environment.js b/test/parallel/test-trace-events-environment.js new file mode 100644 index 00000000000000..39218d0aac225e --- /dev/null +++ b/test/parallel/test-trace-events-environment.js @@ -0,0 +1,61 @@ +// Flags: --no-warnings + +'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'); + +// This tests the emission of node.environment trace events + +if (!common.isMainThread) + common.skip('process.chdir is not available in Workers'); + +const names = new Set([ + 'Environment', + 'RunAndClearNativeImmediates', + 'CheckImmediate', + 'RunTimers', + 'BeforeExit', + 'RunCleanup', + 'AtExit' +]); + +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); + + const proc = cp.fork(__filename, + [ 'child' ], { + execArgv: [ + '--trace-event-categories', + 'node.environment' + ] + }); + + proc.once('exit', common.mustCall(async () => { + const file = path.join(tmpdir.path, 'node_trace.1.log'); + const checkSet = new Set(); + + assert(fs.existsSync(file)); + 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.has(trace.name)); + checkSet.add(trace.name); + }); + + assert.deepStrictEqual(names, checkSet); + })); +}