Internals of Node.js - First request gets executed and then everything else

Viewed 28

I created a simple project to understand the internals of Node.js (Event Loop, libuv, threads) and ended up facing an unexpected behavior that I don't get it.

Here is the code. Basically the server listens for requests and does a calculation that takes some time. (approximately 750ms)

process.env.UV_THREADPOOL_SIZE = 1;

const express = require('express');
const crypto = require('crypto');
const cluster = require('cluster');

const serverStartTime = Date.now();

const consoleColors = ["\x1b[31m", "\x1b[31m", "\x1b[32m", "\x1b[33m", "\x1b[34m"];

if (cluster.isMaster) {
  cluster.fork();
} else {
  const app = express();

  const color = consoleColors[cluster.worker.id];
  let requestCount = 0;
  let firstRequestTime = null;

  app.get('/', (req, res) => {
    const requestStartTime = Date.now();
    if (firstRequestTime === null) {
      firstRequestTime = requestStartTime;
    }
    const requestNum = requestCount + 1;
    console.log(color, `[Request ${requestNum}][PID ${process.pid}][Started: ${requestStartTime - serverStartTime}]`);
    requestCount += 1;
    crypto.pbkdf2('a', 'b', 100000, 512, 'sha512', () => {
      const requestEndTime = Date.now();
      const sinceFirstRequest = requestEndTime - firstRequestTime;
      const tookTime = requestEndTime - requestStartTime;
      console.log(color, `[Request ${requestNum}][PID ${process.pid}][Ended: ${requestEndTime - serverStartTime}][Took: ${tookTime}ms][SinceFirstRequest: ${sinceFirstRequest}ms]`);
      res.send('Hi there');
    });
  });

  app.listen(3000);
}

After running the command (to make 5 requests simultaneously): ab -c 5 -n 5 localhost:3000/ I get the following logs:

 [Request 1][PID 41495][Started: 1395]
 [Request 1][PID 41495][Ended: 2072][Took: 677ms][SinceFirstRequest: 677ms]
 [Request 2][PID 41495][Started: 2077]
 [Request 3][PID 41495][Started: 2082]
 [Request 4][PID 41495][Started: 2084]
 [Request 5][PID 41495][Started: 2086]
 [Request 2][PID 41495][Ended: 2797][Took: 720ms][SinceFirstRequest: 1402ms]
 [Request 3][PID 41495][Ended: 3465][Took: 1383ms][SinceFirstRequest: 2070ms]
 [Request 4][PID 41495][Ended: 4132][Took: 2048ms][SinceFirstRequest: 2737ms]
 [Request 5][PID 41495][Ended: 4801][Took: 2715ms][SinceFirstRequest: 3406ms]

Can someone explain why the second request always waits for the first to finish and all subsequent ones start almost simultaneously? No matter how many simultaneous requests I make, the first one always ends and then all other requests start.

I read that networking uses resources from the OS and some blocking operations (such as pbkdf2) uses the thread pool. The behavior I expected was: log the beginning of all requests and then, one by one, log the end of each one.

My first guess was: the phases of the Event Loop and the order in which they are executed.

So I put one more cluster.fork(), (now there are two Event Loops). If this behavior was due to the phases, the first request of each Event Loop should be executed. But it doesn't. Only one request of the first cluster.fork() is executed initially, and then everything else happens.

I don't know if my chain of thought is correct, please help me understand.

0 Answers
Related