nazoです。
最近Symfonyを2.8にアップグレードしたのですが、その時にテストがものすごく遅くなってしまいました。ここではその調査と対処法について調べようと思います。
はじめに
Symfonyのバージョンを2.8にアップグレードした際に、CIの総実行時間が約10分→約30分（CircleCI上）になってしまいました。これでは開発効率が大幅に下がってしまいます。
テストが遅くなってしまったのですが、まず AliceBundle のバージョンを上げた時に挙動が大幅に変わったので、そのあたりが影響しているのかと思いました。確かにそこが遅い箇所もあったのですが、そうではなかったようです。
まずはProfile
とりあえずテスト（の一部）をXdebugに食わせて、遅い箇所を出しました。すると以下のような結果が得られました。（ハイライト行は本件とは関係ありません）
Monologが上位にいることから、ログが遅いことがわかったので、これのcall stackを辿ると、deprecatedなエラーを大量に出していることがわかりました。更に読み進めると、BCResourceInterfaceCheckerがdeprecatedを常に出すことがわかりました。エラーログが大量に出ることでMonologの処理が圧迫されているものだということがわかりました。
具体的な原因と対策
Symfony 2.8/3.0から、「キャッシュが最新かどうかはタイムスタンプの比較だけじゃないだろ！というかキャッシュがファイルとは限らないだろ！」という方針で、キャッシュの有効性を自前でチェックするためのinterfaceであるところのSymfony\Component\Config\Resource\SelfCheckingResourceInterfaceが用意され、従来のSymfony\Component\Config\Resource\ResourceInterfaceは残るものの、それをチェックするための機構は自前で実装する必要があります。この互換性の維持のために、2.8にはSymfony\Component\Config\Resource\BCResourceInterfaceCheckerというクラスが作られました。これはあくまで2系の互換性のために用意されたもので、ここを通るとThe class "%s" is performing resource checking through ResourceInterface::isFresh(), which is deprecated since 2.8 and will be removed in 3.0という警告が毎回出力されます。
一見、Monolog側の設定でログを抑えればいいように見えますが、MonologBundleでは、parameterに profiler という定義が存在し、かつ kernel.debug が true の場合、強制的にDebugレベルのログを処理するDebugHandlerが差し込まれます。このため、ログレベルの制御では回避することは難しくなっています。（テストをenv=prodで行えば一応回避できますが…）
これを調査した時点では、JMSDiExtraBundleとAsseticBundleがこれに対応しておらず、この状態を作っている原因ということがわかりました。 JMSDiExtraBundleは今のところ使っていなかったので一度削除、AsseticBundleはdev-masterでは対応されていたので一時的にそちらを見るように変更しました。
これにより、以下のようにMonologの実行時間の割合が大幅に下がりました。
またCIの実行時間も、10分くらいの実行時間に戻りました。
まとめ
Symfony 2.8は、3.0に向けた踏み台という印象が強く、かなり3.0に寄せた修正が入っています。 Symfony 2.8でdeprecatedが全て消えれば、3.0に移行するのは簡単になっている、という感じですが、全て対応するには使用しているBundleが全て対応される必要があり、それまではdeprecatedに悩まされることが多いと思います。
CIの実行時間の大半はテストに費やされる（このプロジェクトではこの修正後でも実行時間の8割がテストです）ため、テストの実行時間には常に悩まされる問題ですが、プロファイラを使って的確に計測することによって高速化できる可能性があります。今後も計測と高速化を定期的に行っていこうと思います。
UUUMでは、しっかりユニットテストを書いて開発したいエンジニアを募集しています。詳しくは以下をご覧下さい。
