diff --git a/README.md b/README.md index 610fd38..817aa42 100644 --- a/README.md +++ b/README.md @@ -86,56 +86,57 @@ As far as we know, it is one of the fastest loggers in town: `pino.info('hello world')`: ``` -benchBunyan*10000: 1355.229ms -benchWinston*10000: 2226.117ms -benchBole*10000: 291.727ms -benchDebug*10000: 445.291ms -benchLogLevel*10000: 322.181ms -benchPino*10000: 269.109ms -benchPinoExtreme*10000: 102.239ms +BASIC benchmark averages +Bunyan average: 549.042ms +Winston average: 467.873ms +Bole average: 201.529ms +Debug average: 253.724ms +LogLevel average: 282.653ms +Pino average: 188.956ms +PinoExtreme average: 108.809ms ``` `pino.info({'hello': 'world'})`: ``` -benchBunyanObj*10000: 1464.568ms -benchWinstonObj*10000: 2177.602ms -benchBoleObj*10000: 322.105ms -benchLogLevelObject*10000: 1443.148ms -benchPinoObj*10000: 309.564ms -benchPinoUnsafeObj*10000: 301.308ms -benchPinoExtremeObj*10000: 130.343ms -benchPinoUnsafeExtremeObj*10000: 131.322ms +OBJECT benchmark averages +BunyanObj average: 564.363ms +WinstonObj average: 464.824ms +BoleObj average: 230.220ms +LogLevelObject average: 474.857ms +PinoObj average: 201.442ms +PinoUnsafeObj average: 202.687ms +PinoExtremeObj average: 108.689ms +PinoUnsafeExtremeObj average: 106.718ms ``` `pino.info(aBigDeeplyNestedObject)`: ``` -benchBunyanDeepObj*10000: 8749.174ms -benchWinstonDeepObj*10000: 17761.409ms -benchBoleDeepObj*10000: 5252.563ms -benchLogLevelDeepObj*10000: 43518.525ms -benchPinoDeepObj*10000: 5124.361ms -benchPinoUnsafeDeepObj*10000: 3539.253ms -benchPinoExtremeDeepObj*10000: 5138.457ms -benchPinoUnsafeExtremeDeepObj*10000: 3480.270ms +DEEPOBJECT benchmark averages +BunyanDeepObj average: 5293.279ms +WinstonDeepObj average: 9020.292ms +BoleDeepObj average: 9169.043ms +LogLevelDeepObj average: 15260.917ms +PinoDeepObj average: 8467.807ms +PinoUnsafeDeepObj average: 6159.227ms +PinoExtremeDeepObj average: 8354.557ms +PinoUnsafeExtremeDeepObj average: 6214.073ms ``` `pino.info('hello %s %j %d', 'world', {obj: true}, 4, {another: 'obj'})`: ``` -benchDebugInterpolateExtra*10000: 640.001ms -benchBunyanInterpolateExtra*10000: 2888.825ms -benchWinstonInterpolateExtra*10000: 2616.285ms -benchBoleInterpolateExtra*10000: 1313.470ms -benchLogLevelInterpolateExtra*10000: 1487.610ms -benchPinoInterpolateExtra*10000: 486.367ms -benchPinoUnsafeInterpolateExtra*10000: 457.778ms -benchPinoExtremeInterpolateExtra*10000: 314.635ms -benchPinoUnsafeExtremeInterpolateExtra*10000: 294.915ms +BunyanInterpolateExtra average: 778.408ms +WinstonInterpolateExtra average: 627.956ms +BoleInterpolateExtra average: 429.757ms +PinoInterpolateExtra average: 316.043ms +PinoUnsafeInterpolateExtra average: 316.809ms +PinoExtremeInterpolateExtra average: 218.468ms +PinoUnsafeExtremeInterpolateExtra average: 215.040ms ``` -In many cases, pino is over 6x faster than alternatives. +In many cases, pino is over 5x faster than alternatives. For a fair comparison, [LogLevel](http://npm.im/loglevel) was extended to include a timestamp and [bole](http://npm.im/bole) had diff --git a/benchmarks/basic.bench.js b/benchmarks/basic.bench.js index 7972ae7..6678618 100644 --- a/benchmarks/basic.bench.js +++ b/benchmarks/basic.bench.js @@ -31,8 +31,13 @@ require('bole').output({ stream: dest }).setFastTime(true) -winston.add(winston.transports.File, { filename: '/dev/null' }) -winston.remove(winston.transports.Console) +var chill = winston.createLogger({ + transports: [ + new winston.transports.Stream({ + stream: fs.createWriteStream('/dev/null') + }) + ] +}) var run = bench([ function benchBunyan (cb) { @@ -43,7 +48,7 @@ var run = bench([ }, function benchWinston (cb) { for (var i = 0; i < max; i++) { - winston.info('hello world') + chill.log('info', 'hello world') } setImmediate(cb) }, diff --git a/benchmarks/deep-object.bench.js b/benchmarks/deep-object.bench.js index dde6f7f..5a1bef6 100644 --- a/benchmarks/deep-object.bench.js +++ b/benchmarks/deep-object.bench.js @@ -17,7 +17,7 @@ var plogUnsafeExtreme = require('../')({extreme: true, safe: false}, dest) var loglevel = require('./loglevelMock')(dest) -var deep = require('../package.json') +var deep = Object.assign({}, require('../package.json'), { level: 'info' }) deep.deep = Object.assign({}, JSON.parse(JSON.stringify(deep))) deep.deep.deep = Object.assign({}, JSON.parse(JSON.stringify(deep))) deep.deep.deep.deep = Object.assign({}, JSON.parse(JSON.stringify(deep))) @@ -36,8 +36,13 @@ require('bole').output({ stream: dest }).setFastTime(true) -winston.add(winston.transports.File, { filename: '/dev/null' }) -winston.remove(winston.transports.Console) +var chill = winston.createLogger({ + transports: [ + new winston.transports.Stream({ + stream: fs.createWriteStream('/dev/null') + }) + ] +}) var run = bench([ function benchBunyanDeepObj (cb) { @@ -48,7 +53,7 @@ var run = bench([ }, function benchWinstonDeepObj (cb) { for (var i = 0; i < max; i++) { - winston.info(deep) + chill.log(deep) } setImmediate(cb) }, diff --git a/benchmarks/long-string.bench.js b/benchmarks/long-string.bench.js index feb6007..503353b 100644 --- a/benchmarks/long-string.bench.js +++ b/benchmarks/long-string.bench.js @@ -32,8 +32,13 @@ require('bole').output({ stream: dest }).setFastTime(true) -winston.add(winston.transports.File, { filename: '/dev/null' }) -winston.remove(winston.transports.Console) +var chill = winston.createLogger({ + transports: [ + new winston.transports.Stream({ + stream: fs.createWriteStream('/dev/null') + }) + ] +}) var run = bench([ function benchBunyan (cb) { @@ -44,7 +49,7 @@ var run = bench([ }, function benchWinston (cb) { for (var i = 0; i < max; i++) { - winston.info(longStr) + chill.info(longStr) } setImmediate(cb) }, diff --git a/benchmarks/multiArg.bench.js b/benchmarks/multiArg.bench.js index 0368015..cae6757 100644 --- a/benchmarks/multiArg.bench.js +++ b/benchmarks/multiArg.bench.js @@ -40,8 +40,13 @@ require('bole').output({ stream: dest }).setFastTime(true) -winston.add(winston.transports.File, { filename: '/dev/null' }) -winston.remove(winston.transports.Console) +var chill = winston.createLogger({ + transports: [ + new winston.transports.Stream({ + stream: fs.createWriteStream('/dev/null') + }) + ] +}) var run = bench([ function benchBunyanMulti (cb) { @@ -52,7 +57,7 @@ var run = bench([ }, function benchWinstonMulti (cb) { for (var i = 0; i < max; i++) { - winston.info('hello', 'world') + chill.log('info', 'hello', 'world') } setImmediate(cb) }, @@ -94,7 +99,7 @@ var run = bench([ }, function benchWinstonInterpolate (cb) { for (var i = 0; i < max; i++) { - winston.info('hello %s', 'world') + chill.log('info', 'hello %s', 'world') } setImmediate(cb) }, @@ -125,7 +130,7 @@ var run = bench([ function benchWinstonInterpolateAll (cb) { for (var i = 0; i < max; i++) { - winston.info('hello %s %j %d', 'world', {obj: true}, 4) + chill.log('info', 'hello %s %j %d', 'world', {obj: true}, 4) } setImmediate(cb) }, @@ -167,7 +172,7 @@ var run = bench([ }, function benchWinstonInterpolateExtra (cb) { for (var i = 0; i < max; i++) { - winston.info('hello %s %j %d', 'world', {obj: true}, 4, {another: 'obj'}) + chill.log('info', 'hello %s %j %d', 'world', {obj: true}, 4, {another: 'obj'}) } setImmediate(cb) }, @@ -209,7 +214,7 @@ var run = bench([ }, function benchWinstonInterpolateDeep (cb) { for (var i = 0; i < max; i++) { - winston.info('hello %j', deep) + chill.log('info', 'hello %j', deep) } setImmediate(cb) }, diff --git a/benchmarks/object.bench.js b/benchmarks/object.bench.js index 27a2e37..9ad4a52 100644 --- a/benchmarks/object.bench.js +++ b/benchmarks/object.bench.js @@ -30,8 +30,13 @@ require('bole').output({ stream: dest }).setFastTime(true) -winston.add(winston.transports.File, { filename: '/dev/null' }) -winston.remove(winston.transports.Console) +var chill = winston.createLogger({ + transports: [ + new winston.transports.Stream({ + stream: fs.createWriteStream('/dev/null') + }) + ] +}) var run = bench([ function benchBunyanObj (cb) { @@ -42,7 +47,7 @@ var run = bench([ }, function benchWinstonObj (cb) { for (var i = 0; i < max; i++) { - winston.info({ hello: 'world' }) + chill.info({ hello: 'world' }) } setImmediate(cb) }, diff --git a/benchmarks/runbench.js b/benchmarks/runbench.js index fc24a40..b02ea0f 100644 --- a/benchmarks/runbench.js +++ b/benchmarks/runbench.js @@ -1,6 +1,7 @@ 'use strict' var fs = require('fs') +var os = require('os') var path = require('path') var spawn = require('child_process').spawn var pump = require('pump') @@ -76,16 +77,20 @@ function displayResults (results) { console.log('==========') var benchNames = Object.keys(results) for (var i = 0; i < benchNames.length; i += 1) { - console.log(benchNames[i] + ' averages') + console.log(benchNames[i].toUpperCase() + ' benchmark averages') var benchmark = results[benchNames[i]] var loggers = Object.keys(benchmark) for (var j = 0; j < loggers.length; j += 1) { var logger = benchmark[loggers[j]] var average = sum(logger) / logger.length - console.log(loggers[j] + ' average: ' + average) + console.log(loggers[j] + ' average: ' + average.toFixed(3) + 'ms') } } console.log('==========') + console.log('System: %s/%s %s %s ~ %s (cores/threads: %s)', + os.type(), os.platform(), os.arch(), os.release(), + os.cpus()[0].model, os.cpus().length + ) } function toBench (done) { diff --git a/docs/API.md b/docs/API.md index 17c2700..1b161da 100644 --- a/docs/API.md +++ b/docs/API.md @@ -47,7 +47,7 @@ of objects. These functions should return an JSONifiable object and they should never throw. When logging an object, each top-level property matching the exact key of a serializer will be serialized using the defined serializer. - + Alternatively, it is possible to register a serializer under the key `Symbol.for('pino.*')` which will act upon the complete log object, i.e. every property. * `timestamp` (boolean|function): Enables or disables the inclusion of a timestamp in the log message. If a function is supplied, it must synchronously return a JSON string @@ -297,12 +297,18 @@ You can pass `'silent'` to disable logging. + `...` (*): format string values when `msg` is a format string ### Discussion: -Log at `'fatal'` level the given `msg`. If the first argument is an -object, all its properties will be included in the JSON line. -If more args follows `msg`, these will be used to format `msg` using -[`util.format`][util-format]. +Log at `'fatal'` level the given `msg`. The `msg` may contain up to 10 +[format string tokens][formatstrs] (given that the method accetps up to 11 +arguments total). The subsequent parameters passed will be used to fill in these +placeholder tokens with the associated value. Any extra parameters will be +silently ignored. For example, `log.fatal('%s', 'a', 'b')` will only log the +string `a` and ignore the `'b'` parameter. -[util-format]: https://nodejs.org/api/util.html#util_util_format_format +If the first argument is an object, all its properties will be included in the +JSON line. The number of available format string tokens and associated +parameters will be reduced accodringly. + +[formatstrs]: https://nodejs.org/dist/latest-v8.x/docs/api/util.html#util_util_format_format_args ## .error([obj], msg, [...]) @@ -313,10 +319,16 @@ If more args follows `msg`, these will be used to format `msg` using + `...` (*): format string values when `msg` is a format string ### Discussion: -Log at `'error'` level the given `msg`. If the first argument is an -object, all its properties will be included in the JSON line. -If more args follows `msg`, these will be used to format `msg` using -[`util.format`][util-format]. +Log at `'error'` level the given `msg`. The `msg` may contain up to 10 +[format string tokens][formatstrs] (given that the method accetps up to 11 +arguments total). The subsequent parameters passed will be used to fill in these +placeholder tokens with the associated value. Any extra parameters will be +silently ignored. For example, `log.error('%s', 'a', 'b')` will only log the +string `a` and ignore the `'b'` parameter. + +If the first argument is an object, all its properties will be included in the +JSON line. The number of available format string tokens and associated +parameters will be reduced accodringly. ## .warn([obj], msg, [...]) @@ -327,10 +339,16 @@ If more args follows `msg`, these will be used to format `msg` using + `...` (*): format string values when `msg` is a format string ### Discussion: -Log at `'warn'` level the given `msg`. If the first argument is an -object, all its properties will be included in the JSON line. -If more args follows `msg`, these will be used to format `msg` using -[`util.format`][util-format]. +Log at `'warn'` level the given `msg`. The `msg` may contain up to 10 +[format string tokens][formatstrs] (given that the method accetps up to 11 +arguments total). The subsequent parameters passed will be used to fill in these +placeholder tokens with the associated value. Any extra parameters will be +silently ignored. For example, `log.warn('%s', 'a', 'b')` will only log the +string `a` and ignore the `'b'` parameter. + +If the first argument is an object, all its properties will be included in the +JSON line. The number of available format string tokens and associated +parameters will be reduced accodringly. ## .info([obj], msg, [...]) @@ -341,10 +359,16 @@ If more args follows `msg`, these will be used to format `msg` using + `...` (*): format string values when `msg` is a format string ### Discussion: -Log at `'info'` level the given `msg`. If the first argument is an -object, all its properties will be included in the JSON line. -If more args follows `msg`, these will be used to format `msg` using -[`util.format`][util-format]. +Log at `'info'` level the given `msg`. The `msg` may contain up to 10 +[format string tokens][formatstrs] (given that the method accetps up to 11 +arguments total). The subsequent parameters passed will be used to fill in these +placeholder tokens with the associated value. Any extra parameters will be +silently ignored. For example, `log.info('%s', 'a', 'b')` will only log the +string `a` and ignore the `'b'` parameter. + +If the first argument is an object, all its properties will be included in the +JSON line. The number of available format string tokens and associated +parameters will be reduced accodringly. ## .debug([obj], msg, [...]) @@ -355,10 +379,16 @@ If more args follows `msg`, these will be used to format `msg` using + `...` (*): format string values when `msg` is a format string ### Discussion: -Log at `'debug'` level the given `msg`. If the first argument is an -object, all its properties will be included in the JSON line. -If more args follows `msg`, these will be used to format `msg` using -[`util.format`][util-format]. +Log at `'debug'` level the given `msg`. The `msg` may contain up to 10 +[format string tokens][formatstrs] (given that the method accetps up to 11 +arguments total). The subsequent parameters passed will be used to fill in these +placeholder tokens with the associated value. Any extra parameters will be +silently ignored. For example, `log.debug('%s', 'a', 'b')` will only log the +string `a` and ignore the `'b'` parameter. + +If the first argument is an object, all its properties will be included in the +JSON line. The number of available format string tokens and associated +parameters will be reduced accodringly. ## .trace([obj], msg, [...]) @@ -369,10 +399,16 @@ If more args follows `msg`, these will be used to format `msg` using + `...` (*): format string values when `msg` is a format string ### Discussion: -Log at `'trace'` level the given `msg`. If the first argument is an -object, all its properties will be included in the JSON line. -If more args follows `msg`, these will be used to format `msg` using -[`util.format`][util-format]. +Log at `'trace'` level the given `msg`. The `msg` may contain up to 10 +[format string tokens][formatstrs] (given that the method accetps up to 11 +arguments total). The subsequent parameters passed will be used to fill in these +placeholder tokens with the associated value. Any extra parameters will be +silently ignored. For example, `log.trace('%s', 'a', 'b')` will only log the +string `a` and ignore the `'b'` parameter. + +If the first argument is an object, all its properties will be included in the +JSON line. The number of available format string tokens and associated +parameters will be reduced accodringly. ## .flush() diff --git a/package.json b/package.json index f211192..420b5c6 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "pino", - "version": "4.16.0", + "version": "4.16.1", "description": "super fast, all natural json logger", "main": "pino.js", "browser": "./browser.js", @@ -72,7 +72,7 @@ "tap": "^11.1.3", "tape": "^4.9.0", "through2": "^2.0.3", - "winston": "^2.4.1", + "winston": "^3.0.0-rc3", "zuul": "^3.11.1" }, "dependencies": {