Skip to content

Commit bf8cac0

Browse files
committed
perf_hooks: complete overhaul of the implementation
* Update the user timing implementation to conform to User Timing Level 3. * Reimplement user timing and timerify with pure JavaScript implementations * Simplify the C++ implementation for gc and http2 perf * Runtime deprecate additional perf entry properties in favor of the standard detail argument * Disable the `buffered` option on PerformanceObserver, all entries are queued and dispatched on setImmediate. Only entries with active observers are buffered. * This does remove the user timing and timerify trace events. Because the trace_events are still considered experimental, those can be removed without a deprecation cycle. They are removed to improve performance and reduce complexity. Old: `perf_hooks/usertiming.js n=100000: 92,378.01249733355` New: perf_hooks/usertiming.js n=100000: 270,393.5280638482` Signed-off-by: James M Snell <[email protected]>
1 parent 255d633 commit bf8cac0

37 files changed

+1877
-1509
lines changed

benchmark/perf_hooks/usertiming.js

Lines changed: 31 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,31 @@
1+
'use strict';
2+
3+
const common = require('../common.js');
4+
5+
const {
6+
PerformanceObserver,
7+
performance,
8+
} = require('perf_hooks');
9+
10+
const bench = common.createBenchmark(main, {
11+
n: [1e5]
12+
});
13+
14+
function test() {
15+
performance.mark('a');
16+
setImmediate(() => {
17+
performance.mark('b');
18+
performance.measure('a to b', 'a', 'b');
19+
});
20+
}
21+
22+
function main({ n }) {
23+
const obs = new PerformanceObserver(() => {
24+
bench.end(n);
25+
});
26+
obs.observe({ entryTypes: ['measure'], buffered: true });
27+
28+
bench.start();
29+
for (let i = 0; i < n; i++)
30+
test();
31+
}

doc/api/deprecations.md

Lines changed: 16 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2743,6 +2743,22 @@ Previously, `index.js` and extension searching lookups would apply to
27432743
With this deprecation, all ES module main entry point resolutions require
27442744
an explicit [`"exports"` or `"main"` entry][] with the exact file extension.
27452745

2746+
### DEP0XXX: Extension PerformanceEntry properties
2747+
<!-- YAML
2748+
changes:
2749+
- version: REPLACEME
2750+
pr-url: https://github.com/nodejs/node/pull/00000
2751+
description: Runtime deprecation.
2752+
-->
2753+
2754+
Type: Runtime
2755+
2756+
The `'gc'`, `'http2'`, and `'http'` {PerformanceEntry} object types have
2757+
additional properties assigned to them that provide additional information.
2758+
These properties are now available within the standard `detail` property
2759+
of the `PerformanceEntry` object. The existing accessors have been
2760+
deprecated and should no longer be used.
2761+
27462762
[Legacy URL API]: url.md#url_legacy_url_api
27472763
[NIST SP 800-38D]: https://nvlpubs.nist.gov/nistpubs/Legacy/SP/nistspecialpublication800-38d.pdf
27482764
[RFC 6066]: https://tools.ietf.org/html/rfc6066#section-3

doc/api/errors.md

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1891,6 +1891,16 @@ The `package.json` [`"exports"`][] field does not export the requested subpath.
18911891
Because exports are encapsulated, private internal modules that are not exported
18921892
cannot be imported through the package resolution, unless using an absolute URL.
18931893

1894+
<a id="ERR_PERFORMANCE_INVALID_TIMESTAMP"></a>
1895+
### `ERR_PERFORMANCE_INVALID_TIMESTAMP`
1896+
1897+
An invalid timestamp value was provided for a performance mark or measure.
1898+
1899+
<a id="ERR_PERFORMANCE_MEASURE_INVALID_OPTIONS"></a>
1900+
### `ERR_PERFORMANCE_MEASURE_INVALID_OPTIONS`
1901+
1902+
Invalid options were provided for a performance measure.
1903+
18941904
<a id="ERR_PROTO_ACCESS"></a>
18951905
### `ERR_PROTO_ACCESS`
18961906

doc/api/perf_hooks.md

Lines changed: 133 additions & 35 deletions
Original file line numberDiff line numberDiff line change
@@ -23,7 +23,7 @@ const obs = new PerformanceObserver((items) => {
2323
console.log(items.getEntries()[0].duration);
2424
performance.clearMarks();
2525
});
26-
obs.observe({ entryTypes: ['measure'] });
26+
obs.observe({ type: 'measure' });
2727
performance.measure('Start to Now');
2828

2929
performance.mark('A');
@@ -115,23 +115,34 @@ Passing in a user-defined object instead of the result of a previous call to
115115
`eventLoopUtilization()` will lead to undefined behavior. The return values
116116
are not guaranteed to reflect any correct state of the event loop.
117117

118-
### `performance.mark([name])`
118+
### `performance.mark([name[, options]])`
119119
<!-- YAML
120120
added: v8.5.0
121+
changes:
122+
- version: REPLACEME
123+
pr-url: https://github.com/nodejs/node/pull/00000
124+
description: Updated to conform to the User Timing Level 3 specification.
121125
-->
122126

123127
* `name` {string}
128+
* `options` {Object}
129+
* `detail` {any} Additional optional detail to include with the mark.
130+
* `startTime` {number} An optional timestamp to be used as the mark time.
131+
**Defaults**: `performance.now()`.
124132

125133
Creates a new `PerformanceMark` entry in the Performance Timeline. A
126134
`PerformanceMark` is a subclass of `PerformanceEntry` whose
127135
`performanceEntry.entryType` is always `'mark'`, and whose
128136
`performanceEntry.duration` is always `0`. Performance marks are used
129137
to mark specific significant moments in the Performance Timeline.
130138

131-
### `performance.measure(name[, startMark[, endMark]])`
139+
### `performance.measure(name[, startMarkOrOptions[, endMark]])`
132140
<!-- YAML
133141
added: v8.5.0
134142
changes:
143+
- version: REPLACEME
144+
pr-url: https://github.com/nodejs/node/pull/00000
145+
description: Updated to conform to the User Timing Level 3 specification.
135146
- version:
136147
- v13.13.0
137148
- v12.16.3
@@ -140,8 +151,15 @@ changes:
140151
-->
141152

142153
* `name` {string}
143-
* `startMark` {string} Optional.
144-
* `endMark` {string} Optional.
154+
* `startMarkOrOptions` {string|Object} Optional.
155+
* `detail` {Object} Additional optional detail to include with the measure.
156+
* `duration` {number} Duration between start and end times.
157+
* `end` {number|string} Timestamp to be used as the end time, or a string
158+
identifying a previously recorded mark.
159+
* `start` {number|string} Timestamp to be used as the start time, or a string
160+
identifying a previously recorded mark.
161+
* `endMark` {string} Optional. Must be omitted if `startMarkOrOptions` is an
162+
{Object}.
145163

146164
Creates a new `PerformanceMeasure` entry in the Performance Timeline. A
147165
`PerformanceMeasure` is a subclass of `PerformanceEntry` whose
@@ -152,7 +170,7 @@ Creates a new `PerformanceMeasure` entry in the Performance Timeline. A
152170
The `startMark` argument may identify any *existing* `PerformanceMark` in the
153171
Performance Timeline, or *may* identify any of the timestamp properties
154172
provided by the `PerformanceNodeTiming` class. If the named `startMark` does
155-
not exist, then `startMark` is set to [`timeOrigin`][] by default.
173+
not exist, an error is thrown.
156174

157175
The optional `endMark` argument must identify any *existing* `PerformanceMark`
158176
in the Performance Timeline or any of the timestamp properties provided by the
@@ -195,6 +213,11 @@ which the current `node` process began, measured in Unix time.
195213
### `performance.timerify(fn)`
196214
<!-- YAML
197215
added: v8.5.0
216+
changes:
217+
- version: REPLACEME
218+
pr-url: https://github.com/nodejs/node/pull/00000
219+
description: Re-implemented to use pure-JavaScript and the ability
220+
to time async functions.
198221
-->
199222

200223
* `fn` {Function}
@@ -227,11 +250,24 @@ obs.observe({ entryTypes: ['function'] });
227250
wrapped();
228251
```
229252

253+
If the wrapped function returns a promise, a finally handler will be attached
254+
to the promise and the duration will be reported once the finally handler is
255+
invoked.
256+
230257
## Class: `PerformanceEntry`
231258
<!-- YAML
232259
added: v8.5.0
233260
-->
234261

262+
### `performanceEntry.details`
263+
<!-- YAML
264+
added: REPLACEME
265+
-->
266+
267+
* {any}
268+
269+
Additional detail specific to the `entryType`.
270+
235271
### `performanceEntry.duration`
236272
<!-- YAML
237273
added: v8.5.0
@@ -264,6 +300,11 @@ The type of the performance entry. It may be one of:
264300
added:
265301
- v13.9.0
266302
- v12.17.0
303+
changes:
304+
- version: REPLACEME
305+
pr-url: https://github.com/nodejs/node/pull/00000
306+
description: Runtime deprecated. Now moved to the detail property
307+
when entryType is 'gc'.
267308
-->
268309

269310
* {number}
@@ -294,6 +335,11 @@ The name of the performance entry.
294335
### `performanceEntry.kind`
295336
<!-- YAML
296337
added: v8.5.0
338+
changes:
339+
- version: REPLACEME
340+
pr-url: https://github.com/nodejs/node/pull/00000
341+
description: Runtime deprecated. Now moved to the detail property
342+
when entryType is 'gc'.
297343
-->
298344

299345
* {number}
@@ -319,6 +365,72 @@ added: v8.5.0
319365
The high resolution millisecond timestamp marking the starting time of the
320366
Performance Entry.
321367

368+
### Garbage Collection ('gc') Details
369+
370+
When `performanceEntry.type` is equal to `'gc'`, the `performanceEntry.details`
371+
property will be an {Object} with two properties:
372+
373+
* `kind` {number} One of:
374+
* `perf_hooks.constants.NODE_PERFORMANCE_GC_MAJOR`
375+
* `perf_hooks.constants.NODE_PERFORMANCE_GC_MINOR`
376+
* `perf_hooks.constants.NODE_PERFORMANCE_GC_INCREMENTAL`
377+
* `perf_hooks.constants.NODE_PERFORMANCE_GC_WEAKCB`
378+
* `flags` {number} One of:
379+
* `perf_hooks.constants.NODE_PERFORMANCE_GC_FLAGS_NO`
380+
* `perf_hooks.constants.NODE_PERFORMANCE_GC_FLAGS_CONSTRUCT_RETAINED`
381+
* `perf_hooks.constants.NODE_PERFORMANCE_GC_FLAGS_FORCED`
382+
* `perf_hooks.constants.NODE_PERFORMANCE_GC_FLAGS_SYNCHRONOUS_PHANTOM_PROCESSING`
383+
* `perf_hooks.constants.NODE_PERFORMANCE_GC_FLAGS_ALL_AVAILABLE_GARBAGE`
384+
* `perf_hooks.constants.NODE_PERFORMANCE_GC_FLAGS_ALL_EXTERNAL_MEMORY`
385+
* `perf_hooks.constants.NODE_PERFORMANCE_GC_FLAGS_SCHEDULE_IDLE`
386+
387+
### HTTP/2 ('http2') Details
388+
389+
When `performanceEntry.type` is equal to `'http2'`, the
390+
`performanceEntry.details` property will be an {Object} containing
391+
additional performance information.
392+
393+
If `performanceEntry.name` is equal to `Http2Stream`, the `details`
394+
will contain the following properties:
395+
396+
* `bytesRead` {number} The number of `DATA` frame bytes received for this
397+
`Http2Stream`.
398+
* `bytesWritten` {number} The number of `DATA` frame bytes sent for this
399+
`Http2Stream`.
400+
* `id` {number} The identifier of the associated `Http2Stream`
401+
* `timeToFirstByte` {number} The number of milliseconds elapsed between the
402+
`PerformanceEntry` `startTime` and the reception of the first `DATA` frame.
403+
* `timeToFirstByteSent` {number} The number of milliseconds elapsed between
404+
the `PerformanceEntry` `startTime` and sending of the first `DATA` frame.
405+
* `timeToFirstHeader` {number} The number of milliseconds elapsed between the
406+
`PerformanceEntry` `startTime` and the reception of the first header.
407+
408+
If `performanceEntry.name` is equal to `Http2Session`, the `details` will
409+
contain the following properties:
410+
411+
* `bytesRead` {number} The number of bytes received for this `Http2Session`.
412+
* `bytesWritten` {number} The number of bytes sent for this `Http2Session`.
413+
* `framesReceived` {number} The number of HTTP/2 frames received by the
414+
`Http2Session`.
415+
* `framesSent` {number} The number of HTTP/2 frames sent by the `Http2Session`.
416+
* `maxConcurrentStreams` {number} The maximum number of streams concurrently
417+
open during the lifetime of the `Http2Session`.
418+
* `pingRTT` {number} The number of milliseconds elapsed since the transmission
419+
of a `PING` frame and the reception of its acknowledgment. Only present if
420+
a `PING` frame has been sent on the `Http2Session`.
421+
* `streamAverageDuration` {number} The average duration (in milliseconds) for
422+
all `Http2Stream` instances.
423+
* `streamCount` {number} The number of `Http2Stream` instances processed by
424+
the `Http2Session`.
425+
* `type` {string} Either `'server'` or `'client'` to identify the type of
426+
`Http2Session`.
427+
428+
### Timerify ('function') Details
429+
430+
When `performanceEntry.type` is equal to `'function'`, the
431+
`performanceEntry.details` property will be an {Array} listing
432+
the input arguments to the timed function.
433+
322434
## Class: `PerformanceNodeTiming`
323435
<!-- YAML
324436
added: v8.5.0
@@ -457,22 +569,23 @@ Disconnects the `PerformanceObserver` instance from all notifications.
457569
### `performanceObserver.observe(options)`
458570
<!-- YAML
459571
added: v8.5.0
572+
changes:
573+
- version: REPLACEME
574+
pr-url: https://github.com/nodejs/node/pull/00000
575+
description: Updated to conform to User Timing Level 3. The
576+
buffered option has been removed.
460577
-->
461578

462579
* `options` {Object}
580+
* `type` {string} A single {PerformanceEntry} type. Must not be given
581+
if `entryTypes` is already specified.
463582
* `entryTypes` {string[]} An array of strings identifying the types of
464-
`PerformanceEntry` instances the observer is interested in. If not
583+
{PerformanceEntry} instances the observer is interested in. If not
465584
provided an error will be thrown.
466-
* `buffered` {boolean} If true, the notification callback will be
467-
called using `setImmediate()` and multiple `PerformanceEntry` instance
468-
notifications will be buffered internally. If `false`, notifications will
469-
be immediate and synchronous. **Default:** `false`.
470-
471-
Subscribes the `PerformanceObserver` instance to notifications of new
472-
`PerformanceEntry` instances identified by `options.entryTypes`.
473585

474-
When `options.buffered` is `false`, the `callback` will be invoked once for
475-
every `PerformanceEntry` instance:
586+
Subscribes the {PerformanceObserver} instance to notifications of new
587+
{PerformanceEntry} instances identified either by `options.entryTypes`
588+
or `options.type`:
476589

477590
```js
478591
const {
@@ -483,22 +596,7 @@ const {
483596
const obs = new PerformanceObserver((list, observer) => {
484597
// Called three times synchronously. `list` contains one item.
485598
});
486-
obs.observe({ entryTypes: ['mark'] });
487-
488-
for (let n = 0; n < 3; n++)
489-
performance.mark(`test${n}`);
490-
```
491-
492-
```js
493-
const {
494-
performance,
495-
PerformanceObserver
496-
} = require('perf_hooks');
497-
498-
const obs = new PerformanceObserver((list, observer) => {
499-
// Called once. `list` contains three items.
500-
});
501-
obs.observe({ entryTypes: ['mark'], buffered: true });
599+
obs.observe({ type: 'mark' });
502600

503601
for (let n = 0; n < 3; n++)
504602
performance.mark(`test${n}`);
@@ -549,7 +647,7 @@ const obs = new PerformanceObserver((perfObserverList, observer) => {
549647
*/
550648
observer.disconnect();
551649
});
552-
obs.observe({ entryTypes: ['mark'], buffered: true });
650+
obs.observe({ type: 'mark' });
553651

554652
performance.mark('test');
555653
performance.mark('meow');
@@ -603,7 +701,7 @@ const obs = new PerformanceObserver((perfObserverList, observer) => {
603701
console.log(perfObserverList.getEntriesByName('test', 'measure')); // []
604702
observer.disconnect();
605703
});
606-
obs.observe({ entryTypes: ['mark', 'measure'], buffered: true });
704+
obs.observe({ entryTypes: ['mark', 'measure'] });
607705

608706
performance.mark('test');
609707
performance.mark('meow');
@@ -647,7 +745,7 @@ const obs = new PerformanceObserver((perfObserverList, observer) => {
647745
*/
648746
observer.disconnect();
649747
});
650-
obs.observe({ entryTypes: ['mark'], buffered: true });
748+
obs.observe({ type: 'mark' });
651749

652750
performance.mark('test');
653751
performance.mark('meow');

lib/_http_server.js

Lines changed: 4 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -88,9 +88,7 @@ const {
8888
DTRACE_HTTP_SERVER_REQUEST,
8989
DTRACE_HTTP_SERVER_RESPONSE
9090
} = require('internal/dtrace');
91-
const { observerCounts, constants } = internalBinding('performance');
9291
const { setTimeout, clearTimeout } = require('timers');
93-
const { NODE_PERFORMANCE_ENTRY_TYPE_HTTP } = constants;
9492

9593
const dc = require('diagnostics_channel');
9694
const onRequestStartChannel = dc.channel('http.server.request.start');
@@ -192,21 +190,16 @@ function ServerResponse(req) {
192190
this.shouldKeepAlive = false;
193191
}
194192

195-
const httpObserverCount = observerCounts[NODE_PERFORMANCE_ENTRY_TYPE_HTTP];
196-
if (httpObserverCount > 0) {
197-
this[kServerResponseStatistics] = {
198-
startTime: process.hrtime()
199-
};
200-
}
193+
this[kServerResponseStatistics] = {
194+
startTime: process.hrtime()
195+
};
201196
}
202197
ObjectSetPrototypeOf(ServerResponse.prototype, OutgoingMessage.prototype);
203198
ObjectSetPrototypeOf(ServerResponse, OutgoingMessage);
204199

205200
ServerResponse.prototype._finish = function _finish() {
206201
DTRACE_HTTP_SERVER_RESPONSE(this.socket);
207-
if (this[kServerResponseStatistics] !== undefined) {
208-
emitStatistics(this[kServerResponseStatistics]);
209-
}
202+
emitStatistics(this[kServerResponseStatistics]);
210203
FunctionPrototypeCall(OutgoingMessage.prototype._finish, this);
211204
};
212205

0 commit comments

Comments
 (0)