Wednesday, June 22, 2011

Node.js and reckless console.log() statements

I've seen code that over uses, nah rather abuses the logger. Many times teams use it in the wrong way or sometimes over use it and then struggle to improve performance. This simple test will show the effect.

From the synopsis of Node.js doc, this is my server code:

var http = require('http');
http.createServer(function (request, response) {
    response.writeHead(200, {'Content-Type': 'text/plain'});
    response.end('Hello World\n');
}).listen(8124);
console.log('Server running at http://127.0.0.1:8124/');

Now I use JMeter to test the performance. I fire a 1000 HTTP requests within a time frame of 2s, with a wait of 1ms duration in between each new request. In my environment the median response time was 2ms for each request.

Now I add a single console log statement for the callback function in the above server code.

var http = require('http');
http.createServer(function (request, response) {
    response.writeHead(200, {'Content-Type': 'text/plain'});
    response.end('Hello World\n');
    console.log('response sent');
}).listen(8124);
console.log('Server running at http://127.0.0.1:8124/');

I repeat the same JMeter test, but this time the median response time has jumped to 315ms for each request. Food for thought ? :)

3 comments:

  1. Thanks Chetan...shows how we should watch and be careful, before putting those console statements to help us debug better.. and then just forget and leave those statements :)

    ReplyDelete
  2. isn't this problem with console logging!!!. Never the less it should be something in the production mode/release mode the logging should be disabled then it shouldn't be a problem even if you abuse

    ReplyDelete
  3. thanks ashwin, agree with u prasad :)

    ReplyDelete