こんにちは！株式会社OPTiMに所属しております川田剣士です。最近の業務でCIの自動テストのjobの実行時間を10分から38秒まで1人で縮めることに成功しまして、こちらの経験を皆さんにも共有したく技術執筆をしようと思いました。記事に対する質問・コメント大歓迎です！

目次

タスクを取り組むに至った背景
CIが遅い原因の調査
解決方法
最終結果
本タスクを取り組んだ感想
終わりに

タスクを取り組むに至った背景

まず前提知識として私の担当しているプロジェクトでは、主にJava,SpringBoot,テストフレームワークにJUnitを利用しています。また、マイクロサービスアーキテクチャを採用しています。今回、CIの実行時間短縮に成功したマイクロサービスをマイクロサービスAと以下で記載します。また、他に存在する特定のマイクロサービスをマイクロサービスBと以下で記載します。また、マイクロサービスAとマイクロサービスBはどちらもJava,Spring Boot,JUnitを利用しています。

タスクに取り組むきっかけとなったのは、以下の状況であったからです。

マイクロサービスA:　テスト実行時間10分2秒,実行しているテストの数222個
マイクロサービスB:　テスト実行時間4分42秒,実行しているテストの数1821個

技術の構成がマイクロサービスAとBでほぼ同じであるにも関わらず、テストの数が圧倒的に多いマイクロサービスBのテスト実行時間の方がマイクロサービスAの実行時間よりも短い状況でした。そのため、マイクロサービスA内の実装内容やテストの書き方などに問題があるなと推測し、マイクロサービスAのテストが遅い原因の調査をすることになりました。

CIが遅い原因の調査

調査方法としては、まずはボトルネックの特定のためにマイクロサービスAのCIのログを目視で確認していました。とりあえず、1つのテストファイルで1秒以上かかっているテストファイルを探したところ、以下の3つのファイルが見つかりました。

テストファイルX:　テスト実行時間570.8秒,実行しているテストの数44個
テストファイルY:　テスト実行時間1.4秒,実行しているテストの数2個
テストファイルZ:　テスト実行時間1.2秒,実行しているテストの数3個

テストファイルXに関して、1テストあたり平均13秒近くかかっていることがわかりました。そこで、テストファイルY,Zは一旦保留にして、テストファイルXのテストが遅い原因の特定と解決を目指すことにしました。

テストファイルXのテスト実行時に実行される処理を追っていったところ、以下のような実装を発見しました。

import org.springframework.streotype.Component
import org.springframework.retry.annotation.Backoff
import org.springframework.retry.annotation.EnableRetry
import org.springframework.retry.annotation.Retryable
import org.springframework.web.client.RestClientException

@Component
@EnableRetry
public class classA {
    @Retryable(value = { RestClientException.class }, maxAttempts = a, backoff = @Backoff(b))
    functionA{
        ~~~中略~~~
    }
    ~~~中略~~~
    @Retryable(value = { RestClientException.class }, maxAttempts = a, backoff = @Backoff(b))
    functionB{
        ~~~中略~~~
    }
}

実装内容としては、マイクロサービスAから他のマイクロサービス(ここではマイクロサービスCと呼ぶ)にリクエストを送った時にマイクロサービスCの状態が原因でリクエストが正常にできなくRestClientExceptionを取得したときに、b秒間の待機後に最大a回までリトライを行うという実装です。今までは上記のように設定値をハードコーディングしており、実行環境によって設定値を変更できる状態ではなかったです。

続いて、テストファイルXの中身を確認したところ、上記の設定値のままリトライ処理が正しく行われているかをテストで確認するためにThread.sleep()が大量に利用しており、中にはThread.sleep(100000)などもありました。(Thread.sleep()は1000で1秒である。100000だと100秒スリープすることになる。)しかし、設定値a,bをテスト時にも必ず利用する必要はなく、テスト時は設定値を変えた方が良いと判断しました。

そこで、解決方法として、maxAttemptsとbackoffを環境変数として設定し、実行環境によって設定値を変えるように実装修正しました。

解決方法

やり方としては、以下の実装部分

@Retryable(value = { RestClientException.class }, maxAttempts = a, backoff = @Backoff(b))

を

@Retryable(value = { RestClientException.class }, maxAttemptsExpression = "${maxAttempts}", backoff = @Backoff(delayExpression = "${backoff}"))

に修正しました。参考文献：How to make configurable Retryable maxAttempts and backoff from application.properties file in spring boot

環境変数の設定値に関して、デフォルトではapplication.propertiesのファイル内の設定値が読み込まれるのですが、テスト用のpropertiesファイルなどにmaxAttempts,backoffの設定値を加えた場合は、テスト用のpropertiesファイルの設定値がテスト時に利用されます。今回は、maxAttempts=a,backoff=0をテスト用のpropertiesファイルに追加しました。

上記の変更後にとりあえず、Thread.sleep()を全て2000にして何度か実行したところ、全て通りました。この時すでに、最初の状況からはかなり実行時間が改善されたのですが、引き続き適切なThread.sleep()を模索していきました。具体的には、以下のような流れです。

2000から1000に全部かえてテストを全実行して、落ちたテストは2000のまま
1000から500に全部変えてテストを全実行して、落ちたテストは1000のまま
500から300に全部変えてテストを全実行して、落ちたテストは300のまま
...

上記の流れで適切な設定値を判断して設定しました。

最終結果

最終結果を以下にまとめます。

ボトルネックであったテストファイルXの実行時間

# before
テストファイルX:　テスト実行時間570.8秒,実行しているテストの数44個
# after
テストファイルX:　テスト実行時間14.9秒,実行しているテストの数44個

マイクロサービスAのciのテストjobの実行時間

before
マイクロサービスA:　テスト実行時間10分2秒,実行しているテストの数222個,1テストあたりの平均実行時間2.71秒
after
マイクロサービスA:　テスト実行時間38秒,実行しているテストの数222個,1テストあたりの平均実行時間0.17秒

最初に比較材料として出したマイクロサービスBと比較しても、

マイクロサービスB:　テスト実行時間4分42秒,実行しているテストの数1821個,1テストあたりの平均実行時間0.15秒

と平均実行時間が両者でほぼ変わらないことがわかります。

本タスクを取り組んだ感想

今回ボトルネックとなっていたテストファイルはタスクに取り組んだ日からおよそ9ヶ月ほど前から存在しており、かつマイクロサービスAは頻繁に開発していたマイクロサービスであったため、もっと早くに解決できたらよかったなと少し反省しています。また、現在もマイクロサービスAは頻繁に開発しているため、今回のパフォーマンス改善は開発チーム内で喜んでもらえました。今後もパフォーマンス上問題があるなと判断したらどんどん改善して、より良い開発環境・より高品質なプロダクトを追求していこうと思います。後、今まで自分は業務ではapiの開発や改修作業が多く、パフォーマンス改善の経験が少なかったのですが、パフォーマンス改善タスクはどれだけ改善したか数値で判断できるので、今回のタスクをきっかけにパフォーマンス改善の楽しさに気がつきました。皆さんはプロダクトや開発環境のパフォーマンス改善楽しんでいますか？どんな風に取り組んでいらっしゃるのかコメントいただけるとすごく嬉しいです！

終わりに

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