Jest: Performance Issue - 50% of time spent inside `statSync`

[urish]

Do you want to request a feature or report a bug?

Bug

What is the current behavior?

Running jest with about 100 tests take around 10-14 seconds on my machine. After doing some profiling, I figured out it calls fs.statSync() about 150,000 times (so about 1,500 times per single test), and spends there about 6.5 seconds, which is roughly half of the run time. All these calls are initiated by jest-resolve (which eventually uses the resolve package).

Using jest v20.0.1, jest-resolve 20.0.1.

Here are my benchmark results:

Test Suites: 14 passed, 14 total
Tests:       3 skipped, 107 passed, 110 total
Snapshots:   0 total
Time:        13.784s
Ran all test suites.
Total statSync calls: 152244
Total time spent (ms): 6916.388558894396

How did I perform the benchmark?

1. I replaced node_modules/jest-resolve/node_modules/resolve/lib/sync.js with this instrumented version. I instrumented the isFile() method to figure out how many times it is called and time spent inside.
2. I ran jest --runInBand

Also tried to disable cache, but the method was still called ~ 150,000 times.

finally, here is my jest configuration:

  "jest": {
    "preset": "jest-preset-angular",
    "rootDir": "app",
    "setupTestFrameworkScriptFile": "<rootDir>/setupJest.ts",
    "testRegex": "\\.spec\\.(ts)$",
    "transform": {
      "^.+\\.(ts|js|html)$": "<rootDir>/../node_modules/jest-preset-angular/preprocessor.js"
    },
    "globals": {
      "__TS_CONFIG__": "app/tsconfig.spec.json",
      "__TRANSFORM_HTML__": true
    }
  }

If needed, I would love to provide more feedback or dig into it further - but please provide me some pointers where to dig.

[thymikee]

Can you check roughly which files are called and if there are duplicate calls? A repo where we could dive in would also be helpful. I'm curious on how it performs on clean project.
But I have a feeling it may be connected to how many files Angular is calling during test bed initialization and resetting its modules on every beforeEach.
Nevertheless there's probably an opportunity to improve this with some finer caching or memoization.

[cpojer]

Yes, this is bad. We'd like to address this by building a high-performance version of resolve: #2925.

[urish]

@cpojer great to hear you are on it :-)

@thymikee I have investigated further, it seems like every import or require anywhere in the code base results in 10-20 calls, looking for the module in the current directory first (and then in node_modules). For example, I have require('md5') somewhere in my code, and this alone results in 270 statSync calls.

I created a small repo that reproduces it - it uses default jest config and no typescript, but you can still see that a single require('md5') results in 105 statSync calls:

https://github.com/urish/jest-perf/blob/master/md5-stat-sync.txt

p.s. jest is great, I really enjoy using it so far (it's been my second day) so thanks!

[cpojer]

Yeah this is definitely odd. Node's resolution algorithm is inherently slow because it goes to the filesystem a lot, but this seems excessive. We gotta replace resolve, especially since we know a lot of metadata about most files anyway.

[thymikee]

Closing this, but we shall discuss it further in #2925, is that ok @urish?