module: cache stat() results more aggressively #4575

bnoordhuis · 2016-01-07T23:30:18Z

Reduce the number of stat() system calls that require() makes by caching
the results more aggressively.

To avoid unbounded growth without implementing a LRU cache, scope the
cache to the lifetime of the first call to require(). Recursive calls
(i.e. require() calls in the included code) transparently profit from
the cache.

The benchmarked application is the loopback-sample-app[0] and it sees
the number of stat calls at start-up go down by 40%, from 4736 to 2810.

[0] https://github.com/strongloop/loopback-sample-app

CI: https://ci.nodejs.org/job/node-test-pull-request/1160/

fs.statSync() creates and returns a heavy-weight fs.Stat object whereas fs.accessSync() simply returns nothing. The return value is ignored, the call is for its side effect of throwing an ELOOP error in case of cyclic symbolic links.

Reduce the number of stat() system calls that require() makes by caching the results more aggressively. To avoid unbounded growth without implementing a LRU cache, scope the cache to the lifetime of the first call to require(). Recursive calls (i.e. require() calls in the included code) transparently profit from the cache. The benchmarked application is the loopback-sample-app[0] and it sees the number of stat calls at start-up go down by 40%, from 4736 to 2810. [0] https://github.com/strongloop/loopback-sample-app

Avoid an unneeded ArgumentsAdaptorTrampoline stack frame by passing the the right number of arguments to Module._load() in Module.require(). Shortens the following stack trace with one frame: LazyCompile:~Module.load module.js:345 LazyCompile:Module._load module.js:282 Builtin:ArgumentsAdaptorTrampoline LazyCompile:*Module.require module.js:361 LazyCompile:*require internal/module.js:11

bnoordhuis · 2016-01-07T23:31:21Z

Related to nodejs/benchmarking#22 (comment), /cc @sam-github.

Use internalModuleReadFile() to read the file from disk to avoid the fs.fstatSync() call that fs.readFileSync() makes. It does so to know the file size in advance so it doesn't have to allocate O(n) buffers when reading the file from disk. internalModuleReadFile() is plenty efficient though, even more so because we want a string and not a buffer. This way we also don't allocate a buffer that immediately gets thrown away again. This commit reduces the number of fstat() system calls in a benchmark application[0] from 549 to 29, all made by the application itself. [0] https://github.com/strongloop/loopback-sample-app

jasnell · 2016-01-08T16:47:44Z

LGTM

bnoordhuis · 2016-01-08T22:25:04Z

Going to run the CI one more time, the last one aborted on the win-vs2015 buildbot.

https://ci.nodejs.org/job/node-test-pull-request/1173/

jasnell · 2016-01-11T18:00:17Z

@bnoordhuis ... CI blew out on the buildbot again. Otherwise this looks fine.

cjihrig · 2016-01-11T18:43:53Z

LGTM

sam-github · 2016-01-12T01:05:21Z

Haven't had time to look at the code, but this would make a meaningful difference in app startup times for apps with large (aka "real") dependency trees, I'm all for it.

vkurchatkin · 2016-01-12T10:54:39Z

+1 for 5, but I don't think it's suitable for LTS

fs.statSync() creates and returns a heavy-weight fs.Stat object whereas fs.accessSync() simply returns nothing. The return value is ignored, the call is for its side effect of throwing an ELOOP error in case of cyclic symbolic links. PR-URL: #4575 Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: James M Snell <[email protected]>

Reduce the number of stat() system calls that require() makes by caching the results more aggressively. To avoid unbounded growth without implementing a LRU cache, scope the cache to the lifetime of the first call to require(). Recursive calls (i.e. require() calls in the included code) transparently profit from the cache. The benchmarked application is the loopback-sample-app[0] and it sees the number of stat calls at start-up go down by 40%, from 4736 to 2810. [0] https://github.com/strongloop/loopback-sample-app PR-URL: #4575 Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: James M Snell <[email protected]>

Avoid an unneeded ArgumentsAdaptorTrampoline stack frame by passing the the right number of arguments to Module._load() in Module.require(). Shortens the following stack trace with one frame: LazyCompile:~Module.load module.js:345 LazyCompile:Module._load module.js:282 Builtin:ArgumentsAdaptorTrampoline LazyCompile:*Module.require module.js:361 LazyCompile:*require internal/module.js:11 PR-URL: #4575 Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: James M Snell <[email protected]>

Use internalModuleReadFile() to read the file from disk to avoid the fs.fstatSync() call that fs.readFileSync() makes. It does so to know the file size in advance so it doesn't have to allocate O(n) buffers when reading the file from disk. internalModuleReadFile() is plenty efficient though, even more so because we want a string and not a buffer. This way we also don't allocate a buffer that immediately gets thrown away again. This commit reduces the number of fstat() system calls in a benchmark application[0] from 549 to 29, all made by the application itself. [0] https://github.com/strongloop/loopback-sample-app PR-URL: #4575 Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: James M Snell <[email protected]>

jasnell · 2016-01-12T20:36:39Z

Landed in 809bf5e, 83f8d98, 038b636 and 7c60328

Trott · 2016-01-13T07:00:06Z

What's the reason we know these failures are due to CI infrastructure issues and not because the code in this PR is causing the tests to fail? It looks like straightforward test failures at these URLs:

Trott · 2016-01-13T07:25:57Z

It sure does look like this PR really did break tests.

Here's a CI I just ran for the last commit before this PR landed:
https://ci.nodejs.org/job/node-test-commit/1717/

All green! \o/

And here's a CI I just ran for the code right the four commits in this PR landed:
https://ci.nodejs.org/job/node-test-commit/1718/

Same two tests failing on Windows. :-/

jasnell · 2016-01-13T16:49:41Z

hmm ... ok. @bnoordhuis

Trott · 2016-01-13T19:21:40Z

bnoordhuis commented in another issue that he's sick right now. I'm juggling a few things right now, but I might see if I can figure out which commit or set of commits would need to be reverted to fix the issue, then submit a PR to revert. If someone is already working on this or is tackling it from the other end (looking at the tests that are failing to see if they are flawed), let me know and I'll go do something else.

Trott · 2016-01-13T21:38:31Z

Cool. Now I have four other jobs running, each one reverting one of the commits in this PR. Hopefully, the culprit is one and only one commit. If not, more CI FUN!

Trott · 2016-01-13T21:49:26Z

So, this PR results in at least two tests failing. Reverting one commit can fix one, but you can't fix both without reverting at least two commits... So now I have a bunch more CI runs to try (unless we think the best thing to do is just revert all four commits, but I'd rather do the smallest revert possible).

Trott · 2016-01-13T21:52:15Z

I'm pretty sure this will be the one. It reverts 809bf5e and 7c60328:

https://ci.nodejs.org/job/node-test-commit-windows-fanned/919/

cjihrig · 2016-01-13T21:53:49Z

038b636 looks harmless. Can we try to keep it.

7c60328 is in the stack trace of one of the failures. We should probably revert it.

809bf5e appears to be the cause of one of the failures.

Maybe we can keep 83f8d98.

Trott · 2016-01-13T21:56:40Z

@cjihrig Your analysis is exactly in line with the revert combo I'm trying right now. We appear to be converging on the solution...

Trott · 2016-01-13T22:12:04Z

Winner!: https://ci.nodejs.org/job/node-compile-windows/869/

PR to revert incoming... #4679

Avoid an unneeded ArgumentsAdaptorTrampoline stack frame by passing the the right number of arguments to Module._load() in Module.require(). Shortens the following stack trace with one frame: LazyCompile:~Module.load module.js:345 LazyCompile:Module._load module.js:282 Builtin:ArgumentsAdaptorTrampoline LazyCompile:*Module.require module.js:361 LazyCompile:*require internal/module.js:11 PR-URL: #4575 Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: James M Snell <[email protected]>

This reverts commit 809bf5e ("change statSync to accessSync in realpathSync"). It was causing tests to fail on Windows CI. Ref: nodejs#4575 PR-URL: nodejs#4679 Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: Ben Noordhuis <[email protected]>

This reverts commit 7c60328. It is causing CI failures on Windows. Ref: nodejs#4575 PR-URL: nodejs#4679 Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: Ben Noordhuis <[email protected]>

This reverts commit 809bf5e ("change statSync to accessSync in realpathSync"). It was causing tests to fail on Windows CI. Ref: #4575 PR-URL: #4679 Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: Ben Noordhuis <[email protected]>

This reverts commit 7c60328. It is causing CI failures on Windows. Ref: #4575 PR-URL: #4679 Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: Ben Noordhuis <[email protected]>

rvagg · 2016-01-18T04:58:36Z

FTR I've marked this as dont-land-on-v5.x along with the reversion at #4679. However, the following commits have been landed as they were not implicated in the Windows CI failures:

26392ed - module: cache stat() results more aggressively
d8f5bd4 - module: avoid ArgumentsAdaptorTrampoline frame

Reduce the number of stat() system calls that require() makes by caching the results more aggressively. To avoid unbounded growth without implementing a LRU cache, scope the cache to the lifetime of the first call to require(). Recursive calls (i.e. require() calls in the included code) transparently profit from the cache. The benchmarked application is the loopback-sample-app[0] and it sees the number of stat calls at start-up go down by 40%, from 4736 to 2810. [0] https://github.com/strongloop/loopback-sample-app PR-URL: #4575 Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: James M Snell <[email protected]>

Notable changes: * events: make sure console functions exist (Dave) #4479 * fs: add autoClose option to fs.createWriteStream (Saquib) #3679 * http: improves expect header handling (Daniel Sellers) #4501 * node: allow preload modules with -i (Evan Lucas) #4696 * v8,src: expose statistics about heap spaces (`v8.getHeapSpaceStatistics()`) (Ben Ripkens) #4463 * Minor performance improvements: - lib: Use arrow functions instead of bind where possible (Minwoo Jung) #3622 - module: cache stat() results more aggressively (Ben Noordhuis) #4575 - querystring: improve parse() performance (Brian White) #4675 PR-URL: #4742

mhdawson · 2016-02-24T21:17:14Z

@bnoordhuis. Interestingly require performance for master is much better than 4.x. based on benchmark created by Michael Paulson. I'm guessing this might be part of the reason. If you are interested see charts through link in: nodejs/build#281 (comment)

fs.statSync() creates and returns a heavy-weight fs.Stat object whereas fs.accessSync() simply returns nothing. The return value is ignored, the call is for its side effect of throwing an ELOOP error in case of cyclic symbolic links. PR-URL: nodejs#4575 Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: James M Snell <[email protected]>

Reduce the number of stat() system calls that require() makes by caching the results more aggressively. To avoid unbounded growth without implementing a LRU cache, scope the cache to the lifetime of the first call to require(). Recursive calls (i.e. require() calls in the included code) transparently profit from the cache. The benchmarked application is the loopback-sample-app[0] and it sees the number of stat calls at start-up go down by 40%, from 4736 to 2810. [0] https://github.com/strongloop/loopback-sample-app PR-URL: nodejs#4575 Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: James M Snell <[email protected]>

Avoid an unneeded ArgumentsAdaptorTrampoline stack frame by passing the the right number of arguments to Module._load() in Module.require(). Shortens the following stack trace with one frame: LazyCompile:~Module.load module.js:345 LazyCompile:Module._load module.js:282 Builtin:ArgumentsAdaptorTrampoline LazyCompile:*Module.require module.js:361 LazyCompile:*require internal/module.js:11 PR-URL: nodejs#4575 Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: James M Snell <[email protected]>

Use internalModuleReadFile() to read the file from disk to avoid the fs.fstatSync() call that fs.readFileSync() makes. It does so to know the file size in advance so it doesn't have to allocate O(n) buffers when reading the file from disk. internalModuleReadFile() is plenty efficient though, even more so because we want a string and not a buffer. This way we also don't allocate a buffer that immediately gets thrown away again. This commit reduces the number of fstat() system calls in a benchmark application[0] from 549 to 29, all made by the application itself. [0] https://github.com/strongloop/loopback-sample-app PR-URL: nodejs#4575 Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: James M Snell <[email protected]>

This reverts commit 809bf5e ("change statSync to accessSync in realpathSync"). It was causing tests to fail on Windows CI. Ref: nodejs#4575 PR-URL: nodejs#4679 Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: Ben Noordhuis <[email protected]>

This reverts commit 7c60328. It is causing CI failures on Windows. Ref: nodejs#4575 PR-URL: nodejs#4679 Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: Ben Noordhuis <[email protected]>

Notable changes: * events: make sure console functions exist (Dave) nodejs#4479 * fs: add autoClose option to fs.createWriteStream (Saquib) nodejs#3679 * http: improves expect header handling (Daniel Sellers) nodejs#4501 * node: allow preload modules with -i (Evan Lucas) nodejs#4696 * v8,src: expose statistics about heap spaces (`v8.getHeapSpaceStatistics()`) (Ben Ripkens) nodejs#4463 * Minor performance improvements: - lib: Use arrow functions instead of bind where possible (Minwoo Jung) nodejs#3622 - module: cache stat() results more aggressively (Ben Noordhuis) nodejs#4575 - querystring: improve parse() performance (Brian White) nodejs#4675 PR-URL: nodejs#4742

bnoordhuis added 3 commits January 7, 2016 21:59

fs: change statSync to accessSync in realpathSync

66265f1

fs.statSync() creates and returns a heavy-weight fs.Stat object whereas fs.accessSync() simply returns nothing. The return value is ignored, the call is for its side effect of throwing an ELOOP error in case of cyclic symbolic links.

bnoordhuis added the module Issues and PRs related to the module subsystem. label Jan 7, 2016

bnoordhuis mentioned this pull request Jan 8, 2016

[perf] lib/compiler.js makes too many stat() calls strongloop/loopback-boot#167

Closed

jasnell added the lts-watch-v4.x label Jan 8, 2016

jasnell removed the lts-watch-v4.x label Jan 12, 2016

jasnell closed this Jan 12, 2016

Trott mentioned this pull request Jan 13, 2016

test: remove 1 second delay from test #4616

Closed

Trott mentioned this pull request Jan 13, 2016

Revert commits that cause failing tests on Windows CI #4679

Closed

MylesBorins mentioned this pull request Jan 15, 2016

Audit commits not found on v4.x-staging #4698

Closed

rvagg added the dont-land-on-v4.x label Jan 15, 2016

rvagg added the dont-land-on-v5.x label Jan 18, 2016

rvagg mentioned this pull request Jan 19, 2016

v5.5.0 Release Proposal (Stable) #4742

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

module: cache stat() results more aggressively #4575

module: cache stat() results more aggressively #4575

bnoordhuis commented Jan 7, 2016

bnoordhuis commented Jan 7, 2016

jasnell commented Jan 8, 2016

bnoordhuis commented Jan 8, 2016

jasnell commented Jan 11, 2016

cjihrig commented Jan 11, 2016

sam-github commented Jan 12, 2016

vkurchatkin commented Jan 12, 2016

jasnell commented Jan 12, 2016

Trott commented Jan 13, 2016

Trott commented Jan 13, 2016

jasnell commented Jan 13, 2016

Trott commented Jan 13, 2016

Trott commented Jan 13, 2016

Trott commented Jan 13, 2016

Trott commented Jan 13, 2016

cjihrig commented Jan 13, 2016

Trott commented Jan 13, 2016

Trott commented Jan 13, 2016

rvagg commented Jan 18, 2016

mhdawson commented Feb 24, 2016

module: cache stat() results more aggressively #4575

module: cache stat() results more aggressively #4575

Conversation

bnoordhuis commented Jan 7, 2016

bnoordhuis commented Jan 7, 2016

jasnell commented Jan 8, 2016

bnoordhuis commented Jan 8, 2016

jasnell commented Jan 11, 2016

cjihrig commented Jan 11, 2016

sam-github commented Jan 12, 2016

vkurchatkin commented Jan 12, 2016

jasnell commented Jan 12, 2016

Trott commented Jan 13, 2016

Trott commented Jan 13, 2016

jasnell commented Jan 13, 2016

Trott commented Jan 13, 2016

Trott commented Jan 13, 2016

Trott commented Jan 13, 2016

Trott commented Jan 13, 2016

cjihrig commented Jan 13, 2016

Trott commented Jan 13, 2016

Trott commented Jan 13, 2016

rvagg commented Jan 18, 2016

mhdawson commented Feb 24, 2016