I want to measure how much time it takes for a response to arrive from a web server. I know that, with node, I can't get an accurate measure, but I'm rather interested in consistent measurements, so I can detect high lag spikes that I had in the past with my hosting provider.
This is the simplified code I wrote for this (ignore those Log calls):
var t1, t2;
var socket = new net.Socket();
socket.on("data", function(data) {
t2 = new Date;
Log.w("Request time: " + (t2 - t1) + " ms");
});
socket.on("end", function() {
Log.w("Received FIN");
});
socket.on("close", function() {
Log.w("Socket closed");
});
socket.setNoDelay(true);
t1 = new Date;
dns.resolve4("some.host", function(err, addresses) {
t2 = new Date;
if (err) Log.e(err.toString());
else {
Log.d("DNS time: " + (t2-t1) + " ms.");
socket.connect(80, addresses[0], function() {
t2 = new Date;
Log.i("Connection time: " + (t2 - t1) + " ms.");
Log.d('Connected to ' + socket.remoteAddress);
t1 = new Date;
socket.write('GET / HTTP/1.1\r\nhost: some.host\r\nConnection: close\r\n\r\n', function() {
t2 = new Date;
Log.i("Socket writing time: " + (t2-t1) + " ms.");
socket.end();
t1 = new Date;
});
});
t1 = new Date;
}
});
But, there is a strange behavior with this code. When I run it, the time between socket.write() and the data event is unexpectedly high, around 140ms more than the real time.
However, and this is what I don't understand, if I call socket.connect() again with the same options after the socket is closed, or if I rerun the script within 5-15 seconds, I get the correct measurement.
Here is an output example:
~/node $ node test.js
23-3-2015 22:09:19 > DNS time: 12 ms.
23-3-2015 22:09:19 > Connection time: 23 ms.
23-3-2015 22:09:19 > Connected to 91.142.222.187
23-3-2015 22:09:19 > Socket writing time: 6 ms.
23-3-2015 22:09:20 > Request time: 167 ms
23-3-2015 22:09:20 > Received FIN
23-3-2015 22:09:20 > Socket closed
~/node $ node test.js
23-3-2015 22:09:24 > DNS time: 12 ms.
23-3-2015 22:09:25 > Connection time: 23 ms.
23-3-2015 22:09:25 > Connected to 91.142.222.187
23-3-2015 22:09:25 > Socket writing time: 6 ms.
23-3-2015 22:09:25 > Request time: 23 ms
23-3-2015 22:09:25 > Received FIN
23-3-2015 22:09:25 > Socket closed
This happens in the server running Debian as well as in my computer running Windows 8.1
I could of course just run the test twice every time and take the second value, but it seems a bit like a waste of time, and I would like to know what is happening under the hood, and how to get it working right in one-shot.
Thanks in advance.