2

If you observe simple client-side JS like this, it's intuitive that if we run into setTimeouts, the time length (in this example's case, 0 ms) determine what is the interval AFTER which the JS runtime actually adds this to the queue as explained here.

In Node.JS, however, if I have some api invocation that is fundamentally async (like fs.readFile()) and in the same codebase if I have a simple setTimeout, my understanding is that the event loop will start reading the file, and if has been read, it goes ahead and queues it up so that the appropriate callback can be fired once the main node thread isn't doing any sequential operations. My question is that does this notion of "adding the setTimeout callback" only AFTER the specific timeout still hold (in contrast to class client-side JS). Specifically, here is an example:

const fs = require('fs');
// Set timeout for 2 secs
setTimeout(function() { 
  console.log('Timeout ran at ' + new Date().toTimeString()); 
}, 2000);
// Read some file
fs.readFile('sampleFile.txt', function(err, data) {
   if(err) {
     throw err;
   }
   console.log(data.toString() + " " + new Date().toTimeString();
}
var start = new Date();
console.log('Enter loop at: '+start.toTimeString());
// run a loop for 4 seconds
var i = 0;
// increment i while (current time < start time + 4000 ms)
while(new Date().getTime() < start.getTime() + 4000) {
  i++;
}
console.log('Exit loop at: ' +new Date().toTimeString() +'. Ran '+i+' iterations.');

The output i get for this is:

Enter loop at: 18:22:14 GMT-0700 (PDT) Exit loop at: 18:22:18 GMT-0700 (PDT). Ran 33980131 iterations. Timeout ran at 18:22:18 GMT-0700 (PDT) sampleFileContents 18:22:18 GMT-0700 (PDT)

Does this mean that somehow the setTimeout callback+message was placed on the event loop queue BEFORE the file could be read completely? This tells me 1 of 3 things: Either the setTimeout callback+message was placed on the queue ready to be fired after 2 secs and the next available tick. OR the time to actually read the sampleFile.txt took more than 2 seconds. OR the sampleFile.txt was read quickly, but somehow it wasn't placed ahead of the setTimeout in the event loop queue.

Am i using the right mental model for think about this? I'm trying to get a deeper understanding of node's internals but without having to dive through the libuv/libeio C-code. I've tried playing around with the timeout, and interestingly enough when I set the timeout to greater than 4000 ms, it appears that in my output, I always print out the sampleFileContents before actually printing what time the timeout ran at.

BSJ
  • 1,185
  • 2
  • 10
  • 15
  • Your 4000ms comment in your last paragraph just means that the file operation always takes less than 4000ms and thus completes before the `setTimeout()` is scheduled to execute. The first operation that is ready to run gets executed and they should be queued up in the order they were ready to go if the JS engine is busy when they become ready. – jfriend00 Jun 15 '14 at 02:19
  • To rephrase: My understand is that what my main node program sends to its event loop is a pair (operation, callback). The expectation is that ONCE the event loop delegates to the thread pool and the relevant thread is DONE with processing the operation, then the event loop adds the relevant callback to a queue. If nothing else is happening in the main program then this callback is fired back. Is this a correct expectation? – BSJ Jun 15 '14 at 02:42
  • My understanding is this. When an async operation is launched of any kind it goes about it's own business independent of the main thread and it keeps track of the callback to be executed when it's done. When it finishes, it adds an item to the end of the JS event queue that contains the callback to be called and any arguments to be passed to it. If the main thread is not doing anything at the time, that event is fired immediately and the callback is called. If the main thread is busy, then the item stays in the queue until the current thread of execution finishes (cont'd in next comment) – jfriend00 Jun 15 '14 at 03:22
  • When the main thread of execution finishes, it looks to see if there are any more events in the event queue. If theere are, it gets the first event out of the queue (e.g. the oldest event) and executes it. Here's a [reference post on this topic](http://stackoverflow.com/questions/7575589/how-does-javascript-handle-ajax-responses-in-the-background/7575649#7575649) that is written for the browser, but I think most of it pertains to node also. – jfriend00 Jun 15 '14 at 03:23

1 Answers1

3

There is a gotcha. The following lines of code are synchronous and blocking.

// increment i while (current time < start time + 4000 ms)
while(new Date().getTime() < start.getTime() + 4000) {
  i++;
}

Which means that the event loop was hijacked by it and never got to function as you would expect.

The settmeout printing before fileread could mean that at the point of time just before the loop started the timer was already set, but the fileread events were not yet added. I added some more code to verify this idea.

var readStream = fs.createReadStream('sampleFile.txt');

  readStream.on('open', function () {
    console.log('Read started ' + new Date().toTimeString());
  });

  readStream.on('data', function(data) {
  });

  readStream.on('end', function(err) {
   console.log('Read end ' + new Date().toTimeString());
  });   

setTimeout(function() {
  console.log('Timeout ran at ' + new Date().toTimeString());
}, 2000);

var start = new Date();
console.log('Enter loop at: '+start.toTimeString());

var i = 0;
while(new Date().getTime() < start.getTime() + 4000) {
  i++;
}

console.log('Exit loop at: ' +new Date().toTimeString() +'. Ran '+i+' times.');

The output is :

Enter loop at: 22:54:01 GMT+0530 (IST)
Exit loop at: 22:54:05 GMT+0530 (IST). Ran 34893551 times.
Timeout ran at 22:54:05 GMT+0530 (IST)
Read started 22:54:05 GMT+0530 (IST)
Read end 22:54:05 GMT+0530 (IST)

Which proves my theory that they never ran concurrently. As to why this happened I believe that fs events need at least one tick to be queued and sent correctly. But timeouts are added instantly. Since you locked the event loop before the fileread event could be added, it was queued after timeout handler after the loop ended.

You can try running your code without the loop, the output will be 

Enter loop at: 22:57:15 GMT+0530 (IST)
Exit loop at: 22:57:15 GMT+0530 (IST). Ran 0 iterations.
 22:57:15 GMT+0530 (IST)
Timeout ran at 22:57:17 GMT+0530 (IST)

if read finishes first.

user568109
  • 47,225
  • 17
  • 99
  • 123
  • Thank you for adding the rigor of the readStream and logging multiple events. I was under the impression that the event loop can not be "locked" by the main node thread in terms of the event loop having the ability to add msg/callback pairs to its queue. I thought that the only time the event loop is indeed "locked" by the main node thread is if the main thread is still running (in this example, a long while loop) which in turn blocks the event loop from "firing" the callbacks queued up because the main thread is still busy processing stuff. – BSJ Jun 15 '14 at 21:58
  • If my understanding is correct, it makes sense why we see the "Enter loop at .. " msg and the "Exit loop at .. " msg at the top. I don't want to conflate "event loop adding callbacks to the queue" with "event loop adding callbacks to the queue specifically for setTimeouts", and the reason for this is that the setTimeout-based callbacks are not honored in terms of *where* they are placed in the queue but rather *when* they are eligible to be fired (delay + next available tick). For your above example, if you bump up the delay to 4100,u will notice that the timeout-based callback is fired last – BSJ Jun 15 '14 at 22:17
  • @BSJ Yes, for setTimeout it is as if it gets executed after the delay. And by execution, it is added to the queue after all queued callbacks at that moment. – user568109 Jun 16 '14 at 04:16
  • If it is supposed to get queued for the next opportunity to get fired *after* the specified delay is over, that still doesn't explain why in my original example the setTimeout callback consistently got triggered *before* the readFile callback. The setTimeout callback was supposed to get queued after a 2 second delay; does this mean that it took the event loop > 2 seconds to actually read the file (which is why the setTimeout callback gets queued first and fired first?). Unless there's 2 queues that the eventLoop maintains: One for the pure I/O async calls, and another for sync delayed calls. – BSJ Jun 16 '14 at 06:04
  • 1
    @BSJ It doesn't take 2 sec to read file. It is because, the fs events are picked up and queued not untilthe next tick available which happens to be after the loop. After the loop the fs event open file and read are yet to be queued while settimeout is already queued. Yes the event loop maintains a separate queue for async I/O, the sync happens to be blocking and is added to the main queue. – user568109 Jun 16 '14 at 06:45
  • @ user568109 To clarify, there is nothing blocking the event loop from queueing the fs events (open,read) onto its async-IO-queue while the main thread's busywait-while-loop is executing, correct? Once the main-thread is done execute the while-loop and really has nothing else pressing to do, that's what gets counted as a nextTick (i.e. when the main thread is NOT busy processing anything else), correct? On the nextTick, the event loop decides what to dispatch to the main thread; in this case it had 1 queue which had the readFile callback, and another queue which had a timeout callback – BSJ Jun 16 '14 at 07:30
  • The timeout callback sits on what you called a "main" queue. In this case the main queue's first item was enqueued a good 2 seconds after the setTimeout was triggered; the async-IO-queue's first item was enqueued as soon as the file was opened and read (presumably before the 2 second mark). Regardless, the "main"-queue seems to have priority over the async-IO-queue which is why we see the above behavior. This has been a great learning experience, thank you, and I will go ahead and accept your answer. – BSJ Jun 16 '14 at 07:32