Skip to content

Commit 96cb4fb

Browse files
committed
perf_hooks,trace_events: emit perf milestone trace events
Emit the perf_hooks node timing milestones as trace events. PR-URL: #19175 Reviewed-By: Anna Henningsen <anna@addaleax.net>
1 parent 879f521 commit 96cb4fb

File tree

7 files changed

+92
-28
lines changed

7 files changed

+92
-28
lines changed

doc/api/tracing.md

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -16,6 +16,7 @@ The available categories are:
1616

1717
* `node`
1818
* `node.async_hooks` - Enables capture of detailed async_hooks trace data.
19+
* `node.bootstrap` - Enables capture of Node.js bootstrap milestones.
1920
* `node.perf` - Enables capture of [Performance API] measurements.
2021
* `node.perf.usertiming` - Enables capture of only Performance API User Timing
2122
measures and marks.

src/env.cc

Lines changed: 8 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -115,15 +115,14 @@ Environment::Environment(IsolateData* isolate_data,
115115

116116
destroy_async_id_list_.reserve(512);
117117
performance_state_.reset(new performance::performance_state(isolate()));
118-
performance_state_->milestones[
119-
performance::NODE_PERFORMANCE_MILESTONE_ENVIRONMENT] =
120-
PERFORMANCE_NOW();
121-
performance_state_->milestones[
122-
performance::NODE_PERFORMANCE_MILESTONE_NODE_START] =
123-
performance::performance_node_start;
124-
performance_state_->milestones[
125-
performance::NODE_PERFORMANCE_MILESTONE_V8_START] =
126-
performance::performance_v8_start;
118+
performance_state_->Mark(
119+
performance::NODE_PERFORMANCE_MILESTONE_ENVIRONMENT);
120+
performance_state_->Mark(
121+
performance::NODE_PERFORMANCE_MILESTONE_NODE_START,
122+
performance::performance_node_start);
123+
performance_state_->Mark(
124+
performance::NODE_PERFORMANCE_MILESTONE_V8_START,
125+
performance::performance_v8_start);
127126

128127
// By default, always abort when --abort-on-uncaught-exception was passed.
129128
should_abort_on_uncaught_toggle_[0] = 1;

src/node.cc

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -4474,7 +4474,8 @@ inline int Start(Isolate* isolate, IsolateData* isolate_data,
44744474
{
44754475
SealHandleScope seal(isolate);
44764476
bool more;
4477-
PERFORMANCE_MARK(&env, LOOP_START);
4477+
env.performance_state()->Mark(
4478+
node::performance::NODE_PERFORMANCE_MILESTONE_LOOP_START);
44784479
do {
44794480
uv_run(env.event_loop(), UV_RUN_DEFAULT);
44804481

@@ -4490,7 +4491,8 @@ inline int Start(Isolate* isolate, IsolateData* isolate_data,
44904491
// event, or after running some callbacks.
44914492
more = uv_loop_alive(env.event_loop());
44924493
} while (more == true);
4493-
PERFORMANCE_MARK(&env, LOOP_EXIT);
4494+
env.performance_state()->Mark(
4495+
node::performance::NODE_PERFORMANCE_MILESTONE_LOOP_EXIT);
44944496
}
44954497

44964498
env.set_trace_sync_io(false);

src/node_perf.cc

Lines changed: 11 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -40,6 +40,15 @@ uint64_t performance_v8_start;
4040
uint64_t performance_last_gc_start_mark_ = 0;
4141
v8::GCType performance_last_gc_type_ = v8::GCType::kGCTypeAll;
4242

43+
void performance_state::Mark(enum PerformanceMilestone milestone,
44+
uint64_t ts) {
45+
this->milestones[milestone] = ts;
46+
TRACE_EVENT_INSTANT_WITH_TIMESTAMP0(
47+
TRACING_CATEGORY_NODE1(bootstrap),
48+
GetPerformanceMilestoneName(milestone),
49+
TRACE_EVENT_SCOPE_THREAD, ts);
50+
}
51+
4352
double GetCurrentTimeInMicroseconds() {
4453
#ifdef _WIN32
4554
// The difference between the Unix Epoch and the Windows Epoch in 100-ns ticks.
@@ -200,14 +209,11 @@ void Measure(const FunctionCallbackInfo<Value>& args) {
200209
void MarkMilestone(const FunctionCallbackInfo<Value>& args) {
201210
Environment* env = Environment::GetCurrent(args);
202211
Local<Context> context = env->context();
203-
AliasedBuffer<double, v8::Float64Array>& milestones =
204-
env->performance_state()->milestones;
205212
PerformanceMilestone milestone =
206213
static_cast<PerformanceMilestone>(
207214
args[0]->Int32Value(context).ToChecked());
208-
if (milestone != NODE_PERFORMANCE_MILESTONE_INVALID) {
209-
milestones[milestone] = PERFORMANCE_NOW();
210-
}
215+
if (milestone != NODE_PERFORMANCE_MILESTONE_INVALID)
216+
env->performance_state()->Mark(milestone);
211217
}
212218

213219

src/node_perf.h

Lines changed: 12 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -27,6 +27,18 @@ extern const uint64_t timeOrigin;
2727

2828
double GetCurrentTimeInMicroseconds();
2929

30+
static inline const char* GetPerformanceMilestoneName(
31+
enum PerformanceMilestone milestone) {
32+
switch (milestone) {
33+
#define V(name, label) case NODE_PERFORMANCE_MILESTONE_##name: return label;
34+
NODE_PERFORMANCE_MILESTONES(V)
35+
#undef V
36+
default:
37+
UNREACHABLE();
38+
return 0;
39+
}
40+
}
41+
3042
static inline PerformanceMilestone ToPerformanceMilestoneEnum(const char* str) {
3143
#define V(name, label) \
3244
if (strcmp(str, label) == 0) return NODE_PERFORMANCE_MILESTONE_##name;
@@ -44,12 +56,6 @@ static inline PerformanceEntryType ToPerformanceEntryTypeEnum(
4456
return NODE_PERFORMANCE_ENTRY_TYPE_INVALID;
4557
}
4658

47-
NODE_EXTERN inline void MarkPerformanceMilestone(
48-
Environment* env,
49-
PerformanceMilestone milestone) {
50-
env->performance_state()->milestones[milestone] = PERFORMANCE_NOW();
51-
}
52-
5359
class PerformanceEntry {
5460
public:
5561
static void Notify(Environment* env,

src/node_perf_common.h

Lines changed: 3 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -56,12 +56,6 @@ enum PerformanceEntryType {
5656
NODE_PERFORMANCE_ENTRY_TYPE_INVALID
5757
};
5858

59-
#define PERFORMANCE_MARK(env, n) \
60-
do { \
61-
node::performance::MarkPerformanceMilestone(env, \
62-
node::performance::NODE_PERFORMANCE_MILESTONE_##n); \
63-
} while (0);
64-
6559
class performance_state {
6660
public:
6761
explicit performance_state(v8::Isolate* isolate) :
@@ -86,6 +80,9 @@ class performance_state {
8680
AliasedBuffer<double, v8::Float64Array> milestones;
8781
AliasedBuffer<uint32_t, v8::Uint32Array> observers;
8882

83+
void Mark(enum PerformanceMilestone milestone,
84+
uint64_t ts = PERFORMANCE_NOW());
85+
8986
private:
9087
struct performance_state_internal {
9188
// doubles first so that they are always sizeof(double)-aligned
Lines changed: 53 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,53 @@
1+
'use strict';
2+
const common = require('../common');
3+
const assert = require('assert');
4+
const cp = require('child_process');
5+
const path = require('path');
6+
const fs = require('fs');
7+
const tmpdir = require('../common/tmpdir');
8+
9+
const names = [
10+
'environment',
11+
'nodeStart',
12+
'v8Start',
13+
'loopStart',
14+
'loopExit',
15+
'bootstrapComplete',
16+
'thirdPartyMainStart',
17+
'thirdPartyMainEnd',
18+
'clusterSetupStart',
19+
'clusterSetupEnd',
20+
'moduleLoadStart',
21+
'moduleLoadEnd',
22+
'preloadModulesLoadStart',
23+
'preloadModulesLoadEnd'
24+
];
25+
26+
if (process.argv[2] === 'child') {
27+
1 + 1;
28+
} else {
29+
tmpdir.refresh();
30+
process.chdir(tmpdir.path);
31+
32+
const proc = cp.fork(__filename,
33+
[ 'child' ], {
34+
execArgv: [
35+
'--trace-events-enabled',
36+
'--trace-event-categories',
37+
'node.bootstrap'
38+
]
39+
});
40+
41+
proc.once('exit', common.mustCall(() => {
42+
const file = path.join(tmpdir.path, 'node_trace.1.log');
43+
44+
assert(common.fileExists(file));
45+
fs.readFile(file, common.mustCall((err, data) => {
46+
const traces = JSON.parse(data.toString()).traceEvents;
47+
traces.forEach((trace) => {
48+
assert.strictEqual(trace.pid, proc.pid);
49+
assert(names.includes(trace.name));
50+
});
51+
}));
52+
}));
53+
}

0 commit comments

Comments
 (0)