こんにちは。ソフトウェアエンジニアの inari111 です。
RemitAidではバックエンドにGoを採用しています。
本記事では、キャッシュを見直し、GitHub Actionsのテストジョブの実行時間を約8分から3分弱に短縮した事例を紹介します。
前提：バックエンドのテスト構成
まず、バックエンドの3種類のテストについて説明します。
ユニットテスト
ドメイン層の関数を中心に書いているユニットテストです。
go test ./... で実行します。
DBを使ったインテグレーションテスト
アプリケーション層に書いているビジネスロジックとDBの整合性を検証するためのテストです。
テストファイルに //go:build integration を付けているため、go test -tags=integration ./... で実行します。
ビルドタグを付けているのは、インテグレーションテストを個別に実行できるようにするためです。
E2Eテスト
レスポンスボディとHTTPステータスコードを検証するテストです。
このテストをインテグレーションテストと捉える方もいるかもしれませんが、バックエンド視点のE2Eテストということで、本記事ではE2Eテストと呼びます。
テストファイルに //go:build e2e を付けているため、go test -tags=e2e ./... で実行します。
ビルドタグを付けているのは、インテグレーションテストと同様に、E2Eテストを個別に実行できるようにするためです。
ちなみに、E2Eテストには k1LoW/runn を使っています。
CIでテストジョブがタイムアウト
CIにはGitHub Actionsを利用しています。
testジョブとlintジョブがあります。testジョブでは、ユニットテスト → インテグレーションテスト → E2Eテストの順で各ステップを実行します。ジョブのタイムアウトは10分に設定していました。
テストが増えるにつれ、CI上でタイムアウトすることが増えてきました。
ローカルでは、すべてのテストを実行しても10分を超えたことはありません。
タイムアウトの原因
タイムアウトしたジョブを調べると、テストそのものが遅いのではなく、毎回フルコンパイルが走っていることがわかりました。
タイムアウトしたときのステップ別の所要時間は、以下の通りです。
| ステップ | 所要時間 |
|---|---|
| Generate code | 約2分56秒 |
| Unit test | 約2分58秒 |
| Integration test | 約20秒 |
| E2E test | 約3分26秒(タイムアウトにより強制終了) |
当初はDBへのI/Oを疑っていたのですが、DBを使うインテグレーションテストは20秒程度でした。
一方、ユニットテストの約3分は、ログを見るとテスト実行自体は各パッケージ数秒程度で、ほぼすべてがコンパイル時間でした。E2Eテストも同様です。
その他のセットアップステップも含めると、10分を超えていました。
actions/setup-goによって必要なコンパイル結果もキャッシュされていると考えていましたが、実際にはlintジョブが同じキーで先にキャッシュを保存していたため、testジョブのコンパイル結果は保存されていませんでした。
実際の実行結果を見ると、Generate codeとUnit testだけで約6分かかり、E2Eテストの実行中にタイムアウトしていました。
なぜ毎回フルコンパイルになっていたのか
actions/setup-goの内蔵キャッシュ（cache: true）を使っていましたが、その保存キーは「OS + Goバージョン + go.sumのハッシュ」から自動で決まり、ワークフロー名やジョブ名を含みません。
同じリポジトリに lint ジョブがあり、同じgo.sumを参照していたため、testジョブとlintジョブが同じキャッシュキーを使用していました。
GitHub Actionsのキャッシュは同じキーへ上書き保存できないため、lintジョブが先に保存すると、testジョブのコンパイル結果はいつまでもキャッシュに保存されません。
testジョブでも、lintジョブが保存したキャッシュ自体は復元されますが、そのキャッシュにはテストで必要なビルド成果物が十分に含まれていません。
testジョブ内で不足分をコンパイルしても、同じキーのキャッシュは上書きできないため、次回の実行に引き継がれませんでした。
さらに、テストはビルドタグなし / -tags=integration / -tags=e2e の3種類のビルドを行うため、キャッシュが効かない実行では、実質3回分のフルコンパイルが走ることになります。
なぜ「時々」タイムアウトするのか
通常時のジョブ合計は約8分で、タイムアウトの10分にギリギリ収まっていました。
一方、タイムアウトした実行のログには Cache is not found と出ていました。
actions/setup-goの内蔵キャッシュはキーが完全に一致した場合にのみ復元され、restore-keys相当のフォールバックがありません。
そのため、Goバージョンやgo.sumが変わるとキャッシュが効かなくなり、依存モジュールの再ダウンロードとフルコンパイルによってジョブの実行時間が10分を超えていました。
キャッシュの再設計
actions/setup-goの内蔵キャッシュを無効化し（cache: false）、actions/cacheでキャッシュを自前管理するようにしました。
1. キャッシュキーをジョブごとに分ける
キーを backend-test- で始まる独自のものにして、lintジョブとのキャッシュ共有を解消しました。
これにより、testジョブのコンパイル結果がキャッシュに保存されるようになりました。
2. モジュールキャッシュとビルドキャッシュを分離する
- モジュールキャッシュ（
~/go/pkg/mod）: ダウンロード済みの依存モジュール。内容はgo.sumだけで決まる - ビルドキャッシュ（
~/.cache/go-build）: コンパイル結果。ソースが変わるたびに中身が変わる
後述の通り、ビルドキャッシュはコミットごとに保存します。両方を1つのキャッシュにまとめると、内容が変わらないモジュールキャッシュまでコミットごとに複製され、リポジトリのキャッシュ上限（10GB）を圧迫してしまいます。
そのため、キャッシュを2つに分けました。
3. ビルドキャッシュをコミット単位で保存・復元する
GitHub Actionsのキャッシュは同じキーへ上書き保存できないため、キーが固定されていると、初回に保存された古いキャッシュが残り続け、増分が積み上がりません。
そこで、ビルドキャッシュのキー末尾にコミットSHAを付け、コミットごとに新しいキャッシュとして保存するようにしました。
復元時はrestore-keysによって直近のコミットのキャッシュを土台にし、変更分だけを再コンパイルします。
設定は次の通りです。
steps:
- uses: actions/checkout@de0fac2e4500dabe0009e67214ff5f5447ce83dd # v6.0.2
- uses: actions/setup-go@4b73464bb391d4059bd26b0524d20df3927bd417 # v6.3.0
id: setup-go
with:
go-version-file: ./apps/backend/go.mod
cache: false # 内蔵キャッシュを無効化
# module cache: 内容は go.sum だけで決まるので、go.sum のハッシュをキーに1個だけ保存
- name: Restore Go module cache
uses: actions/cache@55cc8345863c7cc4c66a329aec7e433d2d1c52a9 # v6.1.0
with:
path: ~/go/pkg/mod
key: backend-test-go-mod-${{ runner.os }}-${{ hashFiles('apps/backend/go.sum') }}
restore-keys: |
backend-test-go-mod-${{ runner.os }}-
# build cache: コミットごとに中身が変わるので、キー末尾のコミットSHAで毎コミット新しいキャッシュとして保存
- name: Restore Go build cache
uses: actions/cache@55cc8345863c7cc4c66a329aec7e433d2d1c52a9 # v6.1.0
with:
path: ~/.cache/go-build
key: backend-test-go-build-${{ runner.os }}-${{ runner.arch }}-${{ steps.setup-go.outputs.go-version }}-${{ hashFiles('apps/backend/go.sum') }}-${{ github.sha }}
restore-keys: |
backend-test-go-build-${{ runner.os }}-${{ runner.arch }}-${{ steps.setup-go.outputs.go-version }}-${{ hashFiles('apps/backend/go.sum') }}-
backend-test-go-build-${{ runner.os }}-${{ runner.arch }}-${{ steps.setup-go.outputs.go-version }}-
成果：ジョブの実行時間を約8分から2分55秒に短縮
キャッシュの再設計後、前コミットのキャッシュを復元したPRのrunで、ジョブ合計が 約8分 → 2分55秒 になりました。
| ステップ | 変更前 | 変更後 |
|---|---|---|
| Generate code | 約25秒 | 11秒 |
| Unit test | 約2分55秒 | 20秒 |
| Integration test | 約20秒 | 15秒 |
| E2E test | 約3分25秒 | 38秒 |
| ジョブ合計 | 約8分 | 2分55秒 |
変更のないパッケージではgo testの結果キャッシュが利用されていますが、主要なDBインテグレーションテストとE2Eテストは実際に実行されています。
まとめ
- テストが遅いと感じたら、まずステップ別・フェーズ別に計測して分解する
- 当初疑っていたインテグレーションテストは20秒しかかかっておらず、原因はコンパイル時間だった
- actions/setup-goの内蔵キャッシュを複数ジョブで共有すると、必要なビルド結果が保存されない場合がある
- キャッシュがヒットしているのにビルドが速くならない場合は、別のジョブと同じキーを使っていないか確認する
- GitHub Actionsのキャッシュは同じキーへの上書き保存ができない
- 増分を積み上げたいキャッシュはキーにコミットSHAを含めて毎回保存し、復元は
restore-keysに任せる
- 増分を積み上げたいキャッシュはキーにコミットSHAを含めて毎回保存し、復元は
- 内容が変わらないモジュールキャッシュと、増分が積み上がるビルドキャッシュは性質が違うので分離する
当初はDBを使ったテストを疑っていましたが、ステップごとに計測すると、実際のボトルネックはコンパイルでした。思い込みで改善を始めず、まず所要時間を分解して確認する重要性を改めて感じました。
同じようにactions/setup-goのキャッシュが「効いているはずなのに遅い」状態に悩んでいる方の参考になれば幸いです。
Podcast 「RemiTalk」を配信していますので、よければ聴いてみてください。
Discussion