From f3eb224c83f96cff9231f17b1c0a36b762942f48 Mon Sep 17 00:00:00 2001 From: James M Snell Date: Thu, 28 Jan 2021 16:34:27 -0800 Subject: [PATCH] perf_hooks: complete overhaul of the implementation MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * 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: https://github.com/nodejs/node/pull/37136 Refs: https://github.com/nodejs/diagnostics/issues/464 Reviewed-By: Antoine du Hamel Reviewed-By: Matteo Collina Reviewed-By: Michaël Zasso --- benchmark/perf_hooks/usertiming.js | 31 + doc/api/deprecations.md | 16 + doc/api/errors.md | 10 + doc/api/perf_hooks.md | 168 +++- lib/_http_server.js | 15 +- lib/internal/errors.js | 3 + lib/internal/http.js | 27 +- lib/internal/perf/event_loop_delay.js | 55 ++ lib/internal/perf/event_loop_utilization.js | 33 + lib/internal/perf/nodetiming.js | 172 +++++ lib/internal/perf/observe.js | 352 +++++++++ lib/internal/perf/perf.js | 94 +++ lib/internal/perf/timerify.js | 103 +++ lib/internal/perf/usertiming.js | 153 ++++ lib/perf_hooks.js | 718 ++---------------- node.gyp | 7 + src/env-inl.h | 5 - src/env.h | 12 +- src/node_http2.cc | 161 ++-- src/node_http2.h | 106 +-- src/node_perf.cc | 328 ++------ src/node_perf.h | 156 ++-- src/node_perf_common.h | 7 +- src/node_util.cc | 7 + test/parallel/test-http-perf_hooks.js | 15 +- .../test-http2-pack-end-stream-flag.js | 32 +- test/parallel/test-http2-perf_hooks.js | 35 +- test/parallel/test-perf-hooks-usertiming.js | 180 +++++ .../test-performance-function-async.js | 40 + test/parallel/test-performance-gc.js | 4 +- test/parallel/test-performance-measure.js | 10 +- .../test-performanceobserver-asynccontext.js | 37 - test/parallel/test-performanceobserver.js | 91 +-- test/parallel/test-trace-events-api.js | 65 +- .../test-trace-events-dynamic-enable.js | 29 +- test/parallel/test-trace-events-perf.js | 84 -- test/sequential/test-perf-hooks.js | 36 - .../test-performance-eventloopdelay.js | 2 +- 38 files changed, 1880 insertions(+), 1519 deletions(-) create mode 100644 benchmark/perf_hooks/usertiming.js create mode 100644 lib/internal/perf/event_loop_delay.js create mode 100644 lib/internal/perf/event_loop_utilization.js create mode 100644 lib/internal/perf/nodetiming.js create mode 100644 lib/internal/perf/observe.js create mode 100644 lib/internal/perf/perf.js create mode 100644 lib/internal/perf/timerify.js create mode 100644 lib/internal/perf/usertiming.js create mode 100644 test/parallel/test-perf-hooks-usertiming.js create mode 100644 test/parallel/test-performance-function-async.js delete mode 100644 test/parallel/test-performanceobserver-asynccontext.js delete mode 100644 test/parallel/test-trace-events-perf.js diff --git a/benchmark/perf_hooks/usertiming.js b/benchmark/perf_hooks/usertiming.js new file mode 100644 index 00000000000000..ae797351ad78cc --- /dev/null +++ b/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(); +} diff --git a/doc/api/deprecations.md b/doc/api/deprecations.md index 09f05df5b44906..11b14015cfb0fb 100644 --- a/doc/api/deprecations.md +++ b/doc/api/deprecations.md @@ -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 + + +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 diff --git a/doc/api/errors.md b/doc/api/errors.md index 96e810d878653a..ca3de99de9e636 100644 --- a/doc/api/errors.md +++ b/doc/api/errors.md @@ -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. + +### `ERR_PERFORMANCE_INVALID_TIMESTAMP` + +An invalid timestamp value was provided for a performance mark or measure. + + +### `ERR_PERFORMANCE_MEASURE_INVALID_OPTIONS` + +Invalid options were provided for a performance measure. + ### `ERR_PROTO_ACCESS` diff --git a/doc/api/perf_hooks.md b/doc/api/perf_hooks.md index e7dc8c38ac27a2..596bc3025b36e8 100644 --- a/doc/api/perf_hooks.md +++ b/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,12 +115,20 @@ 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]])` * `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 @@ -128,10 +136,13 @@ Creates a new `PerformanceMark` entry in the Performance Timeline. A `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]])` * `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 @@ -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)` * `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` +### `performanceEntry.details` + + +* {any} + +Additional detail specific to the `entryType`. + ### `performanceEntry.duration` * {number} @@ -294,6 +335,11 @@ The name of the performance entry. ### `performanceEntry.kind` * {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` * `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'); diff --git a/lib/_http_server.js b/lib/_http_server.js index d13b2cbbd38fbb..23a6906dab5004 100644 --- a/lib/_http_server.js +++ b/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); }; diff --git a/lib/internal/errors.js b/lib/internal/errors.js index 0cd4d9912b5d04..050193002a9559 100644 --- a/lib/internal/errors.js +++ b/lib/internal/errors.js @@ -1343,6 +1343,9 @@ E('ERR_PACKAGE_PATH_NOT_EXPORTED', (pkgPath, subpath, base = undefined) => { return `Package subpath '${subpath}' is not defined by "exports" in ${ pkgPath}package.json${base ? ` imported from ${base}` : ''}`; }, Error); +E('ERR_PERFORMANCE_INVALID_TIMESTAMP', + '%d is not a valid timestamp', TypeError); +E('ERR_PERFORMANCE_MEASURE_INVALID_OPTIONS', '%s', TypeError); E('ERR_REQUIRE_ESM', (filename, parentPath = null, packageJsonPath = null) => { let msg = `Must use import to load ES Module: ${filename}`; diff --git a/lib/internal/http.js b/lib/internal/http.js index b17687d4d81624..f87dc8aa6cd01b 100644 --- a/lib/internal/http.js +++ b/lib/internal/http.js @@ -8,7 +8,9 @@ const { } = primordials; const { setUnrefTimeout } = require('internal/timers'); -const { PerformanceEntry, notify } = internalBinding('performance'); + +const { InternalPerformanceEntry } = require('internal/perf/perf'); +const { enqueue } = require('internal/perf/observe'); let utcCache; @@ -27,20 +29,17 @@ function resetCache() { utcCache = undefined; } -class HttpRequestTiming extends PerformanceEntry { - constructor(statistics) { - super(); - this.name = 'HttpRequest'; - this.entryType = 'http'; - const startTime = statistics.startTime; - const diff = process.hrtime(startTime); - this.duration = diff[0] * 1000 + diff[1] / 1e6; - this.startTime = startTime[0] * 1000 + startTime[1] / 1e6; - } -} - function emitStatistics(statistics) { - notify('http', new HttpRequestTiming(statistics)); + const startTime = statistics.startTime; + const diff = process.hrtime(startTime); + const entry = new InternalPerformanceEntry( + 'HttpRequest', + 'http', + startTime[0] * 1000 + startTime[1] / 1e6, + diff[0] * 1000 + diff[1] / 1e6, + undefined, + ); + enqueue(entry); } module.exports = { diff --git a/lib/internal/perf/event_loop_delay.js b/lib/internal/perf/event_loop_delay.js new file mode 100644 index 00000000000000..f90bb9e4de7d58 --- /dev/null +++ b/lib/internal/perf/event_loop_delay.js @@ -0,0 +1,55 @@ +'use strict'; +const { + Symbol, + TypeError, +} = primordials; + +const { + ELDHistogram: _ELDHistogram, +} = internalBinding('performance'); + +const { + validateInteger, + validateObject, +} = require('internal/validators'); + +const { + Histogram, + kHandle, +} = require('internal/histogram'); + +const kEnabled = Symbol('kEnabled'); + +class ELDHistogram extends Histogram { + constructor(i) { + if (!(i instanceof _ELDHistogram)) { + // eslint-disable-next-line no-restricted-syntax + throw new TypeError('illegal constructor'); + } + super(i); + this[kEnabled] = false; + } + enable() { + if (this[kEnabled]) return false; + this[kEnabled] = true; + this[kHandle].start(); + return true; + } + disable() { + if (!this[kEnabled]) return false; + this[kEnabled] = false; + this[kHandle].stop(); + return true; + } +} + +function monitorEventLoopDelay(options = {}) { + validateObject(options, 'options'); + + const { resolution = 10 } = options; + validateInteger(resolution, 'options.resolution', 1); + + return new ELDHistogram(new _ELDHistogram(resolution)); +} + +module.exports = monitorEventLoopDelay; diff --git a/lib/internal/perf/event_loop_utilization.js b/lib/internal/perf/event_loop_utilization.js new file mode 100644 index 00000000000000..398c4ad4e42f58 --- /dev/null +++ b/lib/internal/perf/event_loop_utilization.js @@ -0,0 +1,33 @@ +'use strict'; + +const nodeTiming = require('internal/perf/nodetiming'); + +const { now } = require('internal/perf/perf'); + +function eventLoopUtilization(util1, util2) { + const ls = nodeTiming.loopStart; + + if (ls <= 0) { + return { idle: 0, active: 0, utilization: 0 }; + } + + if (util2) { + const idle = util1.idle - util2.idle; + const active = util1.active - util2.active; + return { idle, active, utilization: active / (idle + active) }; + } + + const idle = nodeTiming.idleTime; + const active = now() - ls - idle; + + if (!util1) { + return { idle, active, utilization: active / (idle + active) }; + } + + const idle_delta = idle - util1.idle; + const active_delta = active - util1.active; + const utilization = active_delta / (idle_delta + active_delta); + return { idle: idle_delta, active: active_delta, utilization }; +} + +module.exports = eventLoopUtilization; diff --git a/lib/internal/perf/nodetiming.js b/lib/internal/perf/nodetiming.js new file mode 100644 index 00000000000000..5ff6dd38cd86d3 --- /dev/null +++ b/lib/internal/perf/nodetiming.js @@ -0,0 +1,172 @@ +'use strict'; + +const { + ObjectDefineProperties, + ObjectSetPrototypeOf, + SafeArrayIterator, + SafeSet, +} = primordials; + +const { + PerformanceEntry, + kReadOnlyAttributes, + now, +} = require('internal/perf/perf'); + +const { + customInspectSymbol: kInspect, +} = require('internal/util'); + +const { inspect } = require('util'); + +const { + constants: { + NODE_PERFORMANCE_MILESTONE_NODE_START, + NODE_PERFORMANCE_MILESTONE_V8_START, + NODE_PERFORMANCE_MILESTONE_LOOP_START, + NODE_PERFORMANCE_MILESTONE_LOOP_EXIT, + NODE_PERFORMANCE_MILESTONE_BOOTSTRAP_COMPLETE, + NODE_PERFORMANCE_MILESTONE_ENVIRONMENT + }, + loopIdleTime, + milestones, + timeOrigin, +} = internalBinding('performance'); + +function getMilestoneTimestamp(milestoneIdx) { + const ns = milestones[milestoneIdx]; + if (ns === -1) + return ns; + return ns / 1e6 - timeOrigin; +} + +const readOnlyAttributes = new SafeSet(new SafeArrayIterator([ + 'nodeStart', + 'v8Start', + 'environment', + 'loopStart', + 'loopExit', + 'bootstrapComplete', +])); + +class PerformanceNodeTiming { + constructor() { + ObjectDefineProperties(this, { + name: { + enumerable: true, + configurable: true, + value: 'node' + }, + + entryType: { + enumerable: true, + configurable: true, + value: 'node' + }, + + startTime: { + enumerable: true, + configurable: true, + value: 0 + }, + + duration: { + enumerable: true, + configurable: true, + get: now + }, + + nodeStart: { + enumerable: true, + configurable: true, + get() { + return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_NODE_START); + } + }, + + v8Start: { + enumerable: true, + configurable: true, + get() { + return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_V8_START); + } + }, + + environment: { + enumerable: true, + configurable: true, + get() { + return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_ENVIRONMENT); + } + }, + + loopStart: { + enumerable: true, + configurable: true, + get() { + return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_LOOP_START); + } + }, + + loopExit: { + enumerable: true, + configurable: true, + get() { + return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_LOOP_EXIT); + } + }, + + bootstrapComplete: { + enumerable: true, + configurable: true, + get() { + return getMilestoneTimestamp( + NODE_PERFORMANCE_MILESTONE_BOOTSTRAP_COMPLETE); + } + }, + + idleTime: { + enumerable: true, + configurable: true, + get: loopIdleTime, + } + }); + } + + [kInspect](depth, options) { + if (depth < 0) return this; + + const opts = { + ...options, + depth: options.depth == null ? null : options.depth - 1 + }; + + return `PerformanceNodeTiming ${inspect(this.toJSON(), opts)}`; + } + + toJSON() { + return { + name: 'node', + entryType: 'node', + startTime: this.startTime, + duration: this.duration, + nodeStart: this.nodeStart, + v8Start: this.v8Start, + bootstrapComplete: this.bootstrapComplete, + environment: this.environment, + loopStart: this.loopStart, + loopExit: this.loopExit, + idleTime: this.idleTime, + }; + } + + static get [kReadOnlyAttributes]() { + return readOnlyAttributes; + } +} + +ObjectSetPrototypeOf( + PerformanceNodeTiming.prototype, + PerformanceEntry.prototype); + +module.exports = new PerformanceNodeTiming(); diff --git a/lib/internal/perf/observe.js b/lib/internal/perf/observe.js new file mode 100644 index 00000000000000..a50726c981bb75 --- /dev/null +++ b/lib/internal/perf/observe.js @@ -0,0 +1,352 @@ +'use strict'; + +const { + ArrayFrom, + ArrayIsArray, + ArrayPrototypeFilter, + ArrayPrototypeIncludes, + ArrayPrototypePush, + ArrayPrototypeSlice, + ArrayPrototypeSort, + ObjectDefineProperties, + ObjectFreeze, + ObjectKeys, + SafeMap, + SafeSet, + Symbol, +} = primordials; + +const { + constants: { + NODE_PERFORMANCE_ENTRY_TYPE_GC, + NODE_PERFORMANCE_ENTRY_TYPE_FUNCTION, + NODE_PERFORMANCE_ENTRY_TYPE_HTTP2, + NODE_PERFORMANCE_ENTRY_TYPE_HTTP, + }, + installGarbageCollectionTracking, + observerCounts, + removeGarbageCollectionTracking, + setupObservers, +} = internalBinding('performance'); + +const { + InternalPerformanceEntry, + isPerformanceEntry, +} = require('internal/perf/perf'); + +const { + codes: { + ERR_INVALID_ARG_VALUE, + ERR_INVALID_ARG_TYPE, + ERR_MISSING_ARGS, + }, +} = require('internal/errors'); + +const { + validateCallback, + validateObject, +} = require('internal/validators'); + +const { + customInspectSymbol: kInspect, + deprecate, +} = require('internal/util'); + +const { + setImmediate, +} = require('timers'); + +const { inspect } = require('util'); + +const kBuffer = Symbol('kBuffer'); +const kCallback = Symbol('kCallback'); +const kDispatch = Symbol('kDispatch'); +const kEntryTypes = Symbol('kEntryTypes'); +const kMaybeBuffer = Symbol('kMaybeBuffer'); +const kDeprecatedFields = Symbol('kDeprecatedFields'); +const kType = Symbol('kType'); + +const kDeprecationMessage = + 'Custom PerformanceEntry accessors are deprecated. ' + + 'Please use the detail property.'; + +const kTypeSingle = 0; +const kTypeMultiple = 1; + +const kSupportedEntryTypes = ObjectFreeze([ + 'function', + 'gc', + 'http', + 'http2', + 'mark', + 'measure', +]); + +const kObservers = new SafeSet(); +const kPending = new SafeSet(); +let isPending = false; + +function queuePending() { + if (isPending) return; + isPending = true; + setImmediate(() => { + isPending = false; + for (const pending of kPending) + pending[kDispatch](); + kPending.clear(); + }); +} + +function maybeDecrementObserverCounts(entryTypes) { + for (const type of entryTypes) { + let observerType; + switch (type) { + case 'gc': + observerType = NODE_PERFORMANCE_ENTRY_TYPE_GC; + break; + case 'function': + observerType = NODE_PERFORMANCE_ENTRY_TYPE_FUNCTION; + break; + case 'http2': + observerType = NODE_PERFORMANCE_ENTRY_TYPE_HTTP2; + break; + case 'http': + observerType = NODE_PERFORMANCE_ENTRY_TYPE_HTTP; + break; + } + if (observerType !== undefined) { + observerCounts[observerType]--; + + if (observerType === NODE_PERFORMANCE_ENTRY_TYPE_GC && + observerCounts[observerType] === 0) { + removeGarbageCollectionTracking(); + } + } + } +} + +function maybeIncrementObserverCount(type) { + let observerType; + switch (type) { + case 'gc': + observerType = NODE_PERFORMANCE_ENTRY_TYPE_GC; + break; + case 'function': + observerType = NODE_PERFORMANCE_ENTRY_TYPE_FUNCTION; + break; + case 'http2': + observerType = NODE_PERFORMANCE_ENTRY_TYPE_HTTP2; + break; + case 'http': + observerType = NODE_PERFORMANCE_ENTRY_TYPE_HTTP; + break; + } + if (observerType !== undefined) { + observerCounts[observerType]++; + + if (observerType === NODE_PERFORMANCE_ENTRY_TYPE_GC) + installGarbageCollectionTracking(); + } +} + +class PerformanceObserverEntryList { + constructor(entries) { + this[kBuffer] = ArrayPrototypeSort(entries, (first, second) => { + if (first.startTime < second.startTime) return -1; + if (first.startTime > second.startTime) return 1; + return 0; + }); + } + + getEntries() { + return ArrayPrototypeSlice(this[kBuffer]); + } + + getEntriesByType(type) { + type = `${type}`; + return ArrayPrototypeFilter( + this[kBuffer], + (entry) => entry.entryType === type); + } + + getEntriesByName(name) { + name = `${name}`; + return ArrayPrototypeFilter( + this[kBuffer], + (entry) => entry.name === name); + } + + [kInspect](depth, options) { + if (depth < 0) return this; + + const opts = { + ...options, + depth: options.depth == null ? null : options.depth - 1 + }; + + return `PerformanceObserverEntryList ${inspect(this[kBuffer], opts)}`; + } +} + +class PerformanceObserver { + [kBuffer] = []; + [kEntryTypes] = new SafeSet(); + [kType] = undefined; + + constructor(callback) { + validateCallback(callback); + this[kCallback] = callback; + } + + observe(options = {}) { + validateObject(options, 'options'); + const { + entryTypes, + type, + } = { ...options }; + if (entryTypes === undefined && type === undefined) + throw new ERR_MISSING_ARGS('options.entryTypes', 'options.type'); + + switch (this[kType]) { + case undefined: + if (entryTypes !== undefined) this[kType] = kTypeMultiple; + if (type !== undefined) this[kType] = kTypeSingle; + break; + case kTypeSingle: + if (entryTypes !== undefined) + throw new ERR_INVALID_ARG_VALUE('options.entryTypes', entryTypes); + break; + case kTypeMultiple: + if (type !== undefined) + throw new ERR_INVALID_ARG_VALUE('options.type', type); + break; + } + + if (this[kType] === kTypeMultiple) { + if (!ArrayIsArray(entryTypes)) { + throw new ERR_INVALID_ARG_TYPE( + 'options.entryTypes', + 'string[]', + entryTypes); + } + maybeDecrementObserverCounts(this[kEntryTypes]); + this[kEntryTypes].clear(); + for (let n = 0; n < entryTypes.length; n++) { + if (ArrayPrototypeIncludes(kSupportedEntryTypes, entryTypes[n])) { + this[kEntryTypes].add(entryTypes[n]); + maybeIncrementObserverCount(entryTypes[n]); + } + } + } else { + if (!ArrayPrototypeIncludes(kSupportedEntryTypes, type)) + return; + this[kEntryTypes].add(type); + maybeIncrementObserverCount(type); + } + + if (this[kEntryTypes].size) + kObservers.add(this); + else + this.disconnect(); + } + + disconnect() { + maybeDecrementObserverCounts(this[kEntryTypes]); + kObservers.delete(this); + kPending.delete(this); + this[kBuffer] = []; + this[kEntryTypes].clear(); + this[kType] = undefined; + } + + takeRecords() { + const list = this[kBuffer]; + this[kBuffer] = []; + return new PerformanceObserverEntryList(list); + } + + static get supportedEntryTypes() { + return kSupportedEntryTypes; + } + + [kMaybeBuffer](entry) { + if (!this[kEntryTypes].has(entry.entryType)) + return; + ArrayPrototypePush(this[kBuffer], entry); + kPending.add(this); + if (kPending.size) + queuePending(); + } + + [kDispatch]() { this[kCallback](this.takeRecords(), this); } + + [kInspect](depth, options) { + if (depth < 0) return this; + + const opts = { + ...options, + depth: options.depth == null ? null : options.depth - 1 + }; + + return `PerformanceObserver ${inspect({ + connected: kObservers.has(this), + pending: kPending.has(this), + entryTypes: ArrayFrom(this[kEntryTypes]), + buffer: this[kBuffer], + }, opts)}`; + } +} + +function enqueue(entry) { + if (!isPerformanceEntry(entry)) + throw new ERR_INVALID_ARG_TYPE('entry', 'PerformanceEntry', entry); + + for (const obs of kObservers) { + obs[kMaybeBuffer](entry); + } +} + +function observerCallback(name, type, startTime, duration, details) { + const entry = + new InternalPerformanceEntry( + name, + type, + startTime, + duration, + details); + + if (details !== undefined) { + // GC, HTTP2, and HTTP PerformanceEntry used additional + // properties directly off the entry. Those have been + // moved into the details property. The existing accessors + // are still included but are deprecated. + entry[kDeprecatedFields] = new SafeMap(); + + const detailKeys = ObjectKeys(details); + const props = {}; + for (let n = 0; n < detailKeys.length; n++) { + const key = detailKeys[n]; + entry[kDeprecatedFields].set(key, details[key]); + props[key] = { + configurable: true, + enumerable: true, + get: deprecate(() => { + return entry[kDeprecatedFields].get(key); + }, kDeprecationMessage, 'DEP0XXX'), + set: deprecate((value) => { + entry[kDeprecatedFields].set(key, value); + }, kDeprecationMessage, 'DEP0XXX'), + }; + } + ObjectDefineProperties(entry, props); + } + + enqueue(entry); +} + +setupObservers(observerCallback); + +module.exports = { + PerformanceObserver, + enqueue, +}; diff --git a/lib/internal/perf/perf.js b/lib/internal/perf/perf.js new file mode 100644 index 00000000000000..d049d3c68fff04 --- /dev/null +++ b/lib/internal/perf/perf.js @@ -0,0 +1,94 @@ +'use strict'; + +const { + ObjectSetPrototypeOf, + Symbol, + TypeError, +} = primordials; + +const { + timeOrigin, +} = internalBinding('performance'); + +const { + customInspectSymbol: kInspect, +} = require('internal/util'); + +const { inspect } = require('util'); + +const kName = Symbol('kName'); +const kType = Symbol('kType'); +const kStart = Symbol('kStart'); +const kDuration = Symbol('kDuration'); +const kDetail = Symbol('kDetail'); +const kReadOnlyAttributes = Symbol('kReadOnlyAttributes'); + +function now() { + const hr = process.hrtime(); + return (hr[0] * 1000 + hr[1] / 1e6) - timeOrigin; +} + +function isPerformanceEntry(obj) { + return obj?.[kName] !== undefined; +} + +class PerformanceEntry { + constructor() { + // eslint-disable-next-line no-restricted-syntax + throw new TypeError('illegal constructor'); + } + + get name() { return this[kName]; } + + get entryType() { return this[kType]; } + + get startTime() { return this[kStart]; } + + get duration() { return this[kDuration]; } + + get detail() { return this[kDetail]; } + + [kInspect](depth, options) { + if (depth < 0) return this; + + const opts = { + ...options, + depth: options.depth == null ? null : options.depth - 1 + }; + + return `${this.constructor.name} ${inspect(this.toJSON(), opts)}`; + } + + toJSON() { + return { + name: this.name, + entryType: this.entryType, + startTime: this.startTime, + duration: this.duration, + detail: this.detail, + }; + } +} + +class InternalPerformanceEntry { + constructor(name, type, start, duration, detail) { + this[kName] = name; + this[kType] = type; + this[kStart] = start; + this[kDuration] = duration; + this[kDetail] = detail; + } +} + +InternalPerformanceEntry.prototype.constructor = PerformanceEntry; +ObjectSetPrototypeOf( + InternalPerformanceEntry.prototype, + PerformanceEntry.prototype); + +module.exports = { + InternalPerformanceEntry, + PerformanceEntry, + kReadOnlyAttributes, + isPerformanceEntry, + now, +}; diff --git a/lib/internal/perf/timerify.js b/lib/internal/perf/timerify.js new file mode 100644 index 00000000000000..e79b870f2a2911 --- /dev/null +++ b/lib/internal/perf/timerify.js @@ -0,0 +1,103 @@ +'use strict'; + +const { + FunctionPrototypeBind, + ObjectDefineProperties, + ReflectApply, + ReflectConstruct, + Symbol, +} = primordials; + +const { + InternalPerformanceEntry, + now, +} = require('internal/perf/perf'); + +const { + isConstructor, +} = internalBinding('util'); + +const { + codes: { + ERR_INVALID_ARG_TYPE, + }, +} = require('internal/errors'); + +const { + enqueue, +} = require('internal/perf/observe'); + +const kTimerified = Symbol('kTimerified'); + +function processComplete(name, start, args) { + const duration = now() - start; + const entry = + new InternalPerformanceEntry( + name, + 'function', + start, + duration, + args); + + for (let n = 0; n < args.length; n++) + entry[n] = args[n]; + + enqueue(entry); +} + +function timerify(fn) { + if (typeof fn !== 'function') + throw new ERR_INVALID_ARG_TYPE('fn', 'function', fn); + + if (fn[kTimerified]) return fn[kTimerified]; + + const constructor = isConstructor(fn); + + function timerified(...args) { + const start = now(); + const result = constructor ? + ReflectConstruct(fn, args, fn) : + ReflectApply(fn, this, args); + if (!constructor && typeof result?.finally === 'function') { + return result.finally( + FunctionPrototypeBind( + processComplete, + result, + fn.name, + start, + args)); + } + processComplete(fn.name, start, args); + return result; + } + + ObjectDefineProperties(timerified, { + [kTimerified]: { + configurable: false, + enumerable: false, + value: timerified, + }, + length: { + configurable: false, + enumerable: true, + value: fn.length, + }, + name: { + configurable: false, + enumerable: true, + value: `timerified ${fn.name}` + } + }); + + ObjectDefineProperties(fn, { + [kTimerified]: { + configurable: false, + enumerable: false, + value: timerified, + } + }); + + return timerified; +} + +module.exports = timerify; diff --git a/lib/internal/perf/usertiming.js b/lib/internal/perf/usertiming.js new file mode 100644 index 00000000000000..6672a3f4dfdeb0 --- /dev/null +++ b/lib/internal/perf/usertiming.js @@ -0,0 +1,153 @@ +'use strict'; + +const { + ObjectKeys, + SafeMap, +} = primordials; + +const { + InternalPerformanceEntry, + kReadOnlyAttributes, + now, +} = require('internal/perf/perf'); + +const { enqueue } = require('internal/perf/observe'); + +const nodeTiming = require('internal/perf/nodetiming'); + +const { + validateNumber, + validateObject, + validateString, +} = require('internal/validators'); + +const { + codes: { + ERR_INVALID_ARG_VALUE, + ERR_INVALID_PERFORMANCE_MARK, + ERR_PERFORMANCE_INVALID_TIMESTAMP, + ERR_PERFORMANCE_MEASURE_INVALID_OPTIONS, + }, +} = require('internal/errors'); + +const marks = new SafeMap(); +const nodeTimingReadOnlyAttributes = + nodeTiming.constructor[kReadOnlyAttributes]; + +function getMark(name) { + if (name === undefined) return; + if (typeof name === 'number') { + if (name < 0) + throw new ERR_PERFORMANCE_INVALID_TIMESTAMP(name); + return name; + } + name = `${name}`; + if (nodeTimingReadOnlyAttributes.has(name)) + return nodeTiming[name]; + const ts = marks.get(name); + if (ts === undefined) + throw new ERR_INVALID_PERFORMANCE_MARK(name); + return ts; +} + +class PerformanceMark extends InternalPerformanceEntry { + constructor(name, options = {}) { + name = `${name}`; + if (nodeTimingReadOnlyAttributes.has(name)) + throw new ERR_INVALID_ARG_VALUE('name', name); + validateObject(options, 'options'); + const { + detail, + startTime = now(), + } = options; + validateNumber(startTime, 'startTime'); + if (startTime < 0) + throw new ERR_PERFORMANCE_INVALID_TIMESTAMP(startTime); + marks.set(name, startTime); + super(name, 'mark', startTime, 0, detail); + enqueue(this); + } +} + +class PerformanceMeasure extends InternalPerformanceEntry { + constructor(name, start, duration, detail) { + super(name, 'measure', start, duration, detail); + enqueue(this); + } +} + +function mark(name, options = {}) { + return new PerformanceMark(name, options); +} + +function calculateStartDuration(startOrMeasureOptions, endMark) { + startOrMeasureOptions ??= 0; + let detail; + let start; + let end; + let duration; + if (typeof startOrMeasureOptions === 'object' && + ObjectKeys(startOrMeasureOptions).length) { + ({ + start, + end, + duration, + detail, + } = startOrMeasureOptions); + if (endMark !== undefined) { + throw new ERR_PERFORMANCE_MEASURE_INVALID_OPTIONS( + 'endMark must not be specified'); + } + if (start === undefined && end === undefined) { + throw new ERR_PERFORMANCE_MEASURE_INVALID_OPTIONS( + 'One of options.start or options.end is required'); + } + if (start !== undefined && end !== undefined && duration !== undefined) { + throw new ERR_PERFORMANCE_MEASURE_INVALID_OPTIONS( + 'Must not have options.start, options.end, and ' + + 'options.duration specified'); + } + start = getMark(start); + duration = getMark(duration); + } else { + start = getMark(startOrMeasureOptions); + } + + end = getMark(endMark || end) ?? + ((start !== undefined && duration !== undefined) ? + start + duration : now()); + + start ??= (duration !== undefined) ? end - duration : 0; + + duration ??= end - start; + + return { start, duration, detail }; +} + +function measure(name, startOrMeasureOptions, endMark) { + validateString(name, 'name'); + const { + start, + duration, + detail + } = calculateStartDuration(startOrMeasureOptions, endMark); + return new PerformanceMeasure(name, start, duration, detail); +} + +function clearMarks(name) { + if (name !== undefined) { + name = `${name}`; + if (nodeTimingReadOnlyAttributes.has(name)) + throw new ERR_INVALID_ARG_VALUE('name', name); + marks.delete(name); + return; + } + marks.clear(); +} + +module.exports = { + PerformanceMark, + clearMarks, + mark, + measure, +}; diff --git a/lib/perf_hooks.js b/lib/perf_hooks.js index 6a759bbbf4e2d6..1c183f1a1f2865 100644 --- a/lib/perf_hooks.js +++ b/lib/perf_hooks.js @@ -1,678 +1,116 @@ 'use strict'; const { - ArrayIsArray, - ArrayPrototypeFilter, - ArrayPrototypeForEach, - ArrayPrototypeIncludes, - ArrayPrototypeMap, - ArrayPrototypePush, - ArrayPrototypeSplice, - ArrayPrototypeUnshift, - Boolean, - NumberIsSafeInteger, ObjectDefineProperties, ObjectDefineProperty, - ObjectKeys, - SafeSet, - Symbol, + ObjectSetPrototypeOf, TypeError, } = primordials; const { - ELDHistogram: _ELDHistogram, - PerformanceEntry, - mark: _mark, - clearMark: _clearMark, - measure: _measure, - milestones, - observerCounts, - setupObservers, - timeOrigin, timeOriginTimestamp, - timerify, constants, - installGarbageCollectionTracking, - removeGarbageCollectionTracking, - loopIdleTime, } = internalBinding('performance'); const { - NODE_PERFORMANCE_ENTRY_TYPE_NODE, - NODE_PERFORMANCE_ENTRY_TYPE_MARK, - NODE_PERFORMANCE_ENTRY_TYPE_MEASURE, - NODE_PERFORMANCE_ENTRY_TYPE_GC, - NODE_PERFORMANCE_ENTRY_TYPE_FUNCTION, - NODE_PERFORMANCE_ENTRY_TYPE_HTTP2, - NODE_PERFORMANCE_ENTRY_TYPE_HTTP, - - NODE_PERFORMANCE_MILESTONE_NODE_START, - NODE_PERFORMANCE_MILESTONE_V8_START, - NODE_PERFORMANCE_MILESTONE_LOOP_START, - NODE_PERFORMANCE_MILESTONE_LOOP_EXIT, - NODE_PERFORMANCE_MILESTONE_BOOTSTRAP_COMPLETE, - NODE_PERFORMANCE_MILESTONE_ENVIRONMENT -} = constants; - -const L = require('internal/linkedlist'); -const kInspect = require('internal/util').customInspectSymbol; + PerformanceEntry, + now, +} = require('internal/perf/perf'); +const { PerformanceObserver } = require('internal/perf/observe'); const { - ERR_INVALID_ARG_TYPE, - ERR_INVALID_ARG_VALUE, - ERR_VALID_PERFORMANCE_ENTRY_TYPE, - ERR_INVALID_PERFORMANCE_MARK -} = require('internal/errors').codes; + PerformanceMark, + mark, + measure, + clearMarks, +} = require('internal/perf/usertiming'); const { - Histogram, - createHistogram, - kHandle, + createHistogram } = require('internal/histogram'); -const { - validateCallback, - validateFunction, - validateObject, -} = require('internal/validators'); - -const { setImmediate } = require('timers'); -const kCallback = Symbol('callback'); -const kTypes = Symbol('types'); -const kEntries = Symbol('entries'); -const kBuffer = Symbol('buffer'); -const kBuffering = Symbol('buffering'); -const kQueued = Symbol('queued'); -const kTimerified = Symbol('timerified'); -const kInsertEntry = Symbol('insert-entry'); -const kGetEntries = Symbol('get-entries'); -const kIndex = Symbol('index'); -const kMarks = Symbol('marks'); -const kEnabled = Symbol('kEnabled'); - -const observers = {}; -const observerableTypes = [ - 'node', - 'mark', - 'measure', - 'gc', - 'function', - 'http2', - 'http', -]; - -const IDX_STREAM_STATS_ID = 0; -const IDX_STREAM_STATS_TIMETOFIRSTBYTE = 1; -const IDX_STREAM_STATS_TIMETOFIRSTHEADER = 2; -const IDX_STREAM_STATS_TIMETOFIRSTBYTESENT = 3; -const IDX_STREAM_STATS_SENTBYTES = 4; -const IDX_STREAM_STATS_RECEIVEDBYTES = 5; - -const IDX_SESSION_STATS_TYPE = 0; -const IDX_SESSION_STATS_PINGRTT = 1; -const IDX_SESSION_STATS_FRAMESRECEIVED = 2; -const IDX_SESSION_STATS_FRAMESSENT = 3; -const IDX_SESSION_STATS_STREAMCOUNT = 4; -const IDX_SESSION_STATS_STREAMAVERAGEDURATION = 5; -const IDX_SESSION_STATS_DATA_SENT = 6; -const IDX_SESSION_STATS_DATA_RECEIVED = 7; -const IDX_SESSION_STATS_MAX_CONCURRENT_STREAMS = 8; - -let http2; -let sessionStats; -let streamStats; - -function collectHttp2Stats(entry) { - if (http2 === undefined) http2 = internalBinding('http2'); - switch (entry.name) { - case 'Http2Stream': - if (streamStats === undefined) - streamStats = http2.streamStats; - entry.id = - streamStats[IDX_STREAM_STATS_ID] >>> 0; - entry.timeToFirstByte = - streamStats[IDX_STREAM_STATS_TIMETOFIRSTBYTE]; - entry.timeToFirstHeader = - streamStats[IDX_STREAM_STATS_TIMETOFIRSTHEADER]; - entry.timeToFirstByteSent = - streamStats[IDX_STREAM_STATS_TIMETOFIRSTBYTESENT]; - entry.bytesWritten = - streamStats[IDX_STREAM_STATS_SENTBYTES]; - entry.bytesRead = - streamStats[IDX_STREAM_STATS_RECEIVEDBYTES]; - break; - case 'Http2Session': - if (sessionStats === undefined) - sessionStats = http2.sessionStats; - entry.type = - sessionStats[IDX_SESSION_STATS_TYPE] >>> 0 === 0 ? 'server' : 'client'; - entry.pingRTT = - sessionStats[IDX_SESSION_STATS_PINGRTT]; - entry.framesReceived = - sessionStats[IDX_SESSION_STATS_FRAMESRECEIVED]; - entry.framesSent = - sessionStats[IDX_SESSION_STATS_FRAMESSENT]; - entry.streamCount = - sessionStats[IDX_SESSION_STATS_STREAMCOUNT]; - entry.streamAverageDuration = - sessionStats[IDX_SESSION_STATS_STREAMAVERAGEDURATION]; - entry.bytesWritten = - sessionStats[IDX_SESSION_STATS_DATA_SENT]; - entry.bytesRead = - sessionStats[IDX_SESSION_STATS_DATA_RECEIVED]; - entry.maxConcurrentStreams = - sessionStats[IDX_SESSION_STATS_MAX_CONCURRENT_STREAMS]; - break; - } -} - -function now() { - const hr = process.hrtime(); - return hr[0] * 1000 + hr[1] / 1e6; -} - -function getMilestoneTimestamp(milestoneIdx) { - const ns = milestones[milestoneIdx]; - if (ns === -1) - return ns; - return ns / 1e6 - timeOrigin; -} - -class PerformanceNodeTiming extends PerformanceEntry { - constructor() { - super(); - - ObjectDefineProperties(this, { - name: { - enumerable: true, - configurable: true, - value: 'node' - }, - - entryType: { - enumerable: true, - configurable: true, - value: 'node' - }, - - startTime: { - enumerable: true, - configurable: true, - value: 0 - }, - - duration: { - enumerable: true, - configurable: true, - get() { - return now() - timeOrigin; - } - }, - - nodeStart: { - enumerable: true, - configurable: true, - get() { - return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_NODE_START); - } - }, - - v8Start: { - enumerable: true, - configurable: true, - get() { - return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_V8_START); - } - }, - - environment: { - enumerable: true, - configurable: true, - get() { - return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_ENVIRONMENT); - } - }, - - loopStart: { - enumerable: true, - configurable: true, - get() { - return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_LOOP_START); - } - }, - - loopExit: { - enumerable: true, - configurable: true, - get() { - return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_LOOP_EXIT); - } - }, - - bootstrapComplete: { - enumerable: true, - configurable: true, - get() { - return getMilestoneTimestamp( - NODE_PERFORMANCE_MILESTONE_BOOTSTRAP_COMPLETE); - } - }, - - idleTime: { - enumerable: true, - configurable: true, - get() { - return loopIdleTime(); - } - } - }); - } - [kInspect]() { - return { - name: 'node', - entryType: 'node', - startTime: this.startTime, - duration: this.duration, - nodeStart: this.nodeStart, - v8Start: this.v8Start, - bootstrapComplete: this.bootstrapComplete, - environment: this.environment, - loopStart: this.loopStart, - loopExit: this.loopExit - }; - } -} - -const nodeTiming = new PerformanceNodeTiming(); - -// Maintains a list of entries as a linked list stored in insertion order. -class PerformanceObserverEntryList { - constructor() { - ObjectDefineProperties(this, { - [kEntries]: { - writable: true, - enumerable: false, - value: {} - } - }); - L.init(this[kEntries]); - } - - [kInsertEntry](entry) { - const item = { entry }; - L.append(this[kEntries], item); - } - - [kGetEntries](name, type) { - const ret = []; - const list = this[kEntries]; - if (!L.isEmpty(list)) { - let item = L.peek(list); - while (item && item !== list) { - const entry = item.entry; - if ((name && entry.name !== name) || - (type && entry.entryType !== type)) { - item = item._idlePrev; - continue; - } - sortedInsert(ret, entry); - item = item._idlePrev; - } - } - return ret; - } - - // While the items are stored in insertion order, getEntries() is - // required to return items sorted by startTime. - getEntries() { - return this[kGetEntries](); - } - - getEntriesByType(type) { - return this[kGetEntries](undefined, `${type}`); - } - - getEntriesByName(name, type) { - return this[kGetEntries](`${name}`, type !== undefined ? `${type}` : type); - } -} - -class PerformanceObserver { - constructor(callback) { - validateCallback(callback); - ObjectDefineProperties(this, { - [kTypes]: { - enumerable: false, - writable: true, - value: {} - }, - [kCallback]: { - enumerable: false, - writable: true, - value: callback - }, - [kBuffer]: { - enumerable: false, - writable: true, - value: new PerformanceObserverEntryList() - }, - [kBuffering]: { - enumerable: false, - writable: true, - value: false - }, - [kQueued]: { - enumerable: false, - writable: true, - value: false - } - }); - } - - disconnect() { - const observerCountsGC = observerCounts[NODE_PERFORMANCE_ENTRY_TYPE_GC]; - const types = this[kTypes]; - ArrayPrototypeForEach(ObjectKeys(types), (key) => { - const item = types[key]; - if (item) { - L.remove(item); - observerCounts[key]--; - } - }); - this[kTypes] = {}; - if (observerCountsGC === 1 && - observerCounts[NODE_PERFORMANCE_ENTRY_TYPE_GC] === 0) { - removeGarbageCollectionTracking(); - } - } - - observe(options) { - validateObject(options, 'options'); - const { entryTypes } = options; - if (!ArrayIsArray(entryTypes)) { - throw new ERR_INVALID_ARG_VALUE('options.entryTypes', entryTypes); - } - const filteredEntryTypes = - ArrayPrototypeMap(ArrayPrototypeFilter(entryTypes, filterTypes), - mapTypes); - if (filteredEntryTypes.length === 0) { - throw new ERR_VALID_PERFORMANCE_ENTRY_TYPE(); - } - this.disconnect(); - const observerCountsGC = observerCounts[NODE_PERFORMANCE_ENTRY_TYPE_GC]; - this[kBuffer][kEntries] = []; - L.init(this[kBuffer][kEntries]); - this[kBuffering] = Boolean(options.buffered); - ArrayPrototypeForEach(filteredEntryTypes, (entryType) => { - const list = getObserversList(entryType); - if (this[kTypes][entryType]) return; - const item = { obs: this }; - this[kTypes][entryType] = item; - L.append(list, item); - observerCounts[entryType]++; - }); - if (observerCountsGC === 0 && - observerCounts[NODE_PERFORMANCE_ENTRY_TYPE_GC] === 1) { - installGarbageCollectionTracking(); - } - } -} +const eventLoopUtilization = require('internal/perf/event_loop_utilization'); +const monitorEventLoopDelay = require('internal/perf/event_loop_delay'); +const nodeTiming = require('internal/perf/nodetiming'); +const timerify = require('internal/perf/timerify'); +const { customInspectSymbol: kInspect } = require('internal/util'); +const { inspect } = require('util'); class Performance { constructor() { - this[kIndex] = { - [kMarks]: new SafeSet() - }; + // eslint-disable-next-line no-restricted-syntax + throw new TypeError('Illegal constructor'); } - get nodeTiming() { - return nodeTiming; - } - - get timeOrigin() { - return timeOriginTimestamp; - } - - now() { - return now() - timeOrigin; - } - - mark(name) { - name = `${name}`; - _mark(name); - this[kIndex][kMarks].add(name); - } - - measure(name, startMark, endMark) { - name = `${name}`; - const marks = this[kIndex][kMarks]; - if (arguments.length >= 3) { - if (!marks.has(endMark) && !(endMark in nodeTiming)) - throw new ERR_INVALID_PERFORMANCE_MARK(endMark); - else - endMark = `${endMark}`; - } - startMark = startMark !== undefined ? `${startMark}` : ''; - _measure(name, startMark, endMark); - } - - clearMarks(name) { - if (name !== undefined) { - name = `${name}`; - this[kIndex][kMarks].delete(name); - _clearMark(name); - } else { - this[kIndex][kMarks].clear(); - _clearMark(); - } - } - - timerify(fn) { - validateFunction(fn, 'fn'); - if (fn[kTimerified]) - return fn[kTimerified]; - const ret = timerify(fn, fn.length); - ObjectDefineProperty(fn, kTimerified, { - enumerable: false, - configurable: true, - writable: false, - value: ret - }); - ObjectDefineProperties(ret, { - [kTimerified]: { - enumerable: false, - configurable: true, - writable: false, - value: ret - }, - name: { - enumerable: false, - configurable: true, - writable: false, - value: `timerified ${fn.name}` - } - }); - return ret; - } - - eventLoopUtilization(util1, util2) { - const ls = nodeTiming.loopStart; - - if (ls <= 0) { - return { idle: 0, active: 0, utilization: 0 }; - } + [kInspect](depth, options) { + if (depth < 0) return this; - if (util2) { - const idle = util1.idle - util2.idle; - const active = util1.active - util2.active; - return { idle, active, utilization: active / (idle + active) }; - } - - const idle = nodeTiming.idleTime; - const active = performance.now() - ls - idle; - - if (!util1) { - return { idle, active, utilization: active / (idle + active) }; - } - - const idle_delta = idle - util1.idle; - const active_delta = active - util1.active; - const utilization = active_delta / (idle_delta + active_delta); - return { idle: idle_delta, active: active_delta, utilization }; - } + const opts = { + ...options, + depth: options.depth == null ? null : options.depth - 1 + }; - [kInspect]() { - return { + return `Performance ${inspect({ nodeTiming: this.nodeTiming, timeOrigin: this.timeOrigin, - idleTime: this.idleTime, - }; - } -} - -const performance = new Performance(); - -function getObserversList(type) { - let list = observers[type]; - if (list === undefined) { - list = observers[type] = {}; - L.init(list); - } - return list; -} - -function doNotify(observer) { - observer[kQueued] = false; - observer[kCallback](observer[kBuffer], observer); - observer[kBuffer][kEntries] = []; - L.init(observer[kBuffer][kEntries]); -} - -// Set up the callback used to receive PerformanceObserver notifications -function observersCallback(entry) { - const type = mapTypes(entry.entryType); - - if (type === NODE_PERFORMANCE_ENTRY_TYPE_HTTP2) - collectHttp2Stats(entry); - - const list = getObserversList(type); - - let current = L.peek(list); - - while (current && current.obs) { - const observer = current.obs; - // First, add the item to the observers buffer - const buffer = observer[kBuffer]; - buffer[kInsertEntry](entry); - // Second, check to see if we're buffering - if (observer[kBuffering]) { - // If we are, schedule a setImmediate call if one hasn't already - if (!observer[kQueued]) { - observer[kQueued] = true; - // Use setImmediate instead of nextTick to give more time - // for multiple entries to collect. - setImmediate(doNotify, observer); - } - } else { - // If not buffering, notify immediately - doNotify(observer); - } - current = current._idlePrev; + }, opts)}`; + } +} + +class InternalPerformance {} +InternalPerformance.prototype.constructor = Performance.prototype.constructor; +ObjectSetPrototypeOf(InternalPerformance.prototype, Performance.prototype); + +ObjectDefineProperties(Performance.prototype, { + clearMarks: { + configurable: true, + enumerable: false, + value: clearMarks, + }, + eventLoopUtilization: { + configurable: true, + enumerable: false, + value: eventLoopUtilization, + }, + mark: { + configurable: true, + enumerable: false, + value: mark, + }, + measure: { + configurable: true, + enumerable: false, + value: measure, + }, + nodeTiming: { + configurable: true, + enumerable: false, + value: nodeTiming, + }, + now: { + configurable: true, + enumerable: false, + value: now, + }, + timerify: { + configurable: true, + enumerable: false, + value: timerify, + }, + timeOrigin: { + configurable: true, + enumerable: true, + value: timeOriginTimestamp, } -} -setupObservers(observersCallback); - -function filterTypes(i) { - return ArrayPrototypeIncludes(observerableTypes, `${i}`); -} - -function mapTypes(i) { - switch (i) { - case 'node': return NODE_PERFORMANCE_ENTRY_TYPE_NODE; - case 'mark': return NODE_PERFORMANCE_ENTRY_TYPE_MARK; - case 'measure': return NODE_PERFORMANCE_ENTRY_TYPE_MEASURE; - case 'gc': return NODE_PERFORMANCE_ENTRY_TYPE_GC; - case 'function': return NODE_PERFORMANCE_ENTRY_TYPE_FUNCTION; - case 'http2': return NODE_PERFORMANCE_ENTRY_TYPE_HTTP2; - case 'http': return NODE_PERFORMANCE_ENTRY_TYPE_HTTP; - } -} - -// The specification requires that PerformanceEntry instances are sorted -// according to startTime. Unfortunately, they are not necessarily created -// in that same order, and can be reported to the JS layer in any order, -// which means we need to keep the list sorted as we insert. -function getInsertLocation(list, entryStartTime) { - let start = 0; - let end = list.length; - while (start < end) { - const pivot = (end + start) >>> 1; - if (list[pivot].startTime === entryStartTime) - return pivot; - if (list[pivot].startTime < entryStartTime) - start = pivot + 1; - else - end = pivot; - } - return start; -} - -function sortedInsert(list, entry) { - const entryStartTime = entry.startTime; - if (list.length === 0 || - (list[list.length - 1].startTime < entryStartTime)) { - ArrayPrototypePush(list, entry); - return; - } - if (list[0] && (list[0].startTime > entryStartTime)) { - ArrayPrototypeUnshift(list, entry); - return; - } - const location = getInsertLocation(list, entryStartTime); - ArrayPrototypeSplice(list, location, 0, entry); -} - -class ELDHistogram extends Histogram { - constructor(i) { - if (!(i instanceof _ELDHistogram)) { - // eslint-disable-next-line no-restricted-syntax - throw new TypeError('illegal constructor'); - } - super(i); - this[kEnabled] = false; - } - enable() { - if (this[kEnabled]) return false; - this[kEnabled] = true; - this[kHandle].start(); - return true; - } - disable() { - if (!this[kEnabled]) return false; - this[kEnabled] = false; - this[kHandle].stop(); - return true; - } -} - -function monitorEventLoopDelay(options = {}) { - validateObject(options, 'options'); - const { resolution = 10 } = options; - if (typeof resolution !== 'number') { - throw new ERR_INVALID_ARG_TYPE('options.resolution', - 'number', resolution); - } - if (resolution <= 0 || !NumberIsSafeInteger(resolution)) { - throw new ERR_INVALID_ARG_VALUE.RangeError('resolution', resolution); - } - return new ELDHistogram(new _ELDHistogram(resolution)); -} +}); module.exports = { - performance, + PerformanceEntry, + PerformanceMark, PerformanceObserver, monitorEventLoopDelay, createHistogram, + performance: new InternalPerformance(), }; ObjectDefineProperty(module.exports, 'constants', { diff --git a/node.gyp b/node.gyp index dbcbf4d8ca2f1d..cba5c0113de42e 100644 --- a/node.gyp +++ b/node.gyp @@ -193,6 +193,13 @@ 'lib/internal/modules/esm/translators.js', 'lib/internal/net.js', 'lib/internal/options.js', + 'lib/internal/perf/perf.js', + 'lib/internal/perf/nodetiming.js', + 'lib/internal/perf/usertiming.js', + 'lib/internal/perf/observe.js', + 'lib/internal/perf/event_loop_delay.js', + 'lib/internal/perf/event_loop_utilization.js', + 'lib/internal/perf/timerify.js', 'lib/internal/policy/manifest.js', 'lib/internal/policy/sri.js', 'lib/internal/priority_queue.js', diff --git a/src/env-inl.h b/src/env-inl.h index 86c870ca55f047..cbb7eb6f522864 100644 --- a/src/env-inl.h +++ b/src/env-inl.h @@ -887,11 +887,6 @@ inline performance::PerformanceState* Environment::performance_state() { return performance_state_.get(); } -inline std::unordered_map* - Environment::performance_marks() { - return &performance_marks_; -} - inline IsolateData* Environment::isolate_data() const { return isolate_data_; } diff --git a/src/env.h b/src/env.h index ba0626463f68b6..f2d3c34f9f5c08 100644 --- a/src/env.h +++ b/src/env.h @@ -259,6 +259,8 @@ constexpr size_t kFsStatsBufferLength = V(fingerprint_string, "fingerprint") \ V(flags_string, "flags") \ V(fragment_string, "fragment") \ + V(frames_received_string, "framesReceived") \ + V(frames_sent_string, "framesSent") \ V(function_string, "function") \ V(get_data_clone_error_string, "_getDataCloneError") \ V(get_shared_array_buffer_id_string, "_getSharedArrayBufferId") \ @@ -270,6 +272,7 @@ constexpr size_t kFsStatsBufferLength = V(host_string, "host") \ V(hostmaster_string, "hostmaster") \ V(http_1_1_string, "http/1.1") \ + V(id_string, "id") \ V(identity_string, "identity") \ V(ignore_string, "ignore") \ V(infoaccess_string, "infoAccess") \ @@ -307,6 +310,7 @@ constexpr size_t kFsStatsBufferLength = V(library_string, "library") \ V(mac_string, "mac") \ V(max_buffer_string, "maxBuffer") \ + V(max_concurrent_streams_string, "maxConcurrentStreams") \ V(message_port_constructor_string, "MessagePort") \ V(message_port_string, "messagePort") \ V(message_string, "message") \ @@ -353,6 +357,7 @@ constexpr size_t kFsStatsBufferLength = V(path_string, "path") \ V(pending_handle_string, "pendingHandle") \ V(pid_string, "pid") \ + V(ping_rtt_string, "pingRTT") \ V(pipe_source_string, "pipeSource") \ V(pipe_string, "pipe") \ V(pipe_target_string, "pipeTarget") \ @@ -400,6 +405,8 @@ constexpr size_t kFsStatsBufferLength = V(stats_string, "stats") \ V(status_string, "status") \ V(stdio_string, "stdio") \ + V(stream_average_duration_string, "streamAverageDuration") \ + V(stream_count_string, "streamCount") \ V(subject_string, "subject") \ V(subjectaltname_string, "subjectaltname") \ V(syscall_string, "syscall") \ @@ -407,6 +414,9 @@ constexpr size_t kFsStatsBufferLength = V(thread_id_string, "threadId") \ V(ticketkeycallback_string, "onticketkeycallback") \ V(timeout_string, "timeout") \ + V(time_to_first_byte_string, "timeToFirstByte") \ + V(time_to_first_byte_sent_string, "timeToFirstByteSent") \ + V(time_to_first_header_string, "timeToFirstHeader") \ V(tls_ticket_string, "tlsTicket") \ V(transfer_string, "transfer") \ V(ttl_string, "ttl") \ @@ -1128,7 +1138,6 @@ class Environment : public MemoryRetainer { EnabledDebugList* enabled_debug_list() { return &enabled_debug_list_; } inline performance::PerformanceState* performance_state(); - inline std::unordered_map* performance_marks(); void CollectUVExceptionInfo(v8::Local context, int errorno, @@ -1465,7 +1474,6 @@ class Environment : public MemoryRetainer { uint64_t environment_start_time_; std::unique_ptr performance_state_; - std::unordered_map performance_marks_; bool has_run_bootstrapping_code_ = false; bool has_serialized_options_ = false; diff --git a/src/node_http2.cc b/src/node_http2.cc index ccff6dc4ca60c1..112a3a336e0297 100644 --- a/src/node_http2.cc +++ b/src/node_http2.cc @@ -40,7 +40,6 @@ using v8::Uint8Array; using v8::Undefined; using v8::Value; -using node::performance::PerformanceEntry; namespace http2 { namespace { @@ -466,6 +465,7 @@ Http2Session::Http2Session(Http2State* http2_state, session_type_(type), http2_state_(http2_state) { MakeWeak(); + statistics_.session_type = type; statistics_.start_time = uv_hrtime(); // Capture the configuration options for this session @@ -541,71 +541,121 @@ std::string Http2Session::diagnostic_name() const { std::to_string(static_cast(get_async_id())) + ")"; } +MaybeLocal Http2StreamPerformanceEntryTraits::GetDetails( + Environment* env, + const Http2StreamPerformanceEntry& entry) { + Local obj = Object::New(env->isolate()); + +#define SET(name, val) \ + if (!obj->Set( \ + env->context(), \ + env->name(), \ + Number::New( \ + env->isolate(), \ + static_cast(entry.details.val))).IsJust()) { \ + return MaybeLocal(); \ + } + + SET(bytes_read_string, received_bytes) + SET(bytes_written_string, sent_bytes) + SET(id_string, id) +#undef SET + +#define SET(name, val) \ + if (!obj->Set( \ + env->context(), \ + env->name(), \ + Number::New( \ + env->isolate(), \ + (entry.details.val - entry.details.start_time) / 1e6)) \ + .IsJust()) { \ + return MaybeLocal(); \ + } + + SET(time_to_first_byte_string, first_byte) + SET(time_to_first_byte_sent_string, first_byte_sent) + SET(time_to_first_header_string, first_header) +#undef SET + + return obj; +} + +MaybeLocal Http2SessionPerformanceEntryTraits::GetDetails( + Environment* env, + const Http2SessionPerformanceEntry& entry) { + Local obj = Object::New(env->isolate()); + +#define SET(name, val) \ + if (!obj->Set( \ + env->context(), \ + env->name(), \ + Number::New( \ + env->isolate(), \ + static_cast(entry.details.val))).IsJust()) { \ + return MaybeLocal(); \ + } + + SET(bytes_written_string, data_sent) + SET(bytes_read_string, data_received) + SET(frames_received_string, frame_count) + SET(frames_sent_string, frame_sent) + SET(max_concurrent_streams_string, max_concurrent_streams) + SET(ping_rtt_string, ping_rtt) + SET(stream_average_duration_string, stream_average_duration) + SET(stream_count_string, stream_count) + + if (!obj->Set( + env->context(), + env->type_string(), + OneByteString( + env->isolate(), + (entry.details.session_type == NGHTTP2_SESSION_SERVER) + ? "server" : "client")).IsJust()) { + return MaybeLocal(); + } + +#undef SET + return obj; +} + void Http2Stream::EmitStatistics() { CHECK_NOT_NULL(session()); - if (!HasHttp2Observer(env())) + if (LIKELY(!HasHttp2Observer(env()))) return; - auto entry = + + double start = statistics_.start_time / 1e6; + double duration = (PERFORMANCE_NOW() / 1e6) - start; + + std::unique_ptr entry = std::make_unique( - session()->http2_state(), id_, statistics_); + "Http2Stream", + start, + duration, + statistics_); + env()->SetImmediate([entry = move(entry)](Environment* env) { - if (!HasHttp2Observer(env)) - return; - HandleScope handle_scope(env->isolate()); - AliasedFloat64Array& buffer = entry->http2_state()->stream_stats_buffer; - buffer[IDX_STREAM_STATS_ID] = entry->id(); - if (entry->first_byte() != 0) { - buffer[IDX_STREAM_STATS_TIMETOFIRSTBYTE] = - (entry->first_byte() - entry->startTimeNano()) / 1e6; - } else { - buffer[IDX_STREAM_STATS_TIMETOFIRSTBYTE] = 0; - } - if (entry->first_header() != 0) { - buffer[IDX_STREAM_STATS_TIMETOFIRSTHEADER] = - (entry->first_header() - entry->startTimeNano()) / 1e6; - } else { - buffer[IDX_STREAM_STATS_TIMETOFIRSTHEADER] = 0; - } - if (entry->first_byte_sent() != 0) { - buffer[IDX_STREAM_STATS_TIMETOFIRSTBYTESENT] = - (entry->first_byte_sent() - entry->startTimeNano()) / 1e6; - } else { - buffer[IDX_STREAM_STATS_TIMETOFIRSTBYTESENT] = 0; - } - buffer[IDX_STREAM_STATS_SENTBYTES] = - static_cast(entry->sent_bytes()); - buffer[IDX_STREAM_STATS_RECEIVEDBYTES] = - static_cast(entry->received_bytes()); - Local obj; - if (entry->ToObject().ToLocal(&obj)) entry->Notify(obj); + if (HasHttp2Observer(env)) + entry->Notify(env); }); } void Http2Session::EmitStatistics() { - if (!HasHttp2Observer(env())) + if (LIKELY(!HasHttp2Observer(env()))) return; - auto entry = std::make_unique( - http2_state(), statistics_, session_type_); + + double start = statistics_.start_time / 1e6; + double duration = (PERFORMANCE_NOW() / 1e6) - start; + + std::unique_ptr entry = + std::make_unique( + "Http2Session", + start, + duration, + statistics_); + env()->SetImmediate([entry = std::move(entry)](Environment* env) { - if (!HasHttp2Observer(env)) - return; - HandleScope handle_scope(env->isolate()); - AliasedFloat64Array& buffer = entry->http2_state()->session_stats_buffer; - buffer[IDX_SESSION_STATS_TYPE] = entry->type(); - buffer[IDX_SESSION_STATS_PINGRTT] = entry->ping_rtt() / 1e6; - buffer[IDX_SESSION_STATS_FRAMESRECEIVED] = entry->frame_count(); - buffer[IDX_SESSION_STATS_FRAMESSENT] = entry->frame_sent(); - buffer[IDX_SESSION_STATS_STREAMCOUNT] = entry->stream_count(); - buffer[IDX_SESSION_STATS_STREAMAVERAGEDURATION] = - entry->stream_average_duration(); - buffer[IDX_SESSION_STATS_DATA_SENT] = - static_cast(entry->data_sent()); - buffer[IDX_SESSION_STATS_DATA_RECEIVED] = - static_cast(entry->data_received()); - buffer[IDX_SESSION_STATS_MAX_CONCURRENT_STREAMS] = - static_cast(entry->max_concurrent_streams()); - Local obj; - if (entry->ToObject().ToLocal(&obj)) entry->Notify(obj); + if (HasHttp2Observer(env)) + entry->Notify(env); }); } @@ -1884,6 +1934,7 @@ Http2Stream::Http2Stream(Http2Session* session, current_headers_category_(category) { MakeWeak(); StreamBase::AttachToObject(GetObject()); + statistics_.id = id; statistics_.start_time = uv_hrtime(); // Limit the number of header pairs diff --git a/src/node_http2.h b/src/node_http2.h index 9c7ffce2c41955..4fa2dc446c05af 100644 --- a/src/node_http2.h +++ b/src/node_http2.h @@ -7,6 +7,7 @@ #include #include "nghttp2/nghttp2.h" +#include "env.h" #include "allocated_buffer.h" #include "aliased_struct.h" #include "node_http2_state.h" @@ -456,6 +457,7 @@ class Http2Stream : public AsyncWrap, uint64_t first_byte_sent; // Time first DATA frame byte was sent uint64_t sent_bytes; uint64_t received_bytes; + uint64_t id; }; Statistics statistics_ = {}; @@ -761,6 +763,7 @@ class Http2Session : public AsyncWrap, int32_t stream_count; size_t max_concurrent_streams; double stream_average_duration; + SessionType session_type; }; Statistics statistics_ = {}; @@ -925,96 +928,35 @@ class Http2Session : public AsyncWrap, friend class Http2StreamListener; }; -class Http2SessionPerformanceEntry : public performance::PerformanceEntry { - public: - Http2SessionPerformanceEntry( - Http2State* http2_state, - const Http2Session::Statistics& stats, - SessionType type) : - performance::PerformanceEntry( - http2_state->env(), "Http2Session", "http2", - stats.start_time, - stats.end_time), - ping_rtt_(stats.ping_rtt), - data_sent_(stats.data_sent), - data_received_(stats.data_received), - frame_count_(stats.frame_count), - frame_sent_(stats.frame_sent), - stream_count_(stats.stream_count), - max_concurrent_streams_(stats.max_concurrent_streams), - stream_average_duration_(stats.stream_average_duration), - session_type_(type), - http2_state_(http2_state) { } - - uint64_t ping_rtt() const { return ping_rtt_; } - uint64_t data_sent() const { return data_sent_; } - uint64_t data_received() const { return data_received_; } - uint32_t frame_count() const { return frame_count_; } - uint32_t frame_sent() const { return frame_sent_; } - int32_t stream_count() const { return stream_count_; } - size_t max_concurrent_streams() const { return max_concurrent_streams_; } - double stream_average_duration() const { return stream_average_duration_; } - SessionType type() const { return session_type_; } - Http2State* http2_state() const { return http2_state_.get(); } +struct Http2SessionPerformanceEntryTraits { + static constexpr performance::PerformanceEntryType kType = + performance::NODE_PERFORMANCE_ENTRY_TYPE_HTTP2; - void Notify(v8::Local obj) { - performance::PerformanceEntry::Notify(env(), kind(), obj); - } + using Details = Http2Session::Statistics; - private: - uint64_t ping_rtt_; - uint64_t data_sent_; - uint64_t data_received_; - uint32_t frame_count_; - uint32_t frame_sent_; - int32_t stream_count_; - size_t max_concurrent_streams_; - double stream_average_duration_; - SessionType session_type_; - BaseObjectPtr http2_state_; + static v8::MaybeLocal GetDetails( + Environment* env, + const performance::PerformanceEntry& + entry); }; -class Http2StreamPerformanceEntry - : public performance::PerformanceEntry { - public: - Http2StreamPerformanceEntry( - Http2State* http2_state, - int32_t id, - const Http2Stream::Statistics& stats) : - performance::PerformanceEntry( - http2_state->env(), "Http2Stream", "http2", - stats.start_time, - stats.end_time), - id_(id), - first_header_(stats.first_header), - first_byte_(stats.first_byte), - first_byte_sent_(stats.first_byte_sent), - sent_bytes_(stats.sent_bytes), - received_bytes_(stats.received_bytes), - http2_state_(http2_state) { } - - int32_t id() const { return id_; } - uint64_t first_header() const { return first_header_; } - uint64_t first_byte() const { return first_byte_; } - uint64_t first_byte_sent() const { return first_byte_sent_; } - uint64_t sent_bytes() const { return sent_bytes_; } - uint64_t received_bytes() const { return received_bytes_; } - Http2State* http2_state() const { return http2_state_.get(); } +struct Http2StreamPerformanceEntryTraits { + static constexpr performance::PerformanceEntryType kType = + performance::NODE_PERFORMANCE_ENTRY_TYPE_HTTP2; - void Notify(v8::Local obj) { - performance::PerformanceEntry::Notify(env(), kind(), obj); - } + using Details = Http2Stream::Statistics; - private: - int32_t id_; - uint64_t first_header_; - uint64_t first_byte_; - uint64_t first_byte_sent_; - uint64_t sent_bytes_; - uint64_t received_bytes_; - BaseObjectPtr http2_state_; + static v8::MaybeLocal GetDetails( + Environment* env, + const performance::PerformanceEntry& + entry); }; +using Http2SessionPerformanceEntry = + performance::PerformanceEntry; +using Http2StreamPerformanceEntry = + performance::PerformanceEntry; + class Http2Ping : public AsyncWrap { public: explicit Http2Ping( diff --git a/src/node_perf.cc b/src/node_perf.cc index 73fc31394bdbac..2d6341e01136fe 100644 --- a/src/node_perf.cc +++ b/src/node_perf.cc @@ -1,4 +1,5 @@ #include "aliased_buffer.h" +#include "env-inl.h" #include "histogram-inl.h" #include "memory_tracker-inl.h" #include "node_internals.h" @@ -19,7 +20,6 @@ using v8::FunctionCallbackInfo; using v8::FunctionTemplate; using v8::GCCallbackFlags; using v8::GCType; -using v8::HandleScope; using v8::Int32; using v8::Integer; using v8::Isolate; @@ -87,8 +87,7 @@ std::ostream& operator<<(std::ostream& o, return o; } -void PerformanceState::Mark(enum PerformanceMilestone milestone, - uint64_t ts) { +void PerformanceState::Mark(PerformanceMilestone milestone, uint64_t ts) { this->milestones[milestone] = static_cast(ts); TRACE_EVENT_INSTANT_WITH_TIMESTAMP0( TRACING_CATEGORY_NODE1(bootstrap), @@ -96,234 +95,83 @@ void PerformanceState::Mark(enum PerformanceMilestone milestone, TRACE_EVENT_SCOPE_THREAD, ts / 1000); } -// Initialize the performance entry object properties -inline void InitObject(const PerformanceEntry& entry, Local obj) { - Environment* env = entry.env(); - Isolate* isolate = env->isolate(); - Local context = env->context(); - PropertyAttribute attr = - static_cast(ReadOnly | DontDelete); - obj->DefineOwnProperty(context, - env->name_string(), - String::NewFromUtf8(isolate, - entry.name().c_str()) - .ToLocalChecked(), - attr) - .Check(); - obj->DefineOwnProperty(context, - env->entry_type_string(), - String::NewFromUtf8(isolate, - entry.type().c_str()) - .ToLocalChecked(), - attr) - .Check(); - obj->DefineOwnProperty(context, - env->start_time_string(), - Number::New(isolate, entry.startTime()), - attr).Check(); - obj->DefineOwnProperty(context, - env->duration_string(), - Number::New(isolate, entry.duration()), - attr).Check(); -} - -// Create a new PerformanceEntry object -MaybeLocal PerformanceEntry::ToObject() const { - Local obj; - if (!env_->performance_entry_template() - ->NewInstance(env_->context()) - .ToLocal(&obj)) { - return MaybeLocal(); - } - InitObject(*this, obj); - return obj; -} - -// Allow creating a PerformanceEntry object from JavaScript -void PerformanceEntry::New(const FunctionCallbackInfo& args) { - Environment* env = Environment::GetCurrent(args); - Isolate* isolate = env->isolate(); - Utf8Value name(isolate, args[0]); - Utf8Value type(isolate, args[1]); - uint64_t now = PERFORMANCE_NOW(); - PerformanceEntry entry(env, *name, *type, now, now); - Local obj = args.This(); - InitObject(entry, obj); - PerformanceEntry::Notify(env, entry.kind(), obj); -} - -// Pass the PerformanceEntry object to the PerformanceObservers -void PerformanceEntry::Notify(Environment* env, - PerformanceEntryType type, - Local object) { - Context::Scope scope(env->context()); - AliasedUint32Array& observers = env->performance_state()->observers; - if (!env->performance_entry_callback().IsEmpty() && - type != NODE_PERFORMANCE_ENTRY_TYPE_INVALID && observers[type]) { - node::MakeSyncCallback(env->isolate(), - object.As(), - env->performance_entry_callback(), - 1, &object); - } -} - -// Create a User Timing Mark -void Mark(const FunctionCallbackInfo& args) { - Environment* env = Environment::GetCurrent(args); - HandleScope scope(env->isolate()); - Utf8Value name(env->isolate(), args[0]); - uint64_t now = PERFORMANCE_NOW(); - auto marks = env->performance_marks(); - (*marks)[*name] = now; - - TRACE_EVENT_COPY_MARK_WITH_TIMESTAMP( - TRACING_CATEGORY_NODE2(perf, usertiming), - *name, now / 1000); - - PerformanceEntry entry(env, *name, "mark", now, now); - Local obj; - if (!entry.ToObject().ToLocal(&obj)) return; - PerformanceEntry::Notify(env, entry.kind(), obj); - args.GetReturnValue().Set(obj); -} - -void ClearMark(const FunctionCallbackInfo& args) { - Environment* env = Environment::GetCurrent(args); - auto marks = env->performance_marks(); - - if (args.Length() == 0) { - marks->clear(); - } else { - Utf8Value name(env->isolate(), args[0]); - marks->erase(*name); - } -} - -inline uint64_t GetPerformanceMark(Environment* env, const std::string& name) { - auto marks = env->performance_marks(); - auto res = marks->find(name); - return res != marks->end() ? res->second : 0; -} - -// Create a User Timing Measure. A Measure is a PerformanceEntry that -// measures the duration between two distinct user timing marks -void Measure(const FunctionCallbackInfo& args) { - Environment* env = Environment::GetCurrent(args); - HandleScope scope(env->isolate()); - Utf8Value name(env->isolate(), args[0]); - Utf8Value startMark(env->isolate(), args[1]); - - AliasedFloat64Array& milestones = env->performance_state()->milestones; - - uint64_t startTimestamp = timeOrigin; - uint64_t start = GetPerformanceMark(env, *startMark); - if (start != 0) { - startTimestamp = start; - } else { - PerformanceMilestone milestone = ToPerformanceMilestoneEnum(*startMark); - if (milestone != NODE_PERFORMANCE_MILESTONE_INVALID) - startTimestamp = milestones[milestone]; - } - - uint64_t endTimestamp = 0; - if (args[2]->IsUndefined()) { - endTimestamp = PERFORMANCE_NOW(); - } else { - Utf8Value endMark(env->isolate(), args[2]); - endTimestamp = GetPerformanceMark(env, *endMark); - if (endTimestamp == 0) { - PerformanceMilestone milestone = ToPerformanceMilestoneEnum(*endMark); - if (milestone != NODE_PERFORMANCE_MILESTONE_INVALID) - endTimestamp = milestones[milestone]; - } - } - - if (endTimestamp < startTimestamp) - endTimestamp = startTimestamp; - - TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0( - TRACING_CATEGORY_NODE2(perf, usertiming), - *name, *name, startTimestamp / 1000); - TRACE_EVENT_COPY_NESTABLE_ASYNC_END_WITH_TIMESTAMP0( - TRACING_CATEGORY_NODE2(perf, usertiming), - *name, *name, endTimestamp / 1000); - - PerformanceEntry entry(env, *name, "measure", startTimestamp, endTimestamp); - Local obj; - if (!entry.ToObject().ToLocal(&obj)) return; - PerformanceEntry::Notify(env, entry.kind(), obj); - args.GetReturnValue().Set(obj); -} - // Allows specific Node.js lifecycle milestones to be set from JavaScript void MarkMilestone(const FunctionCallbackInfo& args) { Environment* env = Environment::GetCurrent(args); - Local context = env->context(); PerformanceMilestone milestone = - static_cast( - args[0]->Int32Value(context).ToChecked()); + static_cast(args[0].As()->Value()); if (milestone != NODE_PERFORMANCE_MILESTONE_INVALID) env->performance_state()->Mark(milestone); } - void SetupPerformanceObservers(const FunctionCallbackInfo& args) { Environment* env = Environment::GetCurrent(args); CHECK(args[0]->IsFunction()); env->set_performance_entry_callback(args[0].As()); } -// Creates a GC Performance Entry and passes it to observers -void PerformanceGCCallback(Environment* env, - std::unique_ptr entry) { - HandleScope scope(env->isolate()); - Local context = env->context(); - - AliasedUint32Array& observers = env->performance_state()->observers; - if (observers[NODE_PERFORMANCE_ENTRY_TYPE_GC]) { - Local obj; - if (!entry->ToObject().ToLocal(&obj)) return; - PropertyAttribute attr = - static_cast(ReadOnly | DontDelete); - obj->DefineOwnProperty(context, - env->kind_string(), - Integer::New(env->isolate(), entry->gckind()), - attr).Check(); - obj->DefineOwnProperty(context, - env->flags_string(), - Integer::New(env->isolate(), entry->gcflags()), - attr).Check(); - PerformanceEntry::Notify(env, entry->kind(), obj); - } -} - // Marks the start of a GC cycle -void MarkGarbageCollectionStart(Isolate* isolate, - GCType type, - GCCallbackFlags flags, - void* data) { +void MarkGarbageCollectionStart( + Isolate* isolate, + GCType type, + GCCallbackFlags flags, + void* data) { Environment* env = static_cast(data); env->performance_state()->performance_last_gc_start_mark = PERFORMANCE_NOW(); } +MaybeLocal GCPerformanceEntryTraits::GetDetails( + Environment* env, + const GCPerformanceEntry& entry) { + Local obj = Object::New(env->isolate()); + + if (!obj->Set( + env->context(), + env->kind_string(), + Integer::NewFromUnsigned( + env->isolate(), + entry.details.kind)).IsJust()) { + return MaybeLocal(); + } + + if (!obj->Set( + env->context(), + env->flags_string(), + Integer::NewFromUnsigned( + env->isolate(), + entry.details.flags)).IsJust()) { + return MaybeLocal(); + } + + return obj; +} + // Marks the end of a GC cycle -void MarkGarbageCollectionEnd(Isolate* isolate, - GCType type, - GCCallbackFlags flags, - void* data) { +void MarkGarbageCollectionEnd( + Isolate* isolate, + GCType type, + GCCallbackFlags flags, + void* data) { Environment* env = static_cast(data); PerformanceState* state = env->performance_state(); // If no one is listening to gc performance entries, do not create them. - if (!state->observers[NODE_PERFORMANCE_ENTRY_TYPE_GC]) + if (LIKELY(!state->observers[NODE_PERFORMANCE_ENTRY_TYPE_GC])) return; - auto entry = std::make_unique( - env, - static_cast(type), - static_cast(flags), - state->performance_last_gc_start_mark, - PERFORMANCE_NOW()); - env->SetImmediate([entry = std::move(entry)](Environment* env) mutable { - PerformanceGCCallback(env, std::move(entry)); + + double start_time = state->performance_last_gc_start_mark / 1e6; + double duration = (PERFORMANCE_NOW() / 1e6) - start_time; + + std::unique_ptr entry = + std::make_unique( + "gc", + start_time, + duration, + GCPerformanceEntry::Details( + static_cast(type), + static_cast(flags))); + + env->SetImmediate([entry = std::move(entry)](Environment* env) { + entry->Notify(env); }, CallbackFlags::kUnrefed); } @@ -364,68 +212,6 @@ inline Local GetName(Local fn) { return val; } -// Executes a wrapped Function and captures timing information, causing a -// Function PerformanceEntry to be emitted to PerformanceObservers after -// execution. -void TimerFunctionCall(const FunctionCallbackInfo& args) { - Isolate* isolate = args.GetIsolate(); - Local context = isolate->GetCurrentContext(); - Environment* env = Environment::GetCurrent(context); - CHECK_NOT_NULL(env); - Local fn = args.Data().As(); - size_t count = args.Length(); - size_t idx; - SlicedArguments call_args(args); - Utf8Value name(isolate, GetName(fn)); - bool is_construct_call = args.IsConstructCall(); - - uint64_t start = PERFORMANCE_NOW(); - TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0( - TRACING_CATEGORY_NODE2(perf, timerify), - *name, *name, start / 1000); - v8::MaybeLocal ret; - - if (is_construct_call) { - ret = fn->NewInstance(context, call_args.length(), call_args.out()) - .FromMaybe(Local()); - } else { - ret = fn->Call(context, args.This(), call_args.length(), call_args.out()); - } - - uint64_t end = PERFORMANCE_NOW(); - TRACE_EVENT_COPY_NESTABLE_ASYNC_END_WITH_TIMESTAMP0( - TRACING_CATEGORY_NODE2(perf, timerify), - *name, *name, end / 1000); - - if (ret.IsEmpty()) - return; - args.GetReturnValue().Set(ret.ToLocalChecked()); - - AliasedUint32Array& observers = env->performance_state()->observers; - if (!observers[NODE_PERFORMANCE_ENTRY_TYPE_FUNCTION]) - return; - - PerformanceEntry entry(env, *name, "function", start, end); - Local obj; - if (!entry.ToObject().ToLocal(&obj)) return; - for (idx = 0; idx < count; idx++) - obj->Set(context, idx, args[idx]).Check(); - PerformanceEntry::Notify(env, entry.kind(), obj); -} - -// Wraps a Function in a TimerFunctionCall -void Timerify(const FunctionCallbackInfo& args) { - Environment* env = Environment::GetCurrent(args); - Local context = env->context(); - CHECK(args[0]->IsFunction()); - CHECK(args[1]->IsNumber()); - Local fn = args[0].As(); - int length = args[1]->IntegerValue(context).ToChecked(); - Local wrap = - Function::New(context, TimerFunctionCall, fn, length).ToLocalChecked(); - args.GetReturnValue().Set(wrap); -} - // Notify a custom PerformanceEntry to observers void Notify(const FunctionCallbackInfo& args) { Environment* env = Environment::GetCurrent(args); @@ -512,12 +298,8 @@ void Initialize(Local target, target->Set(context, performanceEntryString, fn).Check(); env->set_performance_entry_template(fn); - env->SetMethod(target, "clearMark", ClearMark); - env->SetMethod(target, "mark", Mark); - env->SetMethod(target, "measure", Measure); env->SetMethod(target, "markMilestone", MarkMilestone); env->SetMethod(target, "setupObservers", SetupPerformanceObservers); - env->SetMethod(target, "timerify", Timerify); env->SetMethod(target, "installGarbageCollectionTracking", InstallGarbageCollectionTracking); diff --git a/src/node_perf.h b/src/node_perf.h index ddd99b33040381..d0f1d68462265c 100644 --- a/src/node_perf.h +++ b/src/node_perf.h @@ -21,8 +21,8 @@ namespace performance { extern const uint64_t timeOrigin; -static inline const char* GetPerformanceMilestoneName( - enum PerformanceMilestone milestone) { +inline const char* GetPerformanceMilestoneName( + PerformanceMilestone milestone) { switch (milestone) { #define V(name, label) case NODE_PERFORMANCE_MILESTONE_##name: return label; NODE_PERFORMANCE_MILESTONES(V) @@ -32,7 +32,7 @@ static inline const char* GetPerformanceMilestoneName( } } -static inline PerformanceMilestone ToPerformanceMilestoneEnum(const char* str) { +inline PerformanceMilestone ToPerformanceMilestoneEnum(const char* str) { #define V(name, label) \ if (strcmp(str, label) == 0) return NODE_PERFORMANCE_MILESTONE_##name; NODE_PERFORMANCE_MILESTONES(V) @@ -40,7 +40,18 @@ static inline PerformanceMilestone ToPerformanceMilestoneEnum(const char* str) { return NODE_PERFORMANCE_MILESTONE_INVALID; } -static inline PerformanceEntryType ToPerformanceEntryTypeEnum( +inline const char* GetPerformanceEntryTypeName( + PerformanceEntryType type) { + switch (type) { +#define V(name, label) case NODE_PERFORMANCE_ENTRY_TYPE_##name: return label; + NODE_PERFORMANCE_ENTRY_TYPES(V) +#undef V + default: + UNREACHABLE(); + } +} + +inline PerformanceEntryType ToPerformanceEntryTypeEnum( const char* type) { #define V(name, label) \ if (strcmp(type, label) == 0) return NODE_PERFORMANCE_ENTRY_TYPE_##name; @@ -49,54 +60,6 @@ static inline PerformanceEntryType ToPerformanceEntryTypeEnum( return NODE_PERFORMANCE_ENTRY_TYPE_INVALID; } -class PerformanceEntry { - public: - static void Notify(Environment* env, - PerformanceEntryType type, - v8::Local object); - - static void New(const v8::FunctionCallbackInfo& args); - - PerformanceEntry(Environment* env, - const char* name, - const char* type, - uint64_t startTime, - uint64_t endTime) : env_(env), - name_(name), - type_(type), - startTime_(startTime), - endTime_(endTime) { } - - virtual ~PerformanceEntry() = default; - - virtual v8::MaybeLocal ToObject() const; - - Environment* env() const { return env_; } - - const std::string& name() const { return name_; } - - const std::string& type() const { return type_; } - - PerformanceEntryType kind() { - return ToPerformanceEntryTypeEnum(type().c_str()); - } - - double startTime() const { return startTimeNano() / 1e6; } - - double duration() const { return durationNano() / 1e6; } - - uint64_t startTimeNano() const { return startTime_ - timeOrigin; } - - uint64_t durationNano() const { return endTime_ - startTime_; } - - private: - Environment* env_; - const std::string name_; - const std::string type_; - const uint64_t startTime_; - const uint64_t endTime_; -}; - enum PerformanceGCKind { NODE_PERFORMANCE_GC_MAJOR = v8::GCType::kGCTypeMarkSweepCompact, NODE_PERFORMANCE_GC_MINOR = v8::GCType::kGCTypeScavenge, @@ -121,25 +84,80 @@ enum PerformanceGCFlags { v8::GCCallbackFlags::kGCCallbackScheduleIdleGarbageCollection }; -class GCPerformanceEntry : public PerformanceEntry { - public: - GCPerformanceEntry(Environment* env, - PerformanceGCKind gckind, - PerformanceGCFlags gcflags, - uint64_t startTime, - uint64_t endTime) : - PerformanceEntry(env, "gc", "gc", startTime, endTime), - gckind_(gckind), - gcflags_(gcflags) { } - - PerformanceGCKind gckind() const { return gckind_; } - PerformanceGCFlags gcflags() const { return gcflags_; } - - private: - PerformanceGCKind gckind_; - PerformanceGCFlags gcflags_; +template +struct PerformanceEntry { + using Details = typename Traits::Details; + std::string name; + double start_time; + double duration; + Details details; + + PerformanceEntry( + const std::string& name_, + double start_time_, + double duration_, + const Details& details_) + : name(name_), + start_time(start_time_), + duration(duration_), + details(details_) {} + + static v8::MaybeLocal GetDetails( + Environment* env, + const PerformanceEntry& entry) { + return Traits::GetDetails(env, entry); + } + + void Notify(Environment* env) { + v8::HandleScope handle_scope(env->isolate()); + v8::Context::Scope scope(env->context()); + AliasedUint32Array& observers = env->performance_state()->observers; + if (env->performance_entry_callback().IsEmpty() || + !observers[Traits::kType]) { + return; + } + + v8::Local detail; + if (!Traits::GetDetails(env, *this).ToLocal(&detail)) { + // TODO(@jasnell): Handle the error here + return; + } + + v8::Local argv[] = { + OneByteString(env->isolate(), name.c_str()), + OneByteString(env->isolate(), GetPerformanceEntryTypeName(Traits::kType)), + v8::Number::New(env->isolate(), start_time), + v8::Number::New(env->isolate(), duration), + detail + }; + + node::MakeSyncCallback( + env->isolate(), + env->context()->Global(), + env->performance_entry_callback(), + arraysize(argv), + argv); + } }; +struct GCPerformanceEntryTraits { + static constexpr PerformanceEntryType kType = + NODE_PERFORMANCE_ENTRY_TYPE_GC; + struct Details { + PerformanceGCKind kind; + PerformanceGCFlags flags; + + Details(PerformanceGCKind kind_, PerformanceGCFlags flags_) + : kind(kind_), flags(flags_) {} + }; + + static v8::MaybeLocal GetDetails( + Environment* env, + const PerformanceEntry& entry); +}; + +using GCPerformanceEntry = PerformanceEntry; + class ELDHistogram : public IntervalHistogram { public: static void Initialize(Environment* env, v8::Local target); diff --git a/src/node_perf_common.h b/src/node_perf_common.h index edc142d351268d..4015a1adb70701 100644 --- a/src/node_perf_common.h +++ b/src/node_perf_common.h @@ -32,13 +32,8 @@ extern uint64_t performance_v8_start; #define NODE_PERFORMANCE_ENTRY_TYPES(V) \ - V(NODE, "node") \ - V(MARK, "mark") \ - V(MEASURE, "measure") \ V(GC, "gc") \ - V(FUNCTION, "function") \ - V(HTTP2, "http2") \ - V(HTTP, "http") + V(HTTP2, "http2") enum PerformanceMilestone { #define V(name, _) NODE_PERFORMANCE_MILESTONE_##name, diff --git a/src/node_util.cc b/src/node_util.cc index 3f829081cb37ff..cc03ec0aba602a 100644 --- a/src/node_util.cc +++ b/src/node_util.cc @@ -277,6 +277,11 @@ static void GuessHandleType(const FunctionCallbackInfo& args) { args.GetReturnValue().Set(OneByteString(env->isolate(), type)); } +static void IsConstructor(const FunctionCallbackInfo& args) { + CHECK(args[0]->IsFunction()); + args.GetReturnValue().Set(args[0].As()->IsConstructor()); +} + void RegisterExternalReferences(ExternalReferenceRegistry* registry) { registry->Register(GetHiddenValue); registry->Register(SetHiddenValue); @@ -293,6 +298,7 @@ void RegisterExternalReferences(ExternalReferenceRegistry* registry) { registry->Register(WeakReference::IncRef); registry->Register(WeakReference::DecRef); registry->Register(GuessHandleType); + registry->Register(IsConstructor); } void Initialize(Local target, @@ -331,6 +337,7 @@ void Initialize(Local target, env->SetMethodNoSideEffect(target, "getConstructorName", GetConstructorName); env->SetMethodNoSideEffect(target, "getExternalValue", GetExternalValue); env->SetMethod(target, "sleep", Sleep); + env->SetMethodNoSideEffect(target, "isConstructor", IsConstructor); env->SetMethod(target, "arrayBufferViewHasBuffer", ArrayBufferViewHasBuffer); Local constants = Object::New(env->isolate()); diff --git a/test/parallel/test-http-perf_hooks.js b/test/parallel/test-http-perf_hooks.js index f28885e4367853..e02eab886fcf6b 100644 --- a/test/parallel/test-http-perf_hooks.js +++ b/test/parallel/test-http-perf_hooks.js @@ -6,14 +6,15 @@ const http = require('http'); const { PerformanceObserver } = require('perf_hooks'); -const obs = new PerformanceObserver(common.mustCall((items) => { - const entry = items.getEntries()[0]; - assert.strictEqual(entry.entryType, 'http'); - assert.strictEqual(typeof entry.startTime, 'number'); - assert.strictEqual(typeof entry.duration, 'number'); -}, 2)); +const obs = new PerformanceObserver(common.mustCallAtLeast((items) => { + items.getEntries().forEach((entry) => { + assert.strictEqual(entry.entryType, 'http'); + assert.strictEqual(typeof entry.startTime, 'number'); + assert.strictEqual(typeof entry.duration, 'number'); + }); +})); -obs.observe({ entryTypes: ['http'] }); +obs.observe({ type: 'http' }); const expected = 'Post Body For Test'; const makeRequest = (options) => { diff --git a/test/parallel/test-http2-pack-end-stream-flag.js b/test/parallel/test-http2-pack-end-stream-flag.js index f6bb4452d95a77..95b9890733ef62 100644 --- a/test/parallel/test-http2-pack-end-stream-flag.js +++ b/test/parallel/test-http2-pack-end-stream-flag.js @@ -30,21 +30,23 @@ server.on('stream', (stream, headers) => { }); function testRequest(path, targetFrameCount, callback) { - const obs = new PerformanceObserver((list, observer) => { - const entry = list.getEntries()[0]; - if (entry.name !== 'Http2Session') return; - if (entry.type !== 'client') return; - assert.strictEqual(entry.framesReceived, targetFrameCount); - observer.disconnect(); - callback(); - }); - obs.observe({ entryTypes: ['http2'] }); - const client = http2.connect(`http://localhost:${server.address().port}`, () => { - const req = client.request({ ':path': path }); - req.resume(); - req.end(); - req.on('end', () => client.close()); - }); + const obs = new PerformanceObserver( + common.mustCallAtLeast((list, observer) => { + const entry = list.getEntries()[0]; + if (entry.name !== 'Http2Session') return; + if (entry.detail.type !== 'client') return; + assert.strictEqual(entry.detail.framesReceived, targetFrameCount); + observer.disconnect(); + callback(); + })); + obs.observe({ type: 'http2' }); + const client = + http2.connect(`http://localhost:${server.address().port}`, () => { + const req = client.request({ ':path': path }); + req.resume(); + req.end(); + req.on('end', () => client.close()); + }); } // SETTINGS => SETTINGS => HEADERS => DATA diff --git a/test/parallel/test-http2-perf_hooks.js b/test/parallel/test-http2-perf_hooks.js index 1023d70ff73f2c..5be9073a56ad5c 100644 --- a/test/parallel/test-http2-perf_hooks.js +++ b/test/parallel/test-http2-perf_hooks.js @@ -1,3 +1,4 @@ +// Flags: --no-warnings 'use strict'; const common = require('../common'); @@ -8,7 +9,7 @@ const h2 = require('http2'); const { PerformanceObserver } = require('perf_hooks'); -const obs = new PerformanceObserver(common.mustCall((items) => { +const obs = new PerformanceObserver(common.mustCallAtLeast((items) => { const entry = items.getEntries()[0]; assert.strictEqual(entry.entryType, 'http2'); assert.strictEqual(typeof entry.startTime, 'number'); @@ -23,14 +24,22 @@ const obs = new PerformanceObserver(common.mustCall((items) => { assert.strictEqual(typeof entry.bytesWritten, 'number'); assert.strictEqual(typeof entry.bytesRead, 'number'); assert.strictEqual(typeof entry.maxConcurrentStreams, 'number'); + assert.strictEqual(typeof entry.detail.pingRTT, 'number'); + assert.strictEqual(typeof entry.detail.streamAverageDuration, 'number'); + assert.strictEqual(typeof entry.detail.streamCount, 'number'); + assert.strictEqual(typeof entry.detail.framesReceived, 'number'); + assert.strictEqual(typeof entry.detail.framesSent, 'number'); + assert.strictEqual(typeof entry.detail.bytesWritten, 'number'); + assert.strictEqual(typeof entry.detail.bytesRead, 'number'); + assert.strictEqual(typeof entry.detail.maxConcurrentStreams, 'number'); switch (entry.type) { case 'server': - assert.strictEqual(entry.streamCount, 1); - assert(entry.framesReceived >= 3); + assert.strictEqual(entry.detail.streamCount, 1); + assert(entry.detail.framesReceived >= 3); break; case 'client': - assert.strictEqual(entry.streamCount, 1); - assert.strictEqual(entry.framesReceived, 7); + assert.strictEqual(entry.detail.streamCount, 1); + assert.strictEqual(entry.detail.framesReceived, 7); break; default: assert.fail('invalid Http2Session type'); @@ -42,20 +51,18 @@ const obs = new PerformanceObserver(common.mustCall((items) => { assert.strictEqual(typeof entry.timeToFirstHeader, 'number'); assert.strictEqual(typeof entry.bytesWritten, 'number'); assert.strictEqual(typeof entry.bytesRead, 'number'); + assert.strictEqual(typeof entry.detail.timeToFirstByte, 'number'); + assert.strictEqual(typeof entry.detail.timeToFirstByteSent, 'number'); + assert.strictEqual(typeof entry.detail.timeToFirstHeader, 'number'); + assert.strictEqual(typeof entry.detail.bytesWritten, 'number'); + assert.strictEqual(typeof entry.detail.bytesRead, 'number'); break; default: assert.fail('invalid entry name'); } -}, 4)); - -// Should throw if entryTypes are not valid -{ - const expectedError = { code: 'ERR_VALID_PERFORMANCE_ENTRY_TYPE' }; - const wrongEntryTypes = { entryTypes: ['foo', 'bar', 'baz'] }; - assert.throws(() => obs.observe(wrongEntryTypes), expectedError); -} +})); -obs.observe({ entryTypes: ['http2'] }); +obs.observe({ type: 'http2' }); const body = '

this is some data

'; diff --git a/test/parallel/test-perf-hooks-usertiming.js b/test/parallel/test-perf-hooks-usertiming.js new file mode 100644 index 00000000000000..401d0a6816481a --- /dev/null +++ b/test/parallel/test-perf-hooks-usertiming.js @@ -0,0 +1,180 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const { + PerformanceObserver, + PerformanceEntry, + PerformanceMark, + performance: { + nodeTiming, + mark, + measure, + clearMarks, + }, +} = require('perf_hooks'); + +assert(PerformanceObserver); +assert(PerformanceEntry); +assert(PerformanceMark); +assert(mark); +assert(measure); + +[undefined, 'a', 'null', 1, true].forEach((i) => { + const m = mark(i); + assert(m instanceof PerformanceEntry); + assert(m instanceof PerformanceMark); + + assert.strictEqual(m.name, `${i}`); + assert.strictEqual(m.entryType, 'mark'); + assert.strictEqual(typeof m.startTime, 'number'); + assert.strictEqual(m.duration, 0); + assert.strictEqual(m.details, undefined); +}); + +clearMarks(); + +assert.throws(() => mark(Symbol('a')), { + message: /Cannot convert a Symbol value to a string/ +}); + +[undefined, null, 1, 'any', {}, []].forEach((detail) => { + const m = mark('a', { detail }); + assert.strictEqual(m.name, 'a'); + assert.strictEqual(m.entryType, 'mark'); + assert.strictEqual(m.detail, detail); +}); + +clearMarks(); + +{ + const m = mark('a', { startTime: 1 }); + assert.strictEqual(m.startTime, 1); +} + +assert.throws(() => mark('a', { startTime: 'a' }), { + code: 'ERR_INVALID_ARG_TYPE' +}); + +clearMarks(); +clearMarks(1); +clearMarks(null); + +assert.throws(() => clearMarks(Symbol('foo')), { + message: /Cannot convert a Symbol value to a string/ +}); + +{ + mark('a', { startTime: 0 }); + mark('b', { startTime: 10 }); + + { + const m3 = measure('foo', 'a', 'b'); + assert.strictEqual(m3.name, 'foo'); + assert.strictEqual(m3.entryType, 'measure'); + assert.strictEqual(m3.startTime, 0); + assert.strictEqual(m3.duration, 10); + } + + { + const m3 = measure('foo', 'a'); + assert.strictEqual(m3.name, 'foo'); + assert.strictEqual(m3.entryType, 'measure'); + assert.strictEqual(m3.startTime, 0); + assert(m3.duration > 0); // Duration is non-deterministic here. + } + + { + const m3 = measure('foo', { start: 'a' }); + assert.strictEqual(m3.name, 'foo'); + assert.strictEqual(m3.entryType, 'measure'); + assert.strictEqual(m3.startTime, 0); + assert(m3.duration > 0); // Duration is non-deterministic here. + } + + { + const m3 = measure('foo', { end: 'b' }); + assert.strictEqual(m3.name, 'foo'); + assert.strictEqual(m3.entryType, 'measure'); + assert.strictEqual(m3.startTime, 0); + assert.strictEqual(m3.duration, 10); + } + + { + const m3 = measure('foo', { duration: 11, end: 'b' }); + assert.strictEqual(m3.name, 'foo'); + assert.strictEqual(m3.entryType, 'measure'); + assert.strictEqual(m3.startTime, -1); + assert.strictEqual(m3.duration, 11); + } + + { + const m3 = measure('foo', { duration: 11, start: 'b' }); + assert.strictEqual(m3.name, 'foo'); + assert.strictEqual(m3.entryType, 'measure'); + assert.strictEqual(m3.startTime, 10); + assert.strictEqual(m3.duration, 11); + } + + { + const m3 = measure('foo', 'nodeStart'); + assert.strictEqual(m3.name, 'foo'); + assert.strictEqual(m3.entryType, 'measure'); + assert.strictEqual(m3.startTime, nodeTiming.nodeStart); + assert(m3.duration > 0); // Duration is non-deterministic here. + } + + { + const m3 = measure('foo', 'nodeStart', 'bootstrapComplete'); + assert.strictEqual(m3.name, 'foo'); + assert.strictEqual(m3.entryType, 'measure'); + assert.strictEqual(m3.startTime, nodeTiming.nodeStart); + assert.strictEqual( + m3.duration, + nodeTiming.bootstrapComplete - nodeTiming.nodeStart); + } + + { + const m3 = measure('foo', { start: 'nodeStart', duration: 10 }); + assert.strictEqual(m3.name, 'foo'); + assert.strictEqual(m3.entryType, 'measure'); + assert.strictEqual(m3.startTime, nodeTiming.nodeStart); + assert.strictEqual(m3.duration, 10); + } + + clearMarks(); +} + +{ + const obs = new PerformanceObserver(common.mustCall((list) => { + { + const entries = list.getEntries(); + assert.strictEqual(entries.length, 3); + } + { + const entries = list.getEntriesByType('mark'); + assert.strictEqual(entries.length, 2); + } + { + const entries = list.getEntriesByType('measure'); + assert.strictEqual(entries.length, 1); + } + { + const entries = list.getEntriesByName('a'); + assert.strictEqual(entries.length, 1); + } + { + const entries = list.getEntriesByName('b'); + assert.strictEqual(entries.length, 1); + } + { + const entries = list.getEntriesByName('a to b'); + assert.strictEqual(entries.length, 1); + } + obs.disconnect(); + })); + obs.observe({ entryTypes: ['mark', 'measure'] }); + mark('a'); + mark('b'); + measure('a to b', 'a', 'b'); +} diff --git a/test/parallel/test-performance-function-async.js b/test/parallel/test-performance-function-async.js new file mode 100644 index 00000000000000..957ff62c38415d --- /dev/null +++ b/test/parallel/test-performance-function-async.js @@ -0,0 +1,40 @@ +'use strict'; + +const common = require('../common'); + +const { + PerformanceObserver, + performance: { + timerify, + }, +} = require('perf_hooks'); + +const assert = require('assert'); + +const { + setTimeout: sleep +} = require('timers/promises'); + +let check = false; + +async function doIt() { + await sleep(100); + check = true; + return check; +} + +const obs = new PerformanceObserver(common.mustCall((list) => { + const entry = list.getEntries()[0]; + assert.strictEqual(entry.name, 'doIt'); + assert(entry.duration > 100); + assert(check); + obs.disconnect(); +})); + +obs.observe({ type: 'function' }); + +const timerified = timerify(doIt); + +const res = timerified(); +assert(res instanceof Promise); +res.then(common.mustCall(assert)); diff --git a/test/parallel/test-performance-gc.js b/test/parallel/test-performance-gc.js index aef0ee14254146..2a489fb67935f4 100644 --- a/test/parallel/test-performance-gc.js +++ b/test/parallel/test-performance-gc.js @@ -1,4 +1,4 @@ -// Flags: --expose-gc +// Flags: --expose-gc --no-warnings 'use strict'; const common = require('../common'); @@ -31,7 +31,9 @@ const kinds = [ assert.strictEqual(entry.name, 'gc'); assert.strictEqual(entry.entryType, 'gc'); assert(kinds.includes(entry.kind)); + assert(kinds.includes(entry.detail.kind)); assert.strictEqual(entry.flags, NODE_PERFORMANCE_GC_FLAGS_FORCED); + assert.strictEqual(entry.detail.flags, NODE_PERFORMANCE_GC_FLAGS_FORCED); assert.strictEqual(typeof entry.startTime, 'number'); assert.strictEqual(typeof entry.duration, 'number'); obs.disconnect(); diff --git a/test/parallel/test-performance-measure.js b/test/parallel/test-performance-measure.js index 06e04cc219c7fd..e9aaca72bdd824 100644 --- a/test/parallel/test-performance-measure.js +++ b/test/parallel/test-performance-measure.js @@ -8,11 +8,11 @@ const DELAY = 1000; const expected = ['Start to Now', 'A to Now', 'A to B']; const obs = new PerformanceObserver(common.mustCall((items) => { - const entries = items.getEntries(); - const { name, duration } = entries[0]; - assert.ok(duration > DELAY); - assert.strictEqual(expected.shift(), name); -}, 3)); + items.getEntries().forEach(({ name, duration }) => { + assert.ok(duration > DELAY); + assert.strictEqual(expected.shift(), name); + }); +})); obs.observe({ entryTypes: ['measure'] }); performance.mark('A'); diff --git a/test/parallel/test-performanceobserver-asynccontext.js b/test/parallel/test-performanceobserver-asynccontext.js deleted file mode 100644 index d3b5bec925d2c3..00000000000000 --- a/test/parallel/test-performanceobserver-asynccontext.js +++ /dev/null @@ -1,37 +0,0 @@ -'use strict'; - -const common = require('../common'); -const assert = require('assert'); -const { - performance, - PerformanceObserver, -} = require('perf_hooks'); -const { - executionAsyncId, - triggerAsyncId, - executionAsyncResource, -} = require('async_hooks'); - -// Test Non-Buffered PerformanceObserver retains async context -{ - const observer = - new PerformanceObserver(common.mustCall(callback)); - - const initialAsyncId = executionAsyncId(); - let asyncIdInTimeout; - let asyncResourceInTimeout; - - function callback(list) { - assert.strictEqual(triggerAsyncId(), initialAsyncId); - assert.strictEqual(executionAsyncId(), asyncIdInTimeout); - assert.strictEqual(executionAsyncResource(), asyncResourceInTimeout); - observer.disconnect(); - } - observer.observe({ entryTypes: ['mark'] }); - - setTimeout(() => { - asyncIdInTimeout = executionAsyncId(); - asyncResourceInTimeout = executionAsyncResource(); - performance.mark('test1'); - }, 0); -} diff --git a/test/parallel/test-performanceobserver.js b/test/parallel/test-performanceobserver.js index 8c4c1bbc9f774e..4862f5fbf02f25 100644 --- a/test/parallel/test-performanceobserver.js +++ b/test/parallel/test-performanceobserver.js @@ -1,8 +1,7 @@ -// Flags: --expose-internals +// Flags: --expose-internals --no-warnings 'use strict'; const common = require('../common'); -const Countdown = require('../common/countdown'); const assert = require('assert'); const { inspect } = require('util'); const { internalBinding } = require('internal/test/binding'); @@ -16,18 +15,12 @@ const { } = require('perf_hooks'); const { - NODE_PERFORMANCE_ENTRY_TYPE_NODE, - NODE_PERFORMANCE_ENTRY_TYPE_MARK, - NODE_PERFORMANCE_ENTRY_TYPE_MEASURE, NODE_PERFORMANCE_ENTRY_TYPE_GC, - NODE_PERFORMANCE_ENTRY_TYPE_FUNCTION, + NODE_PERFORMANCE_ENTRY_TYPE_HTTP2, } = constants; -assert.strictEqual(counts[NODE_PERFORMANCE_ENTRY_TYPE_NODE], 0); -assert.strictEqual(counts[NODE_PERFORMANCE_ENTRY_TYPE_MARK], 0); -assert.strictEqual(counts[NODE_PERFORMANCE_ENTRY_TYPE_MEASURE], 0); assert.strictEqual(counts[NODE_PERFORMANCE_ENTRY_TYPE_GC], 0); -assert.strictEqual(counts[NODE_PERFORMANCE_ENTRY_TYPE_FUNCTION], 0); +assert.strictEqual(counts[NODE_PERFORMANCE_ENTRY_TYPE_HTTP2], 0); { [1, null, undefined, {}, [], Infinity].forEach((i) => { @@ -42,7 +35,7 @@ assert.strictEqual(counts[NODE_PERFORMANCE_ENTRY_TYPE_FUNCTION], 0); }); const observer = new PerformanceObserver(common.mustNotCall()); - [1, null, undefined].forEach((input) => { + [1, 'test'].forEach((input) => { assert.throws( () => observer.observe(input), { @@ -53,13 +46,11 @@ assert.strictEqual(counts[NODE_PERFORMANCE_ENTRY_TYPE_FUNCTION], 0); }); }); - [1, undefined, null, {}, Infinity].forEach((i) => { + [1, null, {}, Infinity].forEach((i) => { assert.throws(() => observer.observe({ entryTypes: i }), { - code: 'ERR_INVALID_ARG_VALUE', - name: 'TypeError', - message: "The property 'options.entryTypes' is invalid. " + - `Received ${inspect(i)}` + code: 'ERR_INVALID_ARG_TYPE', + name: 'TypeError' }); }); @@ -67,83 +58,21 @@ assert.strictEqual(counts[NODE_PERFORMANCE_ENTRY_TYPE_FUNCTION], 0); obs.observe({ entryTypes: ['mark', 'mark'] }); obs.disconnect(); performance.mark('42'); - assert.strictEqual(counts[NODE_PERFORMANCE_ENTRY_TYPE_MARK], 0); } // Test Non-Buffered { const observer = - new PerformanceObserver(common.mustCall(callback, 3)); - - const countdown = - new Countdown(3, () => { - observer.disconnect(); - assert.strictEqual(counts[NODE_PERFORMANCE_ENTRY_TYPE_MARK], 0); - }); - - function callback(list, obs) { - assert.strictEqual(obs, observer); - const entries = list.getEntries(); - assert.strictEqual(entries.length, 1); - countdown.dec(); - } - assert.strictEqual(counts[NODE_PERFORMANCE_ENTRY_TYPE_MARK], 0); - assert.strictEqual(counts[NODE_PERFORMANCE_ENTRY_TYPE_NODE], 0); - observer.observe({ entryTypes: ['mark', 'node'] }); - assert.strictEqual(counts[NODE_PERFORMANCE_ENTRY_TYPE_MARK], 1); - assert.strictEqual(counts[NODE_PERFORMANCE_ENTRY_TYPE_NODE], 1); - performance.mark('test1'); - performance.mark('test2'); - performance.mark('test3'); -} - - -// Test Buffered -{ - const observer = - new PerformanceObserver(common.mustCall(callback, 1)); - assert.strictEqual(counts[NODE_PERFORMANCE_ENTRY_TYPE_MARK], 0); + new PerformanceObserver(common.mustCall(callback)); function callback(list, obs) { assert.strictEqual(obs, observer); const entries = list.getEntries(); assert.strictEqual(entries.length, 3); observer.disconnect(); - assert.strictEqual(counts[NODE_PERFORMANCE_ENTRY_TYPE_MARK], 0); - - { - const entriesByName = list.getEntriesByName('test1'); - assert.strictEqual(entriesByName.length, 1); - assert.strictEqual(entriesByName[0].name, 'test1'); - assert.strictEqual(entriesByName[0].entryType, 'mark'); - } - - { - const entriesByName = list.getEntriesByName('test1', 'mark'); - assert.strictEqual(entriesByName.length, 1); - assert.strictEqual(entriesByName[0].name, 'test1'); - assert.strictEqual(entriesByName[0].entryType, 'mark'); - } - - { - const entriesByName = list.getEntriesByName('test1', 'measure'); - assert.strictEqual(entriesByName.length, 0); - } - - { - const entriesByType = list.getEntriesByType('measure'); - assert.strictEqual(entriesByType.length, 1); - assert.strictEqual(entriesByType[0].name, 'test3'); - assert.strictEqual(entriesByType[0].entryType, 'measure'); - } } - - observer.observe({ entryTypes: ['mark', 'measure'], buffered: true }); - // Do this twice to make sure it doesn't throw - observer.observe({ entryTypes: ['mark', 'measure'], buffered: true }); - // Even tho we called twice, count should be 1 - assert.strictEqual(counts[NODE_PERFORMANCE_ENTRY_TYPE_MARK], 1); + observer.observe({ entryTypes: ['mark', 'node'] }); performance.mark('test1'); performance.mark('test2'); - performance.measure('test3', 'test1', 'test2'); + performance.mark('test3'); } diff --git a/test/parallel/test-trace-events-api.js b/test/parallel/test-trace-events-api.js index 344c2ae47375c9..fa152334bea26c 100644 --- a/test/parallel/test-trace-events-api.js +++ b/test/parallel/test-trace-events-api.js @@ -1,7 +1,8 @@ -// Flags: --expose-gc --no-warnings +// Flags: --expose-gc --no-warnings --expose-internals 'use strict'; const common = require('../common'); +common.skipIfWorker(); // https://github.com/nodejs/node/issues/22767 try { require('trace_events'); @@ -9,8 +10,6 @@ try { common.skip('missing trace events'); } -common.skipIfWorker(); // https://github.com/nodejs/node/issues/22767 - const assert = require('assert'); const cp = require('child_process'); const path = require('path'); @@ -79,22 +78,24 @@ tracing2.disable(); // Purposefully disable twice to test calling twice assert.strictEqual(getEnabledCategories(), enabledCategories); if (isChild) { + const { internalBinding } = require('internal/test/binding'); + + const { + trace: { + TRACE_EVENT_PHASE_NESTABLE_ASYNC_BEGIN: kBeforeEvent, + TRACE_EVENT_PHASE_NESTABLE_ASYNC_END: kEndEvent, + } + } = internalBinding('constants'); + + const { trace } = internalBinding('trace_events'); + tracing.enable(); - const { performance } = require('perf_hooks'); - // Will emit mark and measure trace events - performance.mark('A'); + trace(kBeforeEvent, 'foo', 'test1', 0, 'test'); setTimeout(() => { - performance.mark('B'); - performance.measure('A to B', 'A', 'B'); + trace(kEndEvent, 'foo', 'test1'); }, 1); - - // Intentional non-op, part of the test - function f() {} - const ff = performance.timerify(f); - ff(); // Will emit a timerify trace event } else { - // Test that enabled tracing references do not get garbage collected // until after they are disabled. { @@ -120,7 +121,7 @@ if (isChild) { } } - testApiInChildProcess([], () => { + testApiInChildProcess(['--trace-event-categories', 'foo'], () => { testApiInChildProcess(['--trace-event-categories', 'foo']); }); } @@ -131,19 +132,19 @@ function testApiInChildProcess(execArgs, cb) { const parentDir = process.cwd(); process.chdir(tmpdir.path); - const expectedMarks = ['A', 'B']; - const expectedBegins = [ - { cat: 'node,node.perf,node.perf.timerify', name: 'f' }, - { cat: 'node,node.perf,node.perf.usertiming', name: 'A to B' } - ]; - const expectedEnds = [ - { cat: 'node,node.perf,node.perf.timerify', name: 'f' }, - { cat: 'node,node.perf,node.perf.usertiming', name: 'A to B' } - ]; + const expectedBegins = [{ cat: 'foo', name: 'test1' }]; + const expectedEnds = [{ cat: 'foo', name: 'test1' }]; const proc = cp.fork(__filename, ['child'], - { execArgv: [ '--expose-gc', ...execArgs ] }); + { + execArgv: [ + '--expose-gc', + '--expose-internals', + '--no-warnings', + ...execArgs + ] + }); proc.once('exit', common.mustCall(() => { const file = path.join(tmpdir.path, 'node_trace.1.log'); @@ -152,20 +153,14 @@ function testApiInChildProcess(execArgs, cb) { fs.readFile(file, common.mustSucceed((data) => { const traces = JSON.parse(data.toString()).traceEvents .filter((trace) => trace.cat !== '__metadata'); - assert.strictEqual(traces.length, - expectedMarks.length + - expectedBegins.length + - expectedEnds.length); + + assert.strictEqual( + traces.length, + expectedBegins.length + expectedEnds.length); traces.forEach((trace) => { assert.strictEqual(trace.pid, proc.pid); switch (trace.ph) { - case 'R': - assert.strictEqual(trace.cat, - 'node,node.perf,node.perf.usertiming'); - assert.strictEqual(trace.name, - expectedMarks.shift()); - break; case 'b': const expectedBegin = expectedBegins.shift(); assert.strictEqual(trace.cat, expectedBegin.cat); diff --git a/test/parallel/test-trace-events-dynamic-enable.js b/test/parallel/test-trace-events-dynamic-enable.js index b10152370f0116..237bb1de8df743 100644 --- a/test/parallel/test-trace-events-dynamic-enable.js +++ b/test/parallel/test-trace-events-dynamic-enable.js @@ -1,3 +1,4 @@ +// Flags: --expose-internals 'use strict'; const common = require('../common'); @@ -5,8 +6,17 @@ const common = require('../common'); common.skipIfInspectorDisabled(); common.skipIfWorker(); // https://github.com/nodejs/node/issues/22767 +const { internalBinding } = require('internal/test/binding'); + +const { + trace: { + TRACE_EVENT_PHASE_NESTABLE_ASYNC_BEGIN: kBeforeEvent + } +} = internalBinding('constants'); + +const { trace } = internalBinding('trace_events'); + const assert = require('assert'); -const { performance } = require('perf_hooks'); const { Session } = require('inspector'); const session = new Session(); @@ -33,27 +43,24 @@ async function test() { }); session.on('NodeTracing.tracingComplete', () => tracingComplete = true); - // Generate a node.perf event before tracing is enabled. - performance.mark('mark1'); + trace(kBeforeEvent, 'foo', 'test1', 0, 'test'); - const traceConfig = { includedCategories: ['node.perf'] }; + const traceConfig = { includedCategories: ['foo'] }; await post('NodeTracing.start', { traceConfig }); - // Generate a node.perf event after tracing is enabled. This should be the - // mark event captured. - performance.mark('mark2'); + trace(kBeforeEvent, 'foo', 'test2', 0, 'test'); + trace(kBeforeEvent, 'bar', 'test3', 0, 'test'); await post('NodeTracing.stop', { traceConfig }); - performance.mark('mark3'); - + trace(kBeforeEvent, 'foo', 'test4', 0, 'test'); session.disconnect(); assert.ok(tracingComplete); - const marks = events.filter((t) => null !== /node\.perf\.usertim/.exec(t.cat)); + const marks = events.filter((t) => null !== /foo/.exec(t.cat)); assert.strictEqual(marks.length, 1); - assert.strictEqual(marks[0].name, 'mark2'); + assert.strictEqual(marks[0].name, 'test2'); } test(); diff --git a/test/parallel/test-trace-events-perf.js b/test/parallel/test-trace-events-perf.js deleted file mode 100644 index 2403a8078a47fd..00000000000000 --- a/test/parallel/test-trace-events-perf.js +++ /dev/null @@ -1,84 +0,0 @@ -'use strict'; -const common = require('../common'); -const assert = require('assert'); -const cp = require('child_process'); -const fs = require('fs'); -const path = require('path'); -const tmpdir = require('../common/tmpdir'); - -if (process.argv[2] === 'child') { - const { performance } = require('perf_hooks'); - - // Will emit mark and measure trace events - performance.mark('A'); - setTimeout(() => { - performance.mark('B'); - performance.measure('A to B', 'A', 'B'); - }, 1); - - // Intentional non-op, part of the test - function f() {} - const ff = performance.timerify(f); - ff(); // Will emit a timerify trace event -} else { - tmpdir.refresh(); - - const expectedMarks = ['A', 'B']; - const expectedBegins = [ - { cat: 'node,node.perf,node.perf.timerify', name: 'f' }, - { cat: 'node,node.perf,node.perf.usertiming', name: 'A to B' } - ]; - const expectedEnds = [ - { cat: 'node,node.perf,node.perf.timerify', name: 'f' }, - { cat: 'node,node.perf,node.perf.usertiming', name: 'A to B' } - ]; - - const proc = cp.fork(__filename, - [ - 'child' - ], { - cwd: tmpdir.path, - execArgv: [ - '--trace-event-categories', - 'node.perf' - ] - }); - - proc.once('exit', common.mustCall(() => { - const file = path.join(tmpdir.path, 'node_trace.1.log'); - - assert(fs.existsSync(file)); - fs.readFile(file, common.mustCall((err, data) => { - const traces = JSON.parse(data.toString()).traceEvents - .filter((trace) => trace.cat !== '__metadata'); - assert.strictEqual(traces.length, - expectedMarks.length + - expectedBegins.length + - expectedEnds.length); - - traces.forEach((trace) => { - assert.strictEqual(trace.pid, proc.pid); - switch (trace.ph) { - case 'R': - assert.strictEqual(trace.cat, - 'node,node.perf,node.perf.usertiming'); - assert.strictEqual(trace.name, - expectedMarks.shift()); - break; - case 'b': - const expectedBegin = expectedBegins.shift(); - assert.strictEqual(trace.cat, expectedBegin.cat); - assert.strictEqual(trace.name, expectedBegin.name); - break; - case 'e': - const expectedEnd = expectedEnds.shift(); - assert.strictEqual(trace.cat, expectedEnd.cat); - assert.strictEqual(trace.name, expectedEnd.name); - break; - default: - assert.fail('Unexpected trace event phase'); - } - }); - })); - })); -} diff --git a/test/sequential/test-perf-hooks.js b/test/sequential/test-perf-hooks.js index c9ac860d347eca..d0ee0f5aad04c8 100644 --- a/test/sequential/test-perf-hooks.js +++ b/test/sequential/test-perf-hooks.js @@ -17,42 +17,6 @@ assert(Math.abs(performance.timeOrigin - Date.now()) < 15000); const inited = performance.now(); assert(inited < 15000); -{ - // Should work without throwing any errors - performance.mark('A'); - performance.clearMarks('A'); - - performance.mark('B'); - performance.clearMarks(); -} - -{ - performance.mark('A'); - [undefined, null, 'foo', 'initialize', 1].forEach((i) => { - performance.measure('test', i, 'A'); // Should not throw. - }); - - [undefined, null, 'foo', 1].forEach((i) => { - assert.throws( - () => performance.measure('test', 'A', i), - { - code: 'ERR_INVALID_PERFORMANCE_MARK', - name: 'Error', - message: `The "${i}" performance mark has not been set` - }); - }); - - performance.clearMarks(); -} - -{ - performance.mark('A'); - setImmediate(() => { - performance.mark('B'); - performance.measure('foo', 'A', 'B'); - }); -} - assert.strictEqual(performance.nodeTiming.name, 'node'); assert.strictEqual(performance.nodeTiming.entryType, 'node'); diff --git a/test/sequential/test-performance-eventloopdelay.js b/test/sequential/test-performance-eventloopdelay.js index b23e0977428347..b12d3a72341ee9 100644 --- a/test/sequential/test-performance-eventloopdelay.js +++ b/test/sequential/test-performance-eventloopdelay.js @@ -44,7 +44,7 @@ const { sleep } = require('internal/util'); () => monitorEventLoopDelay({ resolution: i }), { name: 'RangeError', - code: 'ERR_INVALID_ARG_VALUE' + code: 'ERR_OUT_OF_RANGE' } ); });