業務で開発しているプロジェクトで、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でアーカイブを作成するときにナノ秒単位でタイムスタンプを保持する方法がないか聞いたところ、以下のリンクを教えてもらいました。

unix.stackexchange.com

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アーカイブを作成してリストアするとよいでしょう。

まとめ

sbt 1.xではコンパイルキャッシュが使えるかどうかの判定にファイルのナノ秒単位のタイムスタンプを使っているように見える
sbt 1.xではコンパイルキャッシュ関連のファイルが作成されたタイムスタンプと、それがリストアされたときのタイムスタンプが完全に一致していないとコンパイルキャッシュが効かない
tar --format posix オプションでナノ秒単位のファイルのタイムスタンプが保存できる

くろの雑記帳

sbt 1.x 系にアップグレードしたらCIでコンパイルキャッシュが効かなくなったので対処した