先に結論から話すと、マイグレーションが多いほどIntegrantの起動にかかる時間が加速度的に増えるので、定期的にマイグレーションを圧縮しましょう。

背景

リリース当初、CIを回すのに20分程度かかったアプリケーションがある。
改修を重ねるごとにCIは遅くなり、とうとう40分近くかかるようになってしまった。
GitHub Actionsの使用制限は来るし、そもそも待ちが長いのは開発体験が悪い。

当初の直感

`lein test`が悪い？

CIのスクリプトに lein test と書いていて、それがテストの検索と実行に無駄な時間を発生させているかも。

`with-system` が遅い

当社でも、DBやAPIエンドポイントにアクセスするために ClojureのLaciniaでGraphQL API開発してみた
で紹介されているものとほぼ同じような、DIコンテナを起動・終了できるテストヘルパーを用意している。
そしてこれを使ったテストは、当然だがかなり時間がかかる。

だが、Webサーバーの起動、DBのクリーンアップ、DIコンテナの停止... どれが遅いかまでは直感的には分からない。

並列化よりも、そもそも1テスト実行するためにかかる時間を削減する方が効きそう

テストの並列実行も検討したが、GitHub Actionsがホストしてくれる実行環境は2コアで、並列実行したところでCI短縮の役には立たない。
また、テストをディレクトリごとに別のコンテナで実行することで総合的にかかる時間は圧縮できそうだが、アプリケーションの構成に依存したCIスクリプトを作るのはメンテが漏れた時に不具合のあるソースコードがデプロイされる危険性が上がる。

調査

`lein test` が遅い？

実行してみたところ、特に時間が変わったりはしなかったので、ここは本質的な問題ではないことがわかった。

`clojure.core/time` を各所に仕込んだ

上述の with-system を使った、DBアクセス部品のテストの各所に clojure.core/time を仕込んでみたところ、下記のような情報が取れた。

内訳は下記。

"DBクリーンアップ": 36
"DIコンテナの起動": 1546
"テストスクリプトの実行": 249
"DIコンテナの停止": 243

やはりDIコンテナの起動が非常に遅い。
でも一体、どのコンポーネントの起動に一番時間がかかっているんだろうか？

`init-key` を `with-redefs` して時間を測る

Ductが依存しているDIコンテナであるintegrantが提供している、コンポーネント起動用の関数を上書きして、コンポーネントごとに起動にかかる時間を取得してみた。

下記のスクリプトを dev/src/dev.clj とかにコピーして動かすと、 (go) した時に動くコンポーネントの起動時間がわかる。

(defn- measure-startup-time
  "各コンポーネントの起動にかかる時間の統計を取るためにシステムを起動&終了する."
  []
    (time
     (prep))
  (when system
    (throw (ex-info "System is awaken. Halt before measure." {})))
  (prep)
  (let [result-atm (atom {})
        default-init-key-fn integrant.core/init-key]
    (with-redefs [integrant.core/init-key (fn [key value]
                                            (let [start (System/nanoTime)
                                                  res (default-init-key-fn key value)]
                                              (swap! result-atm assoc
                                                     key
                                                     (/ (double (- (System/nanoTime) start))
                                                        1000000.0))
                                              res))]
      (go)
      (halt)
      (clojure.pprint/pprint @result-atm))))

結果、起動時間の長い順にトップ5は下記だった。

コンポーネント名	実行時間(ミリ秒)
:duct.migrator/ragtime	1361.694373
:app.my.component/reitit	54.298454
:duct.database.sql/hikaricp	47.869719
:app.my.component/google-drive	30.77795
:app.my.component/storage	25.766599

jettyサーバーの起動は6位。

よって、

マイグレーションの実行時間を最小化するのがめちゃくちゃ効きそう
次点で、DBしか要らないならreititを起動しない

のが有効そうということがわかった。

結果

当社ではPostgreSQLを利用しているので、 pg_dump を使って既存のマイグレーションを1ファイルにまとめることにした。
結果として、下記のようにテストの実行時間を圧縮することができた。

内訳は下記。

"DBクリーンアップ": 36
"DIコンテナの起動": 424
"テストスクリプトの実行": 249
"DIコンテナの停止": 243

このように、本来計測用のフックなどがない関数でも、好き勝手に計測することができます。
みなさんも、なにかおかしいなと思ったら clojure.core/time や with-redefs を活用して計測と対策の検討を進めてみてくださいね。

株式会社AGE technologiesについて

私の職場である株式会社AGE technologiesでは、煩雑な相続手続きを効率化するWebサービスを開発しています。
少しでも興味をお持ちいただいた方は、ぜひTwitterや弊社求人サイトからお声がけください。

Ductアプリケーションの単体テストが遅い理由を探る方法

背景

当初の直感

lein testが悪い？

with-system が遅い