Akatsuki Hackers Lab | 株式会社アカツキ（Akatsuki Inc.)

Akatsuki Hackers Labは株式会社アカツキが運営しています。

FactoryGirlのログからテストコストを計測してみた

技術

背景

アカツキではサーバーサイドフレームワークとしてRuby on Railsを採用しており、またそのテスト環境としてRspec/FactoryGirlを使用しています。RoR環境下のテスト体制としてはデファクトスタンダードになっているこの組み合わせですが、主にFactoryGirlの採用については 賛否両論だと言われています。採用を見送るネガティブな要員として、きちんとtraitを管理しないと不必要な関連オブジェクトも芋づる式に生成してしまい、テストの実行時間を大幅に増やしてしまうという問題があります(もっとも、これはFactoryの設計、管理を怠った開発者が原因であり、FactoryGirl自体の罪ではないかもしれませんが)。僕も複雑な条件のtraitの組み合わせや、テストの実行時間に日々悩まされています。

調べてみたこと

しかし実行時間に悩まされているとは言っても、どのFactoryがネックになっているか、ということについて実は確信を持っていないことに気づきました。FactoryGirlリポジトリのGETTING_STARTED.mdにあるものをそのままコピペしてきた、重いfactoryを通知してくれるちょっとしたスクリプトは使っていたのですが、どうにも情報源としてはあんまり有用とはいえません。なのでもっと詳しい情報が得られないか、少しFactoryGirlのコードを調べてみました。

コードを読んでみる

FactoryGirlが教えてくれるこのslow factoryの通知はActiveSupport::Notificationsを利用して行われています(こちらのエントリが詳しいです)。つまりActiveSupport::Notifications.subscribe("factory_girl.run_factory")に対応する通知を送っているところ(Notifications.instrument)がどこかにあるはずなのでそれっぽい単語でソースコードを検索すると、

# @lib/factory_girl/factory_runner.rb

instrumentation_payload = { name: @name, strategy: runner_strategy }

ActiveSupport::Notifications.instrument('factory_girl.run_factory', instrumentation_payload) do
  factory.run(runner_strategy, @overrides, &block)
end

というところが見つかります。このinstrumentation_payloadのhashが通知データとして受け取れるので、factory名とstrategy名はここから取得していたのだとわかりますね。とりあえずデフォルトの状態ではこれ以上はなにも情報を渡してくれていないようです。

しかしながらせっかくこのような仕組みを用意してくれてるのだから、勝手にforkして適当なデータを詰めれないものかとみてみると、辺りによさそうなインスタンス変数やらlocal変数がありますね。

factory = factory.with_traits(@traits)
@overrides = traits_and_overrides.extract_options!
@traits    = traits_and_overrides

factoryというデータが一般的な名前なので色々情報持ってそうだな、と期待できますね。適当にinstrunment_payloadに詰めて見てみると、例えば

# factory.definition.callbacks
=>[]

# factory.definition.attributes
=>, :build}]>

などのデータが取得できました。他にも様々なデータが含まれており、うまく処理すれば実行されたfactoryのほとんどの情報を得られそうです。

(簡単な情報をparseするgemを作りましたので、よろしければご利用ください。しかしこのinspectorをテストするためのFactoryオブジェクトの生成方法がわからずテストが書けてない……どなたか助けていただけると大変嬉しいです)

せっかくなので集計してみる

適当にFactoryLogなるモデルを通知から生成して、factory名+trait名の組み合わせを一意の識別子としてかかった時間を集計してランキング化してみると

moz.png

と、（どのtraitの）どのfactoryが1つあたり平均どのくらい時間を取り、またどのくらいの量がテスト中に実行されているのか、というデータがわかりました。これにより、例えばテスト時間を短縮したいと思った時にどのfactoryから改善していくか(例えば一部をDBに静的に置いておくようにしたり、mock objectを使うようにするなど)みたいな戦略が立てやすくなりました。

(ちなみにこちらもRails engineとして簡単なgemを書きました。といっても簡単なクラスメソッドをちょこっと書いたモデルがあるだけのものですが……こっちもcontributeお待ちしております)

まとめ

「推測するな、計測せよ」「プログラムの処理にかかる時間の80%はコード全体の20%の部分が占める」とは有名な言葉ですが、OSSのライブラリの場合、デフォルトでは提供されていないような情報も、少し手を加えることで取得できたりすることがあるので、気になったりしたら少しコードを読んで調べてみると、より効率的な業務が可能になるかもしれません。今回はFactoryGirlのコードに少しだけ手を加えてテストデータ生成のコストを計測する方法についてご紹介しました。

おまけ

実はRspecのそれぞれのexample(テストケース)についても、このようにメタデータが取得できます。 また、独自にメタデータを定義もできるようです。うまく使えばテストに対してtag付けして一部のテストのみを設定でskipしたり、fail時に詳細情報を出力するようにしたり色々便利になりそうです。

参考: RSpec 3の重要な変更