While exploring the node.js event loop, I realized that poll events appear in some random order, rather than following the order described in the event loop.

The logic of the code is trivial: we recursively schedule exactly one setImmediate for each loop iteration. The code inside each setImmediate must schedule one setTimeout and make one request.

Demo:

const http = require("http");
const request = require('request');

const server = http.createServer(function (request, response) {
  response.end();
  console.log("I/O poll", request.url);
});

server.listen(3000, function () {
  console.log("Runing on port 3000");
});

let _i = 0;

var options = {
  'method': 'GET',
  'url': 'https://127.0.0.1:3000/test',
  'headers': {
  },
  form: {}
};

setImmediate(() => {
  console.log("root immediate");
  setImmediate(function loop() {
    let k = _i;
    console.log(`immediate nested => ${k}`, performance.now());
    setTimeout(() => {
      console.log(`setTimeout => ${k}`, performance.now());
    });
    request(options, function (error, response) {
      if (error) throw new Error(error);
      ///console.log(response.body, performance.now());
    });
    /// 50 iterations of event loop
    if (_i++ < 50) setImmediate(loop);
  });
});

When you run this code, you will see something like this:

root immediate
...
I/O poll /test
immediate nested => 19 587.776804
setTimeout => 18 588.651673
setTimeout => 19 588.908073
I/O poll /test
I/O poll /test
I/O poll /test
immediate nested => 20 591.348483
setTimeout => 20 592.245303
I/O poll /test
I/O poll /test
immediate nested => 21 599.421111
I/O poll /test
I/O poll /test
immediate nested => 22 609.22716
setTimeout => 21 609.4331
I/O poll /test
immediate nested => 23 620.868927
setTimeout => 22 621.377087
setTimeout => 23 621.886457
immediate nested => 24 624.343667
setTimeout => 24 625.086037
...

But this is not what is expected. I expected to see, for example, such a picture:

root immediate
...
setTimeout => 18 586.321573
I/O poll /test
immediate nested => 19 587.776804
setTimeout => 19 588.908073
I/O poll /test
immediate nested => 20 591.348483
setTimeout => 20 592.245303
I/O poll /test
...

Why is this happening? Explain what I misunderstand?