Skip to content

Commit f3eb224

Browse files
jasnelljasnell
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` PR-URL: nodejs#37136 Refs: nodejs/diagnostics#464 Reviewed-By: Antoine du Hamel <duhamelantoine1995@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: Michaël Zasso <targos@protonmail.com>
1 parent 9f2efaa commit f3eb224

38 files changed

Lines changed: 1880 additions & 1519 deletions

‎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
@@ -2748,6 +2748,22 @@ Previously, `index.js` and extension searching lookups would apply to
27482748
With this deprecation, all ES module main entry point resolutions require
27492749
an explicit [`"exports"` or `"main"` entry][] with the exact file extension.
27502750

2751+
### DEP0XXX: Extension PerformanceEntry properties
2752+
<!-- YAML
2753+
changes:
2754+
- version: REPLACEME
2755+
pr-url: https://github.com/nodejs/node/pull/37136
2756+
description: Runtime deprecation.
2757+
-->
2758+
2759+
Type: Runtime
2760+
2761+
The `'gc'`, `'http2'`, and `'http'` {PerformanceEntry} object types have
2762+
additional properties assigned to them that provide additional information.
2763+
These properties are now available within the standard `detail` property
2764+
of the `PerformanceEntry` object. The existing accessors have been
2765+
deprecated and should no longer be used.
2766+
27512767
[Legacy URL API]: url.md#url_legacy_url_api
27522768
[NIST SP 800-38D]: https://nvlpubs.nist.gov/nistpubs/Legacy/SP/nistspecialpublication800-38d.pdf
27532769
[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
@@ -1903,6 +1903,16 @@ The `package.json` [`"exports"`][] field does not export the requested subpath.
19031903
Because exports are encapsulated, private internal modules that are not exported
19041904
cannot be imported through the package resolution, unless using an absolute URL.
19051905

1906+
<a id="ERR_PERFORMANCE_INVALID_TIMESTAMP"></a>
1907+
### `ERR_PERFORMANCE_INVALID_TIMESTAMP`
1908+
1909+
An invalid timestamp value was provided for a performance mark or measure.
1910+
1911+
<a id="ERR_PERFORMANCE_MEASURE_INVALID_OPTIONS"></a>
1912+
### `ERR_PERFORMANCE_MEASURE_INVALID_OPTIONS`
1913+
1914+
Invalid options were provided for a performance measure.
1915+
19061916
<a id="ERR_PROTO_ACCESS"></a>
19071917
### `ERR_PROTO_ACCESS`
19081918

‎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/37136
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/37136
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` {any} 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/37136
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/37136
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/37136
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/37136
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
@@ -89,9 +89,7 @@ const {
8989
DTRACE_HTTP_SERVER_REQUEST,
9090
DTRACE_HTTP_SERVER_RESPONSE
9191
} = require('internal/dtrace');
92-
const { observerCounts, constants } = internalBinding('performance');
9392
const { setTimeout, clearTimeout } = require('timers');
94-
const { NODE_PERFORMANCE_ENTRY_TYPE_HTTP } = constants;
9593

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

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

206201
ServerResponse.prototype._finish = function _finish() {
207202
DTRACE_HTTP_SERVER_RESPONSE(this.socket);
208-
if (this[kServerResponseStatistics] !== undefined) {
209-
emitStatistics(this[kServerResponseStatistics]);
210-
}
203+
emitStatistics(this[kServerResponseStatistics]);
211204
FunctionPrototypeCall(OutgoingMessage.prototype._finish, this);
212205
};
213206

0 commit comments

Comments
 (0)