Background
Over here at Infogrid we make extensive use of Jest for our unit testing. One of the typical things that happens with unit tests, is the number of them increase, it's vary rare that the volume of unit tests decreases. Which means when you start hitting performance issues with these tests, you know that the problem is only going to get worse!
This is exactly where we were. In fact the degradation in performance was so bad that:
- Developers were rarely running tests locally
- Developers who did try to run all the tests locally would usually freeze their machine
- The speed on CI was not much better, but given the over-reliance on CI could leave you waiting for test feedback.
This post gives a summary of the investigation that I did at Infogrid, and the actions taken to resolve them.
Firstly, lets took at some metrics. Here is a chart showing our total execution time more than doubling over a 6 month period on our CI runner.
Due to the fact that developers were relying on this for their test runs, this essentially created a really slow feedback loop, one which we weren't happy with, so I did to set off and fix it.
It's worth noting, that when we started this discovery process we were on Jest v27.
Investigating the performance
There were multiple parts of investigating and fixing the slow downs that we discovered. I'll try to break these up as we discovered and dug deeper. Essentially they break down into 3 main sections, but I won't reveal them here so not to spoil the article.
Test Execution Time vs Total Process Time
The first thing I investigated was the fact that there seemed to be a large disparity between the time to run a test, and the actual time that the process itself takes. For example example if we take a look at one of our files we can see:
- Total time running tests: 112ms
- Total process time: 16.8s
❯ yarn test:nocoverage --watchAll=false src/components/material-ui/SearchFilterInput/SearchFilterInput.test.tsx
yarn run v1.22.10
$ craco test --watchAll=false src/components/material-ui/SearchFilterInput/SearchFilterInput.test.tsx
PASS src/components/material-ui/SearchFilterInput/SearchFilterInput.test.tsx (14.213 s)
SearchFilterInput
✓ renders correctly (112 ms)Test Suites: 1 passed, 1 total
Tests: 1 passed, 1 total
Snapshots: 0 total
Time: 14.788 s
Ran all test suites matching /src/components/material-ui/SearchFilterInput/SearchFilterInput.test.tsx/i.
Done in 16.80s.
That gives about 16.6s of the time processing time isn't actually running the tests. In fact the time actually running tests is less than 1% of the total time. In fact some files took over 90s to run... which is suboptimal.
What this points at is obviously the tests themselves are not slow. Instead something about Jest is slow. I spent some time profiling Jest using the --inspect-brk flag and I considered if TypeScript compilation could be the cause. In the end I stumbled across the issue in the next section, relating to imports.
Number of imports slowing Jest down
During some lightweight evening reading I came across this GitHub issue https://github.com/jestjs/jest/issues/11234 which details that "barrel" files potentially slow down Jest. This was really interesting as we had a large number of imports in some our files, which could also affect Jest in the same way as a barrel import.
What is a Barrel file?
It’s common practise when writing flavours of JavaScript to have a directory structure with an index.js file within it.
The barrel file usually re-exports things. So could have contents like:
export * from "./TimeBlock";
export * from "./constants"; // Not actually present in example image above
The reason for this is it makes imports a lot cleaner. It allows you to replace:
import { TimeBlock } from "./TimeBlock/TimeBlock";
import { constants } from "./TimeBlock/constants";
with:
import { TimeBlock, constants } from "./TimeBlock";
Testing whether Barrel Imports were impact us
To test the theory about imports, I created a new file called Foo.test.tsx and used the command:
yarn test:nocoverage --clearCache && yarn test:nocoverage --watchAll=false src/foo.test.tsx
This ensures that the jest cache is cleared before starting to make a fair test, and runs the tests for just that single file.
Baseline
Starting with a test that have no dependencies on any other file:
describe('Foo', () => {
it('should render correctly', () => {
expect(true).toBe(true);
});
});
PASS src/foo.test.tsx
Foo
✓ should render correctly (3 ms)Test Suites: 1 passed, 1 total
Tests: 1 passed, 1 total
Snapshots: 0 total
Time: 1.276 s
Ran all test suites matching /src/foo.test.tsx/i.
Done in 8.03s.
The time for the test itself was just 3ms. The overall process time took 8s which while not amazing, at least gives us a baseline for testing.
A React Component Test
Given our baseline, now let’s add in a React component and do a more typical test which obviously now has some dependencies. To start with we’re going to use the @testing-library/react directly.
import '@testing-library/jest-dom/extend-expect';
import { render, screen } from '@testing-library/react';
describe('Foo', () => {
it('should render correctly', () => {
render(<p>Time period</p>);
expect(screen.getByText('Time period')).toBeInTheDocument();
});
});
> PASS src/foo.test.tsx
> Foo
> ✓ should render correctly (3 ms)
>
> Test Suites: 1 passed, 1 total
> Tests: 1 passed, 1 total
> Snapshots: 0 total
> Time: 1.416 s
> Ran all test suites matching /src/foo.test.tsx/i.
> Done in 8.70s.
So the time for the test itself is still just 3ms. We’ve had a marginal increase to 8.7, so 0.7s to include the additional testing library.
A Typical Infogrid Test
So we use various test helpers that we include, so we don’t typically import the testing library like that. So instead with an ever so slight modification to the import we can re-test what a normal Infogrid test looks like.
import '@testing-library/jest-dom/extend-expect';
import { render, screen } from 'testUtils';
describe('Foo', () => {
it('should render correctly', () => {
render(<p>Time period</p>);
expect(screen.getByText('Time period')).toBeInTheDocument();
});
});
PASS src/foo.test.tsx (69.894 s)
Foo
✓ should render correctly (52 ms)Test Suites: 1 passed, 1 total
Tests: 1 passed, 1 total
Snapshots: 0 total
Time: 70.733 s
Ran all test suites matching /src/foo.test.tsx/i.
Done in 81.55s.
So the test itself is a bit slower adding 52ms, but in the grand scheme of things we need not worry about that. We have however added a whopping 72.85s onto the test time, by changing just a single import statement.
Digging into testUtils.js
So if we take a look at the testUtils.js file, the first thing that jumps out is the 20 or so lines of imports. Some of these imports are from big libraries
import { MuiThemeProvider } from '@material-ui/core/styles';
import { render as rtlRender } from '@testing-library/react';
import { createMemoryHistory } from 'history';
import isObject from 'lodash/isObject';
import PropTypes from 'prop-types';
import { HelmetProvider } from 'react-helmet-async';
import { QueryClientProvider } from 'react-query';
import { Provider } from 'react-redux';
import { Router } from 'react-router-dom';
import { createStore } from 'redux';
import 'configuration/routes';
import { queryClient } from 'apiHooks/queryClient';
import rootReducer from 'configuration/reducers';
import { theme } from 'containers/AppContainer/theme';
import 'react-dates/initialize';
Unfortunately this problem is exasperated by our code/components too. Most files have a significant number of imports, easily ranging from 15-35 individual imports. Here’s an example of a particularly bad file:
import { differenceInDays } from 'date-fns';
import { Trans, useTranslation } from 'react-i18next';
import type { RouteConfigComponentProps } from 'react-router-config';
import { SUPPORT_EMAIL } from 'constants/contacts';
import { ORGANIZATION_FEATURE_FLAG } from 'utils/featureFlags';
import { useOrganizationFeature } from 'utils/hooks/user';
import { SENSOR_TYPE } from 'utils/types/ts/sensorConstants';
import { SOLUTIONS } from 'utils/types/ts/solutions';
import type { ViewSelectors } from 'views/solutions/components/DataContainer/DataContainer';
import DataSourceBlock from 'views/solutions/components/DataSourceBlock';
import { InsightsTabs } from 'views/solutions/components/Insights';
import SolutionPageError from 'views/solutions/components/SolutionPageError';
import TimePresetPicker from 'views/solutions/components/TimePresetPicker';
import {
useTimeFilters,
useLocationFilters,
DATA_CONTAINER_BLOCK_VIEW,
} from 'views/solutions/hooks';
import PageLayout from '../../components/PageLayout';
import {
userSolutionPageAvailability,
userSolutionAvailability,
} from '../../decorators/permission';
import LiveData from './components/LiveData';
import AnalysisTab from './components/blocks/Analysis';
import DataTab from './components/blocks/Data';
import DayTimeBlock from './components/blocks/DayTimeBlock';
import MeetingRoomPersonCountBlock from './components/blocks/MeetingRoomPersonCountBlock';
import MostOccupiedBlock from './components/blocks/MostOccupiedBlock';
import OccupancyOverTime from './components/blocks/OccupancyOverTime';
import UsageOverTimeBlock from './components/blocks/UsageOverTimeBlock';
import { MOSV_TOOLTIP, OSV_TOOLTIP } from './constants';
import { useOccupancyPageStyles } from './styles';
Fix #1
So our first fix, was to stop using our testUtils.tsx file. Instead of importing all those dependencies, and setting up multiple React <ContextProvider> instances for each 3rd party library we used, we instead did that only within the tests that actually required them.
This does add some more duplication (we created some Higher Order Components to make this easier), but it makes for a huge time saving so it was well worth doing the bare minimum required for the test.
Memory Leaks
The next thing I discovered while profiling, is I was getting vastly different times for tests. Check out this output:
@infogrid/solution-views-components:test: PASS src/SolutionInsights/SolutionInsights.test.tsx (331.823 s)
@infogrid/solution-views-components:test: PASS src/Insights/Card/LocationsModal/LocationsModal.test.tsx (459.442 s)
@infogrid/solution-views-components:test: PASS src/DataContainer/DataContainer.test.tsx (460.168 s)
@infogrid/solution-views-components:test: PASS src/Header/Header.test.tsx (283.344 s)
@infogrid/solution-views-components:test: PASS src/SolutionInsights/SolutionInsightsItem/SolutionInsightsItem.test.tsx (461.045 s)
main:test: PASS src/views/dashboards/widgets/HealthyBuildingScoreWidget/Content/CompareModal/CompareModal.test.tsx (25.719 s)
Here we have a bunch of really, really slow tests. Picking out DataContainer.test.tsx as an example, we saw it took 460s just for that 1 test file to complete.
If however we go and run just that single test, it paints a very different story:
packages/solution-views/components on master [$] via v16.14.0 took 7s
❯ time pnpm test src/DataContainer/DataContainer.test.tsx@infogrid/solution-views-components@0.1.0 test /home/ian/src/webclient/packages/solution-views/components
jest --passWithNoTests "src/DataContainer/DataContainer.test.tsx"PASS src/DataContainer/DataContainer.test.tsx
DataContainer
✓ should render correctly (70 ms)
✓ should render the data in chart form when chart is selected (19 ms)
✓ should render the data in table form when table is selected (14 ms)Test Suites: 1 passed, 1 total
Tests: 3 passed, 3 total
Snapshots: 0 total
Time: 4.966 s, estimated 461 s
Ran all test suites matching > /src\/DataContainer\/DataContainer.test.tsx/i.real 0m6.120s
user 0m6.336s
sys 0m0.436s
We can see here that the same test file, took less than 5s to complete. This suggests that Jest itself isn't the problem, and it's something more to do with the system. Looking at anecdotal evidence is that Jest significantly slows down when it starts running out of system resources. The above were all run on a 12 Core (Intel® Core™ i7-10750H CPU @ 2.60GHz × 12), 32GB RAM machine with a 20GB swap file.
Some screenshots of the system monitor are interesting. Running all the tests starts off being CPU throttled (all cores maxed out).
However once all of the memory has also been used up we start hitting the swap file. At this point we become disk IO throttled and the CPU’s are no longer maxed out.
Once the swap file nears capacity the system starts to become unstable and tests durations really start to increase. Applications start to freeze and the machine is unusable until Jest completes.
Checking for memory leaks
Why does the memory usage increase like this? I tried running a memory trace against node. It showed an ever increasing heap size as tests run (between 200-500MB per test file) which suggests a potential memory leak. The next step was to determine if this was our tests, or whether it was Jest.
❯ node --expose-gc ./node_modules/@craco/craco/bin/craco.js test --runInBand --logHeapUsage --watchAll=false
PASS src/components/sensors/ConnectedCloudConnectors/ConnectedCloudConnectors.test.jsx (21.778 s, 351 MB heap size)
PASS src/views/solutions/pages/smartCleaning/components/DeskAndSpaceCleaning/DeskAndSpaceCleaning.test.tsx (5.12 s, 500 MB heap size)
PASS src/views/sensors/SensorsList/SensorsList.test.js (7.367 s, 602 MB heap size)
PASS src/views/dashboards/widgets/IndoorAirQualityWidget/IndoorAirQualityWidget.test.tsx (851 MB heap size)
PASS src/components/material-ui/sensorPicker/SensorPicker/SensorPicker.test.tsx (22.616 s, 1394 MB heap size)
Again GitHub issues to the rescue. I came across https://github.com/jestjs/jest/issues/11956 which indicated an issue in Node 16.11.0+ and the way Jest works. Sure enough, running a sample showed a significant increase in heap memory usage using Node 16.14.0 (which is what we were on at the time).
Fix #2
The fix in this case, firstly was to pin everything at Node 16.10.0 which solved the immediate pain point. Then we got to work upgrading Jest to v29. Once we had completed this migration we switched to the latest Node and applied a 2GB limit using https://jestjs.io/docs/configuration/#workeridlememorylimit-numberstring.
TypeScript compilation
The final step in the puzzle was TypeScript. I didn't think this was an issue at the start, but it turned out that Jest implements a build caching layer that made me draw some incorrect conclusions. When you keep on running the same tests over and over for benchmarking purposes, this messes with your data and doesn't reflect reality, In day to day usage Jest would likely need to rebuild the code fairly frequently.
So instead I started running my tests, but clearing the jest cache between runs. Here's a chart showing the comparison using ts-jest as our runner. If the cache was cold it took 20x as long to run our tests for a single package in our monorepo (about 100 tests). That's almost 10 minutes just running a build, which is painful.
Fix #3
By this point we'd already introduced some other tools to optimise our build process (topic for another post!) to essentially reduce the number of unit tests we were running. But when they did need running, if a build had to happen it was still too slow.
So instead we looked at alternative tools to ts-jest. The TypeScript compiler is known to be slow, however there are efforts such as SWC and ESBuild out there trying to address that. Fortunately there are also jest runners that makes use of these different build tools!
Above is the same set of tests being run across all the tools both with and without the Jest cache. As you can see both SWC and ESBuild are about the same when they hit the cache (actually slightly slower than ts-jest), but much faster when they miss the cache.
So the final fix we introduced was to switch over to @swc/jest for every one of our packages, significantly reducing the cold-start runtimes overall.
It's worth noting if you go down this route, that jest mocking behaves a bit differently We ended up needing to include a package called
jest_workaroundand setting our jest config up like so to save us updating all our mockstransform: { '^.+\\.[tj]sx?$': [ '@swc/jest', { jsc: { experimental: { plugins: [['jest_workaround', {}]], }, }, }, ], },
Top comments (0)