Jest performance is at best 2x slower than Jasmine, in our case 7x slower
EvHaus opened this issue · 48 comments
🐛 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.
@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.
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.
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!
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.
require is both resolution and execution
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.
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!
Jest already does that.
I believe you, but then what are these jest-worker processes?
@rickhanlonii do you have the Jest architecture chart somewhere?
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?
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?
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.
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).
Things we've done to increase the performance of jest in our setup:
- Changed the reporter to not verbose and a dot reporter. For us this 2.5x speed increases
- 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
- 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.
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).
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.
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.
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.
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: {} }
@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
@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.
@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.
@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.
@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
@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?
Mocha takes one second.
Jest takes 12 seconds.
So I removed the Jest from my project.
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...
modulePathIgnorePatterns and transform didn't show any improvements for me. i shoved off few seconds using a dot reporter though
Same issue here on 25.2.2, file resolution takes too long. Is there any plan to speed it up?
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.
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.
@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
Your approach
Jasmine (for comparison)
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.
@EvHaus yea, I think it won't have a difference in this benchmark.
More info about my setup/project.
- we had leaks
- 600 test files, 8000 tests total
- many dependencies - createScriptFromCode is called for 8000 unique files.
- number of resolved files - 20000.
- memory used after test file - up to 1gb. (per each worker). If don't clean - up to 2gb (node max old space)
- workers=8.
- pc - amd 3700x, 8/16 cores, 16gb memory.
- 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)
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.
Exciting, @EvHaus !
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:
~625msis spent doinggetModuleID()which does some expensive FS work to find the absolute location of the module - iteratively check dirs forpackage.json, check if there's aliasing properties in it (resolveExports), then find the actual module itself, and do someresolvecalls as well. SincegetModuleID()is called once per module (`~26000 calls), these FS operations add up.~450msis spent in_execModule()(excluding the actual invocation of the module, of course).~60msis spent intransformFile: read the file, hash it, check if hash matches local cache~350msis spent increateScriptFromCode: 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
~400msleftover, 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:
- Perhaps we can extend file-watching to be more intelligent in
getModuleIDto see if a file's been changed? Of course, if file watching isn't available (nowatchman, etc), then fall back to the current slow mode - It might be worth hashing and storing information about
package.jsonaliasing, so we don't need to load and parse it from scratch every time. Of course, this would still need to be invalidated if thepackage.jsonis changed (hopefully file watching can help us with this) - 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.jsondoesn't exist at in a previous import, perhaps we can avoid astatwhen importing a future module. Maybe this is already happening and I missed it :) - Can we reuse
createScriptFromCodeoutput between test invocations somehow? I wonder if it is Node-VM-specific (so, each time we create a new sandbox, we need tocreateScriptFromCodeagain). - Smaller thing: we initialize our hastemaps and
watchman, even if we aren't in--watchmode. Maybe this can be skipped? - Would it be possible to remove the amount of
resolve()/realpath/general FS operations ingetModuleID()? Perhaps some of them are redundant 🤞 - (Inspired by a workaround discovered by my colleague, Patrik) in watch mode, we can probably lean on
mtimeto 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).
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.
for those of you struggling with memory leaks kulshekhar/ts-jest#1967 (comment)
I have simular performance issues, our tests are running at least 5x slower.
I am having the same issue and it got 2X worse after upgrading Node from 12 to 18.
I am having the same issue and it got 2X worse after upgrading Node from 12 to 18.
Probably explains my issues.
Any news on this?
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.
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.
Stupid bot