はじめまして、エンジニアリンググループの山口です。9月にjoinし、クラウド型電子カルテ「デジカル」を開発しています（今後「エムスリーデジカル」として本格展開することがプレスリリースで発表されました！）。
今回は、テスト並列化や札束ビンタ以外の方法で、GitLab CIの実行時間を15%短縮した話です。
3行でまとめると
- GitLab CIのrawログに隠し要素がある
- 原因の深掘り大事
- キャッシュを雑に設定してはいけない
前提: デジカルの開発スタイル
デジカルは、 Ruby, Scala, Java, JavaScript と複数の言語を組み合わせてサービスを構成しています。
チームの開発スタイルは以下の通りで、比較的安全に開発が進められるようになっています。
- git-flowに近い開発フロー
- GitLab CIによるビルド、ユニットテスト、静的解析
- 窓が壊れているのを放置しない (割れ窓理論 - Wikipedia)
- 誰もレビューしていない状態でマージしない
- CIが通らない状態でマージやリリースをしない
ただし、改善の余地は山ほどあります。そのひとつは、"CIの遅さ"でした。
問題: CIが遅いことによる弊害
CIは、全ジョブ合計で1時間半近く掛かっていました。依存関係のないジョブを複数ランナーで並列実行しても40分。遅い。
CIの遅さによって、主に2つの問題が生じていました。
hotfixリリースに時間が掛かる
好ましくはありませんが、何らかの理由で急いでリリースする場合があります。
その際、CIが通ってからリリースするようにしているため、CIの遅さはそのままリリースの遅さに直結します。仮に不具合の修正だとすると、修正の適用がそれだけ遅れます。これは問題です*1。
また、それを認識した上でCIを待たなければならない、という精神的な辛さもあります。
コンテキストスイッチに時間が掛かる
時々CIの通らないpushをしてしまうこともあります。しかし、その失敗が通知されるのは、最悪の場合1時間半後です。
もう内容はほとんど覚えていません。なんだっけ、と思い出す時間が積み上がります。
原因: なぜCIが遅いのか？
この問題に対処することを決め、早速原因を探っていきます。
どの"ジョブ"が遅いか？
GitLab CIは、CI/CD > Jobsからジョブ単位の実行時間を確認することができます。早速確認します。
| ジョブ | 実行時間 |
|---|---|
| test:rspec | 21分13秒 |
| test:scala | 15分41秒 |
| lint:eslint | 4分59秒 |
| lint:rubocop | 3分24秒 |
| (他省略) |
一見、テストを早くすれば良いように見えます。しかし、本当に「テスト」自体が原因でしょうか？
例えば、rspecジョブには、rspec以外にもDockerコンテナの生成やリポジトリのクローンなど様々な処理を含んでいます。まだ結論づけるには早計です。
どの"セクション"が遅いか？
では、処理ごとの実行時間を調べていきましょう。
隠されたタイムスタンプを表示する
公式ドキュメントには記載されていませんが、GitLab CIのログには、ANSI エスケープシーケンスで隠されている部分があります。そこに、処理（セクション）開始/終了時のタイムスタンプが記録されているのです。
例として、GitLab Community EditionのCIログを見てみましょう。
タイムスタンプは見当たりません。"Show Complete Raw"をクリックして生のログを見てみます。
見えなかった部分が見えてきます。ANSI エスケープシーケンスが混ざっていて分かりにくいですが、反転している箇所がまさにタイムスタンプです。
セクションごとの時間を表示する
さて、タイムスタンプから実態を明らかにしましょう。ドキュメントがないため推測を含みますが、こういったセクション構成のようです。
| セクション | 処理内容 (推測) |
|---|---|
| prepare_script | 不明 *2 |
| get_sources | リポジトリ取得 |
| restore_cache | キャッシュ復元 |
| download_artifacts | アーティファクト(成果物)取得 |
| build_script | scriptに記載したスクリプト実行 |
| after_script | after_scriptに記載したスクリプト実行 |
| archive_cache | キャッシュ保存 |
| upload_artifacts_on_success | アーティファクト(成果物)保存 |
試しに、 test:rspec ジョブのRawログから所要時間を抽出してみます。
start: 1538104357 prepare_script: 1538104358 ( 1 second ) get_sources: 1538104392 ( 34 seconds) restore_cache: 1538104428 ( 36 seconds) build_script: 1538105494 ( 1066 seconds) archive_cache: 1538105563 ( 69 seconds) upload_artifacts_on_success: 1538105565 (2 seconds)
キャッシュの復元・保存、遅くない？
結局、テスト(rspec)の実行が大部分を占めていました… が、今回は一旦置いておきます。
他を見てみると、restore_cacheとarchive_cacheにも多少時間が掛かっています。
さらによく調べてみると、どのジョブもrestore_cacheとarchive_cacheにほぼ一定の時間を消費していることに気づきました。
なぜキャッシュに時間が掛かるか？
早速、.gitlab-ci.ymlのキャッシュ設定を確認してみます（以下、一部抜粋）。
cache: paths: - node_modules - vendor/bundle - engine/sbt-boot - engine/.ivy2
インデントのない部分でのcache定義、つまり全ジョブ共通で1個のキャッシュを持っており、そこにRuby/Scala/Node.jsのライブラリが全部入っていることが読み取れます。
試しに、手元の端末の node_modules と vendor/bundle のサイズを確認すると… 約1.4GB。これをジョブごとに復元・保存するので、時間が掛かるわけです。
$ du -h -d 0 node_modules vendor/bundle 398M node_modules 1.0G vendor/bundle
原因を突き止めるのに手間取りましたが、原因自体は単純なものでした…
解決: キャッシュを適切に
原因は「巨大な」「ひとかたまり」のキャッシュでした。これを「複数の」「小さな」キャッシュに分割します。
cache:keyでキャッシュを分割
rspecを実行するのにNode.jsのライブラリは不要で、逆も然りです。よって、ジョブごとに必要なライブラリのみをキャッシュとして持つように変更します。
GitLab CIのキャッシュはジョブごとに設定ができ、また cache:key によってキャッシュに名前を付けて使い分け／使い回しすることが出来ます。
今回は言語ごとにキーを分け、キャッシュを分割しました。
test:rspec: cache: key: "${CI_PROJECT_PATH}-RUBY" paths: - vendor/bundle
(おまけ) gemのドキュメントはインストールしない
gemはデフォルトでドキュメント類もインストールされますが、CIには不要なのでついでに省きます。
test:rspec: script: - "echo \"install: --no-document\" > ~/.gemrc" - "echo \"update: --no-document\" >> ~/.gemrc"
結果: 15%短縮
この変更を適用した結果です。
| 結果 | 全ジョブ合計時間 |
|---|---|
| 適用前 | 5,223 秒 (87分03秒) |
| 適用後 | 4,452 秒 (74分12秒) |
約13分、15%の実行時間短縮が出来ました。
ジョブが並列実行される場面では、調子が良いと30分を切るくらいになりました。
とはいえ、まだ全然早くありません。10分未満が理想です。
We are hiring!
こうした地道な改善も、チームリーダのUSA出張のような大きなイベントも、「やりたい」と言えば入社歴や立場に関係なくチャレンジできるのがエムスリーの魅力です。
もし興味がありましたら、カジュアル面談などでざっくばらんにお話ししてみませんか？ お待ちしています！
