Skip to content

Commit

Permalink
Merge pull request #5 from mcollina/timestamp
Browse files Browse the repository at this point in the history 
timestamp opt (20-25% speed increase)
  • Loading branch information
@mcollina
mcollina committed Mar 9, 2016
2 parents 6586f7b + f6038fd commit e358d56
Show file tree
Hide file tree
Showing 5 changed files with 105 additions and 53 deletions.
89 changes: 62 additions & 27 deletions README.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,7 @@
[Extremely fast](#benchmarks) node.js logger, inspired by Bunyan.
It also includes a shell utility to pretty-print its log files.

![cli](https://raw.githubusercontent.com/mcollina/pino/master/demo.png)
![cli](demo.png)

* [Installation](#install)
* [Usage](#usage)
Expand Down Expand Up @@ -42,14 +42,48 @@ error(new Error('something bad happened'))
This produces:

```
{"pid":12244,"hostname":"MBP-di-Matteo","level":30,"msg":"hello world","time":"2016-03-05T16:00:45.858Z","v":0}
{"pid":12244,"hostname":"MBP-di-Matteo","level":50,"msg":"this is at error level","time":"2016-03-05T16:00:45.860Z","v":0}
{"pid":12244,"hostname":"MBP-di-Matteo","level":30,"msg":"the answer is 42","time":"2016-03-05T16:00:45.861Z","v":0}
{"pid":12244,"hostname":"MBP-di-Matteo","level":30,"msg":"hello world","time":"2016-03-05T16:00:45.861Z","v":0,"obj":42}
{"pid":12244,"hostname":"MBP-di-Matteo","level":30,"msg":"hello world","time":"2016-03-05T16:00:45.862Z","v":0,"obj":42,"b":2}
{"pid":12244,"hostname":"MBP-di-Matteo","level":30,"msg":"another","time":"2016-03-05T16:00:45.862Z","v":0,"obj":{"aa":"bbb"}}
{"pid":12244,"hostname":"MBP-di-Matteo","level":50,"msg":"an error","time":"2016-03-05T16:00:45.863Z","v":0,"type":"Error","stack":"Error: an error\n at Object.<anonymous> (/Users/matteo/Repositories/pino/example.js:14:7)\n at Module._compile (module.js:435:26)\n at Object.Module._extensions..js (module.js:442:10)\n at Module.load (module.js:356:32)\n at Function.Module._load (module.js:313:12)\n at Function.Module.runMain (module.js:467:10)\n at startup (node.js:136:18)\n at node.js:963:3"}
{"pid":12244,"hostname":"MBP-di-Matteo","level":30,"msg":"after setImmediate","time":"2016-03-05T16:00:45.865Z","v":0}
{"pid":13087,"hostname":"MacBook-Pro-3.home","level":30,"msg":"hello world","time":1457531561635,"v":0}
{"pid":13087,"hostname":"MacBook-Pro-3.home","level":50,"msg":"this is at error level","time":1457531561636,"v":0}
{"pid":13087,"hostname":"MacBook-Pro-3.home","level":30,"msg":"the answer is 42","time":1457531561637,"v":0}
{"pid":13087,"hostname":"MacBook-Pro-3.home","level":30,"msg":"hello world","time":1457531561637,"v":0,"obj":42}
{"pid":13087,"hostname":"MacBook-Pro-3.home","level":30,"msg":"hello world","time":1457531561638,"v":0,"obj":42,"b":2}
{"pid":13087,"hostname":"MacBook-Pro-3.home","level":30,"msg":"another","time":1457531561638,"v":0,"obj":{"aa":"bbb"}}
{"pid":13087,"hostname":"MacBook-Pro-3.home","level":50,"msg":"an error","time":1457531561639,"v":0,"type":"Error","stack":"Error: an error\n at Object.<anonymous> (/Users/davidclements/z/nearForm/pino/example.js:14:7)\n at Module._compile (module.js:413:34)\n at Object.Module._extensions..js (module.js:422:10)\n at Module.load (module.js:357:32)\n at Function.Module._load (module.js:314:12)\n at Function.Module.runMain (module.js:447:10)\n at startup (node.js:141:18)\n at node.js:933:3"}
{"pid":13087,"hostname":"MacBook-Pro-3.home","level":30,"msg":"after setImmediate","time":1457531561641,"v":0}
```

<a name="cli"></a>
## CLI

To use the command line tool, we can install `pino` globally:

```sh
npm install -g pino
```

Then we simply pipe a log file through `pino`:

```sh
cat log | pino
```

There's also a transformer flag that converts Epoch timestamps to ISO timestamps.

```sh
cat log | pino -t
```

For instance, `pino -t` will transform this:

```js
{"pid":14139,"hostname":"MacBook-Pro-3.home","level":30,"msg":"hello world","time":1457537229339,"v":0}
```

Into this:

```js
{"pid":14139,"hostname":"MacBook-Pro-3.home","level":30,"msg":"hello world","time":"2016-03-09T15:27:09.339Z","v":0}
```

<a name="api"></a>
Expand All @@ -76,7 +110,8 @@ Returns a new logger. Allowed options are:
* `name`: the name of the logger, default `undefined`
* `serializers`: an object containing functions for custom serialization
of objects. These functions should return an jsonificable object and
they should never throw.
they should never throw
* `slowtime`: Outputs ISO time stamps (`'2016-03-09T15:18:53.889Z'`) instead of Epoch time stamps (`1457536759176`). **WARNING**: This option carries a 25% performance drop, we recommend using default Epoch timestamps and transforming logs after if required. The `pino -t` command will do this for you (see [CLI](#cli))

`stream` is a Writable stream, defaults to `process.stdout`.

Expand Down Expand Up @@ -217,25 +252,25 @@ It returns an object in the form:
<a name="benchmarks"></a>
## Benchmarks
As far as I know, it is the fastest logger in town:
As far as we know, it is the fastest logger in town:
```
benchBunyan*10000: 1116.721ms
benchWinston*10000: 1783.362ms
benchBole*10000: 1496.580ms
benchPino*10000: 363.430ms
benchBunyanObj*10000: 1228.538ms
benchWinstonObj*10000: 1895.251ms
benchPinoObj*10000: 427.989ms
benchBoleObj*10000: 1487.543ms
benchBunyan*10000: 1088.231ms
benchWinston*10000: 1733.589ms
benchBole*10000: 1514.004ms
benchPino*10000: 377.418ms
benchBunyanObj*10000: 1205.833ms
benchWinstonObj*10000: 1800.594ms
benchPinoObj*10000: 412.170ms
benchBoleObj*10000: 1522.469ms
benchBunyan*10000: 1093.236ms
benchWinston*10000: 1904.147ms
benchBole*10000: 1563.632ms
benchPino*10000: 287.858ms
benchBunyanObj*10000: 1187.016ms
benchWinstonObj*10000: 1990.980ms
benchPinoObj*10000: 366.865ms
benchBoleObj*10000: 1475.934ms
benchBunyan*10000: 1043.486ms
benchWinston*10000: 1801.232ms
benchBole*10000: 1524.136ms
benchPino*10000: 280.797ms
benchBunyanObj*10000: 1188.472ms
benchWinstonObj*10000: 1868.626ms
benchPinoObj*10000: 371.082ms
benchBoleObj*10000: 1496.449ms
```
<a name="rotate"></a>
Expand Down
33 changes: 20 additions & 13 deletions bin.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,8 @@ var chalk = require('chalk')

process.stdin.pipe(split(mapLine)).pipe(process.stdout)

var timeTrans = ~process.argv.indexOf('-t')

var levelColors = {
60: chalk.bgRed,
50: chalk.red,
Expand Down Expand Up @@ -69,19 +71,24 @@ function mapLine (line) {
if (parsed.err) {
// pass through
return line
}

if (timeTrans) {
value.time = new Date(value.time).toISOString()
return JSON.stringify(value) + '\n'
}

line = '[' + new Date(value.time).toISOString() + '] ' + asColoredLevel(value)
line += ' ('
if (value.name) {
line += value.name + '/'
}
line += value.pid + ' on ' + value.hostname + ')'
line += ': ' + chalk.cyan(value.msg) + '\n'
if (value.type === 'Error') {
line += ' ' + withSpaces(value.stack) + '\n'
} else {
line = '[' + value.time + '] ' + asColoredLevel(value)
line += ' ('
if (value.name) {
line += value.name + '/'
}
line += value.pid + ' on ' + value.hostname + ')'
line += ': ' + chalk.cyan(value.msg) + '\n'
if (value.type === 'Error') {
line += ' ' + withSpaces(value.stack) + '\n'
} else {
line += filter(value)
}
return line
line += filter(value)
}
return line
}
Binary file modified demo.png
View file
Loading
Sorry, something went wrong. Reload?
Sorry, we cannot display this file.
Sorry, this file is invalid so it cannot be displayed.
4 changes: 2 additions & 2 deletions pino.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -22,7 +22,7 @@ function pino (opts, stream) {
}
stream = stream || process.stdout
opts = opts || {}

var slowtime = opts.slowtime
var stringify = opts.safe !== false ? stringifySafe : JSON.stringify
var name = opts.name
var level
Expand Down Expand Up @@ -124,7 +124,7 @@ function pino (opts, stream) {
(name === undefined ? '' : '"name":"' + name + '",') +
'"level":' + level + ',' +
(msg === undefined ? '' : '"msg":"' + (msg && msg.toString()) + '",') +
'"time":"' + (new Date()).toISOString() + '",' +
'"time":' + (slowtime ? '"' + (new Date()).toISOString() + '"' : Date.now()) + ',' +
'"v":' + 0
}
}
Expand Down
32 changes: 21 additions & 11 deletions test.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -16,7 +16,7 @@ function sink (func) {
}

function check (t, chunk, level, msg) {
t.ok(Date.parse(chunk.time) <= new Date(), 'time is greater than Date.now()')
t.ok(new Date(chunk.time) <= new Date(), 'time is greater than Date.now()')
delete chunk.time
t.deepEqual(chunk, {
pid: pid,
Expand All @@ -41,7 +41,7 @@ function levelTest (name, level) {
test('passing objects at level ' + name, function (t) {
t.plan(2)
var instance = pino(sink(function (chunk, enc, cb) {
t.ok(Date.parse(chunk.time) <= new Date(), 'time is greater than Date.now()')
t.ok(new Date(chunk.time) <= new Date(), 'time is greater than Date.now()')
delete chunk.time
t.deepEqual(chunk, {
pid: pid,
Expand All @@ -59,7 +59,7 @@ function levelTest (name, level) {
test('passing an object and a string at level ' + name, function (t) {
t.plan(2)
var instance = pino(sink(function (chunk, enc, cb) {
t.ok(Date.parse(chunk.time) <= new Date(), 'time is greater than Date.now()')
t.ok(new Date(chunk.time) <= new Date(), 'time is greater than Date.now()')
delete chunk.time
t.deepEqual(chunk, {
pid: pid,
Expand Down Expand Up @@ -89,7 +89,7 @@ function levelTest (name, level) {
t.plan(2)
var err = new Error('myerror')
var instance = pino(sink(function (chunk, enc, cb) {
t.ok(Date.parse(chunk.time) <= new Date(), 'time is greater than Date.now()')
t.ok(new Date(chunk.time) <= new Date(), 'time is greater than Date.now()')
delete chunk.time
t.deepEqual(chunk, {
pid: pid,
Expand Down Expand Up @@ -172,7 +172,7 @@ test('set the name', function (t) {
var instance = pino({
name: 'hello'
}, sink(function (chunk, enc, cb) {
t.ok(Date.parse(chunk.time) <= new Date(), 'time is greater than Date.now()')
t.ok(new Date(chunk.time) <= new Date(), 'time is greater than Date.now()')
delete chunk.time
t.deepEqual(chunk, {
pid: pid,
Expand Down Expand Up @@ -212,7 +212,7 @@ test('set undefined properties', function (t) {
t.plan(2)

var instance = pino(sink(function (chunk, enc, cb) {
t.ok(Date.parse(chunk.time) <= new Date(), 'time is greater than Date.now()')
t.ok(new Date(chunk.time) <= new Date(), 'time is greater than Date.now()')
delete chunk.time
t.deepEqual(chunk, {
pid: pid,
Expand All @@ -231,7 +231,7 @@ test('set properties defined in the prototype chain', function (t) {
t.plan(2)

var instance = pino(sink(function (chunk, enc, cb) {
t.ok(Date.parse(chunk.time) <= new Date(), 'time is greater than Date.now()')
t.ok(new Date(chunk.time) <= new Date(), 'time is greater than Date.now()')
delete chunk.time
t.deepEqual(chunk, {
pid: pid,
Expand All @@ -257,7 +257,7 @@ test('http request support', function (t) {

var originalReq
var instance = pino(sink(function (chunk, enc, cb) {
t.ok(Date.parse(chunk.time) <= new Date(), 'time is greater than Date.now()')
t.ok(new Date(chunk.time) <= new Date(), 'time is greater than Date.now()')
delete chunk.time
t.deepEqual(chunk, {
pid: pid,
Expand Down Expand Up @@ -299,7 +299,7 @@ test('http request support via serializer', function (t) {
req: pino.stdSerializers.req
}
}, sink(function (chunk, enc, cb) {
t.ok(Date.parse(chunk.time) <= new Date(), 'time is greater than Date.now()')
t.ok(new Date(chunk.time) <= new Date(), 'time is greater than Date.now()')
delete chunk.time
t.deepEqual(chunk, {
pid: pid,
Expand Down Expand Up @@ -337,7 +337,7 @@ test('http response support', function (t) {

var originalRes
var instance = pino(sink(function (chunk, enc, cb) {
t.ok(Date.parse(chunk.time) <= new Date(), 'time is greater than Date.now()')
t.ok(new Date(chunk.time) <= new Date(), 'time is greater than Date.now()')
delete chunk.time
t.deepEqual(chunk, {
pid: pid,
Expand Down Expand Up @@ -376,7 +376,7 @@ test('http response support via a serializer', function (t) {
res: pino.stdSerializers.res
}
}, sink(function (chunk, enc, cb) {
t.ok(Date.parse(chunk.time) <= new Date(), 'time is greater than Date.now()')
t.ok(new Date(chunk.time) <= new Date(), 'time is greater than Date.now()')
delete chunk.time
t.deepEqual(chunk, {
pid: pid,
Expand Down Expand Up @@ -405,3 +405,13 @@ test('http response support via a serializer', function (t) {
})
})
})

test('slowtime', function (t) {
var instance = pino({slowtime: true},
sink(function (chunk, enc, cb) {
t.ok(Date.parse(chunk.time) <= new Date(), 'time is greater than Date.now()')
t.end()
}))

instance.info('hello world')
})

0 comments on commit e358d56

Please sign in to comment.