console.log Tick(Object)ing away?

Back

I’ve recently been wasting my evenings challenging myself with Advent of Code. Excited by Node I’ve been stretching it to do all the grunt work, but twice have come up to a brick will with an unexplainable memory leak.

Stripping out everything, I traced it down to console.log, illustrated in this contrived example.

var i = 0;
while (true)
  console.log(`#${++i}`);

No memory leak here? But a profile of memory usage reveals an inordinate amount of a rather mysterious TickObject. What is it, what’s going and why does it dominate 84% of node’s memory?

alt JS Profile

After a bit of delving further down the rabbit hole, we can see that almost all the TickObject’s represent a callback to afterWrite.

alt TickObject

Inspection into Node’s source reveals that console.log is just being passed on to stdout. (Note to self, be sure to just use process.stdout.write next time to cut out the middle man).

A skim of _stream_writable.js explains what’s going on, and where our afterWrite is being called.

...
function onwrite(stream, er) {
  var state = stream._writableState;
  var sync = state.sync;
  var cb = state.writecb;

  onwriteStateUpdate(state);

   ...

    if (sync) {
      process.nextTick(afterWrite, stream, state, finished, cb);
    } else {
      afterWrite(stream, state, finished, cb);
    }
  }
}
...

Here’s a good point to dip out and catch up on how node uses ticks to queue up events. In short, node queues up ticks, which are just bits of code that are queued up till later to be executed asynchronously. Being event/queued based and running off a single thread, node favours code to that nature. So here appears the problem, running a synchronous application whilst using functions that bank on your app being written in an asynchronous manner are just not going to work.

process.stdout.write uses an asynchronous cleanup function called afterWrite. These queue up, and before you know it, your application runs out of memory and explodes. How do we fix this? Easy, let’s add some more ticks to the pot!

Replacing our while loop with a block of re-executable code queued up as a tick, allows any other system queued code blocks to execute in between ours; and our app continues blissfully on.

var i = 0;
(function whileLoop () {
 process.stdout.write(`#${++i}\r`);

 process.nextTick(whileLoop);
})();

Moral of the story? Node is event based and should be used as such!

tl;dr Replace any long running while / for loops with an asynchronously executable block of code using process.nextTick.