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`

Author: jasnell

benchmark/perf_hooks/usertiming.js

@@ -0,0 +1,31 @@
+'use strict';
+
+const common = require('../common.js');
+
+const {
+ PerformanceObserver,
+ performance,
+} = require('perf_hooks');
+
+const bench = common.createBenchmark(main, {
+ n: [1e5]
+});
+
+function test() {
+ performance.mark('a');
+ setImmediate(() => {
+ performance.mark('b');
+ performance.measure('a to b', 'a', 'b');
+ });
+}
+
+function main({ n }) {
+ const obs = new PerformanceObserver(() => {
+ bench.end(n);
+ });
+ obs.observe({ entryTypes: ['measure'], buffered: true });
+
+ bench.start();
+ for (let i = 0; i < n; i++)
+ test();
+}

doc/api/deprecations.md

@@ -2743,6 +2743,22 @@ Previously, `index.js` and extension searching lookups would apply to
 With this deprecation, all ES module main entry point resolutions require
 an explicit [`"exports"` or `"main"` entry][] with the exact file extension.
 
+### DEP0XXX: Extension PerformanceEntry properties
+<!-- YAML
+changes:
+ - version: REPLACEME
+ pr-url: https://github.com/nodejs/node/pull/37136
+ description: Runtime deprecation.
+-->
+
+Type: Runtime
+
+The `'gc'`, `'http2'`, and `'http'` {PerformanceEntry} object types have
+additional properties assigned to them that provide additional information.
+These properties are now available within the standard `detail` property
+of the `PerformanceEntry` object. The existing accessors have been
+deprecated and should no longer be used.
+
 [Legacy URL API]: url.md#url_legacy_url_api
 [NIST SP 800-38D]: https://nvlpubs.nist.gov/nistpubs/Legacy/SP/nistspecialpublication800-38d.pdf
 [RFC 6066]: https://tools.ietf.org/html/rfc6066#section-3

doc/api/errors.md

@@ -1891,6 +1891,16 @@ The `package.json` [`"exports"`][] field does not export the requested subpath.
 Because exports are encapsulated, private internal modules that are not exported
 cannot be imported through the package resolution, unless using an absolute URL.
 
+<a id="ERR_PERFORMANCE_INVALID_TIMESTAMP"></a>
+### `ERR_PERFORMANCE_INVALID_TIMESTAMP`
+
+An invalid timestamp value was provided for a performance mark or measure.
+
+<a id="ERR_PERFORMANCE_MEASURE_INVALID_OPTIONS"></a>
+### `ERR_PERFORMANCE_MEASURE_INVALID_OPTIONS`
+
+Invalid options were provided for a performance measure.
+
 <a id="ERR_PROTO_ACCESS"></a>
 ### `ERR_PROTO_ACCESS`
 

doc/api/perf_hooks.md

@@ -23,7 +23,7 @@ const obs = new PerformanceObserver((items) => {
  console.log(items.getEntries()[0].duration);
  performance.clearMarks();
 });
-obs.observe({ entryTypes: ['measure'] });
+obs.observe({ type: 'measure' });
 performance.measure('Start to Now');
 
 performance.mark('A');
@@ -115,23 +115,34 @@ Passing in a user-defined object instead of the result of a previous call to
 `eventLoopUtilization()` will lead to undefined behavior. The return values
 are not guaranteed to reflect any correct state of the event loop.
 
-### `performance.mark([name])`
+### `performance.mark([name[, options]])`
 <!-- YAML
 added: v8.5.0
+changes:
+ - version: REPLACEME
+ pr-url: https://github.com/nodejs/node/pull/37136
+ description: Updated to conform to the User Timing Level 3 specification.
 -->
 
 * `name` {string}
+* `options` {Object}
+ * `detail` {any} Additional optional detail to include with the mark.
+ * `startTime` {number} An optional timestamp to be used as the mark time.
+ **Defaults**: `performance.now()`.
 
 Creates a new `PerformanceMark` entry in the Performance Timeline. A
 `PerformanceMark` is a subclass of `PerformanceEntry` whose
 `performanceEntry.entryType` is always `'mark'`, and whose
 `performanceEntry.duration` is always `0`. Performance marks are used
 to mark specific significant moments in the Performance Timeline.
 
-### `performance.measure(name[, startMark[, endMark]])`
+### `performance.measure(name[, startMarkOrOptions[, endMark]])`
 <!-- YAML
 added: v8.5.0
 changes:
+ - version: REPLACEME
+ pr-url: https://github.com/nodejs/node/pull/37136
+ description: Updated to conform to the User Timing Level 3 specification.
  - version:
  - v13.13.0
  - v12.16.3
@@ -140,8 +151,15 @@ changes:
 -->
 
 * `name` {string}
-* `startMark` {string} Optional.
-* `endMark` {string} Optional.
+* `startMarkOrOptions` {string|Object} Optional.
+ * `detail` {Object} Additional optional detail to include with the measure.
+ * `duration` {number} Duration between start and end times.
+ * `end` {number|string} Timestamp to be used as the end time, or a string
+ identifying a previously recorded mark.
+ * `start` {number|string} Timestamp to be used as the start time, or a string
+ identifying a previously recorded mark.
+* `endMark` {string} Optional. Must be omitted if `startMarkOrOptions` is an
+ {Object}.
 
 Creates a new `PerformanceMeasure` entry in the Performance Timeline. A
 `PerformanceMeasure` is a subclass of `PerformanceEntry` whose
@@ -152,7 +170,7 @@ Creates a new `PerformanceMeasure` entry in the Performance Timeline. A
 The `startMark` argument may identify any *existing* `PerformanceMark` in the
 Performance Timeline, or *may* identify any of the timestamp properties
 provided by the `PerformanceNodeTiming` class. If the named `startMark` does
-not exist, then `startMark` is set to [`timeOrigin`][] by default.
+not exist, an error is thrown.
 
 The optional `endMark` argument must identify any *existing* `PerformanceMark`
 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.
 ### `performance.timerify(fn)`
 <!-- YAML
 added: v8.5.0
+changes:
+ - version: REPLACEME
+ pr-url: https://github.com/nodejs/node/pull/37136
+ description: Re-implemented to use pure-JavaScript and the ability
+ to time async functions.
 -->
 
 * `fn` {Function}
@@ -227,11 +250,24 @@ obs.observe({ entryTypes: ['function'] });
 wrapped();
 ```
 
+If the wrapped function returns a promise, a finally handler will be attached
+to the promise and the duration will be reported once the finally handler is
+invoked.
+
 ## Class: `PerformanceEntry`
 <!-- YAML
 added: v8.5.0
 -->
 
+### `performanceEntry.details`
+<!-- YAML
+added: REPLACEME
+-->
+
+* {any}
+
+Additional detail specific to the `entryType`.
+
 ### `performanceEntry.duration`
 <!-- YAML
 added: v8.5.0
@@ -264,6 +300,11 @@ The type of the performance entry. It may be one of:
 added:
  - v13.9.0
  - v12.17.0
+changes:
+ - version: REPLACEME
+ pr-url: https://github.com/nodejs/node/pull/37136
+ description: Runtime deprecated. Now moved to the detail property
+ when entryType is 'gc'.
 -->
 
 * {number}
@@ -294,6 +335,11 @@ The name of the performance entry.
 ### `performanceEntry.kind`
 <!-- YAML
 added: v8.5.0
+changes:
+ - version: REPLACEME
+ pr-url: https://github.com/nodejs/node/pull/37136
+ description: Runtime deprecated. Now moved to the detail property
+ when entryType is 'gc'.
 -->
 
 * {number}
@@ -319,6 +365,72 @@ added: v8.5.0
 The high resolution millisecond timestamp marking the starting time of the
 Performance Entry.
 
+### Garbage Collection ('gc') Details
+
+When `performanceEntry.type` is equal to `'gc'`, the `performanceEntry.details`
+property will be an {Object} with two properties:
+
+* `kind` {number} One of:
+ * `perf_hooks.constants.NODE_PERFORMANCE_GC_MAJOR`
+ * `perf_hooks.constants.NODE_PERFORMANCE_GC_MINOR`
+ * `perf_hooks.constants.NODE_PERFORMANCE_GC_INCREMENTAL`
+ * `perf_hooks.constants.NODE_PERFORMANCE_GC_WEAKCB`
+* `flags` {number} One of:
+ * `perf_hooks.constants.NODE_PERFORMANCE_GC_FLAGS_NO`
+ * `perf_hooks.constants.NODE_PERFORMANCE_GC_FLAGS_CONSTRUCT_RETAINED`
+ * `perf_hooks.constants.NODE_PERFORMANCE_GC_FLAGS_FORCED`
+ * `perf_hooks.constants.NODE_PERFORMANCE_GC_FLAGS_SYNCHRONOUS_PHANTOM_PROCESSING`
+ * `perf_hooks.constants.NODE_PERFORMANCE_GC_FLAGS_ALL_AVAILABLE_GARBAGE`
+ * `perf_hooks.constants.NODE_PERFORMANCE_GC_FLAGS_ALL_EXTERNAL_MEMORY`
+ * `perf_hooks.constants.NODE_PERFORMANCE_GC_FLAGS_SCHEDULE_IDLE`
+
+### HTTP/2 ('http2') Details
+
+When `performanceEntry.type` is equal to `'http2'`, the
+`performanceEntry.details` property will be an {Object} containing
+additional performance information.
+
+If `performanceEntry.name` is equal to `Http2Stream`, the `details`
+will contain the following properties:
+
+* `bytesRead` {number} The number of `DATA` frame bytes received for this
+ `Http2Stream`.
+* `bytesWritten` {number} The number of `DATA` frame bytes sent for this
+ `Http2Stream`.
+* `id` {number} The identifier of the associated `Http2Stream`
+* `timeToFirstByte` {number} The number of milliseconds elapsed between the
+ `PerformanceEntry` `startTime` and the reception of the first `DATA` frame.
+* `timeToFirstByteSent` {number} The number of milliseconds elapsed between
+ the `PerformanceEntry` `startTime` and sending of the first `DATA` frame.
+* `timeToFirstHeader` {number} The number of milliseconds elapsed between the
+ `PerformanceEntry` `startTime` and the reception of the first header.
+
+If `performanceEntry.name` is equal to `Http2Session`, the `details` will
+contain the following properties:
+
+* `bytesRead` {number} The number of bytes received for this `Http2Session`.
+* `bytesWritten` {number} The number of bytes sent for this `Http2Session`.
+* `framesReceived` {number} The number of HTTP/2 frames received by the
+ `Http2Session`.
+* `framesSent` {number} The number of HTTP/2 frames sent by the `Http2Session`.
+* `maxConcurrentStreams` {number} The maximum number of streams concurrently
+ open during the lifetime of the `Http2Session`.
+* `pingRTT` {number} The number of milliseconds elapsed since the transmission
+ of a `PING` frame and the reception of its acknowledgment. Only present if
+ a `PING` frame has been sent on the `Http2Session`.
+* `streamAverageDuration` {number} The average duration (in milliseconds) for
+ all `Http2Stream` instances.
+* `streamCount` {number} The number of `Http2Stream` instances processed by
+ the `Http2Session`.
+* `type` {string} Either `'server'` or `'client'` to identify the type of
+ `Http2Session`.
+
+### Timerify ('function') Details
+
+When `performanceEntry.type` is equal to `'function'`, the
+`performanceEntry.details` property will be an {Array} listing
+the input arguments to the timed function.
+
 ## Class: `PerformanceNodeTiming`
 <!-- YAML
 added: v8.5.0
@@ -457,22 +569,23 @@ Disconnects the `PerformanceObserver` instance from all notifications.
 ### `performanceObserver.observe(options)`
 <!-- YAML
 added: v8.5.0
+changes:
+ - version: REPLACEME
+ pr-url: https://github.com/nodejs/node/pull/37136
+ description: Updated to conform to User Timing Level 3. The
+ buffered option has been removed.
 -->
 
 * `options` {Object}
+ * `type` {string} A single {PerformanceEntry} type. Must not be given
+ if `entryTypes` is already specified.
  * `entryTypes` {string[]} An array of strings identifying the types of
- `PerformanceEntry` instances the observer is interested in. If not
+ {PerformanceEntry} instances the observer is interested in. If not
  provided an error will be thrown.
- * `buffered` {boolean} If true, the notification callback will be
- called using `setImmediate()` and multiple `PerformanceEntry` instance
- notifications will be buffered internally. If `false`, notifications will
- be immediate and synchronous. **Default:** `false`.
-
-Subscribes the `PerformanceObserver` instance to notifications of new
-`PerformanceEntry` instances identified by `options.entryTypes`.
 
-When `options.buffered` is `false`, the `callback` will be invoked once for
-every `PerformanceEntry` instance:
+Subscribes the {PerformanceObserver} instance to notifications of new
+{PerformanceEntry} instances identified either by `options.entryTypes`
+or `options.type`:
 
 ```js
 const {
@@ -483,22 +596,7 @@ const {
 const obs = new PerformanceObserver((list, observer) => {
  // Called three times synchronously. `list` contains one item.
 });
-obs.observe({ entryTypes: ['mark'] });
-
-for (let n = 0; n < 3; n++)
- performance.mark(`test${n}`);
-```
-
-```js
-const {
- performance,
- PerformanceObserver
-} = require('perf_hooks');
-
-const obs = new PerformanceObserver((list, observer) => {
- // Called once. `list` contains three items.
-});
-obs.observe({ entryTypes: ['mark'], buffered: true });
+obs.observe({ type: 'mark' });
 
 for (let n = 0; n < 3; n++)
  performance.mark(`test${n}`);
@@ -549,7 +647,7 @@ const obs = new PerformanceObserver((perfObserverList, observer) => {
  */
  observer.disconnect();
 });
-obs.observe({ entryTypes: ['mark'], buffered: true });
+obs.observe({ type: 'mark' });
 
 performance.mark('test');
 performance.mark('meow');
@@ -603,7 +701,7 @@ const obs = new PerformanceObserver((perfObserverList, observer) => {
  console.log(perfObserverList.getEntriesByName('test', 'measure')); // []
  observer.disconnect();
 });
-obs.observe({ entryTypes: ['mark', 'measure'], buffered: true });
+obs.observe({ entryTypes: ['mark', 'measure'] });
 
 performance.mark('test');
 performance.mark('meow');
@@ -647,7 +745,7 @@ const obs = new PerformanceObserver((perfObserverList, observer) => {
  */
  observer.disconnect();
 });
-obs.observe({ entryTypes: ['mark'], buffered: true });
+obs.observe({ type: 'mark' });
 
 performance.mark('test');
 performance.mark('meow');

lib/_http_server.js

@@ -89,9 +89,7 @@ const {
  DTRACE_HTTP_SERVER_REQUEST,
  DTRACE_HTTP_SERVER_RESPONSE
 } = require('internal/dtrace');
-const { observerCounts, constants } = internalBinding('performance');
 const { setTimeout, clearTimeout } = require('timers');
-const { NODE_PERFORMANCE_ENTRY_TYPE_HTTP } = constants;
 
 const dc = require('diagnostics_channel');
 const onRequestStartChannel = dc.channel('http.server.request.start');
@@ -193,21 +191,16 @@ function ServerResponse(req) {
  this.shouldKeepAlive = false;
  }
 
- const httpObserverCount = observerCounts[NODE_PERFORMANCE_ENTRY_TYPE_HTTP];
- if (httpObserverCount > 0) {
- this[kServerResponseStatistics] = {
- startTime: process.hrtime()
- };
- }
+ this[kServerResponseStatistics] = {
+ startTime: process.hrtime()
+ };
 }
 ObjectSetPrototypeOf(ServerResponse.prototype, OutgoingMessage.prototype);
 ObjectSetPrototypeOf(ServerResponse, OutgoingMessage);
 
 ServerResponse.prototype._finish = function _finish() {
  DTRACE_HTTP_SERVER_RESPONSE(this.socket);
- if (this[kServerResponseStatistics] !== undefined) {
- emitStatistics(this[kServerResponseStatistics]);
- }
+ emitStatistics(this[kServerResponseStatistics]);
  FunctionPrototypeCall(OutgoingMessage.prototype._finish, this);
 };