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 24 is 67% slower than Jest 23.6.0 on the same test suite #7732

Closed
joelgetaction opened this issue Jan 28, 2019 · 31 comments · Fixed by #7746
Closed

Jest 24 is 67% slower than Jest 23.6.0 on the same test suite #7732

joelgetaction opened this issue Jan 28, 2019 · 31 comments · Fixed by #7746

Comments

@joelgetaction
Copy link

🐛 Bug Report

Thanks for your hard work releasing jest 24!

A clear and concise description of what the bug is.

On jest 23.6.0 my test collection that totals 49 test suites and 700 tests took on average 11.9 seconds to run. Now in jest 24.0.0 it takes 19.9 seconds to run, with no changes of any kind to my code, tests or environment other than upgrading to jest 24. I'm not doing anything fancy.

This is a serious performance regression. I want to use jest 24 to take advantage of test.todo but I can't afford to have my tests take 67% longer to run - that's a real drop in my productivity.

Any suggestions how to diagnose this further or fix this issue? I can't post source code because this is proprietary code I'm working on. How can we fix this performance regression?

To Reproduce

Steps to reproduce the behavior:

Run a set of tests in jest 23.6.0.
Run that same set of tests in jest 24.0.0.

Expected behavior

A clear and concise description of what you expected to happen.

Jest 24.0.0 should NOT be 67% slower than jest 23.6.0 for the same set of tests.

Link to repl or repo (highly encouraged)

Please provide either a repl.it demo or a minimal repository on GitHub.

Issues without a reproduction link are likely to stall.

Run npx envinfo --preset jest

Paste the results here:

  System:
    OS: macOS High Sierra 10.13.6
    CPU: (4) x64 Intel(R) Core(TM) i7-5557U CPU @ 3.10GHz
  Binaries:
    Node: 10.15.0 - ~/.nvm/versions/node/v10.15.0/bin/node
    Yarn: 1.13.0 - /usr/local/bin/yarn
    npm: 6.4.1 - ~/.nvm/versions/node/v10.15.0/bin/npm
  npmPackages:
    jest: ^24.0.0 => 24.0.0
@SimenB
Copy link
Member

SimenB commented Jan 28, 2019

We need some sort of reproduction here. I haven't seen any difference between 23 and 24 when upgrading, so it might be certain patterns that hsve regressed

@CrOrc
Copy link

CrOrc commented Jan 28, 2019

For me the Jest keeps writing new jest-transform-cache folder on every jest run.

System:
OS: Windows 7
CPU: (8) x64 Intel(R) Core(TM) i7-2600 CPU @ 3.40GHz
Binaries:
Node: 11.7.0 - C:\Program Files\nodejs\node.EXE
Yarn: 1.13.0 - ~\scoop\apps\yarn\current\Yarn\bin\yarn.CMD
npm: 6.5.0 - C:\Program Files\nodejs\npm.CMD

@SimenB
Copy link
Member

SimenB commented Jan 28, 2019

Interesting! That would definitely slow things down. Does that happen in many projects? Could you post your config?

@CrOrc
Copy link

CrOrc commented Jan 28, 2019

Here are babel.config.js, jest.config.js, package.json, yarn.lock

jest.config.zip

@lirbank
Copy link
Contributor

lirbank commented Jan 28, 2019

To me 24 seems slower when there is a cache available, but about the same as 23 when there is no cache, so it seems like @CrOrc is on to something. Here are my results (ran the tests three times with each config):

23.6.0 - Runs after clearing the cache with --clearCache:

Test Suites: 36 passed, 36 total
Tests: 553 passed, 553 total
Snapshots: 48 passed, 48 total
Time: 64.927s

Test Suites: 36 passed, 36 total
Tests: 553 passed, 553 total
Snapshots: 48 passed, 48 total
Time: 54.173s

Test Suites: 36 passed, 36 total
Tests: 553 passed, 553 total
Snapshots: 48 passed, 48 total
Time: 59.353s

23.6.0 - Runs without clearing the cache:

Test Suites: 36 passed, 36 total
Tests: 553 passed, 553 total
Snapshots: 48 passed, 48 total
Time: 36.196s, estimated 60s

Test Suites: 36 passed, 36 total
Tests: 553 passed, 553 total
Snapshots: 48 passed, 48 total
Time: 32.83s, estimated 33s

Test Suites: 36 passed, 36 total
Tests: 553 passed, 553 total
Snapshots: 48 passed, 48 total
Time: 32.278s

24.0.0 - Runs after clearing the cache with --clearCache:

Test Suites: 36 passed, 36 total
Tests: 553 passed, 553 total
Snapshots: 48 passed, 48 total
Time: 56.718s

Test Suites: 36 passed, 36 total
Tests: 553 passed, 553 total
Snapshots: 48 passed, 48 total
Time: 64.682s

Test Suites: 36 passed, 36 total
Tests: 553 passed, 553 total
Snapshots: 48 passed, 48 total
Time: 61.646s

24.0.0 - Runs without clearing the cache:

Test Suites: 36 passed, 36 total
Tests: 553 passed, 553 total
Snapshots: 48 passed, 48 total
Time: 42.998s

Test Suites: 36 passed, 36 total
Tests: 553 passed, 553 total
Snapshots: 48 passed, 48 total
Time: 44.611s

Test Suites: 36 passed, 36 total
Tests: 553 passed, 553 total
Snapshots: 48 passed, 48 total
Time: 48.576s

@overlookmotel
Copy link
Contributor

overlookmotel commented Jan 29, 2019

Just to say that I'm seeing the same as @CrOrc. Every run of jest with 24.0.0 produces a new jest-transform-cache folder plus new perf-cache and haste-map. Hence every test run takes as long as the first - the cache seems to be ignored. This doesn't happen with jest 23.6.0.

@csvan
Copy link

csvan commented Jan 29, 2019

Cannot provide repro due to working on proprietary code, but I can confirm this from our CI logs. Tests phase takes up to 5 minutes longer after moving from Jest 23.6 -> 24.0, with no other code changes being made.

I tried adding the --no-cache flag to see if it could be cache related as per @CrOrc suggestion above. I saw no difference in runtime. I then investigated I/O activity differences between 23.6 and 24.0 and found quite a significant difference:

Jest 24.0 : 10-15 MB/s total for 4 Jest workers
Jest 23.6: 1-3 MB/s total for 4 Jest workers

I know the above is anecdotal for our machines, but as suggested by @CrOrc it seems that Jest 24.0 makes significantly more cache writes than 23.6.

@SimenB
Copy link
Member

SimenB commented Jan 29, 2019

I can confirm caching of transformed files are broken.

It's due to this line (from #5862): https://github.com/facebook/jest/blob/31b81ba37eb779161b6db78aa862c0bcd6465bd5/packages/jest-config/src/normalize.js#L272

Removing it speeds up rerunning the same tests by 300% for me in watch mode.

When we get to the cache key, the entire config serialized as a string is part of the cache name, and that will change for every single invocation of Jest:

https://github.com/facebook/jest/blob/31b81ba37eb779161b6db78aa862c0bcd6465bd5/packages/jest-runtime/src/ScriptTransformer.js#L84

@SimenB
Copy link
Member

SimenB commented Jan 29, 2019

We should probably revert a370c21 to make it stable

/cc @thymikee

@SimenB
Copy link
Member

SimenB commented Jan 29, 2019

workaround is to set name in your config

@SimenB
Copy link
Member

SimenB commented Jan 29, 2019

PR: #7746

@viknes-interana
Copy link

workaround is to set name in your config

Sorry, where do we set the name? I only have a single config and it is declared in package.json. Adding a name property inside the jest object didn't help.

@csvan
Copy link

csvan commented Jan 30, 2019

Also wondering where to set the name option - it is not documented on https://jestjs.io/docs/en/configuration.html

Setting it in my jest.config.js did not fix the issue.

@DylanVann
Copy link
Contributor

DylanVann commented Feb 4, 2019

Setting name in my jest.config.js file does significantly speed up runs after the first one, but even after that I've found Jest 24 is about 50% slower than Jest 23.

Jest 23: 70s
Jest 24: 105s

Both of those times are from a warm start (I ran Jest twice before recording the time).

Unfortunately I can't share the code. It's running around 300 test suites, around 3000 tests, and around 300 snapshots.

Edit:

I also have api.cache.using(() => process.env.NODE_ENV) in my babel.config.js, doesn't seem to help.

@joelgetaction
Copy link
Author

joelgetaction commented Feb 4, 2019 via email

@jeysal
Copy link
Contributor

jeysal commented Feb 5, 2019

24.1.0 is released

@SimenB
Copy link
Member

SimenB commented Feb 5, 2019

Can people test that, and if they still have perf regressions compared to 23, open up a new issue?

@joelgetaction
Copy link
Author

joelgetaction commented Feb 5, 2019 via email

@Jony-Y
Copy link

Jony-Y commented Mar 10, 2019

using jest 24.3.1 vs jest 23.6.0

jest 24.3.1: 108s
jest 23.6.0: 66s

@csvan
Copy link

csvan commented Mar 14, 2019

@Jony-Y that is not related to this bug though, see #7811

@mucsi96
Copy link

mucsi96 commented Aug 1, 2019

Let me share my profiling here.
Specs:

  • Windows 10 Pro
  • Node 10.15.3
  • Intel Core i7-4702MQ 2.2GHz
  • 8GB RAM
  • x64
  • SSD

Steps:

  1. npx create-react-app my-app --typescript
  2. change App.test.tsx
  3. run npm test

CPU Profile:
image
CPU-20190801T141211.zip

Is it expected that 15 seconds are spent only with requring modules for single trivial React component and test?

Can someone with more experience on CPU profiling take a look?

@jeysal
Copy link
Contributor

jeysal commented Aug 1, 2019

@mucsi96 a big part of that is likely micromatch, which is already known as a performance problem and will be fixed in 25

@mucsi96
Copy link

mucsi96 commented Aug 1, 2019

Which Jest package depends on micromatch 3 causing the performance problem? Can I try bumping it within the package?

@jeysal
Copy link
Contributor

jeysal commented Aug 1, 2019

more info in
#7963
#8032

@mucsi96
Copy link

mucsi96 commented Aug 1, 2019

Thanks! I have tried to replace micromatch 3 with latest 4.0.2 in node_modules and achieved 4 seconds shorter test execution time. Initial time was 20 seconds on npx create-react-app my-app --typescript. So that`s 20% speed improvement. But I still feel it very slow. 16 seconds for single trivial React component and test feels too much for me.

Specs:

  • Windows 10 Pro
  • Node 10.15.3
  • Intel Core i7-4702MQ 2.2GHz
  • 8GB RAM
  • x64
  • SSD

Steps:

  1. npx create-react-app my-app --typescript
  2. change App.test.tsx
  3. run npm test

CPU Profile:
image
CPU-micromatch-4.zip

@thymikee
Copy link
Collaborator

thymikee commented Aug 1, 2019

@mucsi96 The issue with TS being slow may be caused by the order of module extension resolution. By default, Jest searches first for ['js', 'json', 'jsx', 'ts', 'tsx', 'node'] – so TS is supported, but at a performance cost. You can adjust the moduleFileExtensions config, to have ts and tsx at the very beginning, e.g. ['ts', 'tsx', 'js', 'json', 'jsx', 'node'].

However, looking at the source, CRA has its own list, which is not allowed to be overridden: https://github.com/facebook/create-react-app/blob/b96ac6c2c007db85812a6e9c0ec54509019c0fea/packages/react-scripts/config/paths.js#L49-L61. You could try passing it as a flag to the CLI, but not sure about that. I'd try adjusting the list in node_modules, making sure it works faster and then send a PR to CRA with adjusted moduleFileExtensions for TS

@mucsi96
Copy link

mucsi96 commented Aug 1, 2019

Thanks for noting this. I have already submitted an different issue due to roots not set. facebook/create-react-app#7458

@mucsi96
Copy link

mucsi96 commented Aug 1, 2019

I have tried ['ts', 'tsx', 'js', 'json', 'jsx', 'node'] but it made the execution even slower. Probably due to single React component and test vs. much more build-in modules.

@mucsi96
Copy link

mucsi96 commented Aug 1, 2019

Also this issue seems to be not related to TypeScript. With npx create-react-app my-app the test execution is about 1 second faster then the TS version. So 18.69 seconds on my machine after adding roots to createJestConfig

@Darth-koder007
Copy link

My project was using the old one jest-dom/extend-expect, so I replaced it with @testing-library/jest-dom/extend-expect and upgraded jest to 24.9.0, now tests and coverage are lightning fast.

@github-actions
Copy link

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.
Please note this issue tracker is not a help forum. We recommend using StackOverflow or our discord channel for questions.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators May 11, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging a pull request may close this issue.