diff --git a/README.md b/README.md index 3690bd5..222ed6f 100644 --- a/README.md +++ b/README.md @@ -27,6 +27,15 @@ It supports Fastify versions `>=3.0.0`. - [Notes](#notes) - [Metrics collected](#metrics-collected) - [Decorators](#decorators) + - [`fastify.stats`](#fastifystats) + - [`fastify.doc`:](#fastifydoc) + - [`fastify.hrtime2ns(time)`](#fastifyhrtime2nstime) + - [`fastify.hrtime2us(time)`](#fastifyhrtime2ustime) + - [`fastify.hrtime2ms(time)`](#fastifyhrtime2mstime) + - [`fastify.hrtime2s(time)`](#fastifyhrtime2stime) + - [`fastify.timerify(fn[, options])`](#fastifytimerifyfn-options) + - [Caveats](#caveats) + - [onSend(name, value)](#onsendname-value) - [Hooks](#hooks) - [API](#api) - [Configuration `options`](#configuration-options) @@ -107,13 +116,61 @@ These are the metrics that are collected automatically. ## Decorators -The plugin adds the following decorators: +The plugin adds the following decorators. -- `fastify.stats`: A [dats](https://github.com/immobiliare/dats) instance -- `fastify.doc`: A [doc](https://github.com/dnlup/doc) instance used to sample process metrics, if `options.collect.health` is `true -- `fastify.hrtime2ns`: A utility function to convert the legacy `process.hrtime([time])` value to nanoseconds -- `fastify.hrtime2ms`: A utility function to convert the legacy `process.hrtime([time])` value to milliseconds -- `fastify.hrtime2s`: A utility function to convert the legacy `process.hrtime([time])` value to seconds +### `fastify.stats` + +- [``](https://github.com/immobiliare/dats#client) + +A [dats](https://github.com/immobiliare/dats) instance. + +### `fastify.doc`: + +- [``](https://github.com/dnlup/doc#class-docsampler) + +A [doc](https://github.com/dnlup/doc) sampler instance used to sample process metrics, if `options.collect.health` is `true`. + +### `fastify.hrtime2ns(time)` + +A [utility function](https://github.com/dnlup/hrtime-utils#hrtime2nstime) to convert the legacy `process.hrtime([time])` value to nanoseconds. + +### `fastify.hrtime2us(time)` + +A [utility function](https://github.com/dnlup/hrtime-utils#hrtime2ustime) to convert the legacy `process.hrtime([time])` value to microseconds. + +### `fastify.hrtime2ms(time)` + +A [utility function](https://github.com/dnlup/hrtime-utils#hrtime2mstime) to convert the legacy `process.hrtime([time])` value to milliseconds. + +### `fastify.hrtime2s(time)` + +A [utility function](https://github.com/dnlup/hrtime-utils#hrtime2stime) to convert the legacy `process.hrtime([time])` value to seconds. + +### `fastify.timerify(fn[, options])` + +- `fn` [``](https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/Function): the function to time. It can be a sync function, an async function, a function returning a promise, or a constructor. Functions with the callback pattern are not supported. +- `options` [``](https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/Object): optional configuration options. + - `label` [``](https://developer.mozilla.org/en-US/docs/Web/JavaScript/Data_structures#String_type): the label of the metric, by default is the function name. + - `onSend` [``](https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/Function): a custom function to send the timing metric. By default it is a function that send the execution time in millisencods with the passed `name` as label. See the [`onSend`](#onsendname-value) definition. + - `timerifyOptions` [``](https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/Object): the same options object used to configure the Node core [`timerify`](https://nodejs.org/dist/latest-v16.x/docs/api/perf_hooks.html#performancetimerifyfn-options) function. + +It creates a new function that automatically tracks its execution time and sends the corresponding metric. + +TODO: add examples + +#### Caveats + +This decorator uses the core [`timerify`](https://nodejs.org/dist/latest-v16.x/docs/api/perf_hooks.html#performancetimerifyfn-options) api in conjunction with a [`PerformanceObserver`](https://nodejs.org/dist/latest-v16.x/docs/api/perf_hooks.html#class-perf_hooksperformanceobserver) to time the execution of a function. +Since the `name` property of the original function is used to create a [`PerfomanceEntry`](https://nodejs.org/dist/latest-v16.x/docs/api/perf_hooks.html#class-performanceentry) in the timeline, passing anonymous functions or using the same name for multiple functions will result in conflicts when the `PerformanceObserver` callback of this decorator function tries to understand which execution time has been tracked. So, avoid using conflicting names when creating timerified functions whenever possible. + +#### onSend(name, value) + +- `name` [``](https://developer.mozilla.org/en-US/docs/Web/JavaScript/Data_structures#String_type): the label of the metric. +- `value` [``](https://nodejs.org/dist/latest-v16.x/docs/api/perf_hooks.html#class-performanceentry): the performance entry of the function. + +A syncronous function to send the function execution time. The function context is bound to the `fastify` instance that registered the plugin. + +TODO: add examples ## Hooks @@ -137,7 +194,7 @@ This module exports a [plugin registration function](https://github.com/fastify/ - `bufferSize`: Number. Metrics buffer size. See [dats](https://github.com/immobiliare/dats#new-clientoptions). - `bufferFlushTimeout`: Number. Metrics buffer flush timeout. See [dats](https://github.com/immobiliare/dats#new-clientoptions). - `sampleInterval`: Number. Optional. Sample interval in `ms` used to gather process stats. Defaults to `1000`. -- `onError`: Function: `(err) => void`. Optional. This function to handle possible Dats errors. See [dats](https://github.com/immobiliare/dats#new-clientoptions). Default: `(err) => log(err)` +- `onError`: Function: `(err) => void`. Optional. This function to handle possible Dats errors. See [dats](https://github.com/immobiliare/dats#new-clientoptions). Default: `(err) => fastify.log.error(err)` - `udpDnsCache`: Boolean. Optional. Activate udpDnsCache. Default `true`. - `udpDnsCacheTTL`: Number. Optional. DNS cache Time to live of an entry in seconds. Default `120`. - `collect`: Object. Optional. Which metrics the plugin should track. diff --git a/index.d.ts b/index.d.ts index d0cb95e..c01d336 100644 --- a/index.d.ts +++ b/index.d.ts @@ -1,8 +1,24 @@ -import { FastifyPluginCallback, FastifyPluginAsync } from 'fastify'; - +import { + FastifyInstance, + FastifyPluginCallback, + FastifyPluginAsync, +} from 'fastify'; +import { TimerifyOptions, PerformanceEntry } from 'perf_hooks'; import Client, { Options } from '@immobiliarelabs/dats'; import { Sampler } from '@dnlup/doc'; +export type OnSendHook = ( + this: FastifyInstance, + name: string, + value: PerformanceEntry +) => void; + +export type MetricsTimerifyOptions = { + label?: string; + onSend?: OnSendHook; + timerifyOptions?: TimerifyOptions; +}; + export interface MetricsPluginOptions extends Options { sampleInterval?: number; collect?: { @@ -23,7 +39,12 @@ declare module 'fastify' { stats: Client; doc?: Sampler; hrtime2ns: (time: [number, number]) => number; + hrtime2us: (time: [number, number]) => number; hrtime2ms: (time: [number, number]) => number; hrtime2s: (time: [number, number]) => number; + timerify any>( + fn: T, + options?: MetricsTimerifyOptions + ): T; } } diff --git a/index.js b/index.js index 81f50e6..bbbf526 100644 --- a/index.js +++ b/index.js @@ -3,7 +3,20 @@ const fp = require('fastify-plugin'); const { default: Client } = require('@immobiliarelabs/dats'); const doc = require('@dnlup/doc'); -const { hrtime2ns, hrtime2ms, hrtime2s } = require('@dnlup/hrtime-utils'); +const { + hrtime2ns, + hrtime2us, + hrtime2ms, + hrtime2s, +} = require('@dnlup/hrtime-utils'); +const { gte16 } = require('./lib/utils'); + +const timerifyNotSupported = () => { + throw new Error('Timerify is supported only on Node version 16 and newer.'); +}; +const timerifyWrap = gte16 + ? require('./lib/timerifyWrap').timerifyWrap + : () => timerifyNotSupported; function clientMock() { const mock = { @@ -109,12 +122,14 @@ module.exports = fp( bufferFlushTimeout, udpDnsCache, udpDnsCacheTTL, - onError: onError, + onError, }) : clientMock(); fastify.decorate('stats', stats); + fastify.decorate('timerify', timerifyWrap(fastify)); fastify.decorate('hrtime2ns', hrtime2ns); + fastify.decorate('hrtime2us', hrtime2us); fastify.decorate('hrtime2ms', hrtime2ms); fastify.decorate('hrtime2s', hrtime2s); diff --git a/index.test-d.ts b/index.test-d.ts index 4ee601f..8cd9509 100644 --- a/index.test-d.ts +++ b/index.test-d.ts @@ -1,5 +1,5 @@ -import { expectType } from 'tsd'; - +import { PerformanceEntry } from 'perf_hooks'; +import { expectType, expectError } from 'tsd'; import Fastify, { FastifyPluginCallback, FastifyPluginAsync } from 'fastify'; import Client from '@immobiliarelabs/dats'; import { Sampler } from '@dnlup/doc'; @@ -17,9 +17,42 @@ const fastify = Fastify(); fastify.register(plugin).after((err) => { if (err) throw err; + expectType<(time: [number, number]) => number>(fastify.hrtime2ns); + expectType<(time: [number, number]) => number>(fastify.hrtime2us); expectType<(time: [number, number]) => number>(fastify.hrtime2ms); - expectType<(time: [number, number]) => number>(fastify.hrtime2ms); - expectType<(time: [number, number]) => number>(fastify.hrtime2ms); + expectType<(time: [number, number]) => number>(fastify.hrtime2s); expectType(fastify.stats); expectType(fastify.doc); + + // These should work + const sendPerfEntry = (name: string, value: PerformanceEntry) => { + console.log(name, value.duration); + }; + let timerified = fastify.timerify(function test1() {}, { label: 'test1' }); + expectType<() => void>(timerified); + fastify.timerify(function test2() {}, { + label: 'test2', + onSend: sendPerfEntry, + }); + fastify.timerify(function test3() {}, { label: 'test3' }); + + // These should not + expectError(fastify.timerify()); + expectError(fastify.timerify('test')); + expectError(fastify.timerify('test', {})); + expectError(fastify.timerify(function test5() {}, { label: 3 })); + expectError( + fastify.timerify(function test6() {}, { + label: 'test', + onSend: 'string', + }) + ); + expectError( + fastify.timerify(function test6() {}, { + label: 'test', + onSend: (label: number, value: number) => { + console.log(label, value); + }, + }) + ); }); diff --git a/lib/timerifyWrap.js b/lib/timerifyWrap.js new file mode 100644 index 0000000..856643a --- /dev/null +++ b/lib/timerifyWrap.js @@ -0,0 +1,86 @@ +'use strict'; + +const { performance, PerformanceObserver } = require('perf_hooks'); + +/** + * A map that associates metrics labels to timerified + * functions and send hooks. + */ +const map = new Map(); +let obs = null; + +const registry = new FinalizationRegistry((label) => { + map.delete(label); + if (map.size === 0 && obs) { + obs.disconnect(); + obs = null; + } +}); + +function wrap(fn, opts) { + // TODO: throw an error if a function woth the same name is already + // present? + const wrapped = performance.timerify(fn, opts.timerifyOptions); + if (!obs) { + obs = new PerformanceObserver((list) => { + for (const entry of list.getEntries()) { + const i = map.get(entry.name); + const name = i[0]; + const onSend = i[1]; + /* istanbul ignore else */ + if (name) { + onSend(name, entry); + } + } + }); + obs.observe({ entryTypes: ['function'] }); + } + map.set(fn.name, [opts.label, opts.onSend, wrapped]); + registry.register(wrapped, opts.label); + return wrapped; +} + +function sendPerfEntry(name, entry) { + this.stats.timing(name, entry.duration); +} + +// This is here just to simplify testing. +exports.clear = function () { + for (const [k, v] of map.entries()) { + registry.unregister(v[2]); + map.delete(k); + } + obs && obs.disconnect(); + obs = null; +}; + +// Bind a timerify wrap factory to a specific fastify instance. +exports.timerifyWrap = function (fastify) { + const _onSend = sendPerfEntry.bind(fastify); + return function timerify(fn, opts) { + if (typeof fn !== 'function') { + throw new Error('You have to pass a function to timerify'); + } + const defaults = { + label: fn.name, + onSend: _onSend, + timerifyOptions: undefined, + }; + const options = Object.assign({}, defaults, opts); + if (typeof options.label !== 'string') { + throw new Error( + 'You have to pass a string to label the timerified function metric' + ); + } + if (typeof options.onSend !== 'function') { + throw new Error( + 'You have to pass a function to the custom onSend hook' + ); + } + if (options.onSend !== _onSend) { + // `this` refers to the fastify instance decorated with the timerify util. + options.onSend = options.onSend.bind(this); + } + return wrap(fn, options); + }; +}; diff --git a/lib/utils.js b/lib/utils.js new file mode 100644 index 0000000..549bff9 --- /dev/null +++ b/lib/utils.js @@ -0,0 +1,3 @@ +'use strict'; + +exports.gte16 = Number(process.version.split('.')[0].replace('v', '')) >= 16; diff --git a/nyc.config.js b/nyc.config.js index 79139cc..b1e7234 100644 --- a/nyc.config.js +++ b/nyc.config.js @@ -1,5 +1,10 @@ 'use strict'; +const defaultExclude = require('@istanbuljs/schema/default-exclude'); +const { gte16 } = require('./lib/utils'); + +const onLt16 = ['lib/timerifyWrap.js', 'lib/sendPerfEntry.js']; + module.exports = { - exclude: ['*tests*'], + exclude: defaultExclude.concat(gte16 ? [] : onLt16), }; diff --git a/package.json b/package.json index d33c9c9..fe9848f 100644 --- a/package.json +++ b/package.json @@ -22,11 +22,11 @@ "files": [ "index.js", "index.d.ts", - "util.js" + "lib" ], "scripts": { "lint": "eslint --fix --ignore-path .gitignore .", - "test": "tsd && nyc --reporter=lcov --reporter=text-summary ava && nyc check-coverage --lines 100 --branches 100 --functions 100", + "test": "tsd && nyc --reporter=lcov --reporter=text-summary ava", "bench:base": "concurrently -k -s first \"node benchmarks/fixtures/base.js\" \"node -e 'setTimeout(() => {}, 1000)' && npx autocannon -c 100 -d 30 http://localhost:3000\"", "bench": "concurrently -k -s first \"node benchmarks/fixtures/withMetrics.js\" \"node benchmarks/fixtures/statsd.js\" \"node -e 'setTimeout(() => {}, 1000)' && npx autocannon -c 100 -d 30 http://localhost:3001\"", "toc": "markdown-toc -i README.md", @@ -80,9 +80,5 @@ "@dnlup/hrtime-utils": "^1.0.1", "@immobiliarelabs/dats": "^1.0.0", "fastify-plugin": "^3.0.0" - }, - "volta": { - "node": "16.12.0", - "npm": "8.1.1" } } diff --git a/tests/plugin.test.js b/tests/plugin.test.js index d41c518..f2b4226 100644 --- a/tests/plugin.test.js +++ b/tests/plugin.test.js @@ -1,15 +1,19 @@ 'use strict'; const test = require('ava'); +const fastify = require('fastify'); const sinon = require('sinon'); -const { StatsdMock } = require('./helpers/statsd'); const { hrtime2ms } = require('@dnlup/hrtime-utils'); +const { StatsdMock } = require('./helpers/statsd'); +const { gte16 } = require('../lib/utils'); +const plugin = require('../'); const PLUGINS_METHODS = ['counter', 'timing', 'gauge', 'set']; +const sleep = (time) => new Promise((resolve) => setTimeout(resolve, time)); async function setup(options) { - const server = require('fastify')(); - server.register(require('../'), options); + const server = fastify(); + server.register(plugin, options); server.get('/', (request, reply) => { reply.send('ok'); }); @@ -25,6 +29,7 @@ async function configMacro(t, options) { t.true(server.hasDecorator('stats')); t.true(server.hasDecorator('doc')); t.true(server.hasDecorator('hrtime2ns')); + t.true(server.hasDecorator('hrtime2us')); t.true(server.hasDecorator('hrtime2ms')); t.true(server.hasDecorator('hrtime2s')); for (const method of PLUGINS_METHODS) { @@ -34,7 +39,6 @@ async function configMacro(t, options) { test.beforeEach(async (t) => { t.context.statsd = new StatsdMock(); - /* eslint require-atomic-updates: 0 */ t.context.address = await t.context.statsd.start(); }); @@ -53,6 +57,8 @@ test.serial('configuration with custom sampleInterval', configMacro, { sampleInterval: 2000, }); +test.serial.todo('should not decorate doc if health is not enabled'); + test.serial('sending process health metrics', async (t) => { const start = process.hrtime(); await setup({ @@ -464,3 +470,150 @@ test.serial( } } ); + +test.serial('timerify bad args', async (t) => { + if (!gte16) { + t.log('skipping test'); + return t.pass(); + } + const list = [ + { + args: [], + message: 'You have to pass a function to timerify', + }, + { + args: [() => {}, { label: 3 }], + message: + 'You have to pass a string to label the timerified function metric', + }, + { + args: [() => {}, { onSend: '' }], + message: 'You have to pass a function to the custom onSend hook', + }, + ]; + for (const opts of list) { + const server = await setup({ + host: `udp://127.0.0.1:${t.context.address.port}`, + namespace: 'ns', + collect: { + timing: false, + hits: false, + errors: false, + health: false, + }, + }); + const error = t.throws(() => server.timerify(...opts.args), { + instanceOf: Error, + }); + t.is(opts.message, error.message, error.stack); + } +}); + +test.serial('timerify', async (t) => { + if (!gte16) { + t.log('skipping test'); + return t.pass(); + } + const { clear } = require('../lib/timerifyWrap'); + t.teardown(clear); + const func = async () => { + await sleep(100); + }; + const server = await setup({ + host: `udp://127.0.0.1:${t.context.address.port}`, + namespace: 'ns', + collect: { + timing: false, + hits: false, + errors: false, + health: false, + }, + }); + + t.true(server.hasDecorator('timerify')); + const timerified = server.timerify(func, { + label: 'func', + }); + await Promise.all([ + new Promise((resolve) => { + t.context.statsd.on('metric', (buffer) => { + t.true(/ns\.func:\d+(\.\d+)?\|ms/.test(buffer.toString())); + resolve(); + }); + }), + timerified(), + ]); + const sameFunc = () => {}; + const func1 = server.timerify(sameFunc); + const func2 = server.timerify(sameFunc); + t.is(func1, func2); +}); + +test.serial('timerify custom onSend', async (t) => { + if (!gte16) { + t.log('skipping test'); + return t.pass(); + } + const { clear } = require('../lib/timerifyWrap'); + t.teardown(clear); + const { PerformanceEntry } = require('perf_hooks'); + + const onSend = sinon.spy(); + const asyncFunc1 = async () => { + await sleep(100); + }; + const asyncFunc2 = async () => { + await sleep(200); + }; + const syncFunc = () => {}; + + const server = await setup({ + host: `udp://127.0.0.1:${t.context.address.port}`, + namespace: 'ns', + collect: { + timing: false, + hits: false, + errors: false, + health: false, + }, + }); + const asyncTimerified1 = server.timerify(asyncFunc1, { + label: 'asyncFunc1', + onSend, + }); + const asyncTimerified2 = server.timerify(asyncFunc2, { + label: 'asyncFunc2', + onSend, + }); + const syncTimerified = server.timerify(syncFunc, { + label: 'syncFunc', + onSend, + }); + const arrowFuncTimerified = server.timerify(() => {}, { + label: 'arrow', + onSend, + }); + const anonFuncTimerified = server.timerify(function () {}, { + label: 'anon', + }); + const asyncJobs = Promise.all([asyncTimerified2(), asyncTimerified1()]); + + syncTimerified(); + // All the anonymous functions will conflict with each other. + arrowFuncTimerified(); + anonFuncTimerified(); + await asyncJobs; + + // Wait for all the callbacks of the perf observer to be fired. + await sleep(100); + + t.is(3, onSend.callCount); + t.is('syncFunc', onSend.firstCall.firstArg); + t.true(onSend.firstCall.lastArg instanceof PerformanceEntry); + t.is('asyncFunc1', onSend.secondCall.firstArg); + t.true(onSend.secondCall.lastArg instanceof PerformanceEntry); + t.is('asyncFunc2', onSend.lastCall.firstArg); + t.true(onSend.lastCall.lastArg instanceof PerformanceEntry); +}); + +test.todo('timerify cleanup');