Skip to content

Commit

Permalink
perf_hooks: complete overhaul of the implementation
Browse files Browse the repository at this point in the history
* 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: #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>
  • Loading branch information
jasnell committed Feb 22, 2021
1 parent 9f2efaa commit f3eb224
Show file tree
Hide file tree
Showing 38 changed files with 1,880 additions and 1,519 deletions.
31 changes: 31 additions & 0 deletions benchmark/perf_hooks/usertiming.js
Original file line number Diff line number Diff line change
@@ -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();
}
16 changes: 16 additions & 0 deletions doc/api/deprecations.md
Original file line number Diff line number Diff line change
Expand Up @@ -2748,6 +2748,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
Expand Down
10 changes: 10 additions & 0 deletions doc/api/errors.md
Original file line number Diff line number Diff line change
Expand Up @@ -1903,6 +1903,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`

Expand Down
168 changes: 133 additions & 35 deletions doc/api/perf_hooks.md
Original file line number Diff line number Diff line change
Expand Up @@ -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');
Expand Down Expand Up @@ -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
Expand All @@ -140,8 +151,15 @@ changes:
-->

* `name` {string}
* `startMark` {string} Optional.
* `endMark` {string} Optional.
* `startMarkOrOptions` {string|Object} Optional.
* `detail` {any} 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
Expand All @@ -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
Expand Down Expand Up @@ -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}
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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}
Expand Down Expand Up @@ -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}
Expand All @@ -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
Expand Down Expand Up @@ -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 {
Expand All @@ -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}`);
Expand Down Expand Up @@ -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');
Expand Down Expand Up @@ -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');
Expand Down Expand Up @@ -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');
Expand Down
15 changes: 4 additions & 11 deletions lib/_http_server.js
Original file line number Diff line number Diff line change
Expand Up @@ -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');
Expand Down Expand Up @@ -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);
};

Expand Down
Loading

0 comments on commit f3eb224

Please sign in to comment.