require is 3.54x times slower on Windows compared to Linux on same machine

[mucsi96]

I have noticed big performance difference between Windows and Linux platforms on same code and machine. Wondering if we can improve the performance of module loading on Windows as it's 3.54x times slower compared to Linux.

Version: 12.7.0
Platform: Windows 10 Pro vs Ubuntu 19.04 both 64-bit (both installed properly without virtualization)
CPU: Intel Core i7-4702MQ 2.2GHz
RAM: 8GB
Drive: SSD
Code for reproduction: https://github.com/mucsi96/nodejs-windows-vs-linux-performace-issue

Windows CPU profile:

Linux CPU profile:

[Trott]

@nodejs/platform-windows

[mscdex]

I don't know if this is causing this issue but I noticed when profiling (via --prof/--prof-process), Windows was not showing any C++ entries and was showing abnormally high percentages (and in some cases NaN/Infinity) for JavaScript and GC under the summary section. Linux on the other hand showed results that you'd expect.

Example `--prof-process` Windows output (I tried this on an old win2012r2 VM)

Statistical profiling result from isolate-00000042E04773E0-2768-v8.log, (22 ticks, 0 unaccounted, 0 excluded).

 [Shared libraries]:
   ticks  total  nonlib   name
     16   72.7%          C:\Program Files\nodejs\node.exe
      6   27.3%          C:\Windows\SYSTEM32\ntdll.dll

 [JavaScript]:
   ticks  total  nonlib   name

 [C++]:
   ticks  total  nonlib   name

 [Summary]:
   ticks  total  nonlib   name
      0    0.0%    NaN%  JavaScript
      0    0.0%    NaN%  C++
      3   13.6%  Infinity%  GC
     22  100.0%          Shared libraries

 [C++ entry points]:
   ticks    cpp   total   name

 [Bottom up (heavy) profile]:
  Note: percentage shows a share of a particular caller in the total
  amount of its parent calls.
  Callers occupying less than 1.0% are not shown.

   ticks parent  name
     16   72.7%  C:\Program Files\nodejs\node.exe
     15   93.8%    C:\Program Files\nodejs\node.exe
      4   26.7%      LazyCompile: ~Module._compile internal/modules/cjs/loader.js:699:37
      4  100.0%        LazyCompile: ~Module._extensions..js internal/modules/cjs/loader.js:786:37
      3   75.0%          LazyCompile: ~Module.load internal/modules/cjs/loader.js:635:33
      3  100.0%            LazyCompile: ~Module._load internal/modules/cjs/loader.js:508:24
      1   25.0%          LazyCompile: *Module._load internal/modules/cjs/loader.js:508:24
      1  100.0%            LazyCompile: ~Module.require internal/modules/cjs/loader.js:675:36
      2   13.3%      LazyCompile: ~stat internal/modules/cjs/loader.js:80:14
      2  100.0%        LazyCompile: ~Module._findPath internal/modules/cjs/loader.js:301:28
      2  100.0%          LazyCompile: ~Module._resolveFilename internal/modules/cjs/loader.js:570:35
      2  100.0%            LazyCompile: ~Module._load internal/modules/cjs/loader.js:508:24
      2   13.3%      LazyCompile: ~openSync fs.js:438:18
      2  100.0%        LazyCompile: ~readFileSync fs.js:346:22
      2  100.0%          LazyCompile: ~Module._extensions..js internal/modules/cjs/loader.js:786:37
      2  100.0%            LazyCompile: ~Module.load internal/modules/cjs/loader.js:635:33
      1    6.7%      LazyCompile: ~realpathSync fs.js:1389:22
      1  100.0%        LazyCompile: ~toRealPath internal/modules/cjs/loader.js:267:20
      1  100.0%          LazyCompile: ~Module._findPath internal/modules/cjs/loader.js:301:28
      1  100.0%            LazyCompile: ~Module._resolveFilename internal/modules/cjs/loader.js:570:35
      1    6.7%      LazyCompile: ~Module._findPath internal/modules/cjs/loader.js:301:28
      1  100.0%        LazyCompile: ~Module._resolveFilename internal/modules/cjs/loader.js:570:35
      1  100.0%          LazyCompile: ~Module._load internal/modules/cjs/loader.js:508:24
      1  100.0%            LazyCompile: ~Module.require internal/modules/cjs/loader.js:675:36
      1    6.7%      LazyCompile: ~Module._extensions..json internal/modules/cjs/loader.js:793:39
      1  100.0%        LazyCompile: *Module._load internal/modules/cjs/loader.js:508:24
      1  100.0%          LazyCompile: ~Module.require internal/modules/cjs/loader.js:675:36
      1  100.0%            LazyCompile: ~require internal/modules/cjs/helpers.js:15:19
      1    6.7%      Eval: ~<anonymous> os.js:1:1
      1  100.0%        LazyCompile: ~NativeModule.compile internal/bootstrap/loaders.js:287:42
      1  100.0%          LazyCompile: ~NativeModule.compileForPublicLoader internal/bootstrap/loaders.js:211:57
      1  100.0%            LazyCompile: ~Module._load internal/modules/cjs/loader.js:508:24
      1    6.7%      Eval: ~<anonymous> C:\test\node_modules\qs\lib\utils.js:5:26
      1  100.0%        Eval: ~<anonymous> C:\test\node_modules\qs\lib\utils.js:1:1
      1  100.0%          LazyCompile: ~Module._compile internal/modules/cjs/loader.js:699:37
      1  100.0%            LazyCompile: ~Module._extensions..js internal/modules/cjs/loader.js:786:37
      1    6.7%      Eval: ~<anonymous> C:\test\node_modules\jsdom\lib\jsdom\living\register-elements.js:1:1
      1  100.0%        LazyCompile: ~Module._compile internal/modules/cjs/loader.js:699:37
      1  100.0%          LazyCompile: ~Module._extensions..js internal/modules/cjs/loader.js:786:37
      1  100.0%            LazyCompile: ~Module.load internal/modules/cjs/loader.js:635:33
      1    6.7%      Eval: ~<anonymous> C:\test\node_modules\asn1\lib\ber\index.js:1:1
      1  100.0%        LazyCompile: ~Module._compile internal/modules/cjs/loader.js:699:37
      1  100.0%          LazyCompile: ~Module._extensions..js internal/modules/cjs/loader.js:786:37
      1  100.0%            LazyCompile: ~Module.load internal/modules/cjs/loader.js:635:33
      1    6.3%    LazyCompile: ~isFileType fs.js:172:20
      1  100.0%      LazyCompile: ~readFileSync fs.js:346:22
      1  100.0%        LazyCompile: ~Module._extensions..js internal/modules/cjs/loader.js:786:37
      1  100.0%          LazyCompile: ~Module.load internal/modules/cjs/loader.js:635:33
      1  100.0%            LazyCompile: ~Module._load internal/modules/cjs/loader.js:508:24

      6   27.3%  C:\Windows\SYSTEM32\ntdll.dll
      3   50.0%    C:\Program Files\nodejs\node.exe
      1   33.3%      LazyCompile: ~Module.require internal/modules/cjs/loader.js:675:36
      1  100.0%        LazyCompile: ~require internal/modules/cjs/helpers.js:15:19
      1  100.0%          Eval: ~<anonymous> C:\test\node_modules\sshpk\lib\formats\putty.js:1:1
      1  100.0%            LazyCompile: ~Module._compile internal/modules/cjs/loader.js:699:37
      1   33.3%      Eval: ~<anonymous> C:\test\node_modules\parse5\lib\common\unicode.js:1:1
      1  100.0%        LazyCompile: ~Module._compile internal/modules/cjs/loader.js:699:37
      1  100.0%          LazyCompile: ~Module._extensions..js internal/modules/cjs/loader.js:786:37
      1  100.0%            LazyCompile: ~Module.load internal/modules/cjs/loader.js:635:33
      1   33.3%      Eval: ~<anonymous> C:\test\node_modules\jsdom\lib\jsdom\living\generated\HTMLFormElement.js:1:1
      1  100.0%        LazyCompile: ~Module._compile internal/modules/cjs/loader.js:699:37
      1  100.0%          LazyCompile: ~Module._extensions..js internal/modules/cjs/loader.js:786:37
      1  100.0%            LazyCompile: ~Module.load internal/modules/cjs/loader.js:635:33

[bnoordhuis]

I don't think the performance difference is unexpected.

require() is heavy on the stat(2) system calls (just check strace -e stat node app.js on linux) and those are emulated through multiple system calls on Windows, hence why ntdll.dll shows up in the call graph.

It might be possible to speed it up by trying access(2) first and trying stat(2) only when the first one doesn't error because:

1. Most stat(2) calls fail with ENOENT (file not found), and
2. The access(2) wrapper is implemented using a single system call on Windows and Unices.

I expect it to introduce a regression on Unices because they need to do more work now in the happy path so it should probably be an #ifdef _WIN32 in InternalModuleStat() in src/node_file.cc.

[nasreddineskandrani]

@bnoordhuis this problem is [maybe] causing an issue in facebook jest testing library on Windows for months now. Check linked issue.

Do you think someone is going to apply a fix soon?

I am not used to work on the node project. But if needed i am going to run it locally and check if your proposition solve the problem or directly going in debug to fix it... It's really important to take action and don't let the issue going Idle. Thank you very much for your time.

[bnoordhuis]

@nasreddineskandrani I'm unaware of anyone working on this right now. You're welcome to pick it up.

[jasnell]

There's been no further activity on this. Closing, but since it's not fully resolved I'm adding this to the Futures project board so it does not get lost.