Properly measuring HTTP request time with node.js

Date: February 23, 2018

When your backend code is calling external APIs you may want to measure particular request time to identify bottlenecks.

The most straightforward, but incorrect, way to measure how long a request takes is to use JavaScript Date object:

var request = require('request');

let start_time = new Date().getTime();

request.get('https://google.com', function (err, response) {
    console.log('Time elapsed:', new Date().getTime() - start_time);
});

However, this won't give you the actual time that request takes. The above request call is async, and you start measuring time at the time when the request was queued, not actually sent.

In order to determine how much time elapsed since sending the request, you can use the time parameter:

var request = require('request');

request.get({ url: 'http://www.google.com', time: true }, function (err, response) {
    console.log('The actual time elapsed:', response.elapsedTime);
});

You can also compare results returned by both methods:

var request = require('request');

let start_time = new Date().getTime();

request.get('https://google.com', function (err, response) {
    console.log('Time elapsed since queuing the request:', new Date().getTime() - start_time);
});

request.get({ url: 'http://www.google.com', time: true }, function (err, response) {
    console.log('The actual time elapsed:', response.elapsedTime);
});

When I run it, I got the following results:

The actual time elapsed: 72 Time elapsed since queuing the request: 156

Notice that the first callback resolves after the second one(!)

The difference is almost 2x. Depending on your server-side code, this difference might be even larger, and give you incorrect hints while you are profiling your application.

2023 Update

Since request package is deprecated, you can use superagent-node-http-timings to get detailed http timings information:

const superagent = require('superagent');
const logNetworkTime = require('superagent-node-http-timings');

superagent
  .get(`https://google.com`)
  .use(logNetworkTime((err, result) => {
    console.log(result);
  }))
  .then(x => x);

Sample result:

{
  url: 'https://www.google.com/',
  status: 200,
  timings: {
    socketAssigned: 0.659234,
    dnsLookup: 5.110974,
    tcpConnection: 10.424859,
    tlsHandshake: 22.362443,
    firstByte: 66.831464,
    contentTransfer: 14.258803,
    total: 119.647777
  }
}

Categories: programming

Tags: node