CIのボトルネックを特定してJestの実行時間をチョット速くした話

この記事は「レバテック開発部 Advent Calendar 2024」の 21 日目の記事です！
昨日の記事は、ばば さんの「開発チームのバックエンド、フロントエンド担当を入れ替えてみた」でした！

はじめに

こんにちは、7月末からレバテックにJoinしました、大内です。
不慣れなことも多いですが、周りからいろんな刺激をもらいながら日々楽しく開発してます！

参加しているプロダクトのGitHub Actions（以下GHA）で、結合テストの実行速度が遅くなっていて、バックエンドの改修をデプロイするスピードに影響がでそうな状態だったので、あまり時間をかけずにチョットだけ速度改善する応急対応を行った時の話をします！

使用した技術スタック

• TypeScript
• NestJS with TypeORM
• Jest

最初に結論

大体実行時間が半分くらいになりました！

速度改善 実施前

速度改善 実施後

現状分析と課題把握

課題は実行時間

実際にどのくらい遅くなっているかを確認するために、結合テストのJobの実行時間を確認したところ、14〜16分ほど実行にかかっていることがわかりました。

また、その内訳として、結合テスト自体の実行には13〜14分ほどかかっていることがわかりました。

どのくらい遅いかが把握できたので、どこがボトルネックになっているかを特定するために、まずはJestの実行オプションや処理を追えるようにJestの仕様などをキャッチアップし、その後情報を元にボトルネックを特定しました。

Jestを把握 & ボトルネック特定

直列処理

実行コマンドを確認したところ、

jest --runInBand --coverage

となっていました。--runInBandはworkerを1つにして直列で処理するというオプションのため、1つのテストファイルの実行が終わったら、次のテストファイルを実行するという形になっています。

セットアップ

Jestは、テスト実行前にいくつかセットアップをするタイミングを設けています。
具体的には、

• globalSetup
  全てのテストスイートの実行前に1度だけ実行される
• setUpFiles
  各テストファイルごとに実行される
  ただしJestのインストール前に実行されるため、Jestのグローバル関数などは使用できない
• setUpFilesAfterEnv
  各テストファイルごとに実行される
  Jestのインストール後に実行されるため、Jestのグローバル関数が使用できる

という3つのフェーズがあります。

私たちのプロダクトのJestの設定ファイルにも、setupFilesAfterEnvに定義されているセットアップファイルが存在しました。その内容を確認します。

tests/integration/setup.js

import ormconfigA from '../src/infrastructure/A/ormconfig';
import ormconfigB from '../src/infrastructure/B/ormconfig';

const dataSourceA: DataSource = new DataSource({
  ...ormconfigA,
});
const dataSourceLtr: DataSource = new DataSource({
  ...ormconfigB,
});

beforeAll(async () => {
  await dataSourceA.initialize();
  await dataSourceA.runMigrations();
  await dataSourceB.initialize();
  await dataSourceB.runMigrations();
});

afterAll(async () => {
  await dataSourceA.dropDatabase();
  await dataSourceA.destroy();
  await dataSourceB.dropDatabase();
  await dataSourceB.destroy();
});

DataSourceはTypeORMの機能で、特定のデータベースの設定を持ったオブジェクトです。
AとBがあるのは、このプロダクトでは複数のデータベースへの接続が必要であったためです。

beforeAll はテスト実行前に処理が実行されるglobal関数で、
afterAll はテスト実行後に処理が実行されるglobal関数です。

beforeAllではデータベースに接続し、マイグレーションを実行し、
afterAllではデータベースのテーブルを全てdropし、接続を切っています。
要するに、１テストファイルごとにテーブルを作り直していました。

ボトルネック特定

• テスト実行の直列処理
• 1テストごとのデータベースの作り直し

これらが組み合わさって、実行時間が遅くなっていました。
今まではテストファイル数がそこまで多くなかったのですが、機能が増え、テストファイルも増えたことによって表面化しました。
こちらを、チョットだけ改善していきます。

なにをしたか

「実行が1度だけでいいものは1度だけ」という方針のもと、対応しました。

マイグレーションの実行を一度だけにする

新たにsetupGlobal.tsを作成し、マイグレーション処理をglobalSetupのタイミングに寄せました。

tests/integration/setupGlobal.ts

// importや変数定義は省略
await dataSourceA.initialize();
await dataSourceA.runMigrations();
await dataSourceB.initialize();
await dataSourceB.runMigrations();

また、全テスト実行後の後処理として、データベースを初期化する必要があったため、globalTeardownという設定を使用して、データベースの初期化を全テストの最後に行うように修正しました。

tests/integration/teardownGlobal.ts

// importや変数定義は省略
export default async (): Promise<void> => {
  ...中略...
  await dataSourceA.dropDatabase();
  await dataSourceA.destroy();
  await dataSourceB.dropDatabase();
  await dataSourceB.destroy();
};

設定後のconfigはこちらです。

jest.config.integration.js

module.exports = {
  ...中略...
  globalSetup: "<rootDir>/test/integration/setupGlobal.ts"
  globalTeardown: "<rootDir>/test/integration/teardownGlobal.ts",
  ...中略...
  // setupFilesAfterEnvは一旦設定が必要ないと感じ、コメントアウト
  // setupFilesAfterEnv: ["./test/integration/setup.ts"],
  testMatch: ['**/test/integration/**/*.spec.(ts|js)'],
}

リファレンスデータの投入も一度だけにする

テストファイルごとにリファレンスデータの投入の処理もされていました。
リファレンスデータの更新テストは結合テストでは実行していなかったため、リファレンスデータは不変であり、テストごとに入れ直す必要がなかったため一度だけ投入するように変更しました。

データの投入はシーダーで実行していたため、リファレンスデータ投入用のシーダーを動的に取得して実行する仕組みを作成し、それをsetupGlobal.tsの処理に追加しました。

seeds/master/index.ts

import * as fs from 'fs';
import * as path from 'path';

import { Seeder } from 'typeorm-seeding';

// seeds/master に配置されているシーダーファイルを読み込んでモジュール化してexport
const seedsDirectory = path.join(__dirname);
const seedModules: Seeder[] = [];

fs.readdirSync(seedsDirectory).forEach(async (file) => {
  if (file.endsWith('seed.ts')) {
    const module = await import(path.join(seedsDirectory, file));
    seedModules.push(new module.default());
  }
});

export { seedModules };

tests/integration/setupGlobal.ts

import { seedModules as Aseeds } from '../../src/seeds/databaseA/master/index';
import { seedModules as Bseeds } from '../../src/seeds/databaseB/master/index';
...中略...
// 読み込んだシーダーをデータベースAに順次実行
for (const seed of Aseeds) {
  await seed.run({} as unknown as Factory, dataSourceA);
}
// 読み込んだシーダーをデータベースBに順次実行
for (const seed of Bseeds) {
  await seed.run({} as unknown as Factory, dataSourceB);
}

これで、リファレンスデータのシーダー実行は1度だけとなり、テストファイル側に記載されていたリファレンスデータの投入処理が共通化され、コードも少しスッキリしました。

コネクション処理を追加

ここまでの対応を行い、結合テストを実行したところDBへのコネクションエラーが発生するようになりました。
原因は、Jestではテストファイルごとにセッションが分かれており、DBへの接続をテストファイルごとに都度行う必要があるためでした。
そのため、コメントアウトしていたsetUpFilesAfterEnvのDB接続の処理を復活させます。
同様に、テスト後に接続を解除しないと、DBコネクション数の上限になりエラーになるため、コネクションの解除処理も復活させます。

tests/integration/setup.js

beforeAll(async () => {
  await dataSourceA.initialize();
  await dataSourceB.initialize();
});

afterAll(async () => {
  await dataSourceA.destroy();
  await dataSourceB.destroy();
});

jest.config.integration.js

module.exports = {
  ...中略...
  globalSetup: "<rootDir>/test/integration/setupGlobal.ts"
  globalTeardown: "<rootDir>/test/integration/teardownGlobal.ts",
  ...中略...
  setupFilesAfterEnv: ["./test/integration/setup.ts"], // <= コメントアウト解除
  testMatch: ['**/test/integration/**/*.spec.(ts|js)'],
}

ここまでの対応で、ローカルで結合テストを実行したところ、

修正前

Time 508.805 s

Test Suites: 1 skipped, 81 passed, 81 of 82 total
Tests:       22 skipped, 3025 passed, 3047 total
Snapshots:   0 total
Time:        508.805 s

修正後

Time 229.981 s

Test Suites: 1 skipped, 81 passed, 81 of 82 total
Tests:       22 skipped, 3025 passed, 3047 total
Snapshots:   0 total
Time:        229.981 s

実行時間が半分くらいになりました㊗️

GHAで実行する

ローカルでうまく実行できたので、GHA上でどれくらい速くなるだろうと実行してみたところ、おびただしいエラーが発生しました。

GHA環境のみで発生する問題だったので、デバッグに苦労しましたが、setupGlobalにDBへの接続処理を移したことで、DBコンテナのMySQLサーバーが起動する前にアクセスしていたためコネクションエラーが発生していました。

解消のために、インターバルを設けた接続のリトライ処理を追加しました。

tests/integration/setupGlobal.ts

// DB接続リトライ上限回数（10回に設定）
const maxRetry = 10;

// 接続できるか、リトライ上限回数までリトライする
for (let i: number = 0; maxRetry > i; i++) {
  try {
    await dataSourceA.initialize();
    break;
  } catch (error) {
    // 接続失敗した場合、mysqlが立ち上がっていない可能性があるので少し間を空けて再接続を試みる
    await new Promise((resolve) => setTimeout(resolve, 10000));
  }
}

// dataSourceBも同様にリトライを追加

この処理を追加したことで、1度目のアクセスでコネクションエラーを吐いた後、インターバル後に再接続してしっかりと動作し始めました。最初からコネクションエラーが出ないように調整もできそうです。

しかし、また別のエラーに遭遇します。

<--- Last few GCs --->

[2883:0x698b190]   344627 ms: Mark-Compact 1974.9 (2081.3) -> 1948.2 (2065.9) MB, 1292.88 / 0.20 ms  (average mu = 0.307, current mu = 0.295) allocation failure; scavenge might not succeed
[2883:0x698b190]   346288 ms: Mark-Compact 1972.9 (2083.3) -> 1954.9 (2072.1) MB, 1247.99 / 0.04 ms  (average mu = 0.280, current mu = 0.248) allocation failure; scavenge might not succeed


<--- JS stacktrace --->

FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
----- Native stack trace -----

ヒープメモリエラーが発生しました。
GitHubのissueで新しいテストごとにメモリ使用量が増加するバグがあるというものを見つけたため、
こちらの解消としてworkerIdleMemoryLimitをjest.integration.configに定義して解決しました。

workerIdleMemoryLimitは、デフォルトでundefinedですが、この設定値にメモリが到達するとワーカーが再起動されてリセットできる閾値のため、100%を設定しました。

jest.config.integration.js

module.exports = {
  ...中略...
  globalSetup: "<rootDir>/test/integration/setupGlobal.ts"
  globalTeardown: "<rootDir>/test/integration/teardownGlobal.ts",
  ...中略...
  setupFilesAfterEnv: ["./test/integration/setup.ts"],
  workerIdleMemoryLimit: '100%', 
  testMatch: ['**/test/integration/**/*.spec.(ts|js)'],
}

ここまでの対応で、結合テストの実行時刻が約13分から約6分になっていることが確認できました。

修正前

修正後

全体の実行時刻も最初に述べたように半分の実行時刻になりました㊗️

修正前

修正後

おわりに

今回は直列処理の中で、無駄な処理を省くことで時間短縮を行いました。
並列処理化や、テストの見直しなどもしていくことで、さらなる速度改善が見込めそうですが、限られた工数の中での戦いだったので、自分の中ではベターだったのかなと思います。

ただ、実行時間は速くなった一方で、チョット無理矢理な実装だなぁ...と自分で進めていて思ったので、もっといい方法があればコメントなどで教えていただけると助かります🪓

最後まで読んでいただき、ありがとうございました！

明日の記事は、HY さんが執筆します！
ぜひご一読ください😃

参考文献

• https://jestjs.io/ja/docs/configuration
• https://qiita.com/rokumura7/items/51622ce55282c80ac6c5
• https://qiita.com/noriaki/items/5d800ea1813c465a0a11
• https://qiita.com/YutamaKotaro/items/798832e108585c7892a4