Skip to content

Commit 9e509b6

Browse files
jasnelljasnell
committed
perf_hooks: emit trace events for marks, measures, and timerify
Adds the `node.perf.usertiming` trace events category for recording usertiming marks and measures (e.g. `perf_hooks.performance.mark()`) in the trace events timeline. Adds the `node.perf.function` trace events category for recording `perf_hooks.performance.timerify()` durations in the trace events timeline. PR-URL: #18789 Reviewed-By: Ali Ijaz Sheikh <[email protected]> Reviewed-By: Matteo Collina <[email protected]>
1 parent aca8e76 commit 9e509b6

6 files changed

Lines changed: 131 additions & 11 deletions

File tree

‎doc/api/perf_hooks.md‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -268,8 +268,8 @@ added: v8.5.0
268268

269269
* {string}
270270

271-
The type of the performance entry. Current it may be one of: `'node'`, `'mark'`,
272-
`'measure'`, `'gc'`, or `'function'`.
271+
The type of the performance entry. Currently it may be one of: `'node'`,
272+
`'mark'`, `'measure'`, `'gc'`, or `'function'`.
273273

274274
### performanceEntry.kind
275275
<!-- YAML

‎doc/api/tracing.md‎

Lines changed: 16 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -10,8 +10,20 @@ starting a Node.js application.
1010

1111
The set of categories for which traces are recorded can be specified using the
1212
`--trace-event-categories` flag followed by a list of comma separated category
13-
names. By default the `node`, `node.async_hooks`, and `v8` categories are
14-
enabled.
13+
names.
14+
15+
The available categories are:
16+
17+
* `node`
18+
* `node.async_hooks` - Enables capture of detailed async_hooks trace data.
19+
* `node.perf` - Enables capture of [Performance API] measurements.
20+
* `node.perf.usertiming` - Enables capture of only Performance API User Timing
21+
measures and marks.
22+
* `node.perf.timerify` - Enables capture of only Performance API timerify
23+
measurements.
24+
* `v8`
25+
26+
By default the `node`, `node.async_hooks`, and `v8` categories are enabled.
1527

1628
```txt
1729
node --trace-events-enabled --trace-event-categories v8,node,node.async_hooks server.js
@@ -24,3 +36,5 @@ tab of Chrome.
2436
Starting with Node 10.0.0, the tracing system uses the same time source as the
2537
one used by `process.hrtime()` however the trace-event timestamps are expressed
2638
in microseconds, unlike `process.hrtime()` which returns nanoseconds.
39+
40+
[Performance API]: perf_hooks.html

‎src/node_perf.cc‎

Lines changed: 16 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -105,8 +105,8 @@ void Mark(const FunctionCallbackInfo<Value>& args) {
105105
auto marks = env->performance_marks();
106106
(*marks)[*name] = now;
107107

108-
// TODO(jasnell): Once Tracing API is fully implemented, this should
109-
// record a trace event also.
108+
TRACE_EVENT_COPY_MARK_WITH_TIMESTAMP(
109+
"node.perf,node.perf.usertiming", *name, now / 1000);
110110

111111
PerformanceEntry entry(env, *name, "mark", now, now);
112112
Local<Object> obj = entry.ToObject();
@@ -153,8 +153,10 @@ void Measure(const FunctionCallbackInfo<Value>& args) {
153153
if (endTimestamp < startTimestamp)
154154
endTimestamp = startTimestamp;
155155

156-
// TODO(jasnell): Once Tracing API is fully implemented, this should
157-
// record a trace event also.
156+
TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
157+
"node.perf,node.perf.usertiming", *name, *name, startTimestamp / 1000);
158+
TRACE_EVENT_COPY_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
159+
"node.perf,node.perf.usertiming", *name, *name, endTimestamp / 1000);
158160

159161
PerformanceEntry entry(env, *name, "measure", startTimestamp, endTimestamp);
160162
Local<Object> obj = entry.ToObject();
@@ -269,22 +271,32 @@ void TimerFunctionCall(const FunctionCallbackInfo<Value>& args) {
269271
v8::TryCatch try_catch(isolate);
270272
if (args.IsConstructCall()) {
271273
start = PERFORMANCE_NOW();
274+
TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
275+
"node.perf,node.perf.timerify", *name, *name, start / 1000);
272276
v8::MaybeLocal<Object> ret = fn->NewInstance(context,
273277
call_args.size(),
274278
call_args.data());
275279
end = PERFORMANCE_NOW();
280+
TRACE_EVENT_COPY_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
281+
"node.perf,node.perf.timerify", *name, *name, end / 1000);
282+
276283
if (ret.IsEmpty()) {
277284
try_catch.ReThrow();
278285
return;
279286
}
280287
args.GetReturnValue().Set(ret.ToLocalChecked());
281288
} else {
282289
start = PERFORMANCE_NOW();
290+
TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
291+
"node.perf,node.perf.timerify", *name, *name, start / 1000);
283292
v8::MaybeLocal<Value> ret = fn->Call(context,
284293
args.This(),
285294
call_args.size(),
286295
call_args.data());
287296
end = PERFORMANCE_NOW();
297+
TRACE_EVENT_COPY_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
298+
"node.perf,node.perf.timerify", *name, *name, end / 1000);
299+
288300
if (ret.IsEmpty()) {
289301
try_catch.ReThrow();
290302
return;

‎src/node_perf.h‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@
44
#if defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS
55

66
#include "node.h"
7+
#include "node_internals.h"
78
#include "node_perf_common.h"
89
#include "env.h"
910
#include "base_object-inl.h"

‎src/tracing/trace_event.h‎

Lines changed: 14 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -244,9 +244,20 @@ enum CategoryGroupEnabledFlags {
244244

245245
// Adds a trace event with a given id, thread_id, and timestamp. Not
246246
// Implemented.
247-
#define INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP( \
248-
phase, category_group, name, id, thread_id, timestamp, flags, ...) \
249-
UNIMPLEMENTED()
247+
#define INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP( \
248+
phase, category_group, name, id, thread_id, timestamp, flags, ...) \
249+
do { \
250+
INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category_group); \
251+
if (INTERNAL_TRACE_EVENT_CATEGORY_GROUP_ENABLED_FOR_RECORDING_MODE()) { \
252+
unsigned int trace_event_flags = flags | TRACE_EVENT_FLAG_HAS_ID; \
253+
node::tracing::TraceID trace_event_trace_id(id, \
254+
&trace_event_flags); \
255+
node::tracing::AddTraceEventWithTimestamp( \
256+
phase, INTERNAL_TRACE_EVENT_UID(category_group_enabled), name, \
257+
trace_event_trace_id.scope(), trace_event_trace_id.raw_id(), \
258+
node::tracing::kNoId, trace_event_flags, timestamp, ##__VA_ARGS__);\
259+
} \
260+
} while (0)
250261

251262
// Enter and leave a context based on the current scope.
252263
#define INTERNAL_TRACE_EVENT_SCOPED_CONTEXT(category_group, name, context) \

‎test/parallel/test-trace-events-perf.js‎

Lines changed: 82 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,82 @@
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+
if (process.argv[2] === 'child') {
10+
const { performance } = require('perf_hooks');
11+
12+
// Will emit mark and measure trace events
13+
performance.mark('A');
14+
setTimeout(() => {
15+
performance.mark('B');
16+
performance.measure('A to B', 'A', 'B');
17+
}, 1);
18+
19+
// Intentional non-op, part of the test
20+
function f() {}
21+
const ff = performance.timerify(f);
22+
ff(); // Will emit a timerify trace event
23+
} else {
24+
tmpdir.refresh();
25+
process.chdir(tmpdir.path);
26+
27+
const expectedMarks = ['A', 'B'];
28+
const expectedBegins = [
29+
{ cat: 'node.perf,node.perf.timerify', name: 'f' },
30+
{ cat: 'node.perf,node.perf.usertiming', name: 'A to B' }
31+
];
32+
const expectedEnds = [
33+
{ cat: 'node.perf,node.perf.timerify', name: 'f' },
34+
{ cat: 'node.perf,node.perf.usertiming', name: 'A to B' }
35+
];
36+
37+
const proc = cp.fork(__filename,
38+
[
39+
'child'
40+
], {
41+
execArgv: [
42+
'--trace-events-enabled',
43+
'--trace-event-categories',
44+
'node.perf'
45+
]
46+
});
47+
48+
proc.once('exit', common.mustCall(() => {
49+
const file = path.join(tmpdir.path, 'node_trace.1.log');
50+
51+
assert(common.fileExists(file));
52+
fs.readFile(file, common.mustCall((err, data) => {
53+
const traces = JSON.parse(data.toString()).traceEvents;
54+
assert.strictEqual(traces.length,
55+
expectedMarks.length +
56+
expectedBegins.length +
57+
expectedEnds.length);
58+
59+
traces.forEach((trace) => {
60+
assert.strictEqual(trace.pid, proc.pid);
61+
switch (trace.ph) {
62+
case 'R':
63+
assert.strictEqual(trace.cat, 'node.perf,node.perf.usertiming');
64+
assert.strictEqual(trace.name, expectedMarks.shift());
65+
break;
66+
case 'b':
67+
const expectedBegin = expectedBegins.shift();
68+
assert.strictEqual(trace.cat, expectedBegin.cat);
69+
assert.strictEqual(trace.name, expectedBegin.name);
70+
break;
71+
case 'e':
72+
const expectedEnd = expectedEnds.shift();
73+
assert.strictEqual(trace.cat, expectedEnd.cat);
74+
assert.strictEqual(trace.name, expectedEnd.name);
75+
break;
76+
default:
77+
assert.fail('Unexpected trace event phase');
78+
}
79+
});
80+
}));
81+
}));
82+
}

0 commit comments

Comments
 (0)