From 171e102d9b3df339ed209ed95724568a377bd699 Mon Sep 17 00:00:00 2001 From: Matteo Collina Date: Wed, 1 Jun 2022 08:27:43 +0200 Subject: [PATCH] Async by default (#1448) * Remove prettyPrint option. 100% code coverage back. * Remove pino.final * Fix jsdom TS issue * Restore lost error * Add link to pino-pretty * Update Node.js in workflows * Async loggic by default Signed-off-by: Matteo Collina * Update docs/asynchronous.md Co-authored-by: Igor Savin * Update docs/asynchronous.md Co-authored-by: Igor Savin * Update docs/asynchronous.md Co-authored-by: James Sumners * fix flaky test Signed-off-by: Matteo Collina Co-authored-by: Igor Savin Co-authored-by: James Sumners --- benchmarks/basic.bench.js | 6 +-- benchmarks/child-child.bench.js | 6 +-- benchmarks/child-creation.bench.js | 6 +-- benchmarks/child.bench.js | 6 +-- benchmarks/deep-object.bench.js | 6 +-- benchmarks/long-string.bench.js | 6 +-- benchmarks/multi-arg.bench.js | 18 +++---- benchmarks/object.bench.js | 6 +-- docs/api.md | 8 ++- docs/asynchronous.md | 78 +++--------------------------- docs/benchmarks.md | 69 +++++++++++++------------- lib/tools.js | 6 +-- package.json | 2 +- pino.js | 2 +- test/broken-pipe.test.js | 2 +- 15 files changed, 83 insertions(+), 144 deletions(-) diff --git a/benchmarks/basic.bench.js b/benchmarks/basic.bench.js index 7e6abf1b0..9fd597f78 100644 --- a/benchmarks/basic.bench.js +++ b/benchmarks/basic.bench.js @@ -10,7 +10,7 @@ const dest = fs.createWriteStream('/dev/null') const loglevel = require('./utils/wrap-log-level')(dest) const plogNodeStream = pino(dest) delete require.cache[require.resolve('../')] -const plogAsync = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 })) +const plogMinLength = require('../')(pino.destination({ dest: '/dev/null', minLength: 4096 })) delete require.cache[require.resolve('../')] const plogDest = require('../')(pino.destination('/dev/null')) @@ -78,9 +78,9 @@ const run = bench([ } setImmediate(cb) }, - function benchPinoAsync (cb) { + function benchPinoMinLength (cb) { for (var i = 0; i < max; i++) { - plogAsync.info('hello world') + plogMinLength.info('hello world') } setImmediate(cb) }, diff --git a/benchmarks/child-child.bench.js b/benchmarks/child-child.bench.js index 0ee84ec32..12b4d033d 100644 --- a/benchmarks/child-child.bench.js +++ b/benchmarks/child-child.bench.js @@ -9,7 +9,7 @@ const plogNodeStream = pino(dest).child({ a: 'property' }).child({ sub: 'child' delete require.cache[require.resolve('../')] const plogDest = require('../')(pino.destination('/dev/null')) delete require.cache[require.resolve('../')] -const plogAsync = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 })) +const plogMinLength = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 })) .child({ a: 'property' }) .child({ sub: 'child' }) @@ -35,9 +35,9 @@ const run = bench([ } setImmediate(cb) }, - function benchPinoAsyncChildChild (cb) { + function benchPinoMinLengthChildChild (cb) { for (var i = 0; i < max; i++) { - plogAsync.info({ hello: 'world' }) + plogMinLength.info({ hello: 'world' }) } setImmediate(cb) }, diff --git a/benchmarks/child-creation.bench.js b/benchmarks/child-creation.bench.js index b09099f72..97d2c00f0 100644 --- a/benchmarks/child-creation.bench.js +++ b/benchmarks/child-creation.bench.js @@ -9,7 +9,7 @@ const dest = fs.createWriteStream('/dev/null') const plogNodeStream = pino(dest) const plogDest = pino(pino.destination(('/dev/null'))) delete require.cache[require.resolve('../')] -const plogAsync = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 })) +const plogMinLength = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 })) const max = 10 const blog = bunyan.createLogger({ @@ -47,8 +47,8 @@ const run = bench([ } setImmediate(cb) }, - function benchPinoAsyncCreation (cb) { - const child = plogAsync.child({ a: 'property' }) + function benchPinoMinLengthCreation (cb) { + const child = plogMinLength.child({ a: 'property' }) for (var i = 0; i < max; i++) { child.info({ hello: 'world' }) } diff --git a/benchmarks/child.bench.js b/benchmarks/child.bench.js index 786d94724..0d50bc970 100644 --- a/benchmarks/child.bench.js +++ b/benchmarks/child.bench.js @@ -10,7 +10,7 @@ const plogNodeStream = pino(dest).child({ a: 'property' }) delete require.cache[require.resolve('../')] const plogDest = require('../')(pino.destination('/dev/null')).child({ a: 'property' }) delete require.cache[require.resolve('../')] -const plogAsync = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 })) +const plogMinLength = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 })) const max = 10 const blog = bunyan.createLogger({ @@ -45,9 +45,9 @@ const run = bench([ } setImmediate(cb) }, - function benchPinoAsyncChild (cb) { + function benchPinoMinLengthChild (cb) { for (var i = 0; i < max; i++) { - plogAsync.info({ hello: 'world' }) + plogMinLength.info({ hello: 'world' }) } setImmediate(cb) }, diff --git a/benchmarks/deep-object.bench.js b/benchmarks/deep-object.bench.js index 60de8607c..a31347555 100644 --- a/benchmarks/deep-object.bench.js +++ b/benchmarks/deep-object.bench.js @@ -11,7 +11,7 @@ const plogNodeStream = pino(dest) delete require.cache[require.resolve('../')] const plogDest = require('../')(pino.destination('/dev/null')) delete require.cache[require.resolve('../')] -const plogAsync = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 })) +const plogMinLength = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 })) delete require.cache[require.resolve('../')] const loglevel = require('./utils/wrap-log-level')(dest) @@ -71,9 +71,9 @@ const run = bench([ } setImmediate(cb) }, - function benchPinoAsyncDeepObj (cb) { + function benchPinoMinLengthDeepObj (cb) { for (var i = 0; i < max; i++) { - plogAsync.info(deep) + plogMinLength.info(deep) } setImmediate(cb) }, diff --git a/benchmarks/long-string.bench.js b/benchmarks/long-string.bench.js index 579fa3bb3..6747b728a 100644 --- a/benchmarks/long-string.bench.js +++ b/benchmarks/long-string.bench.js @@ -11,7 +11,7 @@ const plogNodeStream = pino(dest) delete require.cache[require.resolve('../')] const plogDest = require('../')(pino.destination('/dev/null')) delete require.cache[require.resolve('../')] -const plogAsync = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 })) +const plogMinLength = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 })) const crypto = require('crypto') @@ -64,9 +64,9 @@ const run = bench([ } setImmediate(cb) }, - function benchPinoAsync (cb) { + function benchPinoMinLength (cb) { for (var i = 0; i < max; i++) { - plogAsync.info(longStr) + plogMinLength.info(longStr) } setImmediate(cb) }, diff --git a/benchmarks/multi-arg.bench.js b/benchmarks/multi-arg.bench.js index 31f35af2a..0c7af6611 100644 --- a/benchmarks/multi-arg.bench.js +++ b/benchmarks/multi-arg.bench.js @@ -11,7 +11,7 @@ const plogNodeStream = pino(dest) delete require.cache[require.resolve('../')] const plogDest = require('../')(pino.destination('/dev/null')) delete require.cache[require.resolve('../')] -const plogAsync = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 })) +const plogMinLength = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 })) delete require.cache[require.resolve('../')] const deep = require('../package.json') @@ -67,9 +67,9 @@ const run = bench([ } setImmediate(cb) }, - function benchPinoAsyncInterpolate (cb) { + function benchPinoMinLengthInterpolate (cb) { for (var i = 0; i < max; i++) { - plogAsync.info('hello %s', 'world') + plogMinLength.info('hello %s', 'world') } setImmediate(cb) }, @@ -104,9 +104,9 @@ const run = bench([ } setImmediate(cb) }, - function benchPinoAsyncInterpolateAll (cb) { + function benchPinoMinLengthInterpolateAll (cb) { for (var i = 0; i < max; i++) { - plogAsync.info('hello %s %j %d', 'world', { obj: true }, 4) + plogMinLength.info('hello %s %j %d', 'world', { obj: true }, 4) } setImmediate(cb) }, @@ -140,9 +140,9 @@ const run = bench([ } setImmediate(cb) }, - function benchPinoAsyncInterpolateExtra (cb) { + function benchPinoMinLengthInterpolateExtra (cb) { for (var i = 0; i < max; i++) { - plogAsync.info('hello %s %j %d', 'world', { obj: true }, 4, { another: 'obj' }) + plogMinLength.info('hello %s %j %d', 'world', { obj: true }, 4, { another: 'obj' }) } setImmediate(cb) }, @@ -176,9 +176,9 @@ const run = bench([ } setImmediate(cb) }, - function benchPinoAsyncInterpolateDeep (cb) { + function benchPinoMinLengthInterpolateDeep (cb) { for (var i = 0; i < max; i++) { - plogAsync.info('hello %j', deep) + plogMinLength.info('hello %j', deep) } setImmediate(cb) }, diff --git a/benchmarks/object.bench.js b/benchmarks/object.bench.js index 8935461f8..3d75582c5 100644 --- a/benchmarks/object.bench.js +++ b/benchmarks/object.bench.js @@ -12,7 +12,7 @@ const plogNodeStream = pino(dest) delete require.cache[require.resolve('../')] const plogDest = require('../')(pino.destination('/dev/null')) delete require.cache[require.resolve('../')] -const plogAsync = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 })) +const plogMinLength = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 })) const blog = bunyan.createLogger({ name: 'myapp', streams: [{ @@ -65,9 +65,9 @@ const run = bench([ } setImmediate(cb) }, - function benchPinoAsyncObj (cb) { + function benchPinoMinLengthObj (cb) { for (var i = 0; i < max; i++) { - plogAsync.info({ hello: 'world' }) + plogMinLength.info({ hello: 'world' }) } setImmediate(cb) }, diff --git a/docs/api.md b/docs/api.md index 65dcfd240..8f2f883d9 100644 --- a/docs/api.md +++ b/docs/api.md @@ -1000,7 +1000,7 @@ Exposes the Pino package version. Also available on the exported `pino` function ### `pino.destination([opts]) => SonicBoom` Create a Pino Destination instance: a stream-like object with -significantly more throughput (over 30%) than a standard Node.js stream. +significantly more throughput than a standard Node.js stream. ```js const pino = require('pino') @@ -1009,7 +1009,11 @@ const logger2 = pino(pino.destination()) const logger3 = pino(pino.destination({ dest: './my-file', minLength: 4096, // Buffer before writing - sync: false // Asynchronous logging + sync: false // Asynchronous logging, the default +})) +const logger4 = pino(pino.destination({ + dest: './my-file2', + sync: true // Synchronous logging })) ``` diff --git a/docs/asynchronous.md b/docs/asynchronous.md index 1d9dfa414..487ebf81c 100644 --- a/docs/asynchronous.md +++ b/docs/asynchronous.md @@ -1,11 +1,7 @@ # Asynchronous Logging -In essence, asynchronous logging enables even faster performance by Pino. - -In Pino's standard mode of operation log messages are directly written to the -output stream as the messages are generated with a _blocking_ operation. -Asynchronous logging works by buffering -log messages and writing them in larger chunks. +In essence, asynchronous logging enables the minimum overhead of Pino. +Asynchronous logging works by buffering log messages and writing them in larger chunks. ```js const pino = require('pino') @@ -16,74 +12,19 @@ const logger = pino(pino.destination({ })) ``` +It's always possible to turn on synchronous logging by passing `sync: true`. +In this mode of operation log messages are directly written to the +output stream, as the messages are generated with a _blocking_ operation. + * See [`pino.destination`](/docs/api.md#pino-destination) * `pino.destination` is implemented on [`sonic-boom` ⇗](https://github.com/mcollina/sonic-boom). ### AWS Lambda -On AWS Lambda we recommend to call `dest.flushSync()` at the end +Asynchronous logging is disabled by default on AWS Lambda, or any other environment +that modifies `process.stdout`. If forcefully turned on, we recommend to call `dest.flushSync()` at the end of each function execution to avoid losing data. -## Usage - -The `pino.destination({ sync: false })` method will provide an asynchronous destination. - -```js -const pino = require('pino') -const dest = pino.destination({ sync: false }) // logs to stdout with no args -const logger = pino(dest) -``` - - -## Prevent log loss in Node v12 - -In Node.js v14+, streams created by `pino.destination()` are automatically -flushed whenever the process exits. -In Node v12, `pino.final()` can be used to prevent log loss. Here is an example: - -```js -const pino = require('pino') -const dest = pino.destination({ sync: false }) -const logger = pino(dest) - -// asynchronously flush every 10 seconds to keep the buffer empty -// in periods of low activity -setInterval(function () { - logger.flush() -}, 10000).unref() - -// use pino.final to create a special logger that -// guarantees final tick writes -const handler = pino.final(logger, (err, finalLogger, evt) => { - finalLogger.info(`${evt} caught`) - if (err) finalLogger.error(err, 'error caused exit') - process.exit(err ? 1 : 0) -}) -// catch all the ways node might exit -process.on('beforeExit', () => handler(null, 'beforeExit')) -process.on('exit', () => handler(null, 'exit')) -process.on('uncaughtException', (err) => handler(err, 'uncaughtException')) -process.on('SIGINT', () => handler(null, 'SIGINT')) -process.on('SIGQUIT', () => handler(null, 'SIGQUIT')) -process.on('SIGTERM', () => handler(null, 'SIGTERM')) -``` - -The above code will register handlers for the following process events/signals so that -pino can flush the asynchronous logger buffer: - -+ `beforeExit` -+ `exit` -+ `uncaughtException` -+ `SIGINT` -+ `SIGQUIT` -+ `SIGTERM` - -In all of these cases, except `SIGHUP`, the process is in a state that it -*must* terminate. Note that the handler has a `process.exit(1)` at the end. - - -* See also [`pino.final` api](/docs/api.md#pino-final) - ## Caveats Asynchronous logging has a couple of important caveats: @@ -92,9 +33,6 @@ Asynchronous logging has a couple of important caveats: calls to logging methods (e.g. `logger.info`) and writes to a log file * There is a possibility of the most recently buffered log messages being lost in case of a system failure, e.g. a power cut. -* In Node v14+, Pino will register handlers for the `exit` and `beforeExit` handler so that - the stream is flushed automatically. This is implemented with the usage of - [`on-exit-leak-free`](https://github.com/mcollina/on-exit-leak-free). See also: diff --git a/docs/benchmarks.md b/docs/benchmarks.md index ebea56b81..6b6e7698a 100644 --- a/docs/benchmarks.md +++ b/docs/benchmarks.md @@ -1,58 +1,55 @@ -# Benchmarks -The following values show the time spent to call each function 100000 times. +# Benchmarks `pino.info('hello world')`: ``` + BASIC benchmark averages -Bunyan average: 662.904ms -Winston average: 564.752ms -Bole average: 301.894ms -Debug average: 361.052ms -LogLevel average: 330.394ms -Pino average: 246.336ms -PinoAsync average: 129.507ms -PinoNodeStream average: 276.479ms +Bunyan average: 377.434ms +Winston average: 270.249ms +Bole average: 172.690ms +Debug average: 220.527ms +LogLevel average: 222.802ms +Pino average: 114.801ms +PinoMinLength average: 70.968ms +PinoNodeStream average: 159.192ms + ``` `pino.info({'hello': 'world'})`: ``` + OBJECT benchmark averages -BunyanObj average: 678.477ms -WinstonObj average: 563.154ms -BoleObj average: 364.748ms -LogLevelObject average: 627.196ms -PinoObj average: 237.543ms -PinoAsyncObj average: 125.532ms -PinoNodeStreamObj average: 310.614ms +BunyanObj average: 410.379ms +WinstonObj average: 273.120ms +BoleObj average: 185.069ms +LogLevelObject average: 433.425ms +PinoObj average: 119.315ms +PinoMinLengthObj average: 76.968ms +PinoNodeStreamObj average: 164.268ms + ``` `pino.info(aBigDeeplyNestedObject)`: -``` -DEEPOBJECT benchmark averages -BunyanDeepObj average: 1838.970ms -WinstonDeepObj average: 3173.947ms -BoleDeepObj average: 2888.894ms -LogLevelDeepObj average: 7426.592ms -PinoDeepObj average: 3074.177ms -PinoAsyncDeepObj average: 2987.925ms -PinoNodeStreamDeepObj average: 3459.883ms ``` -`pino.info('hello %s %j %d', 'world', {obj: true}, 4, {another: 'obj'})`: +DEEP-OBJECT benchmark averages +BunyanDeepObj average: 1.839ms +WinstonDeepObj average: 5.604ms +BoleDeepObj average: 3.422ms +LogLevelDeepObj average: 11.716ms +PinoDeepObj average: 2.256ms +PinoMinLengthDeepObj average: 2.240ms +PinoNodeStreamDeepObj average: 2.595ms -``` -BunyanInterpolateExtra average: 971.019ms -WinstonInterpolateExtra average: 535.009ms -BoleInterpolateExtra average: 575.668ms -PinoInterpolateExtra average: 332.099ms -PinoAsyncInterpolateExtra average: 209.552ms -PinoNodeStreamInterpolateExtra average: 413.195ms ``` -For a fair comparison, [LogLevel](https://npm.im/loglevel) was extended -to include a timestamp and [bole](https://npm.im/bole) had +`pino.info('hello %s %j %d', 'world', {obj: true}, 4, {another: 'obj'})`: + +For a fair comparison, [LogLevel](http://npm.im/loglevel) was extended +to include a timestamp and [bole](http://npm.im/bole) had `fastTime` mode switched on. + diff --git a/lib/tools.js b/lib/tools.js index 9f855567c..7e37faf4c 100644 --- a/lib/tools.js +++ b/lib/tools.js @@ -266,13 +266,13 @@ function createArgsNormalizer (defaultOptions) { return function normalizeArgs (instance, caller, opts = {}, stream) { // support stream as a string if (typeof opts === 'string') { - stream = buildSafeSonicBoom({ dest: opts, sync: true }) + stream = buildSafeSonicBoom({ dest: opts }) opts = {} } else if (typeof stream === 'string') { if (opts && opts.transport) { throw Error('only one of option.transport or stream can be specified') } - stream = buildSafeSonicBoom({ dest: stream, sync: true }) + stream = buildSafeSonicBoom({ dest: stream }) } else if (opts instanceof SonicBoom || opts.writable || opts._writableState) { stream = opts opts = {} @@ -305,7 +305,7 @@ function createArgsNormalizer (defaultOptions) { if (enabled === false) opts.level = 'silent' stream = stream || process.stdout if (stream === process.stdout && stream.fd >= 0 && !hasBeenTampered(stream)) { - stream = buildSafeSonicBoom({ fd: stream.fd, sync: true }) + stream = buildSafeSonicBoom({ fd: stream.fd }) } return { opts, stream } } diff --git a/package.json b/package.json index aa09bcc24..d83e6ef08 100644 --- a/package.json +++ b/package.json @@ -108,7 +108,7 @@ "dependencies": { "atomic-sleep": "^1.0.0", "fast-redact": "^3.0.0", - "on-exit-leak-free": "^0.2.0", + "on-exit-leak-free": "^1.0.0", "pino-abstract-transport": "v0.5.0", "pino-std-serializers": "^4.0.0", "process-warning": "^1.0.0", diff --git a/pino.js b/pino.js index 667112d96..7dcb489da 100644 --- a/pino.js +++ b/pino.js @@ -190,7 +190,7 @@ module.exports.destination = (dest = process.stdout.fd) => { dest.dest = normalizeDestFileDescriptor(dest.dest || process.stdout.fd) return buildSafeSonicBoom(dest) } else { - return buildSafeSonicBoom({ dest: normalizeDestFileDescriptor(dest), minLength: 0, sync: true }) + return buildSafeSonicBoom({ dest: normalizeDestFileDescriptor(dest), minLength: 0 }) } } diff --git a/test/broken-pipe.test.js b/test/broken-pipe.test.js index bfb9deb3a..7a492b098 100644 --- a/test/broken-pipe.test.js +++ b/test/broken-pipe.test.js @@ -27,7 +27,7 @@ test('syncfalse.js') t.test('let error pass through', ({ equal, plan }) => { plan(3) - const stream = pino.destination() + const stream = pino.destination({ sync: true }) // side effect of the pino constructor is that it will set an // event handler for error