Measuring time on node.js http requests

Question

I was wondering if we can measure the time it takes for an http request to be completed using node.js. Modifying slightly an example from the documentation (here), one can easily write down the following code.

var http = require('http');
var stamp1 = new Date();
var stamp2, stamp3, stamp4;
var options = {
  hostname: 'www.google.com',
  port: 80,
  path: '/upload',
  method: 'POST'
};

var req = http.request(options, function(res) {
  stamp3 = new Date();
  console.log('STATUS: ' + res.statusCode);
  console.log('HEADERS: ' + JSON.stringify(res.headers));
  res.setEncoding('utf8');
  res.on('data', function (chunk) {
    console.log('BODY: ' + chunk);
  });
  res.on('end', function () {
    stamp4 = new Date();
    console.log ("Stamp 3: " + stamp3);
    console.log ("Stamp 4: " + stamp4);
  });
});
req.on('error', function(e) {
  console.log('problem with request: ' + e.message);
});

// write data to request body
req.write('data\n');
req.write('data\n');
req.end();

stamp2 = new Date();
console.log ("Stamp 1: " + stamp1);
console.log ("Stamp 2: " + stamp2);

Now let me come to my point. On the response one can easily measure the time it takes for the response, since in the beginning stamp3 is set and on end stamp 4 is set. So, in principle for relatively large amounts of data these two timestamps will be different.

However, the question that I have is whether stamps 1 and 2 actually measure what is happening when the request is being prepared and dispatched. In other words, is req.write(....) a synchronous operation? Based on node.js principles I would expect req.write(...) to be an asynchronous operation where one can pass an arbitrarily large document and then upon successful completion we can have a callback knowing that the request has finished.

Comments?

Tetrode

You may want to create a utility function to perform the measurement and you can get an actual duration out by using Date.now() while subtracting the second timestamp from the first timestamp. Also note you can measure in nanoseconds with process.hrtime. – Scathe

Thanks, I like the process.hrtime suggestion because I was not aware of it! As of the subtraction, that is precisely my point eventually for the actual measurement. – Tetrode

Answer 1

Two function already exist for that:

• console.time(id), start the timer
• console.timeEnd(id) end the timer, print id followed by the time in ms

So in your case:

var req = http.request(options, function(res) {
    console.time('Requete: '); //Begin to count the time
    stamp3 = new Date();
    console.log('STATUS: ' + res.statusCode);
    console.log('HEADERS: ' + JSON.stringify(res.headers));
    res.setEncoding('utf8');
    res.on('data', function (chunk) {
        console.log('BODY: ' + chunk);
    });
    res.on('end', function () {
        stamp4 = new Date();
        console.log ("Stamp 3: " + stamp3);
        console.log ("Stamp 4: " + stamp4);
        console.timeEnd('Requete: '); //Will print "Requete: X" with X being the time in ms
    });
});

Oringa

I do not think you understood my question and I am wondering who upvoted. As it is given one can already compute the time taken for the response (res) simply because timestamp 4 is defined on the callback that is available. My point is that I can not do the same thing with the request (req). In other words write down something along the lines req.on('end', function () {....}); Makes sense the problem that I am trying to describe? – Tetrode

Answer 2

The docs mention no callback, so I'm assuming req.write as well as res.end to be synchronous.

So in your case if you're referring to just that one request that you're initializing, I think the time measurement should be accurate. I don't expect the time difference to be very big though (perhaps even in the same milisecond).

Malleable

This is why I used the phrase "for relatively large amounts of data", so that the measurements can be off by more than a millisecond. On the other hand, res.on('end', function () {....}); works, and stamp4 gets a timestamp and I can see the print statement. On the other hand, a statement of the form req.on('end', function () {....}); does not set stamp2 correctly (assuming stamp2 is set in the event handler function for 'end' of the request and contrary to the event handler for the 'end' of the response). So, there seems to be a slight difference on how request and response are handled. – Tetrode