As a meticulous developer, I use Test Driven Development (TDD) which involves doing a lot of unit and integration testing (around 40 times a day per dev). Now close your eyes and imagine if you have to wait several minutes to run tests, even a small amount of them, 40 times a day. It seems like a nightmare, and trust me it is. It generates a lot of frustration and also a lot of time wasting, you could use this time to actually code or read documentation or even improve your knitting skills.
I was working on a project, a NestJs application that does API calls to external services. After 2 months, we had approximately 50 unit tests on this API that we ran regularly using jest. It takes up to 1mn (!) to run locally. It is huge and it wasted a lot of my time, causing me a lot of frustration.
We started calculating exactly how much time we were losing per day/month and we ended up with this graph:
Duration tu run all the testsTherefore, in my project, launching the tests took approximately 45s in average on my machine. Each member of my team runs around 30 times a day the command yarn test. Therefore, we were loosing 25 min per day (and per dev) just watching the terminal launching test (8h per month), and it was only 50 tests. How long would it takes with 100? And 2000?
With these figures, we decided to take a whole day to study why the testing was taking so long and how we could fix it. The target was to reach 25s maximum per test.
How does jest works
Steps when jest is running
Let’s dive in our yarn test command:
// package.json
"scripts": {
...
"test": ". ./.env.test.rc && jest",
"test:types": "tsc",
"test:watch": "yarn test --watch",
...
}
So two commands are ran when we execute yarn test in our terminal:
- . ./.env.test.rc which is basically source ./.env.test.rc, it sets all the variable environments for the test
- jest
The second one is more interesting. What happens when we run the command jest ? We tried to sum it up on this schema:
The potential problematic steps are highlighted with a red crossBasically we can summarize it in 4 big steps:
- The initialization of jest: It loads the configuration, loads the cache, …
- The compilation of typescript: All the workers select files and compile typescript into javascript
- Running the test: The tests are ran in parallel in all workers
- Print results: It prints the results in the terminal
How to analyse the repartition of time jest testing
In order to analyse the repartition of time between these four steps, we generated a “Flame Graph” using Chrome DevTool profiler. This type of graph allows to see (in one graph) the number of functions called during time and also which and function are called and when.
In order to generate this graph, type in your terminal in the root folder of your project:
$ node --inspect-brk ./node_modules/jest/bin/jest.js
// Debugger listening on ws://127.0.0.1:9229/59cbc8c7-290f-41bc-89fb-f77fde7b2c24
// For help, see: https://nodejs.org/en/docs/inspector
// Debugger attached.
Then:
- Open the Chrome and go to chrome://inspect
- Click Open dedicated DevTools for Node
- Under the tab Profiler click start to begin the acquisition
- Click stop when your task is done
- Finally just under the Profiler tab, select chart in the dropdown
Eventually, at the end we obtained this graph:
Looking at the graph, we immediately spotted two time-consuming steps: the build of workers and the test patient.e2e.spec.ts. Let’s dig in these and understand why it took so long.
How we speeded up jest testing
The idle times
There are three idles time of five seconds each. During this time, jest is literally doing nothing and just waiting for something. After a short inspection in this test, we realised that this matches 3 of our tests. These tests check that after a timeout of 5s of an external API call it returns an error. The test looked like this:
it("should return a 504 when the WebService does not respond after 5s", async () => {
// The call to webservice is mocked inducing a response after 5s
mockService.mockTimedOutCall(/patient.*/, 200, EMPTY_OUTPUT, 5 * 1000);
// The webservice is called and we check that we receive a 504
const response = await request(app.getHttpServer())
.post("/v2/Patient/$lookup")
.send({last_name: "Bruce",first_name: "Wayne"})
.expect(504);
// Then we check that the message received is the right one
expect(response.body).toEqual(
expect.objectContaining({
error: {message: "WebService timed out after 5s"},
})
);
});
So we needed to mock a timeout of 5s of this web service, and to simulate a timeout response of 5s, we mocked our API call like this:
mockTimedOutCall(
url: RegExp,
code: number,
response: WebServiceOutput,
time: number
): Scope {
return this.nock.get(url).delayConnection(time).reply(code, response);
}
delayConnection introduce a REAL timeout, the response is returned 5s after it’s made, during those 5s the connection is idle. If you are interested, you can find more information about delayConnection here.
Therefore, when we ran these tests, it was literally waiting 5s until axios returned timeout error. This explains the idle time we noticed on the Flame Graph.
So, our idea was to use a jest.faketimer() in order to simulate the 5s waiting. The documentation of faketimer is available here.
mockGetCall(
url: RegExp,
code: number,
response: WebServiceOutput,
): Scope {
return this.nock.get(url).reply(code, response);
}
mockTimedOutCall(
url: RegExp,
code: number,
response: WebServiceOutput,
time: number
): Scope {
return this.mockGetCall(url, code, response).prependOnceListener(
"request",
() => {
// we catch the request and advance timer
jest.advanceTimersByTime(time);
}
);
}
it("should return a 504 when the WebService does not respond after 5s", async () => {
jest.useFakeTimers("legacy"); // make sure you use legacy version
mockTimedOutCall(
/patient.*/,
200,
EMPTY_RGDS_OUTPUT,
MAXIMAL_DURATION_QUERY
);
const response = await request(app.getHttpServer())
.post("/v2/Patient/$lookup")
.send({last_name: "Bruce",first_name: "Wayne"})
.expect(504);
jest.useRealTimers(); // don't forget to cancel fakeTimer 🤠
}
Jest compilation of typescript
Faster with —runInBand 🤨 ?
As we saw previously, in order to generate the flame graphs, we had to use jest with the command —runInBand. This parameter makes jest run the tests one after the other, there is no parallelisation anymore. Usually, parallelisation allows to speed up considerably the testing, but it was not the case for us.
Indeed, we were dividing by two our total duration of testing when using —runInBand which was totally illogical. Since —runInBand is not scalable at all (imagine if you have 50 tests to run one after the other) we decided to dig in and find how optimise the compilation of typescript made by jest.
How jest compiles typescript
There seems to be a known issue when using multiple Jest workers, where each of these workers do not share the same cache storage : https://github.com/kulshekhar/ts-jest/issues/259. This issue leads the ts-jest transformer to always compile the input test files, which slows down the test process by compiling all the test files in parallel instead of reusing compiled artifacts from a previous run.
The isolatedModules option is documented in TypeScript option docs. When enabled, it evaluates only types from the input test file instead of resolving the dependencies, speeding up the compilation processes. ts-jest then compiles these files with the transpileModule method.
// package.json
"jest": {
"globals": {
"ts-jest": {
"isolatedModules": true
}
},
.........
⚠️ Since jest just checks the typing of input files instead of dependencies, we did not have a type check in local for our application anymore.
We decided to move type checking in our pre-commit checks. We make approximately 8 commits a day and the typing check last 8s. Therefore, we loose “only” 1min per day:
// .husky/pre-commit
yarn test:type
yarn lint-staged
yarn test:architecture
Presentation of results
After this easy implementation, we were able to measure again the time spent to run all the tests and the result is quite impressive. Indeed, we divided by ten the duration of tests, we passed from 40s to 4s (see graphic below):
We decided to stop here because we had exceeded by far our target, but it’s great to see that with only one day of work and analysis on our code, we were able to have such an impact on our daily performances. That’s the main point I wanted to pass in this article. There are 5% of chances that you test timeouts without knowing jest.fakeTimers() but there are 100% of chances that you could improve drastically your project by spending a whole day on improving one specific metrics.
At Hokla, the quality is the heart of our work, and we make this kind of self-improvement days often, we call it Kaizen (it is a japanese word meaning "changing for the best") Kaizen is not just a powerful and efficient way to improve one performance of your project, it also allows to improve the developers that work on it. Indeed, it’s a great excuse to learn and study tools that we use everyday.
If you have any ideas on how you could improve your project, let me know by mail, linkedin or on my twitter 😉
.jpg)