Pino: Cloudwatch expects microseconds

[stephanebruckert]

Hi,

As you can see here (#datetime_format), Cloudwatch doesn't accept milliseconds, but only microseconds.

My problem now is that PinoJS generates milliseconds but the API doesn't allow to specify a custom time format. What do you think could be a quick and nice way to add microseconds to the ISO time stamps in PinoJS?

Thanks!

[mcollina]

there is the slowtime option that will let pino emit data using ISO timestamps https://github.com/pinojs/pino/blob/master/docs/API.md#parameters.

However, I recommend writing a https://github.com/pinojs/pino/blob/master/docs/transports.md that sends things straight to cloudwatch, without passing through the Agent, see #33.

[stephanebruckert]

Yes I'm already using slowtime: true. Going to have a look at the transports. Thanks

[jsumners]

JavaScript doesn't have such a high resolution timer. The finest resolution you can achieve, natively, is milliseconds. It looks like there is a module that will use the system API gettimeofday to achieve microsecond resolution. I'm against including any node-gyp dependencies in the core library. So I'd rather see it used on a downstream transport.

[davidmarkclements]

we don't need a node-gyp dep - process.hrtime gives [seconds, nanoseconds] tuple

from what I recall we used it in the first place and converted to milliseconds, it's slightly slower the Date.now() so we switched. We could add a hirestime option...

[jsumners]

I was unaware that exists. That being the case, I don't see why another getTime function couldn't be added.

[davidmarkclements]

Such as:

function getMicrosecondTime() {
   var hr = process.hrtime()
   return ',"time":' + Math.round(hr[0] * 1000000 + hr[1] / 1000) + '\n'
}

However, this would def be slower.. perhaps we should just have an hrtime option

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

and then the cloudwatch transport converts that to microseconds,
and the transport readme says, use the hrtime option

[davidmarkclements]

ok let's do this:

1. allow for another option, "hrtime"
2. if hrtime is true use the getHrTime function (above)
3. on instantiation, throw if both slowtime and hrtime are true (can't be both)
4. add unit tests for 1-3
5. add benchmarks for hrtime option
6. use benchmarks to determine the performance cost between default time and hrtime - document this in the same way as it's documented for slowtime

@stephanebruckert would you be interesting in making a PR?

this would then allow us to complete issue #33 using hrtime to determine microseconds

[stephanebruckert]

@davidmarkclements I will make a PR yes. I should come back to you by the end of the week

[stephanebruckert]

slowtime – WARNING: This option carries a 25% performance drop

@davidmarkclements It doesn't look like you currently have anything that benchmarks slowtime? Where does the 25% come from?

[davidmarkclements]

very early local benching - must not have made it into the benchmarks, we should def. add benchmarks for slowtime, would you be interested in making this part of the PR?

[davidmarkclements]

@stephanebruckert see http://npm.im/fast-date for the difference between Date.now() and (new Date).toUTCString())

[stephanebruckert]

Thanks for that. Yep the time benchmarks will be part of the PR.

[davidmarkclements]

discussion in #202 highly relevant to this - before you put effort into PR we should get a cohesive idea of the bigger pic

[jsumners]

@stephanebruckert I have solved #202 and released it as v4.5.0. If you'd like to supply a PR to add this as a standard function, please do.

[jsumners]

ping: @stephanebruckert

[stephanebruckert]

I just realised that hrtime gives an arbitrary time that's not related to the time of day. It seems to me as it won't help achieving what we want. What do you suggest?

Edit: sorry guys I won't be able to allocate more time to this issue

[jsumners]

These times are relative to an arbitrary time in the past, and not related to the time of day and therefore not subject to clock drift. The primary use is for measuring performance between intervals.

That seems way too narrow of a usage situation to be in core if you ask me.

cc: @jasnell

[davidmarkclements]

It seems to me that you have to get hr time at same time as current date, and then calculate the microsecond difference from there

take a look at https://github.com/davidmarkclements/fast-date/blob/master/fallback.js

Notice how we cache the date for each second in the clock by setting a timeout, minus the millisecond difference from that second (already used processing time).

I'm not necessarily saying use a cache mechanism over every second (it depends on the accuracy needed) but to get an accurate microsecond calculation you're going to have subtract the processing time it took to get the date or/and hr time

[willdurand]

Hi everyone, we also use pino and we would like microseconds instead of milliseconds because logs are sent to an Elastic stack. The problem is that milliseconds are not accurate enough, resulting in logs that are not ordered.

I don't know if we'll be able to that because of the state of time in Node/JS, yet if pino could offer a way to hook into the timer function, that'd be a good start.

[mcollina]

You change whatever gets added for time by passing a timestamp  option: https://getpino.io/#/docs/api?id=timestamp-boolean-function.

[willdurand]

@mcollina ah oops, sorry I missed this option, thanks! 😞

[davidmarkclements]

I think this can be closed - we have an option for changing the timestamp format