From 798081655f7c29addbf16512ac7a479be7697970 Mon Sep 17 00:00:00 2001 From: James M Snell Date: Mon, 22 Feb 2021 09:16:32 -0800 Subject: [PATCH 1/2] perf_hooks: add histogram option to timerify Allows setting a `Histogram` object option on timerify to record function execution times over time. Signed-off-by: James M Snell --- doc/api/perf_hooks.md | 9 ++++- lib/internal/histogram.js | 5 +++ lib/internal/perf/timerify.js | 33 +++++++++++++++--- test/parallel/test-performance-function.js | 40 ++++++++++++++++++++++ 4 files changed, 82 insertions(+), 5 deletions(-) diff --git a/doc/api/perf_hooks.md b/doc/api/perf_hooks.md index 596bc3025b36e8..c64e8a5cde9843 100644 --- a/doc/api/perf_hooks.md +++ b/doc/api/perf_hooks.md @@ -210,10 +210,13 @@ added: v8.5.0 The [`timeOrigin`][] specifies the high resolution millisecond timestamp at which the current `node` process began, measured in Unix time. -### `performance.timerify(fn)` +### `performance.timerify(fn[, options])` * `fn` {Function} +* `options` {Object} + * `histogram` {RecordableHistogram} A histogram object created using + `perf_hooks.createHistogram()` that will record runtime durations in + nanoseconds. _This property is an extension by Node.js. It is not available in Web browsers._ diff --git a/lib/internal/histogram.js b/lib/internal/histogram.js index 7a8d79ce4a641b..2df321300fb87e 100644 --- a/lib/internal/histogram.js +++ b/lib/internal/histogram.js @@ -42,6 +42,10 @@ const { JSTransferable, } = require('internal/worker/js_transferable'); +function isHistogram(object) { + return object?.[kHandle] !== undefined; +} + class Histogram extends JSTransferable { constructor(internal) { super(); @@ -193,6 +197,7 @@ module.exports = { RecordableHistogram, InternalHistogram, InternalRecordableHistogram, + isHistogram, kDestroy, kHandle, createHistogram, diff --git a/lib/internal/perf/timerify.js b/lib/internal/perf/timerify.js index e79b870f2a2911..1108f5efb91392 100644 --- a/lib/internal/perf/timerify.js +++ b/lib/internal/perf/timerify.js @@ -3,6 +3,7 @@ const { FunctionPrototypeBind, ObjectDefineProperties, + MathCeil, ReflectApply, ReflectConstruct, Symbol, @@ -13,6 +14,14 @@ const { now, } = require('internal/perf/perf'); +const { + validateObject +} = require('internal/validators'); + +const { + isHistogram +} = require('internal/histogram'); + const { isConstructor, } = internalBinding('util'); @@ -29,8 +38,10 @@ const { const kTimerified = Symbol('kTimerified'); -function processComplete(name, start, args) { +function processComplete(name, start, args, histogram) { const duration = now() - start; + if (histogram !== undefined) + histogram.record(MathCeil(duration * 1e6)); const entry = new InternalPerformanceEntry( name, @@ -45,10 +56,23 @@ function processComplete(name, start, args) { enqueue(entry); } -function timerify(fn) { +function timerify(fn, options = {}) { if (typeof fn !== 'function') throw new ERR_INVALID_ARG_TYPE('fn', 'function', fn); + validateObject(options, 'options'); + const { + histogram + } = options; + + if (histogram !== undefined && + (!isHistogram(histogram) || typeof histogram.record !== 'function')) { + throw new ERR_INVALID_ARG_TYPE( + 'options.histogram', + 'RecordableHistogram', + histogram); + } + if (fn[kTimerified]) return fn[kTimerified]; const constructor = isConstructor(fn); @@ -65,9 +89,10 @@ function timerify(fn) { result, fn.name, start, - args)); + args, + histogram)); } - processComplete(fn.name, start, args); + processComplete(fn.name, start, args, histogram); return result; } diff --git a/test/parallel/test-performance-function.js b/test/parallel/test-performance-function.js index 883def6565947b..ea928028208e47 100644 --- a/test/parallel/test-performance-function.js +++ b/test/parallel/test-performance-function.js @@ -4,10 +4,15 @@ const common = require('../common'); const assert = require('assert'); const { + createHistogram, performance, PerformanceObserver } = require('perf_hooks'); +const { + setTimeout: sleep +} = require('timers/promises'); + { // Intentional non-op. Do not wrap in common.mustCall(); const n = performance.timerify(function noop() {}); @@ -81,3 +86,38 @@ const { assert.strictEqual(n.length, m.length); assert.strictEqual(n.name, 'timerified m'); } + +(async () => { + const histogram = createHistogram(); + const m = (a, b = 1) => {}; + const n = performance.timerify(m, { histogram }); + assert.strictEqual(histogram.max, 0); + for (let i = 0; i < 10; i++) { + n(); + await sleep(10); + } + assert.notStrictEqual(histogram.max, 0); + [1, '', {}, [], false].forEach((histogram) => { + assert.throws(() => performance.timerify(m, { histogram }), { + code: 'ERR_INVALID_ARG_TYPE' + }); + }); +})().then(common.mustCall()); + +(async () => { + const histogram = createHistogram(); + const m = async (a, b = 1) => { + await sleep(10); + }; + const n = performance.timerify(m, { histogram }); + assert.strictEqual(histogram.max, 0); + for (let i = 0; i < 10; i++) { + await n(); + } + assert.notStrictEqual(histogram.max, 0); + [1, '', {}, [], false].forEach((histogram) => { + assert.throws(() => performance.timerify(m, { histogram }), { + code: 'ERR_INVALID_ARG_TYPE' + }); + }); +})().then(common.mustCall()); From 9bdfbee58d64b5b3c13a50656b90daf2c5b032de Mon Sep 17 00:00:00 2001 From: James M Snell Date: Tue, 23 Feb 2021 06:41:07 -0800 Subject: [PATCH 2/2] [Squash] nit MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Michaël Zasso --- doc/api/perf_hooks.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/doc/api/perf_hooks.md b/doc/api/perf_hooks.md index c64e8a5cde9843..4822ca331ee9ce 100644 --- a/doc/api/perf_hooks.md +++ b/doc/api/perf_hooks.md @@ -215,7 +215,7 @@ which the current `node` process began, measured in Unix time. added: v8.5.0 changes: - version: REPLACEME - pr-url: https://github.com/nodejs/node/pull/00000 + pr-url: https://github.com/nodejs/node/pull/37475 description: Added the histogram option. - version: REPLACEME pr-url: https://github.com/nodejs/node/pull/37136