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

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

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

Comments

@EvHaus
Copy link

EvHaus 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
Copy link

@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
Copy link
Collaborator

@lukeapage
Copy link
Contributor

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
Copy link
Member

SimenB 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
Copy link

gsteacy 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
Copy link
Member

SimenB commented Jul 18, 2018

require is both resolution and execution

@EvHaus
Copy link
Author

EvHaus 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
Copy link

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
Copy link
Member

cpojer commented Jul 19, 2018

Jest already does that.

@simonbuchan
Copy link

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

@cpojer
Copy link
Member

cpojer commented Jul 19, 2018

@rickhanlonii do you have the Jest architecture chart somewhere?

@simonbuchan
Copy link

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
Copy link

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
Copy link
Member

cpojer 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’t 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’d 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
Copy link

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
Copy link
Contributor

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
Copy link
Author

EvHaus 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
Copy link
Contributor

That was a windows bash shell in windows 8. It wouldn’t surprise me if shells differed greatly and I’ve previously seen a large slow down from console output.

@sebinsua
Copy link

sebinsua 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
Copy link

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
Copy link
Member

SimenB 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
Copy link

leiyangyou 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
Copy link
Member

SimenB 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
Copy link
Contributor

@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
Copy link

@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
Copy link
Contributor

@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
Copy link

@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
Copy link

@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?

@cscleison
Copy link

modulePathIgnorePatterns and transform didn't show any improvements for me. i shoved off few seconds using a dot reporter though

@Shingaz
Copy link

Shingaz commented Mar 26, 2020

Same issue here on 25.2.2, file resolution takes too long. Is there any plan to speed it up?

@goloveychuk
Copy link

goloveychuk commented May 22, 2020

I think it's interesting to revisit cachedData in context of using esm:
https://github.com/facebook/jest/blob/9ffd368330a3aa05a7db9836be44891419b0b97d/packages/jest-runtime/src/index.ts#L364
I checked using cachedData on one big bundle, I see 500 -> 20ms drop for SourceTextModule constructor.
It's interesting to check if this will improve performance. (we want to know parsing vs evaluation time)
Ideally we want to dump whole memory and reuse it for each test, but I cannot imagine how to do this.

@goloveychuk
Copy link

goloveychuk commented Apr 6, 2021

I've succeeded speeding up jest in our project.
Main issue for us was high memory usage and memory leaks. Solution is - proxy builtin modules and call gc before every test. Other speedup options - cache resolver, transformers, vm.script creation.
you can try in you project.
jest.config.js

resolver: require.resolve('./cached-jest-resolver'),
moduleLoader: require.resolve('./jest-runtime'),

cached-jest-resolver

const cache = new Map();

module.exports = (request, options)  => {
    const cacheKey = `${request}!!${options.basedir}`;
 
    let resolved = cache.get(cacheKey);
    if (!resolved) {
        resolved = options.defaultResolver(request, options);
        cache.set(cacheKey, resolved);
    }

    return resolved   
}

jest-runtime.js

const JestRuntime = require('jest-runtime');
const vm = require('vm');
const {handlePotentialSyntaxError} = require('@jest/transform');
const v8 = require('v8')
//TODO SAFER BUFFER! request/request inherits stream
const PROXY_WHITE_LIST = new Set(['process', 'module', 
// 'buffer', 'stream',
// 'constants',
'fs'
]);
v8.setFlagsFromString('--expose-gc');
//TODO freeze console????????????
const gcClean = vm.runInNewContext('gc')
let RUN_COUNT_FOR_GC = 1
const CLEAN_EVERY_TIME = 1;
const detectLeaks = (() => {
  const weak = require('weak-napi');
  let references = 0;
  return (obj) => {
    references += 1;
    console.log('references count ++', references)
    weak(obj, () => {
      references -= 1;
      console.log('references count --', references)
    })
  }
})()
function makeReadonlyProxy(obj) {
    if (
      !((typeof obj === 'object' && obj !== null) || typeof obj === 'function')
    ) {
      return obj;
    }
    return new Proxy(obj, {
      get: (target, prop, receiver) => {
        return makeReadonlyProxy(Reflect.get(target, prop, receiver), );
      },
      set: (target, property, value, receiver) => {
        if (typeof value !== 'function') {
          return Reflect.set(target, property, value, receiver);
        }
        // console.log(`trying to set! ${path.join(', ')} ${property}, ${typeof value}`);
        // throw new Error(`trying to set! ${filename}, ${property as any}, ${typeof value}`);
        return true;
      },
    });
  }
const __scriptCache = new Map();
const __transformCache = new Map();
module.exports = class MyJestRuntime extends JestRuntime {
    constructor(...args) {
        super(...args);
        this.__coreModulesCache = new Map();
        // Object.freeze(this._environment.global.console);
        if (++RUN_COUNT_FOR_GC % CLEAN_EVERY_TIME === 0) {
            console.log('running gc')
          gcClean();
        }
        detectLeaks(this)
        console.log('memory: ', Math.floor(process.memoryUsage().heapUsed/1000/1000));
    }
    transformFile(filename, options) {
      //TODO IS WATCH
        let result = __transformCache.get(filename);
        if (!result) {
            result = super.transformFile(filename, options);
            __transformCache.set(filename, result); //DO NOT COMMIT IT
        }
        return result
    }
    _requireCoreModule(moduleName) {
        let mod = this.__coreModulesCache.get(moduleName);
        if (!mod) {
            mod = super._requireCoreModule(moduleName);
            if (!PROXY_WHITE_LIST.has(moduleName)) { //TODO!!!!!
                mod = makeReadonlyProxy(mod)
            }
            this.__coreModulesCache.set(moduleName, mod)
        }
        return mod
    }
    createScriptFromCode(scriptSource, filename) {
        const scriptFromCache = __scriptCache.get(filename);
        if (scriptFromCache) {
            return scriptFromCache
        }
        try {
          const scriptFilename = this._resolver.isCoreModule(filename)
            ? `jest-nodejs-core-${filename}`
            : filename;
          const script =  new vm.Script(this.wrapCodeInModuleWrapper(scriptSource), {
            displayErrors: true,
            filename: scriptFilename,
            //is leaking
            // @ts-expect-error: Experimental ESM API
            // importModuleDynamically: async (specifier) => {
            //   invariant(
            //     runtimeSupportsVmModules,
            //     'You need to run with a version of node that supports ES Modules in the VM API. See https://jestjs.io/docs/en/ecmascript-modules',
            //   );
            //   const context = this._environment.getVmContext?.();
            //   invariant(context, 'Test environment has been torn down');
            //   const module = await this.resolveModule(
            //     specifier,
            //     scriptFilename,
            //     context,
            //   );
            //   return this.linkAndEvaluateModule(module);
            // },
          });
          __scriptCache.set(filename, script); //TODO is cache
          return script
        } catch (e) {
          throw handlePotentialSyntaxError(e);
        }
      }
}

You can play with this. Mb you'll need to add more deps to PROXY_WHITE_LIST.
references count should be <=3, if more - you're probably leaking, which will impact performance.

@EvHaus
Copy link
Author

EvHaus commented Apr 8, 2021

@goloveychuk Interesting idea, but your solution didn't seem to make a significant difference in my benchmark. 😢 I've added it to https://github.com/EvHaus/jest-vs-jasmine/.

Native Jest

Screen Shot 2021-04-07 at 7 36 35 PM

Your approach

Screen Shot 2021-04-07 at 7 36 59 PM

Jasmine (for comparison)

Screen Shot 2021-04-07 at 7 42 48 PM

I've updated my repo with the latest benchmarks, latest version of Jest, latest version of Node and a more reproducible benchmarking tool (via hyperfine). Overall, I'm still seeing Jest performing at least 3x slower than Jasmine. So nothing has really changed since the original post.

FYI: I'm not complaining. Just want to ensure those subscribed to the thread know that no significant advancements have been made here yet in the latest versions.

@goloveychuk
Copy link

goloveychuk commented Apr 8, 2021

@EvHaus yea, I think it won't have a difference in this benchmark.
More info about my setup/project.

  1. we had leaks
  2. 600 test files, 8000 tests total
  3. many dependencies - createScriptFromCode is called for 8000 unique files.
  4. number of resolved files - 20000.
  5. memory used after test file - up to 1gb. (per each worker). If don't clean - up to 2gb (node max old space)
  6. workers=8.
  7. pc - amd 3700x, 8/16 cores, 16gb memory.
  8. 26.6 jest, jasmine test runner.

In this setup I have 531s default, and 226s with above optimisations.
Most important trick is to clean memory before each test file, and it will help only if you're using many workers and your tests are taking much memory. In my example - 8 workers * 2 memory, with 16gb total, system is going to swap. And you have this "effect", when at start jest is running pretty fast, and after several test files it's slowed down. If you have such a symptoms - mb gc clean will help you.

So answering on your comment - those optimisations could help on real world heavy projects, it cannot make jest same speed as jasmine, since jest have expensive runtime (think of all those features/overhead: mocks, transformers, reporters, error formatting, tests isolation, caching etc)

@EvHaus
Copy link
Author

EvHaus commented Dec 31, 2021

Just updated my benchmarks with a new player in town -- Vitest. I have good news. It has a compatible API to Jest but in my benchmarks it ran 2x faster than Jest and even outperformed Jasmine. 😮

I'm going to try migrating a larger real world codebase to it early in the new year and report back on the experience for those curious.

@nemoDreamer
Copy link

Exciting, @EvHaus !

@mitchhentgesspotify
Copy link
Contributor

mitchhentgesspotify commented Sep 29, 2022

Hey folks, I've done an investigation run on my own with a no-op test and a lot of imports (requireModuleOrMock() is being called ~12500 times!). Most of my files in this test are TypeScript.

Ignoring jest init time (by strictly measuring the 2nd test of a jest --watch ...), this no-op test takes ~1.5s.
Here's what I'm seeing that's causing that:

  • ~625ms is spent doing getModuleID() which does some expensive FS work to find the absolute location of the module - iteratively check dirs for package.json, check if there's aliasing properties in it (resolveExports), then find the actual module itself, and do some resolve calls as well. Since getModuleID() is called once per module (`~26000 calls), these FS operations add up.
  • ~450ms is spent in _execModule() (excluding the actual invocation of the module, of course).
    • ~60ms is spent in transformFile: read the file, hash it, check if hash matches local cache
    • ~350ms is spent in createScriptFromCode: I think this is Node VM shenanigans requiring a bunch of work to happen on the script before it can be interpreted "for real".
  • There's roughly ~400ms leftover, but I think that it can be explained by interpretation time of the imported modules themselves - there may be other wins in here, but they're going to have depreciating returns.

So, a couple recommendations for things to look into next:

  1. Perhaps we can extend file-watching to be more intelligent in getModuleID to see if a file's been changed? Of course, if file watching isn't available (no watchman, etc), then fall back to the current slow mode
  2. It might be worth hashing and storing information about package.json aliasing, so we don't need to load and parse it from scratch every time. Of course, this would still need to be invalidated if the package.json is changed (hopefully file watching can help us with this)
  3. As we build an understanding of the file system, we might be able to get more clever to avoid some FS work (e.g. if we know that package.json doesn't exist at in a previous import, perhaps we can avoid a stat when importing a future module. Maybe this is already happening and I missed it :)
  4. Can we reuse createScriptFromCode output between test invocations somehow? I wonder if it is Node-VM-specific (so, each time we create a new sandbox, we need to createScriptFromCode again).
  5. Smaller thing: we initialize our hastemaps and watchman, even if we aren't in --watch mode. Maybe this can be skipped?
  6. Would it be possible to remove the amount of resolve()/realpath/general FS operations in getModuleID()? Perhaps some of them are redundant 🤞
  7. (Inspired by a workaround discovered by my colleague, Patrik) in watch mode, we can probably lean on mtime to determine if a file is changed on re-runs. This sidesteps hashing all input files, which is a big win.

If I have time, I may be able to dig into some of these potential perf-gain options in the next few months, but no guarantees. I wanted to brain-dump here in case any other Jesters and Fools got inspired :)


(note that I do have some low-hanging-fruit PRs that I'll be upstreaming, but none of them address the remaining code hotspots mentioned above).

@goloveychuk
Copy link

To "fix" imports overhead, I've written custom test runner.
It's using posix fork() to clone processes (more docs are in link)
In our case, we reduced our test run from 18 to 4.5 minutes, from which 1 minute is warmup and could be speed up by moving to swc/esbuild.

https://github.com/goloveychuk/fastest-jest-runner

@cscleison
Copy link

for those of you struggling with memory leaks kulshekhar/ts-jest#1967 (comment)

@muhamedkarajic
Copy link

I have simular performance issues, our tests are running at least 5x slower.

@BrevAlessio
Copy link

I am having the same issue and it got 2X worse after upgrading Node from 12 to 18.

@muhamedkarajic
Copy link

I am having the same issue and it got 2X worse after upgrading Node from 12 to 18.

Probably explains my issues.

@muhamedkarajic
Copy link

muhamedkarajic commented Jun 19, 2023

Any news on this?

@m-abboud
Copy link

m-abboud commented Dec 5, 2023

I made a hacked together runtime and test env that doesn't isolate the test suites that improved our frontend tests by 8x with a cold cache. It also has a few caveats. So depending on your project setup it may or may not help. https://github.com/m-abboud/hella-fast-jest-runtime.

Copy link

github-actions bot commented Dec 5, 2024

This issue is stale because it has been open for 1 year with no activity. Remove stale label or comment or this will be closed in 30 days.

@github-actions github-actions bot added the Stale label Dec 5, 2024
@tkrotoff
Copy link
Contributor

tkrotoff commented Dec 5, 2024

Stupid bot

@github-actions github-actions bot removed the Stale label Dec 5, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests