Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Cache the pid and hostname globally, flatstr before writing #60

Merged
merged 3 commits into from
Jun 20, 2016
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
61 changes: 35 additions & 26 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -72,52 +72,61 @@ This produces:
<a name="benchmarks"></a>
## Benchmarks

As far as we know, it is one of the fastest loggers in town:
As far as we know Pino is fastest logger in town.
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would leave this as before. The difference is so tiny, and the approach between bole and pino is essentially the same now.
20ms over 10000 log lines is hardly perceivable.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fair enough


`pino.info('hello world')`:

```
benchBunyan*10000: 1752.137ms
benchWinston*10000: 2642.697ms
benchBole*10000: 349.301ms
benchDebug*10000: 621.877ms
benchLogLevel*10000: 392.642ms
benchPino*10000: 365.075ms
benchPinoExreme*10000: 112.848ms
benchBunyan*10000: 1355.229ms
benchWinston*10000: 2226.117ms
benchBole*10000: 291.727ms
benchDebug*10000: 445.291ms
benchLogLevel*10000: 322.181ms
benchPino*10000: 269.109ms
benchPinoExreme*10000: 102.239ms
```

`pino.info({'hello': 'world'})`:

```
benchBunyanObj*10000: 1717.269ms
benchWinstonObj*10000: 2409.900ms
benchBoleObj*10000: 364.634ms
benchLogLevelObject*10000: 1641.296ms
benchPinoObj*10000: 385.967ms
benchPinoUnsafeObj*10000: 383.686ms
benchPinoExtremeObj*10000: 171.360ms
benchPinoUnsafeExtremeObj*10000: 165.241ms
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
```

`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
```

`pino.info('hello %s %j %d', 'world', {obj: true}, 4, {another: 'obj'})`:

```
benchDebugInterpolateExtra*10000: 946.580ms
benchBunyanInterpolateExtra*10000: 3663.827ms
benchWinstonInterpolateExtra*10000: 3339.332ms
benchBoleInterpolateExtra*10000: 2004.084ms
benchLogLevelInterpolateExtra*10000: 2150.711ms
benchPinoInterpolateExtra*10000: 706.112ms
benchPinoUnsafeInterpolateExtra*10000: 674.391ms
benchPinoExtremeInterpolateExtra*10000: 359.784ms
benchPinoUnsafeExtremeInterpolateExtra*10000: 346.463ms
benchDebugInterpolateExtra*10000: 640.001ms
benchBunyanInterpolateExtra*10000: 2888.825ms
benchWinstonInterpolateExtra*10000: 2616.285ms
benchBoleInterpolateExtra*10000: 1313.470ms
benchLogLevelInterpolateExtra*10000: 1487.610ms
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@rvagg you should use quick-format as well :D.

benchPinoInterpolateExtra*10000: 486.367ms
benchPinoUnsafeInterpolateExtra*10000: 457.778ms
benchPinoExtremeInterpolateExtra*10000: 314.635ms
benchPinoUnsafeExtremeInterpolateExtra*10000: 294.915ms
```

In multiple cases, pino is over 6x faster than alternatives.
In many cases, pino is over 6x 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
Expand Down
12 changes: 5 additions & 7 deletions pino.js
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@ var once = require('once')
var noop = require('./noop')
var pid = process.pid
var hostname = os.hostname()
var baseLog = flatstr('{"pid":' + pid + ',"hostname":"' + hostname + '",')

var LOG_VERSION = 1

Expand Down Expand Up @@ -61,7 +62,7 @@ function pino (opts, stream) {
level = 'silent'
}

var logger = new Pino(level, stream, serializers, stringify, end, name, hostname, slowtime, '', cache, formatOpts)
var logger = new Pino(level, stream, serializers, stringify, end, name, slowtime, '', cache, formatOpts)
if (cache) {
onExit(function (code, evt) {
if (cache.buf) {
Expand Down Expand Up @@ -95,13 +96,12 @@ Object.defineProperty(pino, 'levels', {
enumerable: true
})

function Pino (level, stream, serializers, stringify, end, name, hostname, slowtime, chindings, cache, formatOpts) {
function Pino (level, stream, serializers, stringify, end, name, slowtime, chindings, cache, formatOpts) {
this.stream = stream
this.serializers = serializers
this.stringify = stringify
this.end = end
this.name = name
this.hostname = hostname
this.slowtime = slowtime
this.chindings = chindings
this.cache = cache
Expand Down Expand Up @@ -193,8 +193,7 @@ Pino.prototype.asJson = function asJson (obj, msg, num) {
// returns string json with final brace omitted
// the final brace is added by asJson
Pino.prototype.message = function message (level, msg) {
return '{"pid":' + pid + ',' +
(this.hostname === undefined ? '' : '"hostname":"' + this.hostname + '",') +
return baseLog +
(this.name === undefined ? '' : '"name":"' + this.name + '",') +
'"level":' + level + ',' +
(msg === undefined ? '' : '"msg":"' + (msg && msg.toString()) + '",') +
Expand Down Expand Up @@ -225,7 +224,6 @@ Pino.prototype.child = function child (bindings) {
this.stringify,
this.end,
this.name,
this.hostname,
this.slowtime,
data,
this.cache,
Expand All @@ -235,7 +233,7 @@ Pino.prototype.child = function child (bindings) {
Pino.prototype.write = function (obj, msg, num) {
var s = this.asJson(obj, msg, num)
if (!this.cache) {
this.stream.write(s)
this.stream.write(flatstr(s))
return
}

Expand Down