jest 25 performance

[benmonro]

💥 Regression Report

we upgraded jest from 24 to 25 and saw our unit tests go from taking 5min 23sec in jenkins to now over 11 minutes. only a few snapshot tests broke in the upgrade, we -u'd them, but this is a severe regression imo. please help me understand how we can fix this. We clear cache in CI to ensure we always run the latest.

A clear and concise description of what the regression is. run time went from 5:23, to 11:00

Last working version

24.8.0 Worked up to version: 24.8.0 Stopped working in version: 25.1.0

To Reproduce

sorry can't share our codebase Steps to reproduce the behavior:

Expected behavior

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

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 Mojave 10.14.6
    CPU: (12) x64 Intel(R) Core(TM) i9-8950HK CPU @ 2.90GHz
  Binaries:
    Node: 10.16.0 - ~/.nvm/versions/node/v10.16.0/bin/node
    Yarn: 1.19.0 - ~/.nvm/versions/node/v10.16.0/bin/yarn
    npm: 6.13.6 - ~/.nvm/versions/node/v10.16.0/bin/npm

[SimenB]

Sorry about the regression but

sorry can't share our codebase

means we can do absolutely nothing. This is the first I've heard of performance regressing, everywhere else I've heard from 10-40% improvement in performance going from 24 to 25. You need to provide some sort of reproduction, otherwise we'll have to close this issue as it's not actionable at all as it stands.

If you want to see this adressed, you'll need to spend some time putting together a reproduction case, or hope somebody else does so.

[benmonro]

ok i will see if i can pull our 10 slowest tests maybe, then try to run them in 24 vs 25. in the meantime, what do you recommend with regards to clearing cache before running tests in CI? do it? don't do it?

[SimenB]

Your configuration, especially transforms and setup files are probably relevant as well

what do you recommend with regards to clearing cache before running tests in CI

I personally think it's a good idea just to be sure there's nothing stale laying around giving false negative or positives. Does it make a huge difference to the runtime of your tests to not clear the cache?

[benmonro]

it appears to be quite a bit slower when run after clearing cache. thanks for the tips i'll look into it and see if i can attempt a repro

[milesj]

FWIW, I've also noticed that v25 is either slightly slower or right on par with v24. Have not seen anywhere near 10-40% improvement.

[csvan]

I saw a significant speedup over jest 24 as noted here: https://github.com/facebook/jest/issues/7811#issuecomment-577057189

The above was tested on osx.

However, the exact same setup runs much, much slower on our CI which runs CentOS.

Linux specific issue? I/O related issues when writing cache files? Is it possible to turn off cache generation altogether to rule this out?

[csvan]

I think I found the culprit in our case, it's the --collectCoverage flag. When it is removed for both Jest 24 and 25, our tests run roughly twice as fast under 25. When it is enabled, our tests under 25 are almost 4 times as slow as the same ones under 24.

This is reproducible both on OSX and CentOS, so contrary to my previous comment the issue does not appear Linux-specific.

[SimenB]

Interesting! We've updated Istanbul to v3, maybe something in there has regressed. We've added support for v8 code coverage, so I might also have messed up the refactoring when doing so

[benmonro]

Yes! That's consistent with what I'm seeing as well. We are running with coverage in CI where it's 2x slower. And when I run locally without covg is quite fast. @SimenB is there any config option to use the older Istanbul? :)

[benmonro]

Echoing what @csvan said it would be nice to turn off cache generation in CI if that is in fact a culprit since we delete it prior to building anyway

[SimenB]

I'm unable to reproduce this - the repos I test have about the same performance with --coverage between v24 and v25. Would somebody be able to put together a repository with jest 24 and jest 25 where switching between them shows a difference?

[benmonro]

just ran our CI build w/ coverage disabled, I think @csvan is on to something. The tests run in 4:00 w/ coverage turned off vs 11 min w/ coverage turned on. I will try to see if i can create repro this weekend at some point.

our exinfo from the build agent:

00:03:31.992   System:
00:03:31.992     OS: Linux 3.10 CentOS Linux 7 (Core)
00:03:31.992     CPU: (8) x64 Intel Core Processor (Skylake, IBRS)
00:03:31.992   Binaries:
00:03:31.992     Node: 10.16.0 - ~/workspace/grocery-electrode/tools/nix_64/nodejs-10.16.0/bin/node
00:03:31.992     npm: 6.9.0 - ~/workspace/grocery-electrode/tools/nix_64/npm-6.9.0/node_modules/.bin/npm
00:03:31.993   npmPackages:
00:03:31.993     jest: 25.1.0 => 25.1.0 

[EvHaus]

We're seeing a similar issue. Upgrading Jest 25 made our tests slower when using coverage (166s with Jest 24 vs. 381s with Jest 25). With Jest 25 displaying many of these errors while running the checks:

FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
 1: 0x10003d041 node::Abort() [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 2: 0x10003d24b node::OnFatalError(char const*, char const*) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 3: 0x1001b8e25 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 4: 0x100586d82 v8::internal::Heap::FatalProcessOutOfMemory(char const*) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 5: 0x100589855 v8::internal::Heap::CheckIneffectiveMarkCompact(unsigned long, double) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 6: 0x1005856ff v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::GCCallbackFlags) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 7: 0x1005838d4 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 8: 0x10059016c v8::internal::Heap::AllocateRawWithLigthRetry(int, v8::internal::AllocationSpace, v8::internal::AllocationAlignment) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 9: 0x1005901ef v8::internal::Heap::AllocateRawWithRetryOrFail(int, v8::internal::AllocationSpace, v8::internal::AllocationAlignment) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
10: 0x10055fb34 v8::internal::Factory::NewFillerObject(int, bool, v8::internal::AllocationSpace) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
11: 0x1007e7e14 v8::internal::Runtime_AllocateInNewSpace(int, v8::internal::Object**, v8::internal::Isolate*) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
12: 0xb9c575dbe3d 
13: 0xb9c57ab091a 
14: 0xb9c579e7d65 
15: 0xb9c579ebaf3 

<--- Last few GCs --->

[733:0x102804000]    84639 ms: Mark-sweep 1335.2 (1449.6) -> 1325.4 (1452.1) MB, 1443.2 / 0.0 ms  (average mu = 0.135, current mu = 0.076) allocation failure scavenge might not succeed
[733:0x102804000]    85872 ms: Mark-sweep 1338.3 (1452.1) -> 1327.8 (1455.1) MB, 1159.4 / 0.0 ms  (average mu = 0.101, current mu = 0.059) allocation failure scavenge might not succeed


<--- JS stacktrace --->

Downgrading to Jest 24 makes those errors go away.

I also noticed Jest 25 handles the collectCoverageFrom differently as it seems to collect coverage from files we have explicitly disabled in that configuration. Did support for the glob syntax change there?

[SimenB]

Any JS traces at all? Would be interesting to see where it died.

I also noticed Jest 25 handles the collectCoverageFrom differently as it seems to collect coverage from files we have explicitly disabled in that configuration. Did support for the glob syntax change there?

We upgraded to Micromatch 4, it might've changed something. No changes to it on purpose, though. Could you open up a separate issue with a reproduction?

[EvHaus]

Any JS traces at all?

This was printed:

==== JS stack trace =========================================

    0: ExitFrame [pc: 0x521cca5be3d]
Security context: 0x0ebfa799e6e9 <JSObject>
    1: _clearMemoizedQueries [0xebf2a5aba99] [/Users/evhaus/Git/zenhub/client/node_modules/jest-environment-jsdom/node_modules/jsdom/lib/jsdom/living/nodes/Node-impl.js:~208] [pc=0x521cd0d9a4e](this=0x0ebf5bee2aa9 <EventTargetImpl map = 0xebf7963d039>)
    2: _clearMemoizedQueries [0xebf2a5aba99] [/Users/evhaus/Git/zenhub/client/node_modules/jest-environment-...

EDIT: Actually, I'm seeing heap errors even with coverage disabled.

We upgraded to Micromatch 4, it might've changed something. No changes to it on purpose, though. Could you open up a separate issue with a reproduction?

Will do.

[milesj]

Chiming in again. Coverage is definitely slower, and seems to be spurious. Here's the timings for OSX.

v24
46.69
41.77
45.06

v24 coverage
78.60
75.79
80.38

v25
45.93
52.49
53.36

v25 circus
61.27
52.08

v25 coverage
310.98
227.15
153.81

Timings for CI (travis).

v24 coverage -w 4
101.634s

v25 coverage -w 4
178.306s

[benmonro]

@milesj what is v25 circus?

[milesj]

It's jests new runner, which is supposed to be faster, but it never is from what I've seen. https://www.npmjs.com/package/jest-circus

[SimenB]

@EvHaus Traces from JSDOM is interesting (might also be completely coincidental, of course). Could you try installing jest-environment-jsdom@24 and using that? We upgraded from 11 to 15, so something in there might have changed. Seems like a longshot, but who knows

[EvHaus]

@SimenB Rolling back just jest-environment-jsdom to <24.0.0 in my package.json definitely made an impact. The heap out of memory errors are gone and Jest seems to complete its runs without any issue.

[SimenB]

Interesting! If you have time, it'd be lovely if you could test

• https://www.npmjs.com/package/jest-environment-jsdom-twelve
• https://www.npmjs.com/package/jest-environment-jsdom-thirteen
• https://www.npmjs.com/package/jest-environment-jsdom-fourteen

Or just link in jsdom and bisect. I'll do that tomorrow, but I don't really have a good reproduction yet

[EvHaus]

For the following tests I don't have coverage enabled.

• With [email protected]
  • 143s to run tests
  • No issues
• With [email protected]
  • 154s to run tests
  • No issues
• With [email protected]
  • 228s to run tests
  • 🚨Many JavaScript heap out of memory errors

Stack traces

These are some of the stack traces from the jest-environment-jsdom-fourteen run:

==== JS stack trace =========================================

    0: ExitFrame [pc: 0x20deef6dbe3d]
Security context: 0x36ee8219e6e9 <JSObject>
    1: _modified [0x36ee35982ec1] [/Users/evhaus/Git/zenhub/client/node_modules/jest-environment-jsdom-fourteen/node_modules/jsdom/lib/jsdom/living/nodes/Node-impl.js:~189] [pc=0x20deefba6433](this=0x36eef3246e99 <EventTargetImpl map = 0x36ee99264ee9>)
    2: _insert [0x36eeb41f1e41] [/Users/evhaus/Git/zenhub/client/node_modules/jest-environment-jsdom-fourte...

    0: ExitFrame [pc: 0x2aa5df5be3d]
Security context: 0x116a8d49e6e9 <JSObject>
    1: _clearMemoizedQueries [0x116a365133d1] [/Users/evhaus/Git/zenhub/client/node_modules/jest-environment-jsdom-fourteen/node_modules/jsdom/lib/jsdom/living/nodes/Node-impl.js:~208] [pc=0x2aa5dfe7dae](this=0x116a8f16cd11 <EventTargetImpl map = 0x116ae7cc9b61>)
    2: _clearMemoizedQueries [0x116a365133d1] [/Users/evhaus/Git/zenhub/client/node_modules/jest-...

FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
 1: 0x10003d041 node::Abort() [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 2: 0x10003d24b node::OnFatalError(char const*, char const*) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 3: 0x1001b8e25 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 4: 0x100586d82 v8::internal::Heap::FatalProcessOutOfMemory(char const*) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 5: 0x100589855 v8::internal::Heap::CheckIneffectiveMarkCompact(unsigned long, double) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 6: 0x1005856ff v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::GCCallbackFlags) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 7: 0x1005838d4 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 8: 0x10059016c v8::internal::Heap::AllocateRawWithLigthRetry(int, v8::internal::AllocationSpace, v8::internal::AllocationAlignment) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 9: 0x1005901ef v8::internal::Heap::AllocateRawWithRetryOrFail(int, v8::internal::AllocationSpace, v8::internal::AllocationAlignment) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
10: 0x10055fb34 v8::internal::Factory::NewFillerObject(int, bool, v8::internal::AllocationSpace) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
11: 0x1007e7e14 v8::internal::Runtime_AllocateInNewSpace(int, v8::internal::Object**, v8::internal::Isolate*) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
12: 0x20deef6dbe3d 
13: 0x20deefba6433 

    0: ExitFrame [pc: 0xb8909f5be3d]
Security context: 0x09e628d9e6e9 <JSObject>
    1: childrenIterator [0x9e612e1d581] [/Users/evhaus/Git/zenhub/client/node_modules/symbol-tree/lib/SymbolTree.js:~367] [pc=0xb890a41010e](this=0x09e612e3eb01 <SymbolTree map = 0x9e6a7f56c09>,parent=0x09e685ca27d1 <EventTargetImpl map = 0x9e6061f36f1>,options=0x09e67b6026f1 <undefined>)
    2: arguments adaptor frame: 1->2
    3: _detach [0x9e65c4ae341] [/U...

FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
 1: 0x10003d041 node::Abort() [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 2: 0x10003d24b node::OnFatalError(char const*, char const*) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 3: 0x1001b8e25 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 4: 0x100586d82 v8::internal::Heap::FatalProcessOutOfMemory(char const*) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 5: 0x100589855 v8::internal::Heap::CheckIneffectiveMarkCompact(unsigned long, double) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 6: 0x1005856ff v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::GCCallbackFlags) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 7: 0x1005838d4 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 8: 0x10059016c v8::internal::Heap::AllocateRawWithLigthRetry(int, v8::internal::AllocationSpace, v8::internal::AllocationAlignment) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 9: 0x1005901ef v8::internal::Heap::AllocateRawWithRetryOrFail(int, v8::internal::AllocationSpace, v8::internal::AllocationAlignment) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
10: 0x10055fb34 v8::internal::Factory::NewFillerObject(int, bool, v8::internal::AllocationSpace) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
11: 0x1007e7e14 v8::internal::Runtime_AllocateInNewSpace(int, v8::internal::Object**, v8::internal::Isolate*) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
12: 0x2aa5df5be3d 

    0: ExitFrame [pc: 0x180d6e95be3d]
Security context: 0x02052079e6e9 <JSObject>
    1: _modified [0x205b86c1861] [/Users/evhaus/Git/zenhub/client/node_modules/jest-environment-jsdom-fourteen/node_modules/jsdom/lib/jsdom/living/nodes/Node-impl.js:~189] [pc=0x180d6ede24fa](this=0x0205c8284411 <EventTargetImpl map = 0x205c1ea9769>)
    2: _attrModified [0x205b86ba771] [/Users/evhaus/Git/zenhub/client/node_modules/jest-environment-jsdom-fou...

FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
 1: 0x10003d041 node::Abort() [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 2: 0x10003d24b node::OnFatalError(char const*, char const*) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 3: 0x1001b8e25 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 4: 0x100586d82 v8::internal::Heap::FatalProcessOutOfMemory(char const*) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 5: 0x100589855 v8::internal::Heap::CheckIneffectiveMarkCompact(unsigned long, double) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 6: 0x1005856ff v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::GCCallbackFlags) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 7: 0x1005838d4 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 8: 0x10059016c v8::internal::Heap::AllocateRawWithLigthRetry(int, v8::internal::AllocationSpace, v8::internal::AllocationAlignment) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
 9: 0x1005901ef v8::internal::Heap::AllocateRawWithRetryOrFail(int, v8::internal::AllocationSpace, v8::internal::AllocationAlignment) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
10: 0x10055fb34 v8::internal::Factory::NewFillerObject(int, bool, v8::internal::AllocationSpace) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
11: 0x1007e7e14 v8::internal::Runtime_AllocateInNewSpace(int, v8::internal::Object**, v8::internal::Isolate*) [/Users/evhaus/.nvm/versions/node/v10.17.0/bin/node]
12: 0xb8909f5be3d 

Hope this helps

[rosasynstylae]

I don't know if this will help, but my organization had a massive slow down from Jest 24 to Jest 25 (18 minutes to 28 minutes) that went away after turning off coverage collection (down to 10 minutes).

[benmonro]

@rosasynstylae out of curiosity, does your code have a lot of snapshot tests?

[rosasynstylae]

@benmonro It does, yes.

[benmonro]

So does ours! @SimenB do you think lots of snapshots in a repo could cause this?

[joelpalmer]

We are having the performance issues with no snapshots. We are collecting coverage though. Significant slowdown from 24 -> 25. 2 different projects. It varies but the slowdown is significant and consistent.

I can run the tests over and over with no changes and the tests are 10 times slower on average then they were with 24.

I switch back to 24 and the runs are back to the speed we were used to.

I can provide more info if needed. I wanted to make sure to mention our 2 projects with no snapshot tests.

[milesj]

From all the comments here, it definitely sounds like coverage is the problem, and probably a regression in istanbul?

[EvHaus]

From all the comments here, it definitely sounds like coverage is the problem, and probably a regression in istanbul?

I wouldn't be so fast to point the finger at istanbul. In my case, even with coverage disabled, I'm seeing significant performance and stability issues in Jest 25. See https://github.com/facebook/jest/issues/9457#issuecomment-579423330

It's possible there are two separate issues:

1. Issues with jest-environment-jsdom-fourteen, and
2. Issues with istanbul coverage

[csvan]

I downgraded micromatch to ^3.0.0 and saw a massive speedup using --coverage, more or less back to the performance we saw under Jest 24. Can anybody reproduce?

UPDATE: However, now running without --coverage is also back to Jest 24 levels of performance - twice as slow :-/