0

I created a function to understand the behavior of the setTimeout() function in javascript. I created a recursive function which keeps calling itself. It worked fine until I added a sleep function inside. Here's the code.

'use strict';

(function iterate(i) {
  var t=setTimeout(function () {
    console.log('timeout ' + i + ' ' + (new Date()));
    sleep(1000);
    console.log('timeout ' + i + ' ' + (new Date()));
    //clearTimeout(t);
    iterate(++i);
  },2000);
})(0);

function sleep(millis) {
  console.log('sleeping...');
  var date = new Date();
  var curDate = null;
  do {
    curDate = new Date();
  }
  while (curDate - date < millis);
}

Here's the output when I run this code.

timeout 0 Wed May 13 2015 12:07:21 GMT+0530 (IST)
sleeping...
timeout 0 Wed May 13 2015 12:07:22 GMT+0530 (IST)
timeout 1 Wed May 13 2015 12:07:25 GMT+0530 (IST)
sleeping...
timeout 1 Wed May 13 2015 12:07:26 GMT+0530 (IST)
timeout 2 Wed May 13 2015 12:07:29 GMT+0530 (IST)
sleeping...
timeout 2 Wed May 13 2015 12:07:30 GMT+0530 (IST)

The difference between two iterate calls should be 2 seconds but it is always sleep_time + delay_time, which in this case is 3 seconds. Also adding clearTimeout() just before calling iterate(), makes it work normal.

Can anyone explain what is happening here?

Nakul Mohan
  • 11
  • 3
  • i think when you put it to sleep, the setTimeout clock also is put to sleep since js is single threaded. Hence 2sec + 1sec(sleep) gives you the 3sec you are experiencing – wallop May 13 '15 at 06:48
  • Isn't it kind of hard to measure timing to the second when all you're logging is a time with seconds? I'd suggest you log the time to at least tenths of seconds to see better what is really happening with the timing. – jfriend00 May 13 '15 at 06:58
  • It should more or less work as you expect when you'd move the `iterate()` call before your sleep. But really, just don't sleep, use a `setTimeout`. – Bergi May 13 '15 at 06:59
  • Ran the code again with a tenth of the current delays. Still the output is similar. It seems to be following the rule that total_delay = sleep_delay + timeout_delay. Here's the output - – Nakul Mohan May 13 '15 at 07:16
  • timeout 0 215 sleeping... timeout 0 317 timeout 1 635 sleeping... timeout 1 735 timeout 2 35 sleeping... timeout 2 135 timeout 3 435 sleeping... timeout 3 535 timeout 4 835 sleeping... timeout 4 935 timeout 5 235 – Nakul Mohan May 13 '15 at 07:16
  • [This answer](http://stackoverflow.com/questions/7575589/how-does-javascript-handle-ajax-responses-in-the-background/7575649#7575649) that describes how the JS event queue works may help you understand how `setTimeout()` works. The article was written about asynchronous Ajax in the browser, but the same principles apply to timers in node.js and the article contains many good references to other articles. – jfriend00 May 13 '15 at 08:17
  • @NakulMohan - See this jsFiddle: http://jsfiddle.net/jfriend00/8m4gkLet/. The timing seems to be exactly as expected, sleeps for 1 second, then sets a timer which fires 2 seconds later. Time for each cycle is 3 seconds which is sleep time + timer time as it should be. The reason they are sequential rather than in parallel is because the next timer is not set until after the sleep loop finishes. So you wait 1 second in the loop, then set a timer to fire 2 seconds later. The only mystery here is why your output is not what others get. – jfriend00 May 13 '15 at 09:22
  • Yes, same behavior with chrome console. Seems like it's giving unexpected results only with the node. – Nakul Mohan May 13 '15 at 11:46

2 Answers2

1

what is happening here is that you get your code stuck in a while loop for 1 second each time , before the setTimeout is recalled , that is why you get 3 seconds delay .

ProllyGeek
  • 15,517
  • 9
  • 53
  • 72
0

EDIT (I don't know why I assume that you sleep sleep(1000) after both console.log):

Are you sure it's correct output? When I run it, it generates expected values:

timeout 0 Wed May 13 2015 09:16:16 GMT+0200 (Środkowoeuropejski czas letni)
VM631:15 sleeping...
VM631:8 timeout 0 Wed May 13 2015 09:16:17 GMT+0200 (Środkowoeuropejski czas letni)
VM631:6 timeout 1 Wed May 13 2015 09:16:19 GMT+0200 (Środkowoeuropejski czas letni)
VM631:15 sleeping...
VM631:8 timeout 1 Wed May 13 2015 09:16:20 GMT+0200 (Środkowoeuropejski czas letni)
VM631:6 timeout 2 Wed May 13 2015 09:16:22 GMT+0200 (Środkowoeuropejski czas letni)
VM631:15 sleeping...
VM631:8 timeout 2 Wed May 13 2015 09:16:23 GMT+0200 (Środkowoeuropejski czas letni)
VM631:6 timeout 3 Wed May 13 2015 09:16:25 GMT+0200 (Środkowoeuropejski czas letni)
VM631:15 sleeping...
VM631:8 timeout 3 Wed May 13 2015 09:16:26 GMT+0200 (Środkowoeuropejski czas letni)
VM631:6 timeout 4 Wed May 13 2015 09:16:28 GMT+0200 (Środkowoeuropejski czas letni)

So we have 1 second delay between console.log and 2 seconds of iterate(i) delay due to setTimeout. It seems to be correct.

Sebastian Budka
  • 396
  • 1
  • 8
  • 19