Skip to content

Commit 74ddae7

Browse files
committed
src: add trace events for env.cc
PR-URL: #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>
1 parent 1336830 commit 74ddae7

File tree

3 files changed

+116
-1
lines changed

3 files changed

+116
-1
lines changed

doc/api/tracing.md

+1
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@ The available categories are:
1818
The [`async_hooks`] events have a unique `asyncId` and a special `triggerId`
1919
`triggerAsyncId` property.
2020
* `node.bootstrap` - Enables capture of Node.js bootstrap milestones.
21+
* `node.environment` - Enables capture of Node.js Environment milestones.
2122
* `node.fs.sync` - Enables capture of trace data for file system sync methods.
2223
* `node.perf` - Enables capture of [Performance API] measurements.
2324
* `node.perf.usertiming` - Enables capture of only Performance API User Timing

src/env.cc

+54-1
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@
77
#include "node_context_data.h"
88
#include "node_worker.h"
99
#include "tracing/agent.h"
10+
#include "tracing/traced_value.h"
1011

1112
#include <stdio.h>
1213
#include <algorithm>
@@ -33,6 +34,25 @@ using worker::Worker;
3334

3435
#define kTraceCategoryCount 1
3536

37+
// TODO(@jasnell): Likely useful to move this to util or node_internal to
38+
// allow reuse. But since we're not reusing it yet...
39+
class TraceEventScope {
40+
public:
41+
TraceEventScope(const char* category,
42+
const char* name,
43+
void* id) : category_(category), name_(name), id_(id) {
44+
TRACE_EVENT_NESTABLE_ASYNC_BEGIN0(category_, name_, id_);
45+
}
46+
~TraceEventScope() {
47+
TRACE_EVENT_NESTABLE_ASYNC_END0(category_, name_, id_);
48+
}
49+
50+
private:
51+
const char* category_;
52+
const char* name_;
53+
void* id_;
54+
};
55+
3656
int const Environment::kNodeContextTag = 0x6e6f64;
3757
void* Environment::kNodeContextTagPtr = const_cast<void*>(
3858
static_cast<const void*>(&Environment::kNodeContextTag));
@@ -224,6 +244,9 @@ Environment::~Environment() {
224244
delete[] heap_statistics_buffer_;
225245
delete[] heap_space_statistics_buffer_;
226246
delete[] http_parser_buffer_;
247+
248+
TRACE_EVENT_NESTABLE_ASYNC_END0(
249+
TRACING_CATEGORY_NODE1(environment), "Environment", this);
227250
}
228251

229252
void Environment::Start(const std::vector<std::string>& args,
@@ -232,6 +255,23 @@ void Environment::Start(const std::vector<std::string>& args,
232255
HandleScope handle_scope(isolate());
233256
Context::Scope context_scope(context());
234257

258+
if (*TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED(
259+
TRACING_CATEGORY_NODE1(environment)) != 0) {
260+
auto traced_value = tracing::TracedValue::Create();
261+
traced_value->BeginArray("args");
262+
for (const std::string& arg : args)
263+
traced_value->AppendString(arg);
264+
traced_value->EndArray();
265+
traced_value->BeginArray("exec_args");
266+
for (const std::string& arg : exec_args)
267+
traced_value->AppendString(arg);
268+
traced_value->EndArray();
269+
TRACE_EVENT_NESTABLE_ASYNC_BEGIN1(
270+
TRACING_CATEGORY_NODE1(environment),
271+
"Environment", this,
272+
"args", std::move(traced_value));
273+
}
274+
235275
CHECK_EQ(0, uv_timer_init(event_loop(), timer_handle()));
236276
uv_unref(reinterpret_cast<uv_handle_t*>(timer_handle()));
237277

@@ -401,6 +441,8 @@ void Environment::PrintSyncTrace() const {
401441
}
402442

403443
void Environment::RunCleanup() {
444+
TraceEventScope trace_scope(TRACING_CATEGORY_NODE1(environment),
445+
"RunCleanup", this);
404446
CleanupHandles();
405447

406448
while (!cleanup_hooks_.empty()) {
@@ -432,6 +474,8 @@ void Environment::RunCleanup() {
432474
}
433475

434476
void Environment::RunBeforeExitCallbacks() {
477+
TraceEventScope trace_scope(TRACING_CATEGORY_NODE1(environment),
478+
"BeforeExit", this);
435479
for (ExitCallback before_exit : before_exit_functions_) {
436480
before_exit.cb_(before_exit.arg_);
437481
}
@@ -443,6 +487,8 @@ void Environment::BeforeExit(void (*cb)(void* arg), void* arg) {
443487
}
444488

445489
void Environment::RunAtExitCallbacks() {
490+
TraceEventScope trace_scope(TRACING_CATEGORY_NODE1(environment),
491+
"AtExit", this);
446492
for (ExitCallback at_exit : at_exit_functions_) {
447493
at_exit.cb_(at_exit.arg_);
448494
}
@@ -496,13 +542,16 @@ void Environment::EnvPromiseHook(v8::PromiseHookType type,
496542

497543
Environment* env = Environment::GetCurrent(context);
498544
if (env == nullptr) return;
499-
545+
TraceEventScope trace_scope(TRACING_CATEGORY_NODE1(environment),
546+
"EnvPromiseHook", env);
500547
for (const PromiseHookCallback& hook : env->promise_hooks_) {
501548
hook.cb_(type, promise, parent, hook.arg_);
502549
}
503550
}
504551

505552
void Environment::RunAndClearNativeImmediates() {
553+
TraceEventScope trace_scope(TRACING_CATEGORY_NODE1(environment),
554+
"RunAndClearNativeImmediates", this);
506555
size_t count = native_immediate_callbacks_.size();
507556
if (count > 0) {
508557
size_t ref_count = 0;
@@ -555,6 +604,8 @@ void Environment::ToggleTimerRef(bool ref) {
555604

556605
void Environment::RunTimers(uv_timer_t* handle) {
557606
Environment* env = Environment::from_timer_handle(handle);
607+
TraceEventScope trace_scope(TRACING_CATEGORY_NODE1(environment),
608+
"RunTimers", env);
558609

559610
if (!env->can_call_into_js())
560611
return;
@@ -615,6 +666,8 @@ void Environment::RunTimers(uv_timer_t* handle) {
615666

616667
void Environment::CheckImmediate(uv_check_t* handle) {
617668
Environment* env = Environment::from_immediate_check_handle(handle);
669+
TraceEventScope trace_scope(TRACING_CATEGORY_NODE1(environment),
670+
"CheckImmediate", env);
618671

619672
if (env->immediate_info()->count() == 0)
620673
return;
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,61 @@
1+
// Flags: --no-warnings
2+
3+
'use strict';
4+
const common = require('../common');
5+
const assert = require('assert');
6+
const cp = require('child_process');
7+
const path = require('path');
8+
const fs = require('fs');
9+
const tmpdir = require('../common/tmpdir');
10+
11+
// This tests the emission of node.environment trace events
12+
13+
if (!common.isMainThread)
14+
common.skip('process.chdir is not available in Workers');
15+
16+
const names = new Set([
17+
'Environment',
18+
'RunAndClearNativeImmediates',
19+
'CheckImmediate',
20+
'RunTimers',
21+
'BeforeExit',
22+
'RunCleanup',
23+
'AtExit'
24+
]);
25+
26+
if (process.argv[2] === 'child') {
27+
// This is just so that the child has something to do.
28+
1 + 1;
29+
// These ensure that the RunTimers, CheckImmediate, and
30+
// RunAndClearNativeImmediates appear in the list.
31+
setImmediate(() => { 1 + 1; });
32+
setTimeout(() => { 1 + 1; }, 1);
33+
} else {
34+
tmpdir.refresh();
35+
process.chdir(tmpdir.path);
36+
37+
const proc = cp.fork(__filename,
38+
[ 'child' ], {
39+
execArgv: [
40+
'--trace-event-categories',
41+
'node.environment'
42+
]
43+
});
44+
45+
proc.once('exit', common.mustCall(async () => {
46+
const file = path.join(tmpdir.path, 'node_trace.1.log');
47+
const checkSet = new Set();
48+
49+
assert(fs.existsSync(file));
50+
const data = await fs.promises.readFile(file);
51+
JSON.parse(data.toString()).traceEvents
52+
.filter((trace) => trace.cat !== '__metadata')
53+
.forEach((trace) => {
54+
assert.strictEqual(trace.pid, proc.pid);
55+
assert(names.has(trace.name));
56+
checkSet.add(trace.name);
57+
});
58+
59+
assert.deepStrictEqual(names, checkSet);
60+
}));
61+
}

0 commit comments

Comments
 (0)