Jest is leaking memory even on a simple default redwood app

[zygopleural]

Expected behaviour

yarn redwood test should use ~ same heap size for each test unless the user has specifically done something wrong.

i.e. the heap size should not spiral out of control just by creating more tests

What currently happens

The heap size spirals out of control by creating more tests

Steps to reproduce

1. Create new app

yarn create redwood-app --typescript test

2. Add some models to ./api/db/schema.prisma

Excuse the silly models, just something quick to generate tests.

model Man {
  id   String @id @default(cuid())
  name String
}

model Woman {
  id   String @id @default(cuid())
  name String
}

model Boy {
  id   String @id @default(cuid())
  name String
}

model Girl {
  id   String @id @default(cuid())
  name String
}

model Dog {
  id   String @id @default(cuid())
  name String
}

model Cat {
  id   String @id @default(cuid())
  name String
}

3. Generate some tests

yarn redwood generate sdl --crud man
yarn redwood generate sdl --crud woman
yarn redwood generate sdl --crud boy
yarn redwood generate sdl --crud girl
yarn redwood generate sdl --crud dog
yarn redwood generate sdl --crud cat

4. Run tests

yarn redwood test --logHeapUsage

5. Checkout heap spiral

[callingmedic911]

If possible, can you try pinning the Node.js version to 16.10?

There seems to be a memory usage issue with Jest on the Node version higher than 16.10. More details here: jestjs/jest#11956

[zygopleural]

@callingmedic911 don't see any difference, in fact it is arguably worse:

[zygopleural]

Much the same with v16.9.1

[jmackie]

Same issue for me, Node version v16.11.1

[thedavidprice]

Hi all! Some updates here based on my evaluation of #4024, which will be included in the imminent release. (Full related comment here.)

Here's the relevant results of a simple performance test comparing v0.41 (latest) with recent canary (next).

Note: the PR itself address 95% changes to Web Jest config. But there are command considerations we have to handle when running both Web and API at once vs each individually. So the results below are promising:

1. we made major peformance gains for web
2. which also have positive effect on api when run together

Performance Results

I used my standard https://github.com/thedavidprice/redwood-tutorial-test repo.

v0.41.0

https://s.tape.sh/ORsePaAK

1. rw test
   • 27.22 sec
   • 1996 MB final heap
2. rw test web
   • 18.98 sec
   • 1412 MB final heap
3. rw test api
   • 8.45 sec
   • 717 MB final heap

v0.41.1-canary.162 (latest)

https://s.tape.sh/99YpX63l

1. rw test
   • 20.35 sec
   • 570 MB final heap
2. rw test web
   • 9.46 sec
   • 399 MB final heap
3. rw test api
   • 9.51 sec
   • 766 MB final heap

We see both time and heap improvements for Web tests, as intended with this PR! Even more important (and unexpected) is that we see a massive improvement to heap when running both via rw test, especially given that there are negligible changes when running rw test api alone.

[zygopleural]

FYI @thedavidprice I noticed that v0.42.0 went out, so quickly updated with yarn rw upgrade to try out your suggestion.

Something's broke, but don't have time to investigate right this second:
(same command yarn redwood test --logHeapUsage)

[thedavidprice]

Thanks @zygopleural That should have been a seemless update. Appreciate you reporting this.

• question: how did you upgrade?

Looping in @dac09 @callingmedic911 Any thoughts about next steps here to diagnose? Possible it's related to #4024?

[dac09]

Hey folks, can you confirm you weren't seeing this prior to 0.42? We diagnosed this heap usage issue present in all the previous versions, and from our tests .42 seemed to improve it. The issue seems to be related to jest and node, so I'd be surprised if this is a new one.

Any details of the errors would be appreciated, can't really diagnose from the screen shot ✌🏽

@callingmedic911 and I have definitely seen usage drop switching to node 16.10 (as recommended in the issue in jests repo)

[callingmedic911]

Looping in @dac09 @callingmedic911 Any thoughts about the next steps here to diagnose? Possible it's related to #4024?

It's a SIGKILL, can't say for sure if it's related. I can't seem to replicate the error with the repro listed (first post). @zygopleural Is this from the same project? If we can get a reproduction that would be ideal.

[zygopleural]

@zygopleural Is this from the same project? If we can get a reproduction that would be ideal.

Yeah it is the same project as I used last time, just updated with yarn rw upgrade.

I'll try with a fresh repo tomorrow morning 👍🏼

[thedavidprice]

We haven't been able to reproduce this on our end @zygopleural Any updates on your end?

[zygopleural]

yarn redwood test --logHeapUsage

$ /Users/lee/Code/sandbox/something/node_modules/.bin/jest --logHeapUsage true --passWithNoTests --config /Users/lee/Code/sandbox/something/node_modules/@redwoodjs/testing/config/jest/jest.config.js --projects web api
 PASS   api  api/src/services/women/women.test.ts (266 MB heap size)
 PASS   api  api/src/services/men/men.test.ts (379 MB heap size)
 PASS   api  api/src/services/girls/girls.test.ts (490 MB heap size)
 PASS   api  api/src/services/boys/boys.test.ts (602 MB heap size)
 PASS   api  api/src/services/dogs/dogs.test.ts (714 MB heap size)
 PASS   api  api/src/services/cats/cats.test.ts (421 MB heap size)
 PASS   api  api/src/directives/requireAuth/requireAuth.test.ts (526 MB heap size)
 PASS   api  api/src/directives/skipAuth/skipAuth.test.ts (641 MB heap size)

Test Suites: 8 passed, 8 total
Tests:       33 passed, 33 total
Snapshots:   0 total
Time:        5.503 s
Ran all test suites.
✨  Done in 11.31s.
❯ yarn redwood info
yarn run v1.22.17
$ /Users/lee/Code/sandbox/something/node_modules/.bin/redwood info

  System:
    OS: macOS 11.5.2
    Shell: 5.8 - /bin/zsh
  Binaries:
    Node: 14.18.1 - /var/folders/42/lwp4lm_5415fc4jjqbldypmr0000gn/T/yarn--1642794025352-0.6315454678746926/node
    Yarn: 1.22.17 - /var/folders/42/lwp4lm_5415fc4jjqbldypmr0000gn/T/yarn--1642794025352-0.6315454678746926/yarn
  Databases:
    SQLite: 3.32.3 - /usr/bin/sqlite3
  Browsers:
    Chrome: 97.0.4692.99
    Safari: 14.1.2
  npmPackages:
    @redwoodjs/core: 0.42.0 => 0.42.0

✨  Done in 1.44s.

I mean it is somewhat better

[thedavidprice]

@zygopleural Great to see v0.42 working! Those results are not unexpected as the improvements were specific to Web testing.

What I found curious about my tests is how the API heap seemed to stabalize when run with the existing Web tests. Referring specifically to this result:

rw test
20.35 sec
570 MB final heap

From this comment above.

Still work to do here. Just pulling threads and appreciate your help doing so.

[zygopleural]

@thedavidprice I just tried out with a new project (v0.42.1). This time I created some web tests via:

yarn redwood generate component man
yarn redwood generate component woman
yarn redwood generate component boy
yarn redwood generate component girl
yarn redwood generate component dog
yarn redwood generate component cat

This is the output from running tests:

❯ NODE_NO_WARNINGS=1 yarn redwood test --logHeapUsage --no-watch
yarn run v1.22.17
$ /Users/lee/Code/sandbox/test/node_modules/.bin/redwood test --logHeapUsage --no-watch
$ /Users/lee/Code/sandbox/test/node_modules/.bin/rw prisma db push --force-reset --accept-data-loss

Running Prisma CLI...
$ yarn prisma db push --force-reset --accept-data-loss --schema "/Users/lee/Code/sandbox/test/api/db/schema.prisma"

Environment variables loaded from .env
Prisma schema loaded from api/db/schema.prisma
Datasource "db": SQLite database "test.db" at "file:/Users/lee/Code/sandbox/test/.redwood/test.db"

The SQLite database "test.db" from "file:/Users/lee/Code/sandbox/test/.redwood/test.db" was successfully reset.

🚀  Your database is now in sync with your schema. Done in 3ms

✔ Generated Prisma Client (3.8.1 | library) to ./node_modules/@prisma/client in 47ms

$ /Users/lee/Code/sandbox/test/node_modules/.bin/jest --logHeapUsage true --passWithNoTests --config /Users/lee/Code/sandbox/test/node_modules/@redwoodjs/testing/config/jest/jest.config.js --projects web api
 PASS   web  web/src/components/Man/Man.test.tsx (7.436 s, 389 MB heap size)
 PASS   web  web/src/components/Woman/Woman.test.tsx (7.513 s, 389 MB heap size)
 PASS   web  web/src/components/Boy/Boy.test.tsx (7.579 s, 382 MB heap size)
 PASS   web  web/src/components/Girl/Girl.test.tsx (7.635 s, 383 MB heap size)
 PASS   web  web/src/components/Cat/Cat.test.tsx (7.683 s, 377 MB heap size)
 PASS   web  web/src/components/Dog/Dog.test.tsx (7.691 s, 378 MB heap size)
 PASS   api  api/src/services/women/women.test.ts (309 MB heap size)
 PASS   api  api/src/services/boys/boys.test.ts (375 MB heap size)
 PASS   api  api/src/services/dogs/dogs.test.ts (539 MB heap size)
 PASS   api  api/src/services/girls/girls.test.ts (709 MB heap size)
 PASS   api  api/src/services/cats/cats.test.ts (620 MB heap size)
 PASS   api  api/src/services/men/men.test.ts (783 MB heap size)
 PASS   api  api/src/directives/requireAuth/requireAuth.test.ts (949 MB heap size)
 PASS   api  api/src/directives/skipAuth/skipAuth.test.ts (1112 MB heap size)

Test Suites: 14 passed, 14 total
Tests:       39 passed, 39 total
Snapshots:   0 total
Time:        18.098 s
Ran all test suites in 2 projects.
✨  Done in 24.00s.
❯ yarn redwood info
yarn run v1.22.17
$ /Users/lee/Code/sandbox/test/node_modules/.bin/redwood info
(node:17885) ExperimentalWarning: stream/web is an experimental feature. This feature could change at any time
(Use `node --trace-warnings ...` to show where the warning was created)

  System:
    OS: macOS 11.5.2
    Shell: 5.8 - /bin/zsh
  Binaries:
    Node: 16.13.2 - /var/folders/42/lwp4lm_5415fc4jjqbldypmr0000gn/T/yarn--1642864210051-0.18646776545157917/node
    Yarn: 1.22.17 - /var/folders/42/lwp4lm_5415fc4jjqbldypmr0000gn/T/yarn--1642864210051-0.18646776545157917/yarn
  Databases:
    SQLite: 3.32.3 - /usr/bin/sqlite3
  Browsers:
    Chrome: 97.0.4692.99
    Safari: 14.1.2
  npmPackages:
    @redwoodjs/core: 0.42.1 => 0.42.1

✨  Done in 1.59s.

Notice that the web tests are indeed fairly quick and the heap is consistent.

It seems the problem is stemming from the API tests as the heap is still spiralling out of control.

[dac09]

Heyoo... I've been trying to find a way to fix this, and I've made a little progress in #4096.

There is still an open issue on Jest's repo that is related: jestjs/jest#12142

While the changes I'm making should reduce memory usage about 50%, I'm hopeful that the jest team will have a solution for this too on their side.

Couple other things to note if you want to eek out a little bit more memory,

a) you can also run jest/rw test with the --no-cache flag, which seems to help.
b) we can also force a garbage collection at the node level by doing
i) Running jest like this: node --expose-gc ../node_modules/.bin/jest
ii) In the afterEach function in jest.setup calling
if (global.gc) { global.gc() }
I'm hesitant to have (b) merged into redwood, because I'm not sure of the implications, but putting it here if its helpful.

[thedavidprice]

Update

Based on @dac09 fantastic work in #4096 there's now performance improvements on both Web and API sides.

To be clear, we aren't saying API leak is resolved. But the heap seems to be reduced by about 50%.

Here's a comparison using my test project.

Before: using latest version

https://s.tape.sh/56vy6UpM

After: using code from #4096

https://s.tape.sh/sfu51d1b

[thedavidprice]

Update

Given that there's been progress on this (in the coming v0.44) but not complete resolution, I am moving this topic to a new Issue with updated benchmarks and a reproduction repo:

• rw test api Jest memory performance and benchmarks; api test leaking #4360

Closing this out. Look for v0.44 release comming asap