chained setTimeout failures in node.js

broken-setTimeout.js

var iterations = 5;
var timeout;
var last = Date.now();

// --------------------
// version 1, this behaves pretty much as you'd expect - this loop takes 0-1ms and runs almost exactly ever 200ms
// 
var loop1 = function() {
  var start = Date.now();
  // do nothing
  var end = Date.now();
  console.log('started ' + start + ' (delta: ' + (start-last) + '), ended ' + end + ', elapsed ' + (end-start));
  last = start;
  if (--iterations > 0) {
    timeout = setTimeout(loop, 200);
  }
}
timeout = setTimeout(loop, 200);

// version 1 output is straightforward, showing that the time between invocations is almost perfectly 200ms
//
// started 1417755482722 (delta: 201), ended 1417755482722, elapsed 0
// started 1417755482922 (delta: 200), ended 1417755482922, elapsed 0
// started 1417755483124 (delta: 202), ended 1417755483124, elapsed 0
// started 1417755483325 (delta: 201), ended 1417755483325, elapsed 0


// --------------------
// version 2: when we add some sleep (or any kind of work that takes time) suddenly the actual time between
// calls starts to go wonky. way outside of normal setTimeout variance, and generally adding exactly the
// amount of time you spent doing sleep/work. note, this happens for any work, it is not a sleep() or CPU-busy
// or GC issue

function sleep(ms) { var start=Date.now(); while (Date.now() - start < ms); }
last = Date.now();
var loop2 = function() {
  var start = Date.now();
  sleep(100);
  var end = Date.now();
  console.log('started ' + start + ' (delta: ' + (start-last) + '), ended ' + end + ', elapsed ' + (end-start));
  last = start;
  if (--iterations > 0) {
    timeout = setTimeout(loop2, 200);
  }
}
timeout = setTimeout(loop2, 200);

// version 2 output - we spent 100ms in sleep/work, but suddenly in the tail setTimeout for 200ms out we end up 400ms
// out, exactly double. we will in fact double any amount of sleep/work we spend inside our setTimeout. WTF?
// 
// started 1417755716414 (delta: 222), ended 1417755716514, elapsed 100
// started 1417755716816 (delta: 402), ended 1417755716916, elapsed 100
// started 1417755717216 (delta: 400), ended 1417755717316, elapsed 100
// started 1417755717617 (delta: 401), ended 1417755717717, elapsed 100


// --------------------
// version 3 - now here's what makes zero sense. if we simply clear the current timeout, everything goes back to
//  correct - tail calls to setTimeout are triggered at exactly the interval we expect
last = Date.now();
var loop3 = function() {
  var start = Date.now();
  sleep(100);
  var end = Date.now();
  console.log('started ' + start + ' (delta: ' + (start-last) + '), ended ' + end + ', elapsed ' + (end-start));
  last = start;
  if (--iterations > 0) {
    clearTimeout(timeout); // this is the only change
    timeout = setTimeout(loop3, 200);
  }
}
timeout = setTimeout(loop3, 200);

// version 3 output. somehow clearing the timeout causes the tail setTimeout() in loop3 to magically happen when we expect it.
//  suspect there is something in the node.js Timer implementationation where clearTimeout does something to the Timer queue, but
//  i haven't spotted exactly what is happening yet
// 
// started 1417756022375 (delta: 220), ended 1417756022476, elapsed 101
// started 1417756022676 (delta: 301), ended 1417756022776, elapsed 100
// started 1417756022977 (delta: 301), ended 1417756023077, elapsed 100
// started 1417756023277 (delta: 300), ended 1417756023377, elapsed 100