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鈥檒l occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jest performance is at best 2x slower than Jasmine, in our case 7x slower #6694

Open
EvHaus opened this issue Jul 15, 2018 · 30 comments

Comments

Projects
None yet
@EvHaus
Copy link

commented Jul 15, 2018

馃悰 Bug Report

We've been using Jest alongside Jasmine for the same test suite for about a year now. We love Jest because it's developer experience is superb, however, on our very large monorepo with ~7000+ test specs, Jest runs about 7 times slower than Jasmine. This problem has been getting worse and worse as the test suite grows and as a result, we always run our test suite via Jasmine and only use Jest for development --watch mode.

We would 鈾 to use Jest as our only test runner, but its poor performance is preventing us from doing so. Having to run both Jest and Jasmine runners requires painful CI setup and constant upkeep of the Jasmine environment setup (which is much more complex than Jest's).

I'd like to better understand why the performance difference is so significant and if there's anything that can be done to optimize it.

To Reproduce

I've created a very detailed project to reproduce and profile both Jest and Jasmine on the same test suite in this project: https://github.com/EvHaus/jest-vs-jasmine

The environment is the same. The configurations are very similar. Both use JSDom. Both use the same Babel setup. Additional instructions are contained therein.

Expected behavior

Running tests through Jest should ideally be as fast as running them through Jasmine.

Link to repl or repo (highly encouraged)

https://github.com/EvHaus/jest-vs-jasmine

Run npx envinfo --preset jest

Tested on a few different platform. See https://github.com/EvHaus/jest-vs-jasmine README for more info.

@layershifter

This comment has been minimized.

Copy link

commented Jul 16, 2018

@EvHaus thanks for the detailed report.

We have similar issues under Semantic-Org/Semantic-UI-React#2971, when Jest's suite is about 5x slower.

@thymikee

This comment has been minimized.

@lukeapage

This comment has been minimized.

Copy link
Contributor

commented Jul 18, 2018

Am I right in saying the problem is that jasmine loads all specs into one process and runs it, where as jest creates a new mini-environment per test suite?
We see exactly the same issue and profiling seems to show a significant amount of time resolving files and parsing javascript - unfortunately the multi-core aspect can't make up for this. I have no idea why resolving is so slow. We made significant speed increases by trying to make suites import the least number of files, but we've hit a wall on going further in that direction as we in many cases want to test multiple components running together and not to mock every dependency.
I planned to do some more profiling and it would be great if anyone on the core jest team can point in any directions to things they would like to see.

@SimenB

This comment has been minimized.

Copy link
Collaborator

commented Jul 18, 2018

I think it's a fair assumption to say it's the module resolution that's taking time. While require('foo'); is an in-memory cache lookup for jasmine (after the first one), every single test file in jest will have to do full resolution, and execution, of foo and all its dependencies. I doubt it's the resolution itself that takes significant time (we should have the fs in memory (after the first run, at least)), but executing the files probably takes up a significant chunk of time.

Another difference is that jest executes your code inside the jsdom vm, while with jasmine you've just copied over all the globals to the node runtime (https://github.com/jsdom/jsdom/wiki/Don't-stuff-jsdom-globals-onto-the-Node-global), which will always be quicker as you skip an entire abstraction layer (https://nodejs.org/api/vm.html).

That said, I agree it's really not ideal (to put it mildly) that Jest is about twice as slow as jasmine. I'm not really sure what we an do, though. We could try to cache the resolution (although we'd still have to run through the entire tree in case there's been any module mocking) which might allow us to not resolve modules by looking around, but again the FS should be in memory, so I doubt it'd have much impact.

@cpojer @mjesun @aaronabramov @rickhanlonii do you think there's anything clever we can do here? Or any awesome ways of profiling what we spend our time on?


Also, thank you so much for setting up a great reproduction case @EvHaus!

@gsteacy

This comment has been minimized.

Copy link

commented Jul 18, 2018

I doubt it's the resolution itself that takes significant time (we should have the fs in memory (after the first run, at least)), but executing the files probably takes up a significant chunk of time.

I did some profiling of the node processes while running Jest on my projects it seemed like requiring was one of the most time consuming tasks. At least that was the case on Windows (not WSL), which I found to be substantially slower than Linux, especially in watch mode. Granted, I'm not particularly confident in my understanding of the node profiler's output, but that's what it looked like. I saw the same thing with this reproduction.

@SimenB

This comment has been minimized.

Copy link
Collaborator

commented Jul 18, 2018

require is both resolution and execution

@EvHaus

This comment has been minimized.

Copy link
Author

commented Jul 18, 2018

I think it's a fair assumption to say it's the module resolution that's taking time. While require('foo'); is an in-memory cache lookup for jasmine (after the first one), every single test file in jest will have to do full resolution, and execution, of foo and all its dependencies.

I haven't looked at the code, so I can't be totally sure -- but this sure "feels" like what's happening. When running through Jasmine there's a very long delay before anything is printed to the console (likely Jasmine resolving/executing ALL deps), and then the tests run through super quick. Whereas with Jest, it immediately starts running tests without any initial lag, but each test is significantly slower to run.

@simonbuchan

This comment has been minimized.

Copy link

commented Jul 19, 2018

Any chance switching from worker processes to the node vm api could help? That permits pre-compiling sources with vm.Script, then running them in isolated, sandboxed contexts. Obviously seems like a lot of work!

@cpojer

This comment has been minimized.

Copy link
Contributor

commented Jul 19, 2018

Jest already does that.

@simonbuchan

This comment has been minimized.

Copy link

commented Jul 19, 2018

I believe you, but then what are these jest-worker processes?

@cpojer

This comment has been minimized.

Copy link
Contributor

commented Jul 19, 2018

@rickhanlonii do you have the Jest architecture chart somewhere?

@simonbuchan

This comment has been minimized.

Copy link

commented Jul 19, 2018

If I had to guess, you use the workers for multi core, but VM as well for isolation, even with --runInBand? With cachedData that should skip most parse time even with multi proc. So the time is literally execution time of the modules, which would be pretty hard to skip I guess.

Maybe a --runVeryInBand that shares a VM?

@simonbuchan

This comment has been minimized.

Copy link

commented Jul 19, 2018

Looks like cachedData isn't being used in new vm.Script() (I'm looking at jest-runtime's ScriptTransformer - V8 can now cache script code after code execution, which looks like it's exposed by vm.Script#createCachedData() from node 10.6, so if there's somewhere sensible to do that, (just before any mock/test code execution somehow?) it might help even multi-proc?

@cpojer

This comment has been minimized.

Copy link
Contributor

commented Jul 19, 2018

I tried to use cachedData for an experiment about two years back. There is even a PR (sorry on mobile so can鈥檛 find the link). There was no difference in perf that I observed. Cached code is much larger and I assume reading and validating that is equal to the parse time overhead that is saved. I鈥檇 be curious to see results of somebody re-running that experiment. Changing the script transformer and running some perf tests should give us some data.

@simonbuchan

This comment has been minimized.

Copy link

commented Jul 19, 2018

That sounds likely, it could well be that the delayed createCachedData() could work better as more useful code would be codegened and thus cacheable (if I'm reading that blog post right).

There's also v8::SnapshotCreator that node started using recently for it's own startup which persists the full execution state, not just parse/codegen output, but it sounds like it's quite fiddly to get working even when you control all the code executed (e.g. it requires all handles to be closed).

@lukeapage

This comment has been minimized.

Copy link
Contributor

commented Aug 1, 2018

Things we've done to increase the performance of jest in our setup:

  1. Changed the reporter to not verbose and a dot reporter. For us this 2.5x speed increases
  2. Implemented our own custom resolver and instead of just caching imports with a cache key of the current directory and the import, cache based on current directory only if its relative or within node_modules, otherwise cache globally no matter what folder we are in - this appeared to save about 10% for us
  3. reduce the files imported per suite - for instance even a static import of ten json files across every suite, when removed saved several seconds. Removing some lazy imports where too much was imported took some suites from 10 seconds to 5 seconds.
@EvHaus

This comment has been minimized.

Copy link
Author

commented Aug 1, 2018

I was intrigued by the 2.5x speed increase mentioned from using a dot reporter, so I gave it a go.

Added verbose: false and reporters: ['jest-dot-reporter'] to the config. On our giant main repo it only offered about a 15% performance improvement (260s instead of 300s to run all tests). That's small but something. And on the test repo it didn't seem to make any difference at all (probably because it doesn't have enough specs for the reporter change to make an impact).

@lukeapage

This comment has been minimized.

Copy link
Contributor

commented Aug 1, 2018

That was a windows bash shell in windows 8. It wouldn鈥檛 surprise me if shells differed greatly and I鈥檝e previously seen a large slow down from console output.

@sebinsua

This comment has been minimized.

Copy link

commented Aug 1, 2018

Is it just console output which is slow or is it colored terminal output?

If it is the latter, perhaps somebody could try switching from chalk to turbocolor? According to the benchmark I linked to it's significantly faster.

@simonbuchan

This comment has been minimized.

Copy link

commented Aug 2, 2018

Perhaps somewhat effected, but windows console (=terminal) just renders very slowly in general, seemingly linear to the characters on screen - you can clearly see the speed increase as you resize the window slower. It's still using the ancient GDI api to render each span of text of the same color, so if there's a lot of switching at the character level that might have some effect. (They have reported they are working on the console rendering recently, but no exact dates)

The results in the original OP's test repo shows similar differences on a macbook, so I doubt this is the real difference here.

@SimenB

This comment has been minimized.

Copy link
Collaborator

commented Sep 17, 2018

Related: #2925 (and #4323 for a PR that gave it a shot). If we could implement that properly (as well as having some sort of state that only on say 20+ transitive dependencies is it activated) that might help

@leiyangyou

This comment has been minimized.

Copy link

commented Sep 18, 2018

also interesting is this, watch mode is three times slower than non watch mode even with the same amount of workers. (35s vs 11s)

tracked it down to the passing of to rawModuleMap in _createParallelTestRun of jest-runner, it seems like not passing the rawModuleMap is faster for some reason, note that in my case,
test.context.moduleMap.getRawModuleMap() always returns { duplicates: {}, map: {}, mocks: {} }

@SimenB

This comment has been minimized.

Copy link
Collaborator

commented Sep 18, 2018

@leiyangyou that was just changed in #6960 (not released yet), maybe it helps? Not sure about the easiest way for you to test it beyond following the steps in the contributing guide on how to use a local version of Jest.

/cc @rubennorte

@rubennorte

This comment has been minimized.

Copy link
Contributor

commented Sep 18, 2018

@SimenB that didn't improve watch mode as the haste map still has to be transferred to the worker processes (it's not persisted in watch mode). It might make that transference a bit slower because we have to serialize the map as a JSON-serializable array.

@leiyangyou

This comment has been minimized.

Copy link

commented Sep 18, 2018

@SimenB thanks. What I don't quite understand is this, according to logging, the sent raw map is pretty much empty { duplicates: {}, map: {}, mocks: {} }, I will set up a local instance with your changes and let you know.

@rubennorte

This comment has been minimized.

Copy link
Contributor

commented Sep 18, 2018

@leiyangyou the map is only empty when not in watch mode, because the worker is going to read it from disk. In watch mode is the updated haste map with any changes in the watched files already applied.

@leiyangyou

This comment has been minimized.

Copy link

commented Sep 18, 2018

@rubennorte so I've added a log inside runTestInWorker inside jest-runner/index.js

const runTestInWorker = function(test) {
        return mutex(
          _asyncToGenerator(function*() {
            if (watcher.isInterrupted()) {
              return Promise.reject();
            }

            yield onStart(test);

            console.log(test.context.moduleMap.getRawModuleMap())
            
            return worker.worker({
              config: test.context.config,
              globalConfig: _this3._globalConfig,
              path: test.path,
              rawModuleMap: (false && watcher.isWatchMode())
                ? test.context.moduleMap.getRawModuleMap()
                : null
            });
          })
        );
      };

in watch mode, on initial ran, { duplicates: {}, map: {}, mocks: {} } is printed for each worker, after I change a file, on subsequent runs it's still { duplicates: {}, map: {}, mocks: {} }

Maybe another bug somewhere? note that I've disabled the actual sending of the module map.

This is on the jest 23.6.0 release

@leiyangyou

This comment has been minimized.

Copy link

commented Sep 18, 2018

@SimenB I tried the latest version of the hash map

in non-watch mode, running through my test suite takes about 12s (comparable to before)
in watch mode, it takes about 24-30s (marginally faster than before, 30-35s)
again, not sending the map is faster, the same speed as non-watch mode.
I do have 8 cpus, and an ssd, and my suite is not huge, 70 suites with 787 tests

what is the initial motivation for dispatching module maps to workers?

@bichikim

This comment was marked as spam.

Copy link

commented Nov 8, 2018

Mocha takes one second.
Jest takes 12 seconds.
So I removed the Jest from my project.

@armano2

This comment has been minimized.

Copy link

commented Jan 12, 2019

i was trying to do migration from mocha to jest... and... mocha is finishing all tests before jest starts first one... i think there is somewhere issue with resolving/reading files -> my project contains ~70k files, and i'm running ~19k tests.

after some digging its looks like jest is trying to import all files from all folders before he starts tests, i'm providing explicit match for test file: testMatch: ['<rootDir>/dist/alignment.spec.js'].

i was able to run tests by adding to jest.config

modulePathIgnorePatterns: ['<rootDir>/fixtures/.*'],

but it's still 11m... as opposed to mocha ~1m and without test framework (try/catch assert) ~40-50s

turning off transformation helped to

transform: {}

so far my configuration looks like this:

module.exports = {
  testEnvironment: 'node',
  testMatch: ['<rootDir>/dist/alignment.spec.js'],
  moduleFileExtensions: ['js'],
  transform: {},
  modulePathIgnorePatterns: ['<rootDir>/projects/.*', '<rootDir>/node_modules/.*']
};

its still slow, ~4min


now i'm looking for way to turn of prettier, i don't care about formatting errors...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can鈥檛 perform that action at this time.