Pino: time plugin system

[davidmarkclements]

Just released http://npm.im/fast-date

It means we can get full UTC timestamps with with performance close to Date.now()

NativeDate*100000: 215.076ms
FastDate*100000: 124.236ms
DateNow*100000: 123.043ms

It grabs this functionality from internal HTTP code, which means that it's using the same date cache as the HTTP module does (for generating Date headers) see https://github.com/davidmarkclements/fast-date#how and https://github.com/davidmarkclements/fast-date#more-benchmarks

The caveat is - to use the same cache, you have to load fast-date (and therefore pino) BEFORE you the http module is loaded, otherwise it'll use a second cache which is still performant but less so.

The question is how do we want to integrate..

1. Add fast utc time as an option
2. Create v2 pino log output, make fast utc the default, of milliseconds and hrtime tuple output as other options - change the slowtime option etc - release new major pino version, backport it to legacy branch

I prefer option 2 even though it's much more work it means we have higher parity with bunyan/winston/bole log formats for very slight cost

[jsumners]

I don't like the thought of loading the http module just to get timestamping in a logger. Not everything Pino gets used for is exposed to the web, or even directly uses http.

[davidmarkclements]

yeah fair point - it doesn't load the whole http module, just a piece
and if you really wanted to avoid that - you could do require('fast-date/fallback') (we could rename) to get the fallback implementation

[jsumners]

And after reading that it is using an internal http module API, I'm even less warm to the idea. I don't think the roughly 3% improvement in timestamping is worth relying on an internal API.

[davidmarkclements]

Not relying on it - if it fails, we have a fallback that is still quite fast

[davidmarkclements]

also it's a ~57% improvement isn't it? (124/215)

[mcollina]

so, I'm 👎 on having pino depends on private APIs from core.
I'm 👍 on refactoring pino, so that we can plug that in as an addon.

Something like:

pino({
  now: require('fast-date')
})

[jsumners]

Fastdate avg reqs/s: 19103.28
Native avg reqs/s: 18582.8

18582.8 / 19103.28 = 0.972757 => 1- 0.972757 = 0.027243 => ~3% difference

Did I math wrong?

[davidmarkclements]

ah yes 3% on http reqs - 57% on microbenchmark (which doesn't need internal api at all)

@mcollina another option is to spin out the independent fallback piece - which would at least give a faster slowtime

(edit: 43% ...)

[mcollina]

I'm up for the second option Dave. How about we make this pluggable?

[davidmarkclements]

to be clear, you mean:

pino({
  now: require('fast-date')
})

?

yeah cool

I think we have something like that with the getTime function

[mcollina]

@davidmarkclements yes!

[davidmarkclements]

@stephanebruckert is putting together a PR for #183 for hi res time,
if @stephanebruckert writes in a pluggable way, then we're pretty much done

Although I think we should deprecate slowtime..

and instead of now we could alter timestamp values to true (Date.now()), false (no time stamp) and <Time Function>

e.g.

pino({
  timestamp: require('fast-date')
})

and

pino({
  timestamp: process.hrtime 
})

Although for speed (and minimum disruptive change), we might want to define an actual time function format (along the lines of https://github.com/pinojs/pino/issues/183#issuecomment-280678708)

So for instance hrtime would be

pino({
  timestamp: require('pino-hrtime')
})

pino-hrtime would be something like:

module.exports = function getHrTime () {
  var hr =  process.hrtime() 
  return ',"time": [' + hr[0] + ',' hr[1] + ']\n'
}

Then pino-utc can be a rehash of fast-date

@jsumners @mcollina @stephanebruckert Thoughts?

[jsumners]

I think the time function should output only the value. For example, in the output"time":"123456" the time function would output 123456.

[mcollina]

I think the time function should return a string, otherwise we would have to do toString(), which we might avoid altogether.

[davidmarkclements]

agreed, not just a string, but also the (JSON) syntax to signal the type, e.g.

"time":"123456" would be a function that outputs '"123456"' (inc quotes),
which would allow hrtime to be a function that outputs (say) [117432, 625559829]

I think (as small as they are) these would still need to be modules in their own right

[jsumners]

This is implemented by #202.