July 17, 2011

We recently ran into a problem where our node.js process was running out of memory very rapidly. We tracked it down to a couple of debug log lines that, when removed, reduced the memory problem considerably. The problem was that because all i/o is asynchronous in node.js we were generating log messages faster than they could be written to the file system. They were getting buffered, piling up until the process ran out of memory.

As an attempt to ameliorate this I wanted to see if changing log4js‘s fileAppender from using fs.write to using a WriteStream would make any difference. My test program looked like this:

It writes one million log lines to a file, and every 5000 it records the memory usage to another file for processing later. I ran two versions of log4js, one with the original fileAppender (using fs.write) and one using a rewritten fileAppender that used a WriteStream. The graph below shows the results.

It is pretty obvious that WriteStream is the better implementation for this application, and the unstable branch of log4js now contains the rewritten fileAppender. I hope to release this within the next couple of days.