CODEWITHSUNDEEP
javascriptnode.js
gerasalus
gerasalus

Reputation: 7697

node.js timing: process.hrtime() vs new Date().getTime()?

I'm trying to troubleshoot an issue where requests from node.js to remote http api take too long. To start with, i've decided to add timing to my node application:

'use strict';

let logger = require('./logger');
let request = require('request');

module.exports = function(uri, done) {
  // set full url.
  let options = {
    uri: `http://example.org/${uri}`,
    timeout: 60000,
    json: true,
    gzip: true,
    encoding: null
  };
  const startDate = new Date().getTime();
  const start = process.hrtime();

  request(options, function(error, response, body) {
    const endDate = new Date().getTime();
    const end = process.hrtime(start);
    const durationDate = endDate - startDate;
    const duration = end[1] / 1000000;
    const diff = Math.abs(Math.round(durationDate - duration));
    logger.debug(`${uri} hrtime: ${duration} ms, date: ${durationDate} ms, diff: ${diff}`);
    if (!error && response.statusCode === 200) {
      done(error, response, body, body);
    } else {
      done(error, response, body);
    }
  });
};

And this is the output i get:

<....>
2016-06-29T10:26:59.230Z /account hrtime: 41.567354 ms, date: 41 ms, diff: 1
2016-06-29T10:27:06.369Z /account hrtime: 42.052154 ms, date: 42 ms, diff: 0
2016-06-29T10:27:13.368Z /account hrtime: 51.582807 ms, date: 5052 ms, diff: 5000
2016-06-29T10:27:14.971Z /account hrtime: 40.705936 ms, date: 40 ms, diff: 1
2016-06-29T10:27:22.490Z /account hrtime: 45.953398 ms, date: 5046 ms, diff: 5000
2016-06-29T10:27:29.669Z /account hrtime: 42.504256 ms, date: 5043 ms, diff: 5000
2016-06-29T10:27:31.622Z /account hrtime: 39.405575 ms, date: 39 ms, diff: 0
<....>
2016-06-29T10:27:45.135Z /account hrtime: 40.594642 ms, date: 41 ms, diff: 0
2016-06-29T10:27:52.682Z /account hrtime: 40.290881 ms, date: 40 ms, diff: 0
2016-06-29T10:28:05.115Z /account hrtime: 50.81821 ms, date: 10050 ms, diff: 9999
2016-06-29T10:28:13.555Z /account hrtime: 52.061123 ms, date: 52 ms, diff: 0
<.....>
2016-06-29T10:29:45.052Z /account hrtime: 44.252486 ms, date: 44 ms, diff: 0
2016-06-29T10:29:46.829Z /account hrtime: 39.652963 ms, date: 40 ms, diff: 0
2016-06-29T10:29:49.101Z /account hrtime: 40.841915 ms, date: 41 ms, diff: 0
2016-06-29T10:29:55.097Z /account hrtime: 44.161802 ms, date: 5044 ms, diff: 5000
2016-06-29T10:30:01.784Z /account hrtime: 47.732807 ms, date: 47 ms, diff: 1
2016-06-29T10:30:04.309Z /account hrtime: 40.151299 ms, date: 40 ms, diff: 0
2016-06-29T10:30:06.926Z /account hrtime: 39.933368 ms, date: 40 ms, diff: 0
2016-06-29T10:30:14.440Z /account hrtime: 53.610396 ms, date: 5054 ms, diff: 5000

So sometimes the difference between hrtime and getTime() is huge.
And this is not just some misreporting, but rather actual behaviour - if look at the remote http server logs, i see that all requests actually took time reported by hrtime, and time reported by getTime() is actually how long the node.js application responds. So it seems that there is some kind of delay on node.js application itself. Any hits on why this is happening ?

Node v4.4.6

Upvotes: 5

Views: 3214

Answers (1)

Madhavrao P
Madhavrao P

Reputation: 31

Use the following :

const start = process.hrtime();
// ... processing
const end = process.hrtime(start);
const duration = (end[0]*1000) + (end[1] / 1000000);

You will get required result. hrtime returns an array of two value - first one is seconds, so multiply it with 1000 to get miliseconds, second value is nanoseconds so divide by 1 followed by 6 zeros i.e. 1000000, add both of them to get result.

Upvotes: 3

Related Questions