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
...
immediate nested => 18 586.183739
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?