src: add trace events for env.cc

PR-URL: nodejs#23674
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Denys Otrishko <shishugi@gmail.com>
Reviewed-By: Refael Ackermann <refack@gmail.com>
Reviewed-By: Ali Ijaz Sheikh <ofrobots@google.com>
Reviewed-By: Matheus Marchini <mat@mmarchini.me>

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

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 <stdio.h>
 #include <algorithm>
@@ -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<void*>(
     static_cast<const void*>(&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<std::string>& args,
@@ -232,6 +255,23 @@ void Environment::Start(const std::vector<std::string>& 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<uv_handle_t*>(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;

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);
+  }));
+}