この記事は、Merpay Advent Calendar 2021 の2日目の記事です。
こんにちは。メルペイのBackendエンジニアの 柴田 です。
はじめに
この記事は昨年書いた開発用ノートPCを活用して長時間ランニングテストを行うことに関する「長時間ランニングテストの勧め 〜開発用ノートPCの活用〜」の続編になります。そのため、前編となる昨年の記事を読まれているという前提で説明します。
昨年の記事では、Go言語でテストを実行する際に、TZ（タイムゾーン）、GOMAXPROCS、-pオプション、-raceオプションを組み合わせて長時間、何度もテストを実行することで、さまざまな問題を見つけられるということを説明しています。実際に、記事を読まれて実践された開発者はどのくらいおられるでしょうか。
今回は、昨年の記事の修正、この一年間で見つかった問題の紹介、長時間ランニングテストの課題について説明します。
前回の記事の修正
最初に、前回の記事の内容の訂正です。前回の記事では、「Spannerへの遅延時間」で、次のように説明していました。
MacBook Proの時刻とSpannerサーバの時刻に差があると、「未来の時間を指定している」としてエラーになることもあり、その場合、MacBook Proの時刻を調整する必要があります。
これは、間違いでした。
真の原因
Spannerでテーブルを作成する際に、フィールドによっては、次のようにallow_commit_timestampオプションを指定できます。
CREATE TABLE Performances (
...
LastUpdateTime TIMESTAMP NOT NULL OPTIONS (allow_commit_timestamp=true)
...
) PRIMARY KEY (...);実際にレコードをInsertしたりUpdateしたりする際に、そのフィールドに現在時刻を入れる代わりに、コミットタイムスタンプを表す値（言語ごとのライブラリで定義されており、Go言語ではspanner.CommitTimestamp）を設定します。その値を設定すると、Spanner側でInsertもしくはUpdateされた時刻を自動的に設定します。
もし、このようなフィールドにtime.Now()から取得した現在時刻を入れた場合、その時刻が、Spannerサーバの時刻よりもたとえ1nsであっても未来になっていると、Cannot write timestamps in the futureというエラーメッセージとともにFailedPreconditionで失敗します。
正直なところ、昨年は私自身がきちんと理解していなかったので、「MacBook Proの時刻を調整する必要があります」と書いてしまっていました。
テーブルの定義でallow_commit_timestampオプションが指定されているフィールドには、決して現在時刻を取得して入れてはいけません。なぜなら、マイクロサービスが動作しているPodの時刻とSpannerサーバの時刻が正確に一致することはないからです。その結果、Cannot write timestamps in the futureというエラーになる可能性はゼロではありませんので、本番環境で失敗する可能性は残ります。
したがって、MacBook Proで行っている長時間ランニングテストで、このエラーが発生したら、MacBook Proの時刻を調整するのではなく、問題となるコードを見つけて修正するのが正しい対処です。
原因調査
実際に調査してみると、テストが失敗する原因は以下の2種類でした。
- 製品コードで、フィールドに
time.Now()から返された値を設定していました。その結果、テストの際に、フィールドが含まれるレコードが挿入されたり、更新されたりすると、Spannerからエラーが返されます。そして、テスト対象のコードがエラーを返して、テストが失敗していました。 - テストコードの中で、事前準備としてテスト用のレコードを作成する際に、フィールドに
time.Now()から返された値を入れていました。そのレコードをテーブルに挿入しようとしてエラーが発生していました。そのようなテストコードでは、time.Now()から返された値をローカル変数に保存していて、Spannerからレコードを検索して取得したときに同じ値になっているかを検査していました。たとえば、次のようなコードです。
user := &database.User {
...
// CreatedAtフィールドはallow_commit_timestampオプションを持つ
CreatedAt: time.Now()
...
}
// userをSpannerのテーブルに挿入
err := database.Insert(ctx, user)
...
// Spannerのテーブルから検索してくる
storedUser := database.FindUser(ctc, ...)
if user.CreatedAt != storedUser.CreatedAt {
t.Errorf("storedUser.Created is %v, want %v",
storedUser.CreatedAt, user.CreatedAt)
}対処
- 製品コードに関しては、すべて担当者に修正してもらい、QA後に本番環境にリリースしてもらいました。
- テストコードに関しては、
time.Now()から返された値ではなく、spanner.CommitTimestampを設定した場合、Spanner側で記録される時刻は正確には分かりません。その対処としては、Spannerから返されたレコード内のフィールドの値を比較する際に、3秒程度の誤差は許容するという修正を私自身で行いました。
昨年の記事の訂正はここまでです。次にこの一年間で新たに気づいた点を説明します。
この一年間でのテスト失敗
この一年間で37件のflaky testの修正を行いました。平均すると3件/月となります。昨年の記事で述べた以下の原因がほとんどでした（詳しくは、昨年の記事を参照してください）。
- テストコードで許容している時刻の差が小さい
- テストコード間でのデータベースアクセスの排他処理が正しくない
- ゴルーチンのスケジューリング次第で発生する
新たなものとしては、以下の原因がありました。
テストレコードの干渉
t.Parallel()を用いたテストでは、テストのために生成されるレコードは、できる限りテストごとに独立するように作成されているはずなのですが、ときどき考慮不足で互いに干渉してしまって、テストが失敗します。
- テスト時間を短縮するために、多くのテストが
t.Parallel()を駆使して並行に実行されるようになっています。しかし、そこには多くの落とし穴があります（詳しくは、「Go言語でのテストの並列化 〜t.Parallel()メソッドを理解する〜」）参照 ）。本来独立したテスト用レコードでなければならないのですが、ときどき他のテストと干渉してしまっていました。 - t.Parallel()を多用したテストでは、多くのテストが並行に実行されます。また、ゴルーチンのスケジュールが必ずしも毎回同じになる保証はありません。その結果、テストレコードの干渉は、まれにテストが失敗するというflaky testの潜在的な原因となります。
DATA RACE
t.Parallel()を使った場合、正しくテストコードが書かれていないため、DATA RACE（データ競合）が発生することがありました。
- Go言語の
-raceオプションは、とても役立つ機能なのですが、実際にDATA RACEが発生しないと報告されないため、長時間実行する必要があります。 - DATA RACEもゴルーチンのスケジューリングに依存して発生しなかったり、発生したりするので、flaky testの原因となります。
日付けの計算間違い
テストコードで、日付を計算するのですが、計算を間違えていて、特定の日や特定の日のある時間帯だけ失敗していました。
たとえば、次の通りです。
- テストコードで3月29日に一ヶ月前を計算しようとして、2月28日ではなく、3月1日になって失敗する
- 月の最終日に、テストコードで翌日を計算しようとして、1日にはなるけど、月が翌月になっていない計算間違いで失敗する
- 日本時間の1日の午前0時から午前9時の間だけ失敗する。これは、JSTで計算すべきなのに、正しくJSTへの調整をしていなかったためにタイムゾーンをUTCとして実行すると失敗する。
- クラウド上のCIサーバでは常にUTCですし、MacBook Proで実行する長時間ランニングテストのスクリプトでは、JSTとUTCの両方でテストしています。
これらのテストコードに共通するのは、次の点です。
- 以前から潜在的に存在していたのではなく、テスト失敗が起きた時点で、一ヶ月以内に追加されたテストがほとんどでした。
- テストが書かれてリポジトリにマージされたときに、CIが成功し、その後しばらくの間（数日から数週間）、CIは成功し続けていました。
幸い、すべてがテストコードの間違いでしたので、本番環境には影響はありませんでした。また、私自身は昔から朝型の生活なのと、現在は在宅勤務なので、このようなテストコードでの日付けの計算間違いは、早朝に発見して修正することが多かったです。
MacBook Pro M1
実際のテストコードとは異なりますが、
time.Now() == time.Now()がMacBook Pro M1でtrueになってしまうことがあり、それが原因で失敗するテストがありました。time.Now()を2回呼び出しているので、通常は異なる値になるのですが、まれに同じ値になってしまうことがあります。
- メルペイに入社して3年以上、Intel CPUのMacBook Proを使っていたのですが、デュアルコアで少し非力でした。社内で、M1への交換ができるようになって早速交換したところ、この問題に遭遇してしまいました。実際のコードはもう少し複雑なのですが、実際に
time.Now() == time.Now()がtrueになるかを試してみたら、まれに、trueになりました（なぜ、このような現象になるのかは、調査していません）。 - これに関したテストは、MacBook Proでの実行はスキップしています。
Spannerのpriority=medium
開発者のテスト用のSpanner環境では、多くの開発者が使うため、Spannerへのアクセスのpriorityをmediumにした操作があると、いつまでも終わらないことがある。
- 以前は、priority=highだった操作が、本番環境でのチューニングとしてmediumになった結果です（詳しくは、@iwataさんの「Cloud SpannerにPriority指定してDMLを実行してみた」を参照）。
- これに関するテストも、MacBook Proでの実行はスキップしています。
一年半の結果
昨年の7月に現在のチームへ異動してきてから、MacBook Proを使った長時間ランニングテストを継続して行ってきました。異動してきたチームが担当しているマイクロサービスの単体テストやE2Eテストがその対象です。
私が異動してきた頃のテストは、次のような課題を抱えていました。
t.Parallel()で並行にテストを動作させると、テスト全体が非常に不安定だったため、t.Parallel()を使わないテストコードとなっていました。- すべてのテストを実行するのに時間を要しており、プルリクエストごとに実行されるCIでのテストもかなりの時間を要していました(10分以上）。
テストの並行化を進めながら、得た知見をまとめたのが、「Go言語でのテストの並列化 〜t.Parallel()メソッドを理解する〜」です。並行化の作業とともに、実践してきたのが、長時間ランニングテストです。結果として、現在は次のような状態になっています。
- テストコード全体は、
t.Parallel()を使って最大限に並行実行されるようになっている - CIでの実行時間が数分となっている
課題とまとめ
この一年半を振り返って、長時間ランニングテストの今後の課題は次のとおりです。
どうやったら多くの開発者に行ってもらうか
昨年の記事にも書きましたが、私が過去に行った二つのソフトウェア開発での長時間ランニングテストは、開発組織として実践したものです。
開発組織としてでも、個人としてでも、長時間ランニングテストを実践する場合、乗り越えなければならないのは次の点です。
自分の開発マシンでテストが失敗していたら、その一次調査の責任は自分自身が負う
他の開発者が書いていて、自分自身がそのコードのレビューさえしていないコードのテスト失敗を調査するというのは、心理的なハードルが高いです。それも、必ず再現するとは限らない失敗の調査です。
この一年半は、私個人として長時間ランニングテストを実施してきたので、私自身が調査してきました。自分では開発していないコードの失敗を調査するので、さまざまな原因の仮説を立てながら試行錯誤を繰り返してきました。
残念ながら、私自身は上記の課題に対する明確な答えはまだ持ち合わせていません。一方で、長時間ランニングテストを通して、この一年半で多くのことを学びました。昨年の記事と今回の記事を参考に、多くの開発者が実践してくれれば幸いです。
明日の記事は@yukinasuさんです。引き続きお楽しみください。
