freeeの開発情報ポータルサイト

自動テスト速度改善 - 自動テストが品質のボトルネックとならないために

freee人事労務の品質改善を専任で活動している keik です。

freee人事労務ではアプリケーション開発の自動テスト環境として CircleCI を利用しています。すべてのコードの変更は GitHub 上の Pull Request を経由して行われますが、Pull Request のマージ条件の一つとして自動テストをパスすることを求めるようにしています。

つまり、どんな些細な変更であっても、急ぎの変更であっても、リリースするためには基本的には自動テストの結果を待つ必要があります。一方で、コードベースは日々成長しており、それに比例して自動テストの実行時間も長くなっています。

ここに、ゆっくりと、ジレンマが生じはじめます。

品質を高める目的の自動テストだが、実行時間が長いと品質のボトルネックになりうる。

具体的には以下のようなシナリオが考えられます。

  • 些細な改善が億劫になる(自動テストの結果を待たなくてはいけないので)
  • 急ぎの変更が急ぎにくくなる(自動テストの結果を待たなくてはいけないので)

想像してみてください。自動テスト実行に30分かかる環境と10分かかる環境があったとします。ここで「不足したソースコードコメントを追加したい」「見出しの文言を微修正したい」と思い立った時の行動の起こしやすさは、結構違ってくるのではないでしょうか。また変更を少しでも早くリリースできることは、DevOps においてキーメトリクスとされる「リードタイム」や「平均修復時間(MTTR )」と直接的な関係にあります。幸いにしてfreee人事労務の異常検知時間やデプロイ所要時間には大きな課題感がなく、故に自動テスト実行に30分かかるともなれば MTTR の内訳として比較的目立つ部分になってくることでしょう。

そのため、自動テストの実行時間を短縮することは重要なのですが、ここにもう一つの課題があります。

自動テストの実行時間の短縮のしかたを誤ると、品質が犠牲になりうる。

自明な例として、「単に遅いテストを削除する」ではまずいわけです。

こうした課題に対して、freee人事労務が自動テスト実行時間の短縮に取り組んだ話をします。実は、上で挙げた自動テスト実行時間の30分や10分という値は、今回の改善前後の実際の値から取ったものです。品質を犠牲にせず、テスト実行時間を 1/3 に短縮するために行ったことを説明します。

自動テスト実行時間の短縮のためにやったこと

次のようなことを行いました。

  1. レガシーテストの削除
  2. Flaky Test の取り扱いに対する啓発
  3. 特定条件でのテストジョブのスキップ
  4. ファイル単位で遅いテストを直す
  5. 全テストケースで共通的に実行される処理の見直し

1. レガシーテストの削除

冒頭で「単に遅いテストを削除する」のはまずいやり方だと言いましたが、その対象が「レガシーテスト」と言えるものであれば積極的に取りうる手段です。

レガシーテストという用語に対するコンセンサスはありませんが、いわゆるレガシーコードの諸条件(意図が理解できない、構造が複雑で読解に苦労を要する、場当たり的な取り扱いが常態化しているなど)が見いだせるテストコードのことを指しています。

今回、実際に削除したテスト例として、RSpec における Request Spec(公開 HTTP エンドポイントに対しリクエスト・レスポンスを検証するテスト)の仕組み上で行っていた大量のパラメータ化テストを削除しました。

このテスト群は「CSV の行ごとにパラメータと期待値のセットを定義して、大量のパラメータ化テストを実施する」というもので、ここまでは悪くないように思えます。しかし、テストデータ作成や検証データ取得をすべて公開された HTTP API 経由で操作していて、Web ブラウザこそ使っていないものの一種の E2E テストと言えそうなものでした。コーナーケースを含め詳細を検証するためのパラメータ化テストを、荒い粒度でソースコードのインテグレーション具合を検証するための E2E テストの手段で実施していることは、HOW として食い合わせが良くありません。更には CSV の値をパラメータ用のオブジェクトにマッピングするための特殊な「テスト用のロジック」もありました。それ故に運用上の苦労も多く、例えばテスト失敗時の原因解読が難しかったり、故に失敗テストに対しては実測値を用いて期待値を書き換える修正方法が常態化していたり、さらには理由も不明瞭のまま恣意的にスキップされているテストケースがあったりなどと、様々な課題があるものでした。

ところで、このようにテストを削除したい理由はある一方、「テストを削除(変更)する」行為自体がなかなかに困難です。削除(変更)する前のテストは何かを守っているはずで、それを削除(変更)して良いと判断・証明するのは難しいからです。

そこで、判断をするための材料集めをしていきます。まずはこのテストに加えられている変更頻度や内容を確認しました。

 % git --no-pager log --pretty='format: %ad' --date='format:%Y' -- spec/requests/integration | sort | uniq -c
     86  2015
     50  2016
     34  2017
     20  2018
     14  2019
     12  2020
      6  2021

変更頻度が年ごとに下がっています。変更内容の詳細を確認してみると、直近3年間ほどはコードフォーマットだったり feature flag の追加・削除に伴う調整的な変更だったりと、ほとんど業務的な意味づけのない変更ばかりでした。さて、責務を閉じた業務コアロジックの実装であれば「枯れる」こともあるでしょうが、今回削除したいと考えているテストはパラメータ化テストの舞台上にあり、それならば新機能追加に伴って新たなテストケースが追加されるのが妥当であって、枯れることはないはずです。3年間で数々の新機能をリリースしたにもかかわらず、新しいテストケースが追加されていないのは、枯れているのではなく「死んでいる」と言えます。そしてこの間に追加された新機能に対するテストは、新機能の業務コアロジッククラスのテストとして書かれていることも確認しました。チームとして責務の設計が上達し、E2E テストのレイヤでパラメータ化テストを行う必要が下がったとも言えるかもしれません。さらにダメ押しで、このテストを削除してテストカバレッジを計測したところ -0.2% しか変化しないことを確認しました。これを以て、このテストで行っていた検証内容の大半は、より小さい粒度のテストでまかなえているであろうことの根拠とし、削除に踏み切りました。

このレガシーテストの削除により、RSpec ジョブの総実行時間が80分も短縮しました。freee人事労務は RSpec ジョブを16並列実行しているため、均等化して実際の待ち時間に換算すると5分の短縮に相当します。

2. Flaky Test の取り扱いに対する啓発

実行結果が不安定なテスト、いわゆる Flaky Test に遭遇した場合の対処として、以前は自動テストをパスするまで CI ジョブを再実行して凌ぐという運用を多く見かける状況でした。

これに対して、Flaky Test を見かけたらチーム全体への共有や、可能ならその場で修正するようにお願いする活動を続けました。また私の所属する品質改善チームが Flaky Test を率先して修正することで、Flaky Test が一つでも残存することに対してチーム全体が課題意識を持てる状態 を作っています。

f:id:keik_117:20220325151232p:plain
Flaky Test おじさん活動

その結果、Flaky Test が見過ごされる状態はなくなり、CircleCI 上に Flaky Test をリストアップする画面(CircleCI の参考記事)上でも0件を維持しています。

また、CI ジョブを再実行する場合についても、全ワークフローを再実行するのではなく失敗したジョブのみを再実行するようにお願いするなど、地味な啓発も行っています。

f:id:keik_117:20220325145709p:plain
CircleCI のジョブの再実行は "Rerun Workflow from Failed" から

3. 特定条件でのテストジョブのスキップ

freee人事労務のソースコードリポジトリはモノリシックで、バックエンドとフロントエンドの両方のソースコードを管理しています。そのため、中にはバックエンドのみの変更やフロントエンドのみの変更といった Pull Request もありえます。そうした Pull Request に対して、関係のない側のテストを実行する必要はありません。このように Pull Request の変更内容に応じてテストジョブをスキップするようにしました。

これはシンプルなアイデアである一方で、本当にスキップして良いのかどうかの条件判断には注意を要します。実は以前、似た仕組みを運用していた別リポジトリにおいて、本来実行すべきだったテストがスキップされてリリースされてしまったことにより、障害につながったことがあります。

テストジョブのスキップ条件を定義・実装するときは、ソースコード間の依存関係の理解が必要です。例えば、スキーマ駆動開発をしている場合においては、スキーマ定義ファイルはバックエンドとフロントエンドの両方から依存される位置にあるため、スキーマ定義ファイルに変更を加えている Pull Request に対しては、バックエンドとフロントエンドの両方のテストを実行する必要があります。さらに注意することとして、「バックエンドが修正されたときはバックエンドテストを実行する」と「フロントエンドのみが修正されたときはバックエンドテストを実行しない」はイコールではないということに気をつける必要があります。つまり、実行の条件を定義するよりも、スキップの条件を定義することにします。こうすることで、新規追加される未知のファイルなどに対しても安全が担保できます。

テストがスキップされたことを Pull Request 作成者やレビュアが認識できることも、まやかしの安全を誤解しないために重要です。そこで、ジョブがスキップされた際は Pull Request にコメントをつけるようにしています。

f:id:keik_117:20220325153436p:plain
ジョブがスキップされた旨を Pull Request にコメントする

参考までに、「フロントエンドのみが修正されたときはバックエンドテストを実行しない」「ジョブがスキップされた際は Pull Request にコメントをつける」を行う CircleCI 設定の例です。

skip_job_if_changes_only_in_frontend: &skip_job_if_changes_only_in_frontend
  name: Skip job if changes are only in frontend files
  command: |
      # PR トリガーではない場合はスキップ
      if [ -z "$CIRCLE_PR_NUMBER" ]; then exit 0; fi

      ISSUE_COMMENT_MARKER="generated by $CIRCLE_JOB job"
      FRONTEND_FILE_PATTERN='^(\.eslintignore|\.eslintrc\.js|\.jest|\.storybook|front|package\.json|tsconfig\.json|webpack\.config|yarn\.lock)'

      # NOTE: $BASE_BRANCH は執筆時点の CircleCI には組み込みで存在しない環境変数なので
      #       別途 GitHub API を用いて取得しセットするなどの手順が必要です
      if git diff --name-only $(git merge-base origin/$BASE_BRANCH HEAD) | grep -vP $FRONTEND_FILE_PATTERN; then
        echo 'There are changes except frontend files. Continue job...'
      else
        echo 'There are no changes expect frontend files. Skip job.'
        # PR にジョブがスキップされた旨をコメント追加する。
        # 並列実行するジョブから複数のコメントが追加されないようにするため1番目のコンテナからのみ行う
        if [ "$CIRCLE_NODE_INDEX" -eq 0 ]; then
          # job 実行ごとにコメントが増殖するのを避けるため古いコメントを削除
          curl \
            -s \
            -X GET \
            -H "Authorization: token $GITHUB_TOKEN" \
            https://api.github.com/repos/$CIRCLE_PROJECT_USERNAME/$CIRCLE_PROJECT_REPONAME/issues/$CIRCLE_PR_NUMBER/comments \
            | jq '.[] | select(.body | test("'"$ISSUE_COMMENT_MARKER"'")) | .id' \
            | while read COMMENT_ID; do
                curl -s \
                  -H "Authorization: token $GITHUB_TOKEN" \
                  -X DELETE \
                  https://api.github.com/repos/$CIRCLE_PROJECT_USERNAME/$CIRCLE_PROJECT_REPONAME/issues/comments/$COMMENT_ID
              done
          # 新しいコメントを追加
          curl \
            -s \
            -X POST \
            -H "Authorization: token $GITHUB_TOKEN" \
            https://api.github.com/repos/$CIRCLE_PROJECT_USERNAME/$CIRCLE_PROJECT_REPONAME/issues/$CIRCLE_PR_NUMBER/comments \
            -d '{"body":"フロントエンドのみの変更のため '$CIRCLE_SHA1' に対する <code>'$CIRCLE_JOB'</code> jobはスキップされました。<!-- '"$ISSUE_COMMENT_MARKER"' -->"}'
        fi
        circleci-agent step halt
      fi
jobs:
  rspec:
    steps:
      - attach_workspace:
          at: ~/
      - run:
          <<: *skip_job_if_changes_only_in_frontend
      ...

4. ファイル単位で遅いテストを直す

freee人事労務のバックエンドテストでは、RSpec を CircleCI のテスト並列実行機能(CircleCIの参考記事)を用いて16並列で実行しています。

CircleCI のテスト並列実行機能は、ジョブの実行時間が最短になることを目指し、並列実行する各コンテナに対して実行時間が極力均等になるようテスト実行対象を自動的に割り振ります。RSpec の場合は、この割り振りの最小分割単位がファイルであるという点に注意が必要です。つまり ファイル単位で極端に時間のかかるテストファイルがあるとそれがボトルネックとなり、いくら並列数を増やしたところで実行時間短縮の効果が出にくい です。

均等化の精度が悪い例を示します。今回諸々を改善する前(2021/10)の Rspec ジョブの実行例を持ってきました。

f:id:keik_117:20220325165607p:plain
各コンテナの実行時間が均等化されていない

16並列コンテナの総実行時間を合計すると272分。これを最も均等化できると 272 / 16 = 17.0分となるのに対して、実際には33.8分かかっています。理想値に対して倍程度の実行時間となっていて、均等化の精度が悪いと言えます。ファイル単位で極端に時間のかかるテストファイルを掴んでしまったコンテナが全体の足を引っ張っている結果です。ちなみに、より細かく分析していくと実際には1テストファイルで17分を超えるファイルは存在していないことがわかっており、理論的には均等化の精度を上げる余地が残されているようにも思いますが、ファイル単位での実行時間の分散が大きい場合は CircleCI 側での自動割り振りの精度が下がるような体感があります。

次に均等化の精度が改善された後の例を示します。諸々を改善した後(2022/2)の Rspec ジョブの実行例を持ってきました。

f:id:keik_117:20220325170016p:plain
各コンテナの実行時間が均等化されてきた

16並列コンテナの総実行時間を合計すると138分。これを最も均等化できると 138 / 16 = 8.6分となるのに対して、実際には9.5分かかっています。改善前の例と比較すると、そもそも総実行時間が大幅に減っているという違いがありますが、それは別として均等化の精度が大幅に改善されていることがわかります。こうなると、更に並列数を増やしていくことでより一層の実行時間の短縮を狙えます。

さて、ファイル単位で遅いテストに問題があるのはわかったとして、それをどのように発見し、どのように改善するとよいでしょうか。

ファイル単位で遅いテストを発見する

まずは遅いテストファイルを発見する必要があります。freee人事労務では RSpec のレポーターに rspec_junit_formatter を利用しているので、これが出力する XML ファイルをパースし、テストファイル単位での総実行時間を集計することで、遅いテストファイルを発見します。

例えばこういう XML レポートです。

<?xml version="1.0" encoding="UTF-8"?>
<testsuite name="rspec" tests="1221" failures="0" errors="0" time="532.492096" timestamp="2022-03-25T18:05:01+09:00">
  <!-- Randomized with seed 12467 -->
  <properties/>
  <testcase classname="spec.models.break_setting_spec" name="BreakSetting#valid? break_type が空の場合 is expected to eq [&quot;休憩種別が未入力です。&quot;]" file="./spec/models/break_setting_spec.rb" time="0.021405"/>
  <testcase classname="spec.models.break_setting_spec" name="BreakSetting#valid? break_type が有効な値の場合 is expected to eq []" file="./spec/models/break_setting_spec.rb" time="0.001795"/>
  ...
</testsuite>

irb などを起動して、XML を読み込んで集計しソートします。

require 'rexml'; pp Dir.glob('/Users/kato-kei/Downloads/rspec*.xml').map {|a| doc = REXML::Document.new(File.new(a)); REXML::XPath.match(doc, '/testsuite/testcase').group_by {|el| el['file']}.map {|k, v| [k, v.sum {|a| a['time'].to_f}]}.to_h }.reduce {|acc, a| a.reduce(acc) {|acc, (k, v)| acc.has_key?(k) ? acc[k] += v : acc[k] = v; acc } }.sort_by {|k, v| v }.to_h; nil

すると遅いテストファイルを発見できます。

{"./spec/<テストファイル名1>"=>1.3e-05,
 "./spec/<テストファイル名2>"=>0.00608,
  ...
 "./spec/<テストファイル名7>"=>41.653222,
 "./spec/<テストファイル名8>"=>143.082863,
 "./spec/<テストファイル名9>"=>454.253146}

ファイル単位で遅いテストを改善する

実際にいくつかのファイルを修正してきた経験則として、一つのテストファイルに数分・数十分も時間のかかってしまう原因としては主として次の3つがあります。

1つ目は、Model Spec と Request Spec など、粒度の違うテストに対する適切な粒度でのテストケースの記述できていないケースです。

Model Spec は比較的ユニットテスト的な粒度の細かいテストを書きやすいレイヤ(Ruby on Rails においてモデルレイヤには様々な責務を持たせることができるため一概には言いにくいですが)であり、一つのテストケース内に一つの expectation を書いていってもパフォーマンスの劣化は気にならないで済むことが多いでしょう。一方で Request Spec は粒度の荒いテストであり、一発の実行に時間がかかるため、一つのテストケースに一つの expectation を書いていくのは富豪的です。Request Spec においては、同条件で行われる実行に対する expectation は一つのテストケースに統合することで実行速度を回復します。

2つ目は、特定のテストケースにおいて不要なテストデータを意図せずに作りすぎているケースです。

RSpec の DSL は強力で、条件コンテキストの階層化やテストケースの抽出と再利用などが行えます。それ故に構造が複雑化して全体感が捉えきれなくなった結果、あるテストケースにおいて不要なテストデータを大量に作成していることが起きやすいです。具体例としてあったのは、ActiveRecord の scope(クエリ条件式に名前をつけて定義する機能) のテスト用の事前データとして、データベーステーブルに100レコードを作成している処理がありました。まずかったのは、実際に100レコードが必要となるテストは数ケースしかないにもかかわらず、事前データの作成処理を広域の before hook で行っており、加えてそのテストファイルには合計200以上のテストケースがあったことです。事前データの作成処理を必要なスコープに限定することで実行速度を回復します。

3つ目は、単に大量のテストケースが実行されているというケースです。

これが起きる原因の一つは、2つ目のケースと同様、構造が複雑化して全体感が捉えきれなくなることで、意図せずに見た目以上の大量のテストケースを実行しているという場合です。もう一つの原因は、互いに影響を及ぼし合わない直交する複数仕様に対して、組合わせ網羅的なテストをしてテストケース数が爆発している場合です。特に Request Spec においてこうした原因により大量のテストケースが実行されている場合は目が当てられないため、Request Spec 上での多層的な contextshared_examples_for / it_behaves_like を使っている場合には注意が必要です。狙いを定めたテストとなるようテストケースを絞り込むことで実行速度を回復します。

5. 全テストケースで共通的に実行される処理の見直し

RSpec の場合、spec_helper.rb などに全テストケースで実行する共通の before / after hook 処理を書くことがあると思います。こうした hook 処理コストは全テストケース数に掛け算されるので、たとえ1回の処理時間がわずかであっても、全体としては巨大な影響を持っている可能性があります。

例えばfreee人事労務では全テストケース数が2万ほどありますが、1回で100msの共通 hook 処理がある場合、全体としては 2000秒=33分、16並列の実行環境においては待ち時間が2分強、かさ増しされることになります。

灯台下暗し。見直してみると思いがけない発見があるかもしれません。

コスト削減は開発体験も改善する

実は、今回の自動テスト実行時間の短縮の取り組みは、全社的な金銭コスト意識の高まり、その中でも開発に利用している SaaS の費用削減の余地を探る取り組みを起点として始まったものでした。

コスト削減、特に費用削減と聞くと、トップダウンでの締め付けを受けながらなんとか達成していく、そんなイメージを想起される方もいるかと思います。ですが、コストを掛けて価値を生み出しているものをターゲットとして、コストを削減すると同時に価値も削減するようなやり方は、エンジニアリングを放棄していると言えるでしょう。それよりも、価値に連なっていない「あるべきではないコスト」を探してみると意外と足元に埋まっているかもしれません。これを削減することは、金銭コストだけでなく開発体験の改善さらには品質の改善にもつながっていきます。

さて、もっと単純に考えみても、自動テスト実行時間の短縮というのは因果や結果がわかりやすい問題設定であり、エンジニアリングしがいのあるテーマです。腕試しに、気晴らし、頭の体操に、挑戦してみてはいかがでしょうか?

※こちらの記事はLaunchable様より転載希望の旨をご連絡いただき、英文にて先方ブログに掲載していただきました。 www.launchableinc.com