-
Notifications
You must be signed in to change notification settings - Fork 898
Commit
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.
- Loading branch information
davidmarkclements
committed
Jul 10, 2018
1 parent
8077987
commit bb31ed7
Showing
13 changed files
with
1,267 additions
and
1,195 deletions.
There are no files selected for viewing
Large diffs are not rendered by default.
Oops, something went wrong.
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -0,0 +1,58 @@ | ||
# Benchmarks | ||
|
||
`pino.info('hello world')`: | ||
|
||
``` | ||
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'})`: | ||
|
||
``` | ||
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)`: | ||
|
||
``` | ||
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'})`: | ||
|
||
``` | ||
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 | ||
``` | ||
|
||
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. |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -0,0 +1,199 @@ | ||
# Browser API | ||
|
||
Pino is compatible with [`browserify`](http://npm.im/browserify) for browser side usage: | ||
|
||
This can be useful with isomorphic/universal JavaScript code. | ||
|
||
By default, in the browser, | ||
`pino` uses corresponding [Log4j](https://en.wikipedia.org/wiki/Log4j) `console` methods (`console.error`, `console.warn`, `console.info`, `console.debug`, `console.trace`) and uses `console.error` for any `fatal` level logs. | ||
|
||
## Options | ||
|
||
Pino can be passed a `browser` object in the options object, | ||
which can have the following properties: | ||
|
||
### `asObject` (Boolean) | ||
|
||
```js | ||
const pino = require('pino')({browser: {asObject: true}}) | ||
``` | ||
|
||
The `asObject` option will create a pino-like log object instead of | ||
passing all arguments to a console method, for instance: | ||
|
||
```js | ||
pino.info('hi') // creates and logs {msg: 'hi', level: 30, time: <ts>} | ||
``` | ||
|
||
When `write` is set, `asObject` will always be `true`. | ||
|
||
### `write` (Function | Object) | ||
|
||
Instead of passing log messages to `console.log` they can be passed to | ||
a supplied function. | ||
|
||
If `write` is set to a single function, all logging objects are passed | ||
to this function. | ||
|
||
```js | ||
const pino = require('pino')({ | ||
browser: { | ||
write: (o) => { | ||
// do something with o | ||
} | ||
} | ||
}) | ||
``` | ||
|
||
If `write` is an object, it can have methods that correspond to the | ||
levels. When a message is logged at a given level, the corresponding | ||
method is called. If a method isn't present, the logging falls back | ||
to using the `console`. | ||
|
||
|
||
```js | ||
const pino = require('pino')({ | ||
browser: { | ||
write: { | ||
info: function (o) { | ||
//process info log object | ||
}, | ||
error: function (o) { | ||
//process error log object | ||
} | ||
} | ||
} | ||
}) | ||
``` | ||
|
||
### `serialize`: (Boolean | Array) | ||
|
||
The serializers provided to `pino` are ignored by default in the browser, including | ||
the standard serializers provided with Pino. Since the default destination for log | ||
messages is the console, values such as `Error` objects are enhanced for inspection, | ||
which they otherwise wouldn't be if the Error serializer was enabled. | ||
|
||
We can turn all serializers on, | ||
|
||
```js | ||
const pino = require('pino')({ | ||
browser: { | ||
serialize: true | ||
} | ||
}) | ||
``` | ||
|
||
Or we can selectively enable them via an array: | ||
|
||
```js | ||
const pino = require('pino')({ | ||
serializers: { | ||
custom: myCustomSerializer, | ||
another: anotherSerializer | ||
}, | ||
browser: { | ||
serialize: ['custom'] | ||
} | ||
}) | ||
// following will apply myCustomSerializer to the custom property, | ||
// but will not apply anotherSerizlier to another key | ||
pino.info({custom: 'a', another: 'b'}) | ||
``` | ||
|
||
When `serialize` is `true` the standard error serializer is also enabled (see https://github.com/pinojs/pino/blob/master/docs/api.md#stdSerializers). | ||
This is a global serializer which will apply to any `Error` objects passed to the logger methods. | ||
|
||
If `serialize` is an array the standard error serializer is also automatically enabled, it can | ||
be explicitly disabled by including a string in the serialize array: `!stdSerializers.err`, like so: | ||
|
||
```js | ||
const pino = require('pino')({ | ||
serializers: { | ||
custom: myCustomSerializer, | ||
another: anotherSerializer | ||
}, | ||
browser: { | ||
serialize: ['!stdSerializers.err', 'custom'] //will not serialize Errors, will serialize `custom` keys | ||
} | ||
}) | ||
``` | ||
|
||
The `serialize` array also applies to any child logger serializers (see https://github.com/pinojs/pino/blob/master/docs/api.md#discussion-2 | ||
for how to set child-bound serializers). | ||
|
||
Unlike server pino the serializers apply to every object passed to the logger method, | ||
if the `asObject` option is `true`, this results in the serializers applying to the | ||
first object (as in server pino). | ||
|
||
For more info on serializers see https://github.com/pinojs/pino/blob/master/docs/api.md#parameters. | ||
|
||
### `transmit` (Object) | ||
|
||
An object with `send` and `level` properties. | ||
|
||
The `transmit.level` property specifies the minimum level (inclusive) of when the `send` function | ||
should be called, if not supplied the `send` function be called based on the main logging `level` | ||
(set via `options.level`, defaulting to `info`). | ||
|
||
The `transmit` object must have a `send` function which will be called after | ||
writing the log message. The `send` function is passed the level of the log | ||
message and a `logEvent` object. | ||
|
||
The `logEvent` object is a data structure representing a log message, it represents | ||
the arguments passed to a logger statement, the level | ||
at which they were logged and the heirarchy of child bindings. | ||
|
||
The `logEvent` format is structured like so: | ||
|
||
```js | ||
{ | ||
ts = Number, | ||
messages = Array, | ||
bindings = Array, | ||
level: { label = String, value = Number} | ||
} | ||
``` | ||
|
||
The `ts` property is a unix epoch timestamp in milliseconds, the time is taken from the moment the | ||
logger method is called. | ||
|
||
The `messages` array is all arguments passed to logger method, (for instance `logger.info('a', 'b', 'c')` | ||
would result in `messages` array `['a', 'b', 'c']`). | ||
|
||
The `bindings` array represents each child logger (if any), and the relevant bindings. | ||
For instance given `logger.child({a: 1}).child({b: 2}).info({c: 3})`, the bindings array | ||
would hold `[{a: 1}, {b: 2}]` and the `messages` array would be `[{c: 3}]`. The `bindings` | ||
are ordered according to their position in the child logger hierarchy, with the lowest index | ||
being the top of the hierarchy. | ||
|
||
By default serializers are not applied to log output in the browser, but they will *always* be | ||
applied to `messages` and `bindings` in the `logEvent` object. This allows us to ensure a consistent | ||
format for all values between server and client. | ||
|
||
The `level` holds the label (for instance `info`), and the corresponding numerical value | ||
(for instance `30`). This could be important in cases where client side level values and | ||
labels differ from server side. | ||
|
||
The point of the `send` function is to remotely record log messages: | ||
|
||
```js | ||
const pino = require('pino')({ | ||
browser: { | ||
transmit: { | ||
level: 'warn', | ||
send: function (level, logEvent) { | ||
if (level === 'warn') { | ||
// maybe send the logEvent to a separate endpoint | ||
// or maybe analyse the messages further before sending | ||
} | ||
// we could also use the `logEvent.level.value` property to determine | ||
// numerical value | ||
if (logEvent.level.value >= 50) { // covers error and fatal | ||
|
||
// send the logEvent somewhere | ||
} | ||
} | ||
} | ||
} | ||
}) | ||
``` |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -0,0 +1,95 @@ | ||
# Child loggers | ||
|
||
Let's assume we want to have `"module":"foo"` added to every log within a | ||
module `foo.js`. | ||
|
||
To accomplish this, simply use a child logger: | ||
|
||
```js | ||
'use strict' | ||
// imports a pino logger instance of `require('pino')()` | ||
const parentLogger = require('./lib/logger') | ||
const log = parentLogger.child({module: 'foo'}) | ||
|
||
function doSomething () { | ||
log.info('doSomething invoked') | ||
} | ||
|
||
module.exports = { | ||
doSomething | ||
} | ||
``` | ||
|
||
## Cost of child logging | ||
|
||
Child logger creation is fast: | ||
|
||
``` | ||
benchBunyanCreation*10000: 564.514ms | ||
benchBoleCreation*10000: 283.276ms | ||
benchPinoCreation*10000: 258.745ms | ||
benchPinoExtremeCreation*10000: 150.506ms | ||
``` | ||
|
||
Logging through a child logger has little performance penalty: | ||
|
||
``` | ||
benchBunyanChild*10000: 556.275ms | ||
benchBoleChild*10000: 288.124ms | ||
benchPinoChild*10000: 231.695ms | ||
benchPinoExtremeChild*10000: 122.117ms | ||
``` | ||
|
||
Logging via the child logger of a child logger also has negligible overhead: | ||
|
||
``` | ||
benchBunyanChildChild*10000: 559.082ms | ||
benchPinoChildChild*10000: 229.264ms | ||
benchPinoExtremeChildChild*10000: 127.753ms | ||
``` | ||
|
||
## Duplicate keys caveat | ||
|
||
It's possible for naming conflicts to arise between child loggers and | ||
children of child loggers. | ||
|
||
This isn't as bad as it sounds, even if you do use the same keys between | ||
parent and child loggers Pino resolves the conflict in the sanest way. | ||
|
||
For example, consider the following: | ||
|
||
```js | ||
const pino = require('pino') | ||
pino(pino.destination('./my-log')) | ||
.child({a: 'property'}) | ||
.child({a: 'prop'}) | ||
.info('howdy') | ||
``` | ||
|
||
```sh | ||
$ cat my-log | ||
{"pid":95469,"hostname":"MacBook-Pro-3.home","level":30,"msg":"howdy","time":1459534114473,"a":"property","a":"prop","v":1} | ||
``` | ||
|
||
Notice how there's two key's named `a` in the JSON output. The sub-childs properties | ||
appear after the parent child properties. | ||
|
||
At some point the logs will most likely be processed (for instance with a [transport](transports.md)), | ||
and this generally involves parsing. `JSON.parse` will return an object where the conflicting | ||
namespace holds the final value assigned to it: | ||
|
||
```sh | ||
$ cat my-log | node -e "process.stdin.once('data', (line) => console.log(JSON.stringify(JSON.parse(line))))" | ||
{"pid":95469,"hostname":"MacBook-Pro-3.home","level":30,"msg":"howdy","time":"2016-04-01T18:08:34.473Z","a":"prop","v":1} | ||
``` | ||
|
||
Ultimately the conflict is resolved by taking the last value, which aligns with Bunyans child logging | ||
behavior. | ||
|
||
There may be cases where this edge case becomes problematic if a JSON parser with alternative behavior | ||
is used to process the logs. It's recommended to be conscious of namespace conflicts with child loggers, | ||
in light of an expected log processing approach. | ||
|
||
One of Pino's performance tricks is to avoid building objects and stringifying | ||
them, so we're building strings instead. This is why duplicate keys between | ||
parents and children will end up in log output. |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Oops, something went wrong.