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`

Signed-off-by: James M Snell <[email protected]>
  • Loading branch information
jasnell committed Jan 30, 2021
1 parent 0a993e1 commit 74ef1c0
Show file tree
Hide file tree
Showing 37 changed files with 1,877 additions and 1,509 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 @@ -2726,6 +2726,22 @@ settings set when the Node.js binary was compiled. However, the property has
been mutable by user code making it impossible to rely on. The ability to
change the value has been deprecated and will be disabled in the future.

### DEP0XXX: Extension PerformanceEntry properties
<!-- YAML
changes:
- version: REPLACEME
pr-url: https://github.com/nodejs/node/pull/00000
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 @@ -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`

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/00000
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/00000
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` {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
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/00000
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/00000
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/00000
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/00000
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 @@ -88,9 +88,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 @@ -192,21 +190,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 74ef1c0

Please sign in to comment.