Skip to content

Event loop execution order changes based on code part that didn't executed #27747

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
davNazaryan opened this issue May 17, 2019 · 12 comments
Closed
Labels
confirmed-bug Issues with confirmed bugs. timers Issues and PRs related to the timers subsystem / setImmediate, setInterval, setTimeout. windows Issues and PRs related to the Windows platform.

Comments

@davNazaryan
Copy link

  • Node.js Version: v10.14.1
  • OS: Windows10x64

No need to init new project. Only the built-in fs module used there.

I have a code that works as designed in Unix based OS, but in windows, it gives the "strange" result.
Code

const fs = require('fs');

function someAsyncOperation(callback) {
  fs.readFile('/path/to/file', callback);
}

const timeoutScheduled = Date.now();

setTimeout(() => {
  const delay = Date.now() - timeoutScheduled;

  console.log(`${delay}ms have passed since I was scheduled`);
}, 1000);

someAsyncOperation(() => {
  console.log('BEFORE WHILE');
  const startCallback = Date.now();

  while (Date.now() - startCallback < 1000) {
    // do nothing
  }

  // setImmediate(() => { console.log('IMMEDIATE'); });

  console.log('AFTER WHILE');
});

The output is

BEFORE WHILE
AFTER WHILE
2007ms have passed since I was scheduled

The output is the same independently of how many timers are present. ( it's always 2000+ )

Which is weird. I guess that such a result is possible if the setTimeout ( I mean the setTimeout itself, not thesetTimeout's callback ) registered AFTER while loop work.

Pay attention at // setImmediate(() => { console.log('IMMEDIATE'); }); line.
If I uncomment it the output will be

BEFORE WHILE
AFTER WHILE
IMMEDIATE
1005ms have passed since I was scheduled

In Unix based system the output always {1000+}ms, and doesn't depend on setImmediate existence.

Can someone explain why it happens, and give event loop execution order?

It's maybe a BUG, but I'm not sure.

Thanks in advance.

Update: This message is copied from nodejs/help#1912

@bzoz
Copy link
Contributor

bzoz commented May 17, 2019

So: https://nodejs.org/api/process.html#process_a_note_on_process_i_o says:

Writes may be synchronous depending on what the stream is connected to and whether the system is Windows or POSIX: (...)
  - TTYs (Terminals): asynchronous on Windows, synchronous on POSIX

IMHO, this is not a bug, its probably the sync/async discrepancy that's causing this. If you can provide a minimal reproachable example, we can investigate this further.

@Fishrock123
Copy link
Contributor

but in windows, it gives the "strange" result.

What exactly is the windows result? You don't seem to have posted it?

Nothing there seems unusual to me so far.

@Fishrock123 Fishrock123 added the question Issues that look for answers. label May 17, 2019
@davNazaryan
Copy link
Author

@Fishrock123 Please read my initial message carefully.

Providing code execution results in screenshots. Pay attention at 23 code line and ${delay}ms have passed since I was scheduled output.

image

image

@davNazaryan
Copy link
Author

davNazaryan commented May 18, 2019

@bzoz

Writes may be synchronous depending on what the stream is connected to and whether the system is Windows or POSIX: (...)
  - TTYs (Terminals): asynchronous on Windows, synchronous on POSIX

Do you mean that the issue can be connected with console.log?

If you can provide a minimal reproachable example, we can investigate this further.

With joy, but I do not understand what reproachable example means.

@Fishrock123
Copy link
Contributor

Why are you uncommenting the Immediate? The Immediate should always run before timers.

I am still unsure of what windows difference there is since there does not appear to be any other than what you modified between runs?

@Trott
Copy link
Member

Trott commented May 20, 2019

With joy, but I do not understand what reproachable example means.

Pretty sure they meant reproducible example.

@Trott
Copy link
Member

Trott commented May 20, 2019

The Immediate should always run before timers.

@Fishrock123 Without the Immediate, execution of the seemingly-unrelated Timeout is nearly a full second slower. Without scheduling the Immediate, the 1000ms Timeout reports firing after 2003ms. When the Immediate is scheduled, it fires after only 1007ms, much closer to the expected time, but why would scheduling an unrelated Immediate cause that?

IIUC, @bzoz is suggesting that it might have to do with async vs sync i/o, which certainly seems plausible (although surprising to me in terms of the magnitude of its impact). I'm unable to replicate this on macOS using the sample code provided in the description. So it would seem to be Windows-specific (although confirmation from another Windows user that they see the same results with the sample code would be helpful).

@davNazaryan If you change the Immediate to do nothing at all (rather than invoking console.log()), does it behave the same as with the console.log(), the same as without the Immediate at all, or neither?

@Fishrock123
Copy link
Contributor

Oh... did I really not see that... well, at least that seems wrong.

@davNazaryan
Copy link
Author

Thanks to @Trott for a clear explanation, and sorry for my English.

So it would seem to be Windows-specific

There are 2 versions of Node, Windows and POSIX. I can't reproduce the issue on Ubuntu. So, Yes, you're right, it's Windows-specific issue.

If you change the Immediate to do nothing at all (rather than invoking console.log()), does it behave the same as with the console.log(), the same as without the Immediate at all, or neither?

Commenting console.log() didn't give any effect.

I provided 3 versions of the fully reproducible code with their results. All you need to get the same results is Windows :)

  1. Without setImmediate
  • output
    image
  1. With setImmediate and consloe.log
  • output
    image
  1. With setImmediate that does nothing ( WITHOUT consloe.log )
  • output
    image
  1. Without setImmediate
  • the code
const fs = require('fs');

function someAsyncOperation(callback) {
  fs.readFile('/path/to/file', callback);
}

const timeoutScheduled = Date.now();

setTimeout(() => {
  const delay = Date.now() - timeoutScheduled;

  console.log(`${delay}ms have passed since I was scheduled`);
}, 1000);

someAsyncOperation(() => {
  console.log('BEFORE WHILE');
  const startCallback = Date.now();
  /*let i = 0;*/

  while (Date.now() - startCallback < 1000) {
    /*console.log(i++);*/
  }

  /*setImmediate(() => { console.log('IMMEDIATE'); });*/

  console.log('AFTER WHILE');
});
  1. With setImmediate and consloe.log
  • the code
const fs = require('fs');

function someAsyncOperation(callback) {
  fs.readFile('/path/to/file', callback);
}

const timeoutScheduled = Date.now();

setTimeout(() => {
  const delay = Date.now() - timeoutScheduled;

  console.log(`${delay}ms have passed since I was scheduled`);
}, 1000);

someAsyncOperation(() => {
  console.log('BEFORE WHILE');
  const startCallback = Date.now();
  /*let i = 0;*/

  while (Date.now() - startCallback < 1000) {
    /*console.log(i++);*/
  }

  setImmediate(() => { console.log('IMMEDIATE'); });

  console.log('AFTER WHILE');
});
  1. With setImmediate that does nothing ( WITHOUT consloe.log )
  • the code
const fs = require('fs');

function someAsyncOperation(callback) {
  fs.readFile('/path/to/file', callback);
}

const timeoutScheduled = Date.now();

setTimeout(() => {
  const delay = Date.now() - timeoutScheduled;

  console.log(`${delay}ms have passed since I was scheduled`);
}, 1000);

someAsyncOperation(() => {
  console.log('BEFORE WHILE');
  const startCallback = Date.now();
  /*let i = 0;*/

  while (Date.now() - startCallback < 1000) {
    /*console.log(i++);*/
  }

  setImmediate(() => { /*console.log('IMMEDIATE');*/ });

  console.log('AFTER WHILE');
});

@targos targos added confirmed-bug Issues with confirmed bugs. v10.x windows Issues and PRs related to the Windows platform. timers Issues and PRs related to the timers subsystem / setImmediate, setInterval, setTimeout. and removed question Issues that look for answers. labels May 20, 2019
@targos
Copy link
Member

targos commented May 20, 2019

I can reproduce on Windows with Node.js 10.15.3.
12.x and 8.x are not affected.

@amsterdam-littlehill
Copy link

amsterdam-littlehill commented Mar 31, 2020

on node v10.15.3 , win10
I had the same problem

@jasnell
Copy link
Member

jasnell commented Apr 26, 2021

While I don't believe this was ever actually resolved, there will not be another 10.x release before it hits end of life in a few days. Closing the issue as it appears to only be relevant to 10.x

@jasnell jasnell closed this as completed Apr 26, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
confirmed-bug Issues with confirmed bugs. timers Issues and PRs related to the timers subsystem / setImmediate, setInterval, setTimeout. windows Issues and PRs related to the Windows platform.
Projects
None yet
Development

No branches or pull requests

7 participants