Skip to content
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

Reduce the promise overhead in the ESM loader #50900

Open
joyeecheung opened this issue Nov 24, 2023 · 7 comments
Open

Reduce the promise overhead in the ESM loader #50900

joyeecheung opened this issue Nov 24, 2023 · 7 comments
Labels
loaders Issues and PRs related to ES module loaders performance Issues and PRs related to the performance of Node.js.

Comments

@joyeecheung
Copy link
Member

joyeecheung commented Nov 24, 2023

As a follow up of #50356, one of the problem of using the current ESM loader as the central loader is that it creates a lot of noisy promises during loading - even when loading a completely synchronous graph. For example, when loading a completely empty .mjs file, it creates 66 promises (using #50899)

See log
[--trace-promises] created promise #0
    at loadESM (node:internal/process/esm_loader:16:16)
    at runMainESM (node:internal/modules/run_main:105:21)
    at executeUserEntryPoint (node:internal/modules/run_main:138:5)
    at node:internal/main/run_main_module:28:49

[--trace-promises] created promise #1
    at import (node:internal/modules/esm/loader:327:15)
    at node:internal/modules/run_main:106:28
    at loadESM (node:internal/process/esm_loader:28:13)
    at runMainESM (node:internal/modules/run_main:105:21)
    at executeUserEntryPoint (node:internal/modules/run_main:138:5)
    at node:internal/main/run_main_module:28:49

[--trace-promises] created promise #2
    at getModuleJob (node:internal/modules/esm/loader:239:21)
    at import (node:internal/modules/esm/loader:328:34)
    at node:internal/modules/run_main:106:28
    at loadESM (node:internal/process/esm_loader:28:13)
    at runMainESM (node:internal/modules/run_main:105:21)
    at executeUserEntryPoint (node:internal/modules/run_main:138:5)
    at node:internal/main/run_main_module:28:49

[--trace-promises] promise #2 created promise #3
    at getModuleJob (node:internal/modules/esm/loader:240:38)
    at import (node:internal/modules/esm/loader:328:34)
    at node:internal/modules/run_main:106:28
    at loadESM (node:internal/process/esm_loader:28:13)
    at runMainESM (node:internal/modules/run_main:105:21)
    at executeUserEntryPoint (node:internal/modules/run_main:138:5)
    at node:internal/main/run_main_module:28:49

[--trace-promises] resolved promise #3
    at getModuleJob (node:internal/modules/esm/loader:240:38)
    at import (node:internal/modules/esm/loader:328:34)
    at node:internal/modules/run_main:106:28
    at loadESM (node:internal/process/esm_loader:28:13)
    at runMainESM (node:internal/modules/run_main:105:21)
    at executeUserEntryPoint (node:internal/modules/run_main:138:5)
    at node:internal/main/run_main_module:28:49

[--trace-promises] promise #3 created promise #4
    at getModuleJob (node:internal/modules/esm/loader:240:38)
    at import (node:internal/modules/esm/loader:328:34)
    at node:internal/modules/run_main:106:28
    at loadESM (node:internal/process/esm_loader:28:13)
    at runMainESM (node:internal/modules/run_main:105:21)
    at executeUserEntryPoint (node:internal/modules/run_main:138:5)
    at node:internal/main/run_main_module:28:49

[--trace-promises] promise #2 created promise #5
    at import (node:internal/modules/esm/loader:328:34)
    at node:internal/modules/run_main:106:28
    at loadESM (node:internal/process/esm_loader:28:13)
    at runMainESM (node:internal/modules/run_main:105:21)
    at executeUserEntryPoint (node:internal/modules/run_main:138:5)
    at node:internal/main/run_main_module:28:49

[--trace-promises] promise #1 created promise #6
    at loadESM (node:internal/process/esm_loader:28:13)
    at runMainESM (node:internal/modules/run_main:105:21)
    at executeUserEntryPoint (node:internal/modules/run_main:138:5)
    at node:internal/main/run_main_module:28:49

[--trace-promises] created promise #7
    at handleMainPromise (node:internal/modules/run_main:114:33)
    at runMainESM (node:internal/modules/run_main:105:3)
    at executeUserEntryPoint (node:internal/modules/run_main:138:5)
    at node:internal/main/run_main_module:28:49

[--trace-promises] promise #0 created promise #8
    at handleMainPromise (node:internal/modules/run_main:120:5)
    at runMainESM (node:internal/modules/run_main:105:3)
    at executeUserEntryPoint (node:internal/modules/run_main:138:5)
    at node:internal/main/run_main_module:28:49

[--trace-promises] created promise #9
    at node:internal/modules/esm/module_job:29:25
    at compileForInternalLoader (node:internal/bootstrap/realm:401:7)
    at requireBuiltin (node:internal/bootstrap/realm:432:14)
    at #createModuleJob (node:internal/modules/esm/loader:302:23)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] resolved promise #9
    at node:internal/modules/esm/module_job:29:25
    at compileForInternalLoader (node:internal/bootstrap/realm:401:7)
    at requireBuiltin (node:internal/bootstrap/realm:432:14)
    at #createModuleJob (node:internal/modules/esm/loader:302:23)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] created promise #10
    at moduleProvider (node:internal/modules/esm/loader:291:7)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] created promise #11
    at load (node:internal/modules/esm/loader:405:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] created promise #12
    at defaultLoad (node:internal/modules/esm/load:110:27)
    at load (node:internal/modules/esm/loader:409:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] created promise #13
    at getSource (node:internal/modules/esm/load:40:25)
    at defaultLoad (node:internal/modules/esm/load:138:40)
    at load (node:internal/modules/esm/loader:409:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] created promise #14
    at readFile (node:internal/fs/promises:1219:24)
    at getSource (node:internal/modules/esm/load:46:20)
    at defaultLoad (node:internal/modules/esm/load:138:40)
    at load (node:internal/modules/esm/loader:409:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] created promise #15
    at open (node:internal/fs/promises:624:20)
    at readFile (node:internal/fs/promises:1228:20)
    at getSource (node:internal/modules/esm/load:46:20)
    at defaultLoad (node:internal/modules/esm/load:138:40)
    at load (node:internal/modules/esm/loader:409:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] created promise #16
    at open (node:internal/fs/promises:629:13)
    at readFile (node:internal/fs/promises:1228:20)
    at getSource (node:internal/modules/esm/load:46:20)
    at defaultLoad (node:internal/modules/esm/load:138:40)
    at load (node:internal/modules/esm/loader:409:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] promise #16 created promise #17
    at open (node:internal/fs/promises:628:31)
    at readFile (node:internal/fs/promises:1228:20)
    at getSource (node:internal/modules/esm/load:46:20)
    at defaultLoad (node:internal/modules/esm/load:138:40)
    at load (node:internal/modules/esm/loader:409:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] promise #17 created promise #18
    at open (node:internal/fs/promises:628:31)
    at readFile (node:internal/fs/promises:1228:20)
    at getSource (node:internal/modules/esm/load:46:20)
    at defaultLoad (node:internal/modules/esm/load:138:40)
    at load (node:internal/modules/esm/loader:409:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] promise #15 created promise #19
    at readFile (node:internal/fs/promises:1228:20)
    at getSource (node:internal/modules/esm/load:46:20)
    at defaultLoad (node:internal/modules/esm/load:138:40)
    at load (node:internal/modules/esm/loader:409:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] promise #14 created promise #20
    at getSource (node:internal/modules/esm/load:46:20)
    at defaultLoad (node:internal/modules/esm/load:138:40)
    at load (node:internal/modules/esm/loader:409:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] promise #13 created promise #21
    at defaultLoad (node:internal/modules/esm/load:138:40)
    at load (node:internal/modules/esm/loader:409:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] promise #12 created promise #22
    at load (node:internal/modules/esm/loader:409:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] promise #11 created promise #23
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] created promise #24
    at link (node:internal/modules/esm/module_job:75:18)
    at ModuleJob (node:internal/modules/esm/module_job:97:19)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] promise #10 created promise #25
    at link (node:internal/modules/esm/module_job:76:32)
    at ModuleJob (node:internal/modules/esm/module_job:97:19)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] promise #24 created promise #26
    at ModuleJob (node:internal/modules/esm/module_job:100:5)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] resolved promise #2
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] resolved promise #4
[--trace-promises] created promise #27
    at run (node:internal/modules/esm/module_job:213:12)
    at import (node:internal/modules/esm/loader:329:40)

[--trace-promises] created promise #28
    at _instantiate (node:internal/modules/esm/module_job:114:21)
    at instantiate (node:internal/modules/esm/module_job:109:32)
    at run (node:internal/modules/esm/module_job:214:16)
    at import (node:internal/modules/esm/loader:329:40)

[--trace-promises] created promise #29
    at addJobsToDependencyGraph (node:internal/modules/esm/module_job:116:38)
    at _instantiate (node:internal/modules/esm/module_job:124:11)
    at instantiate (node:internal/modules/esm/module_job:109:32)
    at run (node:internal/modules/esm/module_job:214:16)
    at import (node:internal/modules/esm/loader:329:40)

[--trace-promises] promise #24 created promise #30
    at addJobsToDependencyGraph (node:internal/modules/esm/module_job:121:46)
    at _instantiate (node:internal/modules/esm/module_job:124:11)
    at instantiate (node:internal/modules/esm/module_job:109:32)
    at run (node:internal/modules/esm/module_job:214:16)
    at import (node:internal/modules/esm/loader:329:40)

[--trace-promises] promise #29 created promise #31
    at _instantiate (node:internal/modules/esm/module_job:124:11)
    at instantiate (node:internal/modules/esm/module_job:109:32)
    at run (node:internal/modules/esm/module_job:214:16)
    at import (node:internal/modules/esm/loader:329:40)

[--trace-promises] promise #28 created promise #32
    at run (node:internal/modules/esm/module_job:214:16)
    at import (node:internal/modules/esm/loader:329:40)

[--trace-promises] promise #27 created promise #33
    at import (node:internal/modules/esm/loader:329:40)

[--trace-promises] resolved promise #5
[--trace-promises] resolved promise #16
[--trace-promises] resolved promise #17
[--trace-promises] resolved promise #15
    at open (node:internal/fs/promises:628:10)

[--trace-promises] resolved promise #18
[--trace-promises] created promise #34
    at readFileHandle (node:internal/fs/promises:500:30)
    at readFile (node:internal/fs/promises:1229:24)

[--trace-promises] created promise #35
    at readFileHandle (node:internal/fs/promises:508:13)
    at readFile (node:internal/fs/promises:1229:24)

[--trace-promises] promise #35 created promise #36
    at readFileHandle (node:internal/fs/promises:507:28)
    at readFile (node:internal/fs/promises:1229:24)

[--trace-promises] promise #36 created promise #37
    at readFileHandle (node:internal/fs/promises:507:28)
    at readFile (node:internal/fs/promises:1229:24)

[--trace-promises] created promise #38
    at handleFdClose (node:internal/fs/promises:415:29)
    at readFile (node:internal/fs/promises:1229:10)

[--trace-promises] promise #34 created promise #39
    at handleFdClose (node:internal/fs/promises:416:10)
    at readFile (node:internal/fs/promises:1229:10)

[--trace-promises] resolved promise #38
    at handleFdClose (node:internal/fs/promises:416:10)
    at readFile (node:internal/fs/promises:1229:10)

[--trace-promises] resolved promise #14
    at readFile (node:internal/fs/promises:1229:10)

[--trace-promises] resolved promise #19
[--trace-promises] promise #39 created promise #40
[--trace-promises] promise #38 created promise #41
[--trace-promises] resolved promise #35
[--trace-promises] resolved promise #36
[--trace-promises] created promise #42
    at readFileHandle (node:internal/fs/promises:543:15)

[--trace-promises] promise #42 created promise #43
    at readFileHandle (node:internal/fs/promises:542:30)

[--trace-promises] promise #43 created promise #44
    at readFileHandle (node:internal/fs/promises:542:30)

[--trace-promises] resolved promise #37
[--trace-promises] resolved promise #42
[--trace-promises] resolved promise #43
[--trace-promises] resolved promise #34
    at readFileHandle (node:internal/fs/promises:565:9)

[--trace-promises] resolved promise #44
[--trace-promises] created promise #45
    at close (node:internal/fs/promises:241:23)
    at node:internal/fs/promises:418:38

[--trace-promises] created promise #46
    at primordials.SafePromisePrototypeFinally (node:internal/per_context/primordials:472:3)
    at close (node:internal/fs/promises:240:29)
    at node:internal/fs/promises:418:38

[--trace-promises] created promise #47
    at SafePromise (node:internal/per_context/primordials:456:29)
    at node:internal/per_context/primordials:473:5
    at primordials.SafePromisePrototypeFinally (node:internal/per_context/primordials:472:3)
    at close (node:internal/fs/promises:240:29)
    at node:internal/fs/promises:418:38

[--trace-promises] promise #45 created promise #48
    at node:internal/per_context/primordials:473:31
    at SafePromise (node:internal/per_context/primordials:456:29)
    at node:internal/per_context/primordials:473:5
    at primordials.SafePromisePrototypeFinally (node:internal/per_context/primordials:472:3)
    at close (node:internal/fs/promises:240:29)
    at node:internal/fs/promises:418:38

[--trace-promises] created promise #49
    at SafePromise (node:internal/per_context/primordials:456:29)
    at node:internal/per_context/primordials:474:15
    at primordials.SafePromisePrototypeFinally (node:internal/per_context/primordials:472:3)
    at close (node:internal/fs/promises:240:29)
    at node:internal/fs/promises:418:38

[--trace-promises] created promise #50
    at SafePromise (node:internal/per_context/primordials:456:29)
    at node:internal/per_context/primordials:475:8
    at primordials.SafePromisePrototypeFinally (node:internal/per_context/primordials:472:3)
    at close (node:internal/fs/promises:240:29)
    at node:internal/fs/promises:418:38

[--trace-promises] promise #46 created promise #51
    at node:internal/fs/promises:418:17

[--trace-promises] resolved promise #39
[--trace-promises] promise #51 created promise #52
[--trace-promises] resolved promise #45
[--trace-promises] resolved promise #47
[--trace-promises] resolved promise #48
[--trace-promises] created promise #53
    at SafePromise (node:internal/per_context/primordials:456:29)

[--trace-promises] resolved promise #53
[--trace-promises] created promise #54
    at SafePromise (node:internal/per_context/primordials:456:29)

[--trace-promises] resolved promise #49
[--trace-promises] resolved promise #54
[--trace-promises] created promise #55
    at SafePromise (node:internal/per_context/primordials:456:29)

[--trace-promises] resolved promise #49
[--trace-promises] resolved promise #55
[--trace-promises] resolved promise #46
[--trace-promises] resolved promise #50
[--trace-promises] resolved promise #51
[--trace-promises] resolved promise #39
[--trace-promises] resolved promise #52
[--trace-promises] resolved promise #38
[--trace-promises] resolved promise #40
[--trace-promises] resolved promise #14
[--trace-promises] resolved promise #41
[--trace-promises] resolved promise #13
    at getSource (node:internal/modules/esm/load:72:42)

[--trace-promises] resolved promise #20
[--trace-promises] resolved promise #12
    at defaultLoad (node:internal/modules/esm/load:158:5)

[--trace-promises] resolved promise #21
[--trace-promises] resolved promise #11
    at load (node:internal/modules/esm/loader:411:5)

[--trace-promises] resolved promise #22
[--trace-promises] created promise #56
    at moduleStrategy (node:internal/modules/esm/translators:150:56)
    at callTranslator (node:internal/modules/esm/loader:285:14)
    at moduleProvider (node:internal/modules/esm/loader:291:30)

[--trace-promises] resolved promise #56
    at moduleStrategy (node:internal/modules/esm/translators:162:3)
    at callTranslator (node:internal/modules/esm/loader:285:14)
    at moduleProvider (node:internal/modules/esm/loader:291:30)

[--trace-promises] resolved promise #10
    at moduleProvider (node:internal/modules/esm/loader:291:30)

[--trace-promises] resolved promise #23
[--trace-promises] promise #56 created promise #57
[--trace-promises] resolved promise #10
[--trace-promises] resolved promise #57
[--trace-promises] created promise #58
    at primordials.SafePromiseAllReturnVoid (node:internal/per_context/primordials:541:3)
    at link (node:internal/modules/esm/module_job:91:15)

[--trace-promises] resolved promise #58
    at node:internal/per_context/primordials:543:32
    at primordials.SafePromiseAllReturnVoid (node:internal/per_context/primordials:541:3)
    at link (node:internal/modules/esm/module_job:91:15)

[--trace-promises] promise #58 created promise #59
    at link (node:internal/modules/esm/module_job:91:15)

[--trace-promises] resolved promise #25
[--trace-promises] created promise #60
    at primordials.SafePromiseAllReturnArrayLike (node:internal/per_context/primordials:515:3)
    at link (node:internal/modules/esm/module_job:94:14)

[--trace-promises] resolved promise #60
    at node:internal/per_context/primordials:520:23
    at primordials.SafePromiseAllReturnArrayLike (node:internal/per_context/primordials:515:3)
    at link (node:internal/modules/esm/module_job:94:14)

[--trace-promises] resolved promise #24
    at link (node:internal/modules/esm/module_job:94:14)

[--trace-promises] resolved promise #59
[--trace-promises] promise #60 created promise #61
[--trace-promises] resolved promise #24
[--trace-promises] resolved promise #61
[--trace-promises] resolved promise #26
[--trace-promises] created promise #62
    at primordials.SafePromiseAllReturnVoid (node:internal/per_context/primordials:541:3)
    at addJobsToDependencyGraph (node:internal/modules/esm/module_job:122:14)

[--trace-promises] resolved promise #62
    at node:internal/per_context/primordials:543:32
    at primordials.SafePromiseAllReturnVoid (node:internal/per_context/primordials:541:3)
    at addJobsToDependencyGraph (node:internal/modules/esm/module_job:122:14)

[--trace-promises] resolved promise #29
    at addJobsToDependencyGraph (node:internal/modules/esm/module_job:122:14)

[--trace-promises] resolved promise #30
[--trace-promises] promise #62 created promise #63
[--trace-promises] resolved promise #29
[--trace-promises] resolved promise #63
[--trace-promises] resolved promise #28
    at _instantiate (node:internal/modules/esm/module_job:192:5)

[--trace-promises] resolved promise #31
[--trace-promises] created promise #64
    at run (node:internal/modules/esm/module_job:218:25)

[--trace-promises] resolved promise #64
    at run (node:internal/modules/esm/module_job:218:25)

[--trace-promises] promise #64 created promise #65
    at run (node:internal/modules/esm/module_job:218:25)

[--trace-promises] resolved promise #32
[--trace-promises] resolved promise #27
    at run (node:internal/modules/esm/module_job:243:44)

[--trace-promises] resolved promise #65
[--trace-promises] resolved promise #1
    at import (node:internal/modules/esm/loader:330:19)

[--trace-promises] resolved promise #33
[--trace-promises] resolved promise #0
    at loadESM (node:internal/process/esm_loader:34:33)

[--trace-promises] resolved promise #6
[--trace-promises] resolved promise #7
    at handleMainPromise (node:internal/modules/run_main:122:13)

[--trace-promises] resolved promise #8

And when loading one extra module in the entry point it creates 125 promises in total - from my testing, every module loaded results in 59 more promises. And this is when the graph is completely synchronous (i.e. no http modules, no top-level await).

// main.mjs
import { hello } from "./mod.mjs"

// mod.mjs
export const hello = 'world';

After discussion with @GeoffreyBooth we think some work should be put into this to reduce the overhead/noise. Either more work can be moved to C++ to restrict unnecessary async-await or we can carve out a synchronous path in the ESM loader to handle synchronous graphs.

Theoretically only one immediately settled promise has to be created by v8 for each synchronous module - even that one may not really have to be a promise - in the V8 API contract, as far as a synchronous graph is concerned, that promise is more of a poor-man's Maybe type rather than an actual async construct (if evaluation succeeds V8 immediately resolves it with undefined, otherwise immediately rejects). So the quest is to ideally reduce the overhead to just that one per module (even then is should be possible for a different V8 API to skip that one completely) for a synchronous graph.

@joyeecheung joyeecheung added performance Issues and PRs related to the performance of Node.js. loaders Issues and PRs related to ES module loaders labels Nov 24, 2023
@GeoffreyBooth
Copy link
Member

@nodejs/loaders @nodejs/performance

@anonrig
Copy link
Member

anonrig commented Nov 24, 2023

Should we move this issue to performance repository?

@joyeecheung
Copy link
Member Author

joyeecheung commented Nov 24, 2023

I'd say this is more than about just performance but also about making the ESM loader generate less async activity when it's loading a synchronous graph (one of the reasons why using ESM loader to load CJS modules can fail the tests).

@H4ad
Copy link
Member

H4ad commented Nov 28, 2023

Using #50899

The amount of promises created for an empty-file.mjs:

logs
[--trace-promises] created promise #0
    at loadESM (node:internal/process/esm_loader:16:16)
    at runMainESM (node:internal/modules/run_main:105:21)
    at executeUserEntryPoint (node:internal/modules/run_main:138:5)
    at node:internal/main/run_main_module:28:49

[--trace-promises] created promise #1
    at import (node:internal/modules/esm/loader:327:15)
    at node:internal/modules/run_main:106:28
    at loadESM (node:internal/process/esm_loader:28:13)
    at runMainESM (node:internal/modules/run_main:105:21)
    at executeUserEntryPoint (node:internal/modules/run_main:138:5)
    at node:internal/main/run_main_module:28:49

[--trace-promises] created promise #2
    at getModuleJob (node:internal/modules/esm/loader:239:21)
    at import (node:internal/modules/esm/loader:328:34)
    at node:internal/modules/run_main:106:28
    at loadESM (node:internal/process/esm_loader:28:13)
    at runMainESM (node:internal/modules/run_main:105:21)
    at executeUserEntryPoint (node:internal/modules/run_main:138:5)
    at node:internal/main/run_main_module:28:49

[--trace-promises] promise #2 created promise #3
    at getModuleJob (node:internal/modules/esm/loader:240:38)
    at import (node:internal/modules/esm/loader:328:34)
    at node:internal/modules/run_main:106:28
    at loadESM (node:internal/process/esm_loader:28:13)
    at runMainESM (node:internal/modules/run_main:105:21)
    at executeUserEntryPoint (node:internal/modules/run_main:138:5)
    at node:internal/main/run_main_module:28:49

[--trace-promises] resolved promise #3
    at getModuleJob (node:internal/modules/esm/loader:240:38)
    at import (node:internal/modules/esm/loader:328:34)
    at node:internal/modules/run_main:106:28
    at loadESM (node:internal/process/esm_loader:28:13)
    at runMainESM (node:internal/modules/run_main:105:21)
    at executeUserEntryPoint (node:internal/modules/run_main:138:5)
    at node:internal/main/run_main_module:28:49

[--trace-promises] promise #3 created promise #4
    at getModuleJob (node:internal/modules/esm/loader:240:38)
    at import (node:internal/modules/esm/loader:328:34)
    at node:internal/modules/run_main:106:28
    at loadESM (node:internal/process/esm_loader:28:13)
    at runMainESM (node:internal/modules/run_main:105:21)
    at executeUserEntryPoint (node:internal/modules/run_main:138:5)
    at node:internal/main/run_main_module:28:49

[--trace-promises] promise #2 created promise #5
    at import (node:internal/modules/esm/loader:328:34)
    at node:internal/modules/run_main:106:28
    at loadESM (node:internal/process/esm_loader:28:13)
    at runMainESM (node:internal/modules/run_main:105:21)
    at executeUserEntryPoint (node:internal/modules/run_main:138:5)
    at node:internal/main/run_main_module:28:49

[--trace-promises] promise #1 created promise #6
    at loadESM (node:internal/process/esm_loader:28:13)
    at runMainESM (node:internal/modules/run_main:105:21)
    at executeUserEntryPoint (node:internal/modules/run_main:138:5)
    at node:internal/main/run_main_module:28:49

[--trace-promises] created promise #7
    at handleMainPromise (node:internal/modules/run_main:114:33)
    at runMainESM (node:internal/modules/run_main:105:3)
    at executeUserEntryPoint (node:internal/modules/run_main:138:5)
    at node:internal/main/run_main_module:28:49

[--trace-promises] promise #0 created promise #8
    at handleMainPromise (node:internal/modules/run_main:120:5)
    at runMainESM (node:internal/modules/run_main:105:3)
    at executeUserEntryPoint (node:internal/modules/run_main:138:5)
    at node:internal/main/run_main_module:28:49

[--trace-promises] created promise #9
    at node:internal/modules/esm/module_job:29:25
    at compileForInternalLoader (node:internal/bootstrap/realm:401:7)
    at requireBuiltin (node:internal/bootstrap/realm:432:14)
    at #createModuleJob (node:internal/modules/esm/loader:302:23)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] resolved promise #9
    at node:internal/modules/esm/module_job:29:25
    at compileForInternalLoader (node:internal/bootstrap/realm:401:7)
    at requireBuiltin (node:internal/bootstrap/realm:432:14)
    at #createModuleJob (node:internal/modules/esm/loader:302:23)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] created promise #10
    at moduleProvider (node:internal/modules/esm/loader:291:7)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] created promise #11
    at load (node:internal/modules/esm/loader:405:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] created promise #12
    at defaultLoad (node:internal/modules/esm/load:110:27)
    at load (node:internal/modules/esm/loader:409:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] created promise #13
    at getSource (node:internal/modules/esm/load:40:25)
    at defaultLoad (node:internal/modules/esm/load:138:40)
    at load (node:internal/modules/esm/loader:409:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] created promise #14
    at readFile (node:internal/fs/promises:1233:24)
    at getSource (node:internal/modules/esm/load:46:20)
    at defaultLoad (node:internal/modules/esm/load:138:40)
    at load (node:internal/modules/esm/loader:409:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] created promise #15
    at open (node:internal/fs/promises:629:20)
    at readFile (node:internal/fs/promises:1242:20)
    at getSource (node:internal/modules/esm/load:46:20)
    at defaultLoad (node:internal/modules/esm/load:138:40)
    at load (node:internal/modules/esm/loader:409:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] created promise #16
    at open (node:internal/fs/promises:634:13)
    at readFile (node:internal/fs/promises:1242:20)
    at getSource (node:internal/modules/esm/load:46:20)
    at defaultLoad (node:internal/modules/esm/load:138:40)
    at load (node:internal/modules/esm/loader:409:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] promise #16 created promise #17
    at open (node:internal/fs/promises:633:31)
    at readFile (node:internal/fs/promises:1242:20)
    at getSource (node:internal/modules/esm/load:46:20)
    at defaultLoad (node:internal/modules/esm/load:138:40)
    at load (node:internal/modules/esm/loader:409:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] promise #17 created promise #18
    at open (node:internal/fs/promises:633:31)
    at readFile (node:internal/fs/promises:1242:20)
    at getSource (node:internal/modules/esm/load:46:20)
    at defaultLoad (node:internal/modules/esm/load:138:40)
    at load (node:internal/modules/esm/loader:409:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] promise #15 created promise #19
    at readFile (node:internal/fs/promises:1242:20)
    at getSource (node:internal/modules/esm/load:46:20)
    at defaultLoad (node:internal/modules/esm/load:138:40)
    at load (node:internal/modules/esm/loader:409:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] promise #14 created promise #20
    at getSource (node:internal/modules/esm/load:46:20)
    at defaultLoad (node:internal/modules/esm/load:138:40)
    at load (node:internal/modules/esm/loader:409:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] promise #13 created promise #21
    at defaultLoad (node:internal/modules/esm/load:138:40)
    at load (node:internal/modules/esm/loader:409:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] promise #12 created promise #22
    at load (node:internal/modules/esm/loader:409:13)
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] promise #11 created promise #23
    at moduleProvider (node:internal/modules/esm/loader:291:56)
    at ModuleJob (node:internal/modules/esm/module_job:65:26)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] created promise #24
    at link (node:internal/modules/esm/module_job:75:18)
    at ModuleJob (node:internal/modules/esm/module_job:97:19)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] promise #10 created promise #25
    at link (node:internal/modules/esm/module_job:76:32)
    at ModuleJob (node:internal/modules/esm/module_job:97:19)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] promise #24 created promise #26
    at ModuleJob (node:internal/modules/esm/module_job:100:5)
    at #createModuleJob (node:internal/modules/esm/loader:303:17)
    at getJobFromResolveResult (node:internal/modules/esm/loader:260:34)
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] resolved promise #2
    at getModuleJob (node:internal/modules/esm/loader:241:17)

[--trace-promises] resolved promise #4
[--trace-promises] created promise #27
    at run (node:internal/modules/esm/module_job:213:12)
    at import (node:internal/modules/esm/loader:329:40)

[--trace-promises] created promise #28
    at _instantiate (node:internal/modules/esm/module_job:114:21)
    at instantiate (node:internal/modules/esm/module_job:109:32)
    at run (node:internal/modules/esm/module_job:214:16)
    at import (node:internal/modules/esm/loader:329:40)

[--trace-promises] created promise #29
    at addJobsToDependencyGraph (node:internal/modules/esm/module_job:116:38)
    at _instantiate (node:internal/modules/esm/module_job:124:11)
    at instantiate (node:internal/modules/esm/module_job:109:32)
    at run (node:internal/modules/esm/module_job:214:16)
    at import (node:internal/modules/esm/loader:329:40)

[--trace-promises] promise #24 created promise #30
    at addJobsToDependencyGraph (node:internal/modules/esm/module_job:121:46)
    at _instantiate (node:internal/modules/esm/module_job:124:11)
    at instantiate (node:internal/modules/esm/module_job:109:32)
    at run (node:internal/modules/esm/module_job:214:16)
    at import (node:internal/modules/esm/loader:329:40)

[--trace-promises] promise #29 created promise #31
    at _instantiate (node:internal/modules/esm/module_job:124:11)
    at instantiate (node:internal/modules/esm/module_job:109:32)
    at run (node:internal/modules/esm/module_job:214:16)
    at import (node:internal/modules/esm/loader:329:40)

[--trace-promises] promise #28 created promise #32
    at run (node:internal/modules/esm/module_job:214:16)
    at import (node:internal/modules/esm/loader:329:40)

[--trace-promises] promise #27 created promise #33
    at import (node:internal/modules/esm/loader:329:40)

[--trace-promises] resolved promise #5
[--trace-promises] resolved promise #16
[--trace-promises] resolved promise #17
[--trace-promises] resolved promise #15
    at open (node:internal/fs/promises:633:10)

[--trace-promises] resolved promise #18
[--trace-promises] created promise #34
    at readFileHandle (node:internal/fs/promises:505:30)
    at readFile (node:internal/fs/promises:1243:24)

[--trace-promises] created promise #35
    at readFileHandle (node:internal/fs/promises:513:13)
    at readFile (node:internal/fs/promises:1243:24)

[--trace-promises] promise #35 created promise #36
    at readFileHandle (node:internal/fs/promises:512:28)
    at readFile (node:internal/fs/promises:1243:24)

[--trace-promises] promise #36 created promise #37
    at readFileHandle (node:internal/fs/promises:512:28)
    at readFile (node:internal/fs/promises:1243:24)

[--trace-promises] created promise #38
    at handleFdClose (node:internal/fs/promises:420:29)
    at readFile (node:internal/fs/promises:1243:10)

[--trace-promises] promise #34 created promise #39
    at handleFdClose (node:internal/fs/promises:421:10)
    at readFile (node:internal/fs/promises:1243:10)

[--trace-promises] resolved promise #38
    at handleFdClose (node:internal/fs/promises:421:10)
    at readFile (node:internal/fs/promises:1243:10)

[--trace-promises] resolved promise #14
    at readFile (node:internal/fs/promises:1243:10)

[--trace-promises] resolved promise #19
[--trace-promises] promise #39 created promise #40
[--trace-promises] promise #38 created promise #41
[--trace-promises] resolved promise #35
[--trace-promises] resolved promise #36
[--trace-promises] created promise #42
    at readFileHandle (node:internal/fs/promises:548:15)

[--trace-promises] promise #42 created promise #43
    at readFileHandle (node:internal/fs/promises:547:30)

[--trace-promises] promise #43 created promise #44
    at readFileHandle (node:internal/fs/promises:547:30)

[--trace-promises] resolved promise #37
[--trace-promises] resolved promise #42
[--trace-promises] resolved promise #43
[--trace-promises] resolved promise #34
    at readFileHandle (node:internal/fs/promises:570:9)

[--trace-promises] resolved promise #44
[--trace-promises] created promise #45
    at close (node:internal/fs/promises:246:23)
    at node:internal/fs/promises:423:38

[--trace-promises] created promise #46
    at primordials.SafePromisePrototypeFinally (node:internal/per_context/primordials:472:3)
    at close (node:internal/fs/promises:245:29)
    at node:internal/fs/promises:423:38

[--trace-promises] created promise #47
    at SafePromise (node:internal/per_context/primordials:456:29)
    at node:internal/per_context/primordials:473:5
    at primordials.SafePromisePrototypeFinally (node:internal/per_context/primordials:472:3)
    at close (node:internal/fs/promises:245:29)
    at node:internal/fs/promises:423:38

[--trace-promises] promise #45 created promise #48
    at node:internal/per_context/primordials:473:31
    at SafePromise (node:internal/per_context/primordials:456:29)
    at node:internal/per_context/primordials:473:5
    at primordials.SafePromisePrototypeFinally (node:internal/per_context/primordials:472:3)
    at close (node:internal/fs/promises:245:29)
    at node:internal/fs/promises:423:38

[--trace-promises] created promise #49
    at SafePromise (node:internal/per_context/primordials:456:29)
    at node:internal/per_context/primordials:474:15
    at primordials.SafePromisePrototypeFinally (node:internal/per_context/primordials:472:3)
    at close (node:internal/fs/promises:245:29)
    at node:internal/fs/promises:423:38

[--trace-promises] created promise #50
    at SafePromise (node:internal/per_context/primordials:456:29)
    at node:internal/per_context/primordials:475:8
    at primordials.SafePromisePrototypeFinally (node:internal/per_context/primordials:472:3)
    at close (node:internal/fs/promises:245:29)
    at node:internal/fs/promises:423:38

[--trace-promises] promise #46 created promise #51
    at node:internal/fs/promises:423:17

[--trace-promises] resolved promise #39
[--trace-promises] promise #51 created promise #52
[--trace-promises] resolved promise #45
[--trace-promises] resolved promise #47
[--trace-promises] resolved promise #48
[--trace-promises] created promise #53
    at SafePromise (node:internal/per_context/primordials:456:29)

[--trace-promises] resolved promise #53
[--trace-promises] created promise #54
    at SafePromise (node:internal/per_context/primordials:456:29)

[--trace-promises] resolved promise #49
[--trace-promises] resolved promise #54
[--trace-promises] created promise #55
    at SafePromise (node:internal/per_context/primordials:456:29)

[--trace-promises] resolved promise #49
[--trace-promises] resolved promise #55
[--trace-promises] resolved promise #46
[--trace-promises] resolved promise #50
[--trace-promises] resolved promise #51
[--trace-promises] resolved promise #39
[--trace-promises] resolved promise #52
[--trace-promises] resolved promise #38
[--trace-promises] resolved promise #40
[--trace-promises] resolved promise #14
[--trace-promises] resolved promise #41
[--trace-promises] resolved promise #13
    at getSource (node:internal/modules/esm/load:72:42)

[--trace-promises] resolved promise #20
[--trace-promises] resolved promise #12
    at defaultLoad (node:internal/modules/esm/load:158:5)

[--trace-promises] resolved promise #21
[--trace-promises] resolved promise #11
    at load (node:internal/modules/esm/loader:411:5)

[--trace-promises] resolved promise #22
[--trace-promises] created promise #56
    at moduleStrategy (node:internal/modules/esm/translators:150:56)
    at callTranslator (node:internal/modules/esm/loader:285:14)
    at moduleProvider (node:internal/modules/esm/loader:291:30)

[--trace-promises] resolved promise #56
    at moduleStrategy (node:internal/modules/esm/translators:162:3)
    at callTranslator (node:internal/modules/esm/loader:285:14)
    at moduleProvider (node:internal/modules/esm/loader:291:30)

[--trace-promises] resolved promise #10
    at moduleProvider (node:internal/modules/esm/loader:291:30)

[--trace-promises] resolved promise #23
[--trace-promises] promise #56 created promise #57
[--trace-promises] resolved promise #10
[--trace-promises] resolved promise #57
[--trace-promises] created promise #58
    at primordials.SafePromiseAllReturnVoid (node:internal/per_context/primordials:541:3)
    at link (node:internal/modules/esm/module_job:91:15)

[--trace-promises] resolved promise #58
    at node:internal/per_context/primordials:543:32
    at primordials.SafePromiseAllReturnVoid (node:internal/per_context/primordials:541:3)
    at link (node:internal/modules/esm/module_job:91:15)

[--trace-promises] promise #58 created promise #59
    at link (node:internal/modules/esm/module_job:91:15)

[--trace-promises] resolved promise #25
[--trace-promises] created promise #60
    at primordials.SafePromiseAllReturnArrayLike (node:internal/per_context/primordials:515:3)
    at link (node:internal/modules/esm/module_job:94:14)

[--trace-promises] resolved promise #60
    at node:internal/per_context/primordials:520:23
    at primordials.SafePromiseAllReturnArrayLike (node:internal/per_context/primordials:515:3)
    at link (node:internal/modules/esm/module_job:94:14)

[--trace-promises] resolved promise #24
    at link (node:internal/modules/esm/module_job:94:14)

[--trace-promises] resolved promise #59
[--trace-promises] promise #60 created promise #61
[--trace-promises] resolved promise #24
[--trace-promises] resolved promise #61
[--trace-promises] resolved promise #26
[--trace-promises] created promise #62
    at primordials.SafePromiseAllReturnVoid (node:internal/per_context/primordials:541:3)
    at addJobsToDependencyGraph (node:internal/modules/esm/module_job:122:14)

[--trace-promises] resolved promise #62
    at node:internal/per_context/primordials:543:32
    at primordials.SafePromiseAllReturnVoid (node:internal/per_context/primordials:541:3)
    at addJobsToDependencyGraph (node:internal/modules/esm/module_job:122:14)

[--trace-promises] resolved promise #29
    at addJobsToDependencyGraph (node:internal/modules/esm/module_job:122:14)

[--trace-promises] resolved promise #30
[--trace-promises] promise #62 created promise #63
[--trace-promises] resolved promise #29
[--trace-promises] resolved promise #63
[--trace-promises] resolved promise #28
    at _instantiate (node:internal/modules/esm/module_job:192:5)

[--trace-promises] resolved promise #31
[--trace-promises] created promise #64
    at run (node:internal/modules/esm/module_job:218:25)

[--trace-promises] resolved promise #64
    at run (node:internal/modules/esm/module_job:218:25)

[--trace-promises] promise #64 created promise #65
    at run (node:internal/modules/esm/module_job:218:25)

[--trace-promises] resolved promise #32
[--trace-promises] resolved promise #27
    at run (node:internal/modules/esm/module_job:243:44)

[--trace-promises] resolved promise #65
[--trace-promises] resolved promise #1
    at import (node:internal/modules/esm/loader:330:19)

[--trace-promises] resolved promise #33
[--trace-promises] resolved promise #0
    at loadESM (node:internal/process/esm_loader:34:33)

[--trace-promises] resolved promise #6
[--trace-promises] resolved promise #7
    at handleMainPromise (node:internal/modules/run_main:122:13)

[--trace-promises] resolved promise #8

@H4ad
Copy link
Member

H4ad commented Nov 29, 2023

Almost half of the promises are created because of readFileAsync on load.

@GeoffreyBooth the esm dependencies are resolved one after another? If so, I don't think that is any advantage of using readFileAsync.

In theory, using readFileSync speedups the loading of an empty file:

h4ad:node-copy-4/ (trace-promises✗) $ hyperfine --warmup 3 './out/Release/node empty-file.mjs' './out/current-main empty-file.mjs'                                                                                                                                   [21:01:36]
Benchmark 1: ./out/Release/node empty-file.mjs
  Time (mean ± σ):      16.8 ms ±   3.1 ms    [User: 12.2 ms, System: 5.5 ms]
  Range (min … max):    12.3 ms …  23.2 ms    171 runs
 
Benchmark 2: ./out/current-main empty-file.mjs
  Time (mean ± σ):      18.8 ms ±   3.1 ms    [User: 14.1 ms, System: 7.6 ms]
  Range (min … max):    13.8 ms …  23.9 ms    138 runs
 
Summary
  './out/Release/node empty-file.mjs' ran
    1.12 ± 0.27 times faster than './out/current-main empty-file.mjs'

But trying to benchmark it in a project:

h4ad:test-esm-initialization/ $ hyperfine --warmup 3 '~/Projects/opensource/node-copy-4/out/Release/node server.js' '~/Projects/opensource/node-copy-4/out/current-main server.js'                                                                                   [20:54:13]
Benchmark 1: ~/Projects/opensource/node-copy-4/out/Release/node server.js
  Time (mean ± σ):     100.9 ms ±   2.6 ms    [User: 113.9 ms, System: 15.1 ms]
  Range (min … max):    95.4 ms … 107.1 ms    30 runs
 
Benchmark 2: ~/Projects/opensource/node-copy-4/out/current-main server.js
  Time (mean ± σ):     101.0 ms ±   3.1 ms    [User: 107.4 ms, System: 45.4 ms]
  Range (min … max):    96.3 ms … 108.3 ms    30 runs
 
Summary
  '~/Projects/opensource/node-copy-4/out/Release/node server.js' ran
    1.00 ± 0.04 times faster than '~/Projects/opensource/node-copy-4/out/current-main server.js'

I don't have a good project to benchmark it, so if someone here has any repository to test these improvements, I will be very happy to test this little change.


In general, I don't think the amount of promises created is problematic, removing some of them makes the debug of this code a little bit harder since we don't know where that promise was created when an error happens (since we didn't await in the original function).

@GeoffreyBooth
Copy link
Member

In general, I don’t think the amount of promises created is problematic, removing some of them makes the debug of this code a little bit harder since we don’t know where that promise was created when an error happens (since we didn’t await in the original function).

There are several benefits from making the ESM loader sync; see #50356 and https://github.com/orgs/nodejs/discussions/45711, for starters. Sure it might get a little harder to debug, but no harder than the all-sync CommonJS loader.

@JakobJingleheimer
Copy link
Member

@GeoffreyBooth the esm dependencies are resolved one after another? If so, I don't think that is any advantage of using readFileAsync.

In theory, using readFileSync speedups the loading of an empty file

I think we talked about this previously and I thought we had made this change already. At the moment, I can't think of a reason to not do this.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
loaders Issues and PRs related to ES module loaders performance Issues and PRs related to the performance of Node.js.
Projects
None yet
Development

No branches or pull requests

5 participants