Merge pull request #13 from mcollina/roll-our-own-format

roll our own format func

README.md

@@ -58,26 +58,34 @@ This produces:
 
 As far as we know, it is the fastest logger in town:
 
+`info('hello world')`:
+
+```
+benchBunyan*10000: 1115.193ms
+benchWinston*10000: 1722.497ms
+benchBole*10000: 1640.052ms
+benchPino*10000: 265.622ms
+```
+
+`info({'hello': 'world'})`:
+
+```
+benchBunyanObj*10000: 1252.539ms
+benchWinstonObj*10000: 1729.837ms
+benchBoleObj*10000: 1491.677ms
+benchPinoObj*10000: 365.207ms
+```
+
+`info('hello %s %j %d', 'world', {obj: true}, 4, {another: 'obj'})`:
+
 ```
-benchBunyan*10000: 1230ms
-benchWinston*10000: 2139ms
-benchBole*10000: 1615ms
-benchPino*10000: 314ms
-benchBunyan*10000: 1135ms
-benchWinston*10000: 2025ms
-benchBole*10000: 1635ms
-benchPino*10000: 312ms
-benchBunyanObj*10000: 1480ms
-benchWinstonObj*10000: 2252ms
-benchPinoObj*10000: 409ms
-benchBoleObj*10000: 1765ms
-benchBunyanObj*10000: 1415ms
-benchWinstonObj*10000: 2224ms
-benchPinoObj*10000: 400ms
-benchBoleObj*10000: 1739ms
-benchBunyanObj*10000: 1366ms
+benchBunyanInterpolateExtra*10000: 2607.519ms
+benchWinstonInterpolateExtra*10000: 2258.154ms
+benchBoleInterpolateExtra*10000: 3069.085ms
+benchPinoInterpolateExtra*10000: 450.634ms
 ```
 
+In multiple cases, pino is 6x faster than alternatives.
 
 <a name="cli"></a>
 ## CLI

benchmarks/multiArg.js

@@ -0,0 +1,121 @@
+'use strict'
+
+var bench = require('fastbench')
+var pino = require('../')
+var bunyan = require('bunyan')
+var bole = require('bole')('bench')
+var winston = require('winston')
+var fs = require('fs')
+var dest = fs.createWriteStream('/dev/null')
+var plog = pino(dest)
+var max = 10
+var blog = bunyan.createLogger({
+  name: 'myapp',
+  streams: [{
+    level: 'trace',
+    stream: dest
+  }]
+})
+
+require('bole').output({
+  level: 'info',
+  stream: dest
+})
+
+winston.add(winston.transports.File, { filename: '/dev/null' })
+winston.remove(winston.transports.Console)
+
+var run = bench([
+  function benchBunyanMulti (cb) {
+    for (var i = 0; i < max; i++) {
+      blog.info('hello', 'world')
+    }
+    setImmediate(cb)
+  },
+  function benchWinstonMulti (cb) {
+    for (var i = 0; i < max; i++) {
+      winston.info('hello', 'world')
+    }
+    setImmediate(cb)
+  },
+  function benchBoleMulti (cb) {
+    for (var i = 0; i < max; i++) {
+      bole.info('hello', 'world')
+    }
+    setImmediate(cb)
+  },
+  function benchPinoMulti (cb) {
+    for (var i = 0; i < max; i++) {
+      plog.info('hello', 'world')
+    }
+    setImmediate(cb)
+  },
+  function benchBunyanInterpolate (cb) {
+    for (var i = 0; i < max; i++) {
+      blog.info('hello %s', 'world')
+    }
+    setImmediate(cb)
+  },
+  function benchWinstonInterpolate (cb) {
+    for (var i = 0; i < max; i++) {
+      winston.info('hello %s', 'world')
+    }
+    setImmediate(cb)
+  },
+  function benchBoleInterpolate (cb) {
+    for (var i = 0; i < max; i++) {
+      bole.info('hello %s', 'world')
+    }
+    setImmediate(cb)
+  },
+  function benchBunyanInterpolateAll (cb) {
+    for (var i = 0; i < max; i++) {
+      blog.info('hello %s %j %d', 'world', {obj: true}, 4)
+    }
+    setImmediate(cb)
+  },
+  function benchWinstonInterpolateAll (cb) {
+    for (var i = 0; i < max; i++) {
+      winston.info('hello %s %j %d', 'world', {obj: true}, 4)
+    }
+    setImmediate(cb)
+  },
+  function benchBoleInterpolateAll (cb) {
+    for (var i = 0; i < max; i++) {
+      bole.info('hello %s %j %d', 'world', {obj: true}, 4)
+    }
+    setImmediate(cb)
+  },
+  function benchPinoInterpolateAll (cb) {
+    for (var i = 0; i < max; i++) {
+      plog.info('hello %s %j %d', 'world', {obj: true}, 4)
+    }
+    setImmediate(cb)
+  },
+  function benchBunyanInterpolateExtra (cb) {
+    for (var i = 0; i < max; i++) {
+      blog.info('hello %s %j %d', 'world', {obj: true}, 4, {another: 'obj'})
+    }
+    setImmediate(cb)
+  },
+  function benchWinstonInterpolateExtra (cb) {
+    for (var i = 0; i < max; i++) {
+      winston.info('hello %s %j %d', 'world', {obj: true}, 4, {another: 'obj'})
+    }
+    setImmediate(cb)
+  },
+  function benchBoleInterpolateExtra (cb) {
+    for (var i = 0; i < max; i++) {
+      bole.info('hello %s %j %d', 'world', {obj: true}, 4, {another: 'obj'})
+    }
+    setImmediate(cb)
+  },
+  function benchPinoInterpolateExtra (cb) {
+    for (var i = 0; i < max; i++) {
+      plog.info('hello %s %j %d', 'world', {obj: true}, 4, {another: 'obj'})
+    }
+    setImmediate(cb)
+  }
+], 10000)
+
+run(run)

benchmarks/object.js

@@ -38,15 +38,15 @@ var run = bench([
     }
     setImmediate(cb)
   },
-  function benchPinoObj (cb) {
+  function benchBoleObj (cb) {
     for (var i = 0; i < max; i++) {
-      plog.info({ hello: 'world' })
+      bole.info({ hello: 'world' })
     }
     setImmediate(cb)
   },
-  function benchBoleObj (cb) {
+  function benchPinoObj (cb) {
     for (var i = 0; i < max; i++) {
-      bole.info({ hello: 'world' })
+      plog.info({ hello: 'world' })
     }
     setImmediate(cb)
   }

package.json

@@ -41,6 +41,7 @@
     "core-util-is": "^1.0.2",
     "fast-json-parse": "^1.0.0",
     "json-stringify-safe": "^5.0.1",
+    "quick-format": "^1.0.0",
     "split2": "^2.0.1"
   }
 }

pino.js

@@ -1,7 +1,7 @@
 'use strict'
 
 var stringifySafe = require('json-stringify-safe')
-var format = require('util').format
+var format = require('quick-format')
 var os = require('os')
 var pid = process.pid
 var hostname = os.hostname()
@@ -80,7 +80,7 @@ function pino (opts, stream) {
       }
       len = params.length = arguments.length - base
       if (len > 1) {
-        msg = format.apply(null, params)
+        msg = format(params)
       } else if (len) {
         msg = params[0]
       }