【Vitest移行を検討する前にやっておきたい】Jestのチューニング

はじめに

弊社ではNode.jsとTypeScriptを採用しておりNode.jsを利用した自動テストをCIで実行しています。テストフレームワークとしては主にJestを採用しています。

最近これらの自動テストの実行時間の肥大化が課題になったため、継続的にチューニングを行っていますが、知見が多少溜まってきたため記事にまとめてみました。

一般的に自動テストの実行が遅いことは確実に開発体験を悪化させます。

ちょっとしたバグ修正のあとのテスト実行に30分もかかるようなプロジェクトはちょっとした悪夢です。そこまでいかなくても、個人的な目安としてCIランナーでのテスト実行時間が10分を超えてくると赤信号かなと思っています。

しかしその一方で、なりゆきにまかせればプロダクトが大きくなるにつれテスト数は単調増加するので、テスト時間が長くなるのは自然の摂理でもあるといえます。機能が増えればそれだけその機能を担保するためにテストが追加されますが、既に存在するテストはたいてい減らせません。テスト実行時間を短くする、テストの「チューニング」が必要になってきます。

テストフレームワークのVitestはJestよりも高速だというふれこみです。またJestの開発にFacebookがあまり力を入れなくなったのもあって新しいプロジェクトではVitestで書こうという風潮があるかなと思います（自分も個人開発とかではとりあえずVitestにします）、しかし既存のテストを高速化のためにVitestに書き換えるのは効果的でしょうか？

テストフレームワークの乗り換えが趣味でない限り、本当にやりたいのはテストというプログラムの実行時間の短縮、つまり「チューニング」であることを思い出してください。Vitestは速いですが仕組みから考えると速いのはビルドやテストコードのトランスパイルであるため、むやみに導入しても効果が出るかわかりません。

パフォーマンスチューニングの基本は「推測するな、計測せよ」といわれます。テスト実行のどこがボトルネックかわからないと効果的な対策はできないため、まず現状の計測、プロファイリングから始める必要があります。

※2019~2023年のbitbankのあるリポジトリのテストファイル数、テスト数、テスト実行時間の推移。赤枠で囲った部分が今回の記事で紹介するチューニングの結果

背景

今回紹介する事例の対象の技術スタックについては先ほども書いた通りNode.js, TypeScript, Jestを使用しています。

個別事例で紹介するテストコードを使用しているリポジトリはWebのバックエンドのAPIサーバです。バックエンドフレームワークとしてNestJSを使用しており、ORMライブラリとしてはTypeORMを使用しています。
テストの構成としてデータベースとの接続部分についてはモックを使用せずDockerを使用しています。

チューニング対象としたリポジトリのチューニング前のテストファイル数、テスト数は以下でした。

Test Suites: 60 passed, 60 total
Tests:       422 passed, 422 total
Snapshots:   0 total
Time:        683.805 s

本記事の構成について

「計測と分析」の「プロファイリングの収集方法」「計測結果の分析」や末尾の「その他のテストが遅くなる理由とその対策」については比較的一般的な話を書いています。
「考察」「対策」「チューニング結果」は個別事例なので参考程度にしてください。

計測と分析

プロファイリングの収集方法

それではまず、テスト実行のプロファイリングを収集していきましょう。ChromeのDevtoolsを使用してNode.jsの実行時のCPUプロファイリングを収集することができます。

まずChromeのURL欄にchrome:inspectと入力して移動し、Open dedicated DevTools for Nodeをクリックして、DevTools を開きます。

つぎに対象のプロジェクトのルートディレクトリで以下を実行します。

node --inspect-brk ./node_modules/jest/bin/jest.js  --runInBand --coverage=false

テスト数が多いとプロファイル結果のファイルが大きすぎて記録・保存時にChromeがクラッシュする場合があります。その場合は--shardオプションを使用すると実行するテストの件数を減らすことができます。すべてのテストが実行されないため不正確になりますが傾向を見る事ができます。

node --inspect-brk ./node_modules/jest/bin/jest.js  --runInBand --shard=1/8 --coverage=false

デフォルトのブレークポイントにヒットしたら、パフォーマンスタブに移動して記録を開始します。

※Chromeのアップデートで頻繁に見た目が変更されるためスクリーンショットはあくまで参考にしてください

テストが完了したら、プロファイラを停止します。記録を表示して、「グラフ」ビューを選択します

無事データが取れたら間違って上書きしてしまわないようにダウンロードしておきましょう。

計測結果の分析

測定結果の見方

収集した結果のグラフをみていきます。

画像の青で囲った部分にCPUの稼働割合が視覚化されています。オレンジの山になっている部分でCPUが使われており、オレンジ色がない箇所はアイドル状態です。

以下の緑色で囲った部分ではメインスレッドでどんなタスクが実行されているかが可視化されています。(--runInBandオプションを付けているためWorkerスレッドは存在しません。)

下部のタブではプロファイルのサマリを見ることができます。
今回の例でBottom-Upタブ（以下の青で囲った部分）をみるとアイドル時間が87.4%にとなっておりアイドル状態が長い事がわかります。

ここで更にCPUが実行されている部分で実行されているタスクを精査していきます。細かくみていくと実際に実行されているテストファイル名まで特定が可能です。

今回の実行ファイルを細かくみていくと、アイドルタイムが存在する処理は個別のテストファイルのファイル名と一致し、個別のテストの実行時にアイドルタイムが存在することがわかりました。

ボトルネックとは

ボトルネックとは、テスト時間の短縮が目的である今回の場合はテストに時間がかかっている箇所ということにほかなりません。

たとえば、全体の90%の時間がかかっている処理を50%削減すれば全体で見れば45%の時間が削減できます。しかし、全体の10%しかない処理を頑張って90%削減しても全体では9%しか短くなりません。単純計算で約２倍頑張ったのに効果は５分の１であり、典型的な徒労であるといえます。

よって効果的な対策のためにはボトルネックの特定が欠かせません。

今回はCPUの実行のグラフやサマリの結果からアイドルタイムがテストの実行時間の90%近くを占めていることがわかりました。これがボトルネックと考えてよいでしょう。

考察

テストの実行というのはテストスクリプトの「トランスパイラ」か「その他のテスト実行前の準備処理」「テスト本体の実行処理」などに分けられます。

モジュールの事前準備を行っている処理はメインスレッドの実行タスクを細かくみていくとjestAdaptorというタスクで実行されています。ここを掘り下げていくとたとえばsetup-jest.tsや関連モジュールを読み込んでトランスパイルを行っている箇所などをファイル単位で確認できます。

今回はこの部分とは関係なく個別のテストコードにボトルネックの原因があるという仮説を立てたられたので、テストコードのほうをみていきます。

たくさんあるテストスイート（テストコードのひとまとまりを指す。今回の場合はテストファイル１つに相当）のうち目立って時間がかかっていたuser-info.service.spec.tsを調べます。
テストコードは以下のようなものでした。

※実際のコードはもっと長くてテストケースは20件ありましたが、みやすいように一部修正、省略しています。

// user-info.service.spec.ts
import { User, UserInfo } from '@bitbank/model';
import { Logger } from '@bitbank/logger';
import { DataSource } from 'typeorm';

import { ConfigService } from '../../common/services/config.service';
import { createDummyUserInfo } from '../../common/test/entity.util';
import { createTestingConnection } from '../../common/test/test.util';
import { UserInfoService } from './user-info.service';


describe('user-info.service', () => {
  let dataSource: DataSource;
  let userInfoService: UserInfoService;

  beforeAll(async () => {
    dataSource = await createTestingConnection();
    userInfoService = new UserInfoService(
      dataSource.getRepository(User),
      dataSource.getRepository(UserInfo),
      new Logger(),
      new ConfigService(),
    );
  });
  beforeEach(async () => {
    await dataSource.synchronize(true);
    await dataSource.runMigrations();
  });
  afterAll(async () => {
    await dataSource.destroy();
  });

  it('should create and find user-info', async () => {
    const user = await dataSource.getRepository(User).save(getDummyUser());
    const createdInfo = await userInfoService.create(user.uuid);
    expect(createdInfo.id).toBe('1');
    expect(createdInfo.name).toBe('dummy_name');
    expect(createdInfo.createdAt).toBeInstanceOf(Date);
    expect(createdInfo.updatedAt).toBeInstanceOf(Date);

    const foundUser = await userInfoService.findOne(user.uuid);
    expect(foundUser.userInfos).not.toBeUndefined();
    expect(foundUser.userInfos).toHaveLength(1);
    expect(foundUser.userInfos![0]).toEqual(createdInfo);
  });

  it('should update user-info with no document required params', async () => {
    const userInfo = await dataSource.getRepository(UserInfo).save(createDummyUserInfo());

    const updateRequest = {
      name: 'updated_name',
    };

    const { info: resInfo } = await userInfoService.update(user.uuid, updateRequest);

    expect(resInfo.name).toBe('updated_name');
  });
  
  // 以下にテストケースがあと18件あったが省略
  // it('should...
});

またローカルマシン（M1 Mac）でこのテストだけ実行した結果が以下のようになりました。

このテストコードではまずbeforeEachの部分に注目すべきです。
というのもbeforeAllやafterAllやその他のテストケースはテスト実行時に一度しか実行されませんが、beforeEachやafterEachはテストケースの数だけ繰り返し実行されるため、ここに重い処理があるとテスト実行時間に大きな影響があるためです。

beforeEachの内容について

  beforeEach(async () => {
    await dataSource.synchronize(true);
    await dataSource.runMigrations();
  });

そもそも前提としてこのテストでは、データベースはモックではなくDockerコンテナで立ち上げたデータベースを使用しているため通信や重いクエリにはそれなりに時間がかかります。
さらにdataSource.synchronize(true)について調べてみるとこのメソッドの実行でDROP TABLEが実行されてすべてのテーブルが削除されていることがわかりました。

参考: TypeORMドキュメント

このテストスイートのテストケースが20件なので20回DROP TABLEが実行されていたことになります。DROP TABLEは当然、重い処理なのでかなり怪しそうです。

ここまで見当がついたら裏取りのために実行時間を実測してしまいます。今回はawait dataSource.synchronize(true);の実行前後でconsole.time()でかかった時間を測定しました。

console.time('test');
await dataSource.synchronize(true);
console.timeEnd('test');

画像の通り毎回1500ミリ秒程度実行に時間がかかっていることがわかりました。単純計算でこの処理だけで30秒（1.5秒 x 20ケース）かかっていたことになります。

ところでCIとローカルマシンでは実行環境も異なるためここでの細かい数値にはあまり意味はありません。とはいえ、テスト実行時間全体に対する割合を考えてもこの処理がボトルネックである確度はかなり高くなりました。

対策

以上の調査結果からテスト実行時間の短縮のボトルネックはデータベースに対する重いクエリ（DROP TABLE）の待ち時間であると仮説を立てました。

この仮説に対して対策を立てて効果を検証していきます。DROP TABLEを何も考えないで消してもテストが壊れるだけなので代替案を考える必要があります。

さて、そもそもDROP TABLEを実行していた目的はなにかというと、前のテストのデータを消して、他のテストに影響されず独立してテストを実行可能にするためです。よってテストデータを毎回削除するような処理はDROP TABLEを消したとしても必要になります。
しかし、個別のテストスイートはせいぜい2~3個の特定のテーブルと結びついているためDROP TABLEのようにすべてのテーブルを消す処理は明らかにオーバースペックであることもあきらかです。それぞれのテストで必要なデータだけ最小限削除するようにすれば軽いクエリで実行可能でしょう。

そこで以下のような対策を行うことにしました。

DROP TABLEの実行はテストスイートごとに1度だけ実行するよう修正する
個別のテストごとのデータベースのリセットには対象のテーブル指定で、より早い処理であるTruncate Tableを実行する関数を作成して使用する

修正後のコードの一部

beforeAll(async () => {
    dataSource = await createTestingConnection();
    userInfoService = new UserInfoService(
      dataSource.getRepository(User),
      dataSource.getRepository(UserInfo),
      new Logger(),
      new ConfigService(),
    );
    await dataSource.synchronize(true);
    await dataSource.runMigrations();
  });
  beforeEach(async () => {
    await truncateTables(dataSource, [User, UserInfo]);
  });

truncateTablesの内容は以下のようにしました

export async function truncateTables(dataSource: DataSource, tables: Function[] | string[]): Promise<void> {
  await dataSource.query(`SET FOREIGN_KEY_CHECKS = 0;`);
  for (const table of tables) {
    await dataSource.getRepository(table).clear();
  }
  await dataSource.query(`SET FOREIGN_KEY_CHECKS = 1;`);
}

この対策をひとつのテストスイートのみに適応してみて実行時間が改善されるかみてみましょう。

対策前

対策後

対策前の実行時間が約33秒、対策後が約9.5秒となり、約70%実行時間が短縮されています。
繰り返しになりますが、ローカルマシンでは実行タイミングでも結果がまちまちになるため、ここで出てくる秒数に意味はあまりないのですが、それを差し引いても明白に実行時間が短縮されました。

そこでこの対策を他のほぼすべてのテストスイートにも平行展開することにしました。

※他の対策として、データベースのテストへの利用をやめてモックと入れ替えるなども考えられますが、今回は修正コストと効果のバランスを考えてこの対策に落ち着きました。
※DROP TABLEの実行を全く実行しない変更ができなかったのはテストスイート個別でテストが実行される可能性があり、テスト実行前にデータベースに存在するデータを削除しておく処理が必要だったため。データベースの初期化を別コマンドに切り出すなどすれば全く実行しない対応も可能なので、他のテストのチューニングでそういう対策を行ったこともあります。

チューニング結果

N1のピックアップの結果ですがチューニング前と後でCIのテスト実行時間を比較した結果以下のようになりました。

チューニング前：
- テストのみ： 11分23秒(683秒)
- CI: 全体: 14分50秒

チューニング後：
- テストのみ： 4分43秒(283秒)
- CI: 全体: 8分42秒

※CIの環境は比較的安定しているためそこまで毎回実行時間にばらつきはありません。

プロファイルも再度取得して前後比較してみましょう。

比較しやすいように対策前のプロファイルも以下に再掲します

テスト実行時間が異なっている（横軸）のは当然ですが、それ以外にも明らかに以下のような違いがあります。

オレンジ色の山と山の間隔（アイドルタイム）が減少
テストごとの実行時間のばらつきが小さくなってオレンジ色の山の間隔がだいたい等間隔になった

ボトルネックとしてターゲットにしていたアイドルタイムを狙い通り減らすことができたことが確かめられました。また、ばらつきが少なくなった理由はテストケース数でDROP TBALEの数が変わってくるためテストケースが多いテストと少ないテストで実行時間にばらつきが出ていたのだと考えられます。

その他のテストが遅くなる理由とその対策

テストが遅くなる原因としては他にもいろいろな要素があります。分析したデータと突き合わせて検討する際に参考になるかと思いますので今回取り扱わなかった要素についても記載しておきます。
ただし、思い込みすぎたり、分析するまえに対策を行うのはやめましょう。

ビルドやトランスパイルの時間

ここがボトルネックであればVitestへの置き換えが効果的な対策になる可能性があります。
またほかの対策として不要なモジュール読み込みを減らすなども考えられます。JestにはBarrel filesの利用によりトランスパイル対象が増えて時間がかかってしまう問題があり、実装のコード側でBarrel filesを使用しないようにしたり不要なモジュールを整理すると改善する可能性があります。

準備処理

準備処理(setupTests.tsなど)で実行している何らかの処理です。テスト実行時に一度ではなく、各テストファイルごとに実行されるため想定より影響が大きい可能性があります。

一つのテストにしか必要ない重い処理をここで実行してしまっていないかなどを確認するのも良いでしょう。

その他

実時間を使ったテストの存在（sleep()のような関数）
- fake timerなどを使用すると改善する可能性がある
テスト実行時の型チェックのスキップ
- 型チェックは他のCIランナー行えば良いのでテスト実行時に行う必要は必ずしもありません

別観点の対策は？

ちょっと視点を変えてみると、別のアプローチからできる対策もあります。
ただし真の目的がなんなのか（CIの実行時間の短縮なのか？ローカルのテストの実行時間の短縮なのか？）によって有効な対策は異なってくるため目的をはっきりさせることがより重要です。

Jestの機能を使ったテストの並列実行（本記事の例ではDBを使用する関係で利用が難しかった）
- Jestでは--maxWorkers等のオプションがありますが、なにも設定せずJestに任せても実行環境に最適化してくれるため、明確な理由なく設定されている場合はむしろ外してみると改善する可能性があります
- --runInBandを設定すると複数スレッドを使用できなくなるためもし設定されていて、かつ不要であればこの設定は外したほうが良いでしょう
CIの機能を使ってCIランナーレベルでのテストの並列実行を行う
- GitHub Actionsではmatrixとよばれる機能、GitLabではparallelという機能を使用して実現できます
- Jest側では--shardというオプションを使用することでテストを分割実行する事ができるのでこれを利用します
- 当然ですが、前提としてテストスイートごとに単独で実行できるようにテストを実装している必要があります
変更した箇所だけテストを実行する
- Jestでは --onlyChanged --changedSinceなどのオプションを使用することが可能です
- チームの運用ポリシーによりますがコード品質を保つには少なくともmaster(main)ブランチではテストをすべて実行する必要がありそうです
- またなるべく早く壊れたコードを発見するというCIの機能を捨ててしまう欠点があります

最後に忘れてはいけないのが、　「テストを実行するマシンのスペックを上げる」　です。
~~もはやチューニングといえるかわかりませんが~~最も単純な対策であるため逆に盲点になりやすいことから、あえて特記しておきたいと思います。
この対策はコストがかかる代わりに非常に大きな利点として、「コードを全く変更しなくて良い」があります。コードを書かないで目的を達成できれば、メンテナンスコストやバグのリスクがあらたに発生しないため、プログラマーにとってはそれは最良の選択になります。
したがって、これは常に最善の対策といっても過言ではありません。必ず検討するようにしましょう。