業務で開発しているプロジェクトで、sbtを0.13.17 から 1.1.1にアップグレードして喜んでいたらCIでキャッシュが効かなくなってしまい、ビルド時間が遅くなるという事象を経験したのでどのような調査をしたのかと、対処方法を書きます。ちなみにCIはCircleCI2.0を使っています。
コンパイルキャッシュが効かなくなる現象の確認
プロジェクトの作成
環境を用意します。Ubuntu16.04上にsbtをインストールしました。手順は以下のものを参考にしました。
sbt Reference Manual — Linux への sbt のインストール
hello と出力するだけのプロジェクトをつくります。 scala/scala-seed.g8 のテンプレートを使いました。
ubuntu@c01:~$ sbt new scala/scala-seed.g8 [info] Set current project to ubuntu (in build file:/home/ubuntu/) A minimal Scala project. name [Scala Seed Project]: hello-world Template applied in ./hello-world
コンパイルと実行
動作確認をします。 sbt run を2度実行しています。
ubuntu@c01:~$ cd hello-world/ ubuntu@c01:~/hello-world$ sbt run [info] Loading project definition from /home/ubuntu/hello-world/project [info] Updating ProjectRef(uri("file:/home/ubuntu/hello-world/project/"), "hello-world-build")... [info] Done updating. [info] Compiling 1 Scala source to /home/ubuntu/hello-world/project/target/scala-2.12/sbt-1.0/classes ... [info] Done compiling. [info] Loading settings from build.sbt ... [info] Set current project to hello-world (in build file:/home/ubuntu/hello-world/) [info] Updating ... [info] Done updating. [info] Compiling 1 Scala source to /home/ubuntu/hello-world/target/scala-2.12/classes ... [info] Done compiling. [info] Packaging /home/ubuntu/hello-world/target/scala-2.12/hello-world_2.12-0.1.0-SNAPSHOT.jar ... [info] Done packaging. [info] Running example.Hello hello [success] Total time: 1 s, completed Mar 21, 2018 6:38:59 AM ubuntu@c01:~/hello-world$ sbt run [info] Loading project definition from /home/ubuntu/hello-world/project [info] Loading settings from build.sbt ... [info] Set current project to hello-world (in build file:/home/ubuntu/hello-world/) [info] Packaging /home/ubuntu/hello-world/target/scala-2.12/hello-world_2.12-0.1.0-SNAPSHOT.jar ... [info] Done packaging. [info] Running example.Hello hello [success] Total time: 0 s, completed Mar 21, 2018 6:39:17 AM
1度目はコンパイルが走っていて、2度目はコンパイルキャッシュが効いているため、コンパイルを行わずに実行されていることがわかります。
CI上で行われているのと同様にコンパイルキャッシュの保存/展開操作を行う
CI上で行う操作は、
です。
CI上の環境と同じ事を行ってみましょう。ソースコードはチェックアウトされたとみなして、初回のテストなのでキャッシュは存在しません。なので3のコンパイル・テストの工程からはじめます。
コンパイル・テスト
ubuntu@c01:~/hello-world$ sbt test [info] Loading project definition from /home/ubuntu/hello-world/project [info] Loading settings from build.sbt ... [info] Set current project to hello-world (in build file:/home/ubuntu/hello-world/) [info] HelloSpec: [info] The Hello object [info] - should say hello [info] Run completed in 567 milliseconds. [info] Total number of tests run: 1 [info] Suites: completed 1, aborted 0 [info] Tests: succeeded 1, failed 0, canceled 0, ignored 0, pending 0 [info] All tests passed. [success] Total time: 1 s, completed Mar 21, 2018 6:52:09 AM
先程実行した時のコンパイルキャッシュが残っているのでコンパイルは走っていませんね。テストもきちんとパスしました。
キャッシュの作成・保存
tarコマンドを使って、 target ディレクトリ以下を1つのアーカイブにまとめます。
その他にも実際のCIでは ~/.sbt や ~/.ivy2 といったディレクトリもキャッシュされるようにする必要があります。今回はこの2つのディレクトリは問題の事象に関係がなかったので target ディレクトリだけを対象にします。
ubuntu@c01:~/hello-world$ tar cvf cache.tar target/ target/ target/streams/ target/streams/$global/ target/streams/$global/dependencyPositions/ target/streams/$global/dependencyPositions/$global/ [... 以下略] target/scala-2.12/hello-world_2.12-0.1.0-SNAPSHOT.jar
実際のCIであれば、生成された cache.tar ファイルを保存して、次回のビルド時にこのファイルを展開してあげればコンパイルキャッシュが効くはず…です。
キャッシュの展開
先程生成したキャッシュを展開してみます。tarでアーカイブしたものをそのまま展開して上書きしただけなので特に変わりはないはずです。
ubuntu@c01:~/hello-world$ ls build.sbt cache.tar project src target ubuntu@c01:~/hello-world$ tar xvf cache.tar target/ target/streams/ target/streams/$global/ target/streams/$global/dependencyPositions/ target/streams/$global/dependencyPositions/$global/ [...以下略] target/scala-2.12/hello-world_2.12-0.1.0-SNAPSHOT.jar
再びテスト実行
再びテストを実行させてみます。
ubuntu@c01:~/hello-world$ sbt test [info] Loading project definition from /home/ubuntu/hello-world/project [info] Loading settings from build.sbt ... [info] Set current project to hello-world (in build file:/home/ubuntu/hello-world/) [info] Updating ... [info] Done updating. [info] Compiling 1 Scala source to /home/ubuntu/hello-world/target/scala-2.12/classes ... [info] Done compiling. [info] Compiling 1 Scala source to /home/ubuntu/hello-world/target/scala-2.12/test-classes ... [info] Done compiling. [info] HelloSpec: [info] The Hello object [info] - should say hello [info] Run completed in 640 milliseconds. [info] Total number of tests run: 1 [info] Suites: completed 1, aborted 0 [info] Tests: succeeded 1, failed 0, canceled 0, ignored 0, pending 0 [info] All tests passed. [success] Total time: 7 s, completed Mar 21, 2018 7:04:58 AM
なんと、コンパイルが再び走ってしまっています。キャッシュが効いていないということですね。sbt0.13.17を使っていたときはこのやり方でうまくいっていたのですが…。
原因
どのディレクトリをtarでアーカイブしてからリストアするとこの事象が発生するのか、 target ディレクトリ以下を順番に掘り下げて行って調査したところ、 target/scala-2.12/resolution-cache/com.example/hello-world_2.12/0.1.0-SNAPSHOT のディレクトリ以下のファイルが影響しているということがわかりました。
ubuntu@c01:~/hello-world/target/scala-2.12/resolution-cache/com.example/hello-world_2.12/0.1.0-SNAPSHOT$ ls -l total 3 -rw-rw-r-- 1 ubuntu ubuntu 647 Mar 21 07:04 resolved.xml.properties -rw-rw-r-- 1 ubuntu ubuntu 1943 Mar 21 07:04 resolved.xml.xml
このディレクトリにはファイルが2つあります。アーカイブなのでファイルの中身が変わるはずはありませんが、一応md5ハッシュの値を展開前と展開後で比べてみます。
# 展開前 ubuntu@c01:~/hello-world/target/scala-2.12/resolution-cache/com.example/hello-world_2.12/0.1.0-SNAPSHOT$ md5sum resolved.xml.* d369e9bf8b52bddc7da2f93e58b6b86f resolved.xml.properties 2c8964010ef6a2835dce1c3f2cc8853d resolved.xml.xml # 展開後 ubuntu@c01:~/hello-world/target/scala-2.12/resolution-cache/com.example/hello-world_2.12/0.1.0-SNAPSHOT$ md5sum resolved.xml.* d369e9bf8b52bddc7da2f93e58b6b86f resolved.xml.properties 2c8964010ef6a2835dce1c3f2cc8853d resolved.xml.xml
当たり前ですが、ハッシュ値は一致しています。
もう一点疑う余地があるとすれば、タイムスタンプです。
# 展開前 ubuntu@c01:~/hello-world/target/scala-2.12/resolution-cache/com.example/hello-world_2.12/0.1.0-SNAPSHOT$ ls -l total 3 -rw-rw-r-- 1 ubuntu ubuntu 647 Mar 21 07:04 resolved.xml.properties -rw-rw-r-- 1 ubuntu ubuntu 1943 Mar 21 07:04 resolved.xml.xml # 展開後 ubuntu@c01:~/hello-world/target/scala-2.12/resolution-cache/com.example/hello-world_2.12/0.1.0-SNAPSHOT$ ls -l total 3 -rw-rw-r-- 1 ubuntu ubuntu 647 Mar 21 07:04 resolved.xml.properties -rw-rw-r-- 1 ubuntu ubuntu 1943 Mar 21 07:04 resolved.xml.xml
特に変わりはないように思えますね…。ここでファイル作成時刻のタイムスタンプはもっと詳細な粒度で保持しているはず、という事を思い出しました。 ls コマンドの --full-time オプションで表示ができるようです。
# 展開前 ubuntu@c01:~/hello-world/target/scala-2.12/resolution-cache/com.example/hello-world_2.12/0.1.0-SNAPSHOT$ ls -l --full-time total 3 -rw-rw-r-- 1 ubuntu ubuntu 647 2018-03-21 07:04:52.724370184 +0000 resolved.xml.properties -rw-rw-r-- 1 ubuntu ubuntu 1943 2018-03-21 07:04:52.716369762 +0000 resolved.xml.xml # 展開後 ubuntu@c01:~/hello-world/target/scala-2.12/resolution-cache/com.example/hello-world_2.12/0.1.0-SNAPSHOT$ ls -l --full-time total 3 -rw-rw-r-- 1 ubuntu ubuntu 647 2018-03-21 07:04:52.000000000 +0000 resolved.xml.properties -rw-rw-r-- 1 ubuntu ubuntu 1943 2018-03-21 07:04:52.000000000 +0000 resolved.xml.xml
おっと…！これですね。タイムスタンプが秒単位で丸められています。ここのタイムスタンプが完全に一致していないためにプロジェクトに変更が加えられたと認識されて、フルでコンパイルが走ってしまっているのではないかという当たりがつけられました。どうやらtarは標準ではファイルのタイムスタンプは秒未満は切り捨てるようです。zipは標準だと2秒単位でタイムスタンプを丸めるようです。
コンパイルキャッシュが効くようにするために対処した
社内でtarでアーカイブを作成するときにナノ秒単位でタイムスタンプを保持する方法がないか聞いたところ、以下のリンクを教えてもらいました。
GNU tarを使っているときにposixフォーマットでアーカイブを作成するとよいということがわかりました。 --format posix をつけるとよいということですね。
再び実験
キャッシュを作ってからリストアする
ubuntu@c01:~/hello-world$ tar --format posix -cvf cache.tar target/ target/ target/streams/ target/streams/$global/ target/streams/$global/dependencyPositions/ target/streams/$global/dependencyPositions/$global/ [... 以下略] target/scala-2.12/hello-world_2.12-0.1.0-SNAPSHOT.jar ubuntu@c01:~/hello-world$ tar xvf cache.tar target/ target/streams/ target/streams/$global/ target/streams/$global/dependencyPositions/ target/streams/$global/dependencyPositions/$global/ [...以下略] target/scala-2.12/hello-world_2.12-0.1.0-SNAPSHOT.jar
テストを実行する
再びテストを実行してみます。
ubuntu@c01:~/hello-world$ sbt test [info] Loading project definition from /home/ubuntu/hello-world/project [info] Loading settings from build.sbt ... [info] Set current project to hello-world (in build file:/home/ubuntu/hello-world/) [info] Updating ... [info] Done updating. [info] HelloSpec: [info] The Hello object [info] - should say hello [info] Run completed in 710 milliseconds. [info] Total number of tests run: 1 [info] Suites: completed 1, aborted 0 [info] Tests: succeeded 1, failed 0, canceled 0, ignored 0, pending 0 [info] All tests passed. [success] Total time: 2 s, completed Mar 21, 2018 7:25:45 AM
今度はちゃんとコンパイルキャッシュが効きました！これで安心してCIをたくさん回せます。
ちなみにCircleCI2.0の persist_to_workspace 機能を使っている時も同様な事象が起きますので、自前で上記の手法でtarアーカイブを作成してリストアするとよいでしょう。
