Crazy Node Behavior- Unexpected Event Loop Events

We have heard about it- The Event Loop. How I knew about it had something to do with callbacks and the notion of asynchronous code.

Hello & Welcome to my post, where I am going to write about an unexpected behavior of event loop. Quite recently I’ve discovered few mind-boggling Node JS behavior from Advanced NodeJS concepts. I am going to put some code which will not behave the way it should have. This example ties together async, event-loop & threads in a multitask. So, let’s get’s started.

Credit- dasunpubudu.wordpress.com

First, I will create a JavaScript file, name it multitask.js and calculate the time taken to render response from a request.

const https = require('https')
const start = Date.now();
function doRequest(){
  https.request('https://www.google.com',res=>{
   res.on('data',()=>{});
   res.on('end',()=>{
    console.log("HTTPS: ",Date.now() - start)
   })
 }).end()
}
doRequest()

Execute the above code and observe the behavior of execution. Since the above function performs a network operation, it takes some time. When the operations in the stack are done (i.e. when the stack is empty), functions in the task queue are executed. In this case, when the stack is empty event loop picks console.log(“HTTPS: “,Date.now() — start) output from task queue and moves it to the stack which outputs to CLI.

Next, I will require in FS & Crypto modules and call them in order.

const https = require('https');
const fs = require('fs');
const crypto = require('crypto');
const start = Date.now();
function doRequest(){
  https.request('https://www.google.com',res=>{
   res.on('data',()=>{});
   res.on('end',()=>{
    console.log("HTTPS: ",Date.now() - start)
   })
 }).end()
}
function getHash(){
  crypto.pbkdf2('a','b',100000,512,'sha512',()=>{
  console.log("Hash: ",Date.now() - start)
})
doRequest()
fs.readFile('multitask.js','utf8',()=>{
  console.log("FS: ",Date.now() - start)
})
getHash()
getHash()
getHash()
getHash()

We are just going to see the execution pattern of the output. Both FS & Crypto modules will execute asynchronously in a top to bottom approach.

But, if you see the output below:😮

HTTPS:  432
Hash:  1312
FS:  1313
Hash:  1398
Hash:  1419
Hash:  1421

getHash() function executes before FS gets executed. Reading a file with FS module from hard drive, there is no way it is going to take 1.3s.
Try commenting out getHash() function calls and let’s see how much it normally takes to read file.

FS:  26
HTTPS:  488

Extremely fast. So clearly we have an interesting behavior here. Let’s see what’s happening behind the scene.

An operating system (OS) controls the execution and provide an environment in which a user can execute programs in a convenient and efficient manner.

Internally Node makes use of threadpool for very specific function calls. Here HTTPS module directly reaches to OS whereas, FS & Crypto module(pbkdf2 function) make use of threadpool and executes the fs.readfile() & getHash() function calls as flowchart shows below.

If you & I notice the behavior of execution, the modules are executed as per the order we have called the functions, FS with thread #1 and so on.. I have not included HTTPS in the flowchart as it does not use threadpool for execution and logs output at the beginning.
The reason that FS module got delayed so long is specifically because of the way threadpool works. So, the function calls that happen inside the threadpool are five different tasks each got assigned to some thread.

fs.readFile('multitask.js','utf8',()=>{
  console.log("FS: ",Date.now() - start)
})
getHash()
getHash()
getHash()
getHash()

In the above flowchart, FS and 3 hash functions(Crypto #1, Crypto #2, Crypto #3) gets assigned to some thread and Crypto #4 is left unassigned as threadpool has 4 threads.
1. Thread #1 is going to start working on File system call and reaches HD to read the file. In this process, Thread #1 waits for node to get some stats from HD (accessibility, read the file contents, return contents).
2. Since Thread #1 sits idle, it leaves FS execution and picks up Crypto #4’s task and starts executing.
3. Meanwhile, Thread #2 finishes hash function and does the console.log as below output.

HTTPS:  432
Hash:  1312
FS:  1313
Hash:  1398
Hash:  1419
Hash:  1421

Thread #2 then picks up pending FS task and reaches to HD to checks on the stats which has returned by now and logs for FS function call following the rest hashes.

So, that’s why we saw that one hash function gets completed before the File System module and takes time longer than usual.

Alright. So that’s it. That’s what going on behind the scene. This can be also a good interview question. It explains what node is doing internally.

Ever thought, what if we increase the size of a threadpool?

set UV_THREADPOOL_SIZE=5 (Windows)

I bet you can take a pretty good guess here. Each functions will be assigned dedicated threads. As a result, FS will be executed in no time and will do console.log() at the top.
That’s all. This is how Node behave when it comes to asynchronous stuff to deal with.

Hope you’ve enjoyed reading my post. Big thanks to Stephen Grider for putting on this lecture. Claps will motivate a novice writer.

Happy learning!