バイセル Tech Blog

バイセル Tech Blogは株式会社BuySellTechnologiesのエンジニア達が知見・発見を共有する技術ブログです。

CASH APIのRspecの実行時間が肥大化していた話

始めまして!2020年に新卒入社したテクノロジー開発部の富澤と申します。

普段は弊社が配信しているCASH(キャッシュ)のサーバーサイドの開発を中心に様々な開発に携わっています。

cash.jp

今回はCASH APIのRspecの実行速度を調査、改善した時の事を記事にさせて頂きます。

はじめに

Rspecの実行時間が1時間近く掛かっていたせいで、

CI待ち→失敗→修正

を繰り返すと尋常じゃない時間が掛かってしまう事が問題になっていました。

f:id:bst-tech:20201212172841p:plain
遅い....。

RspecやCIの高速化について調べてみると、大量のテストケースを分散処理やキャッシュ化を駆使して高速化に成功した例をたくさん見つける事ができます。

今回はそういった話ではなく、

テストケース数に対して実行時間が明らかに肥大化している

場合の話になります。

少し特殊な事をしましたが、同じような状況に遭遇した方の参考になればと思います。

原因調査

まず何が問題なのかを特定するために計測を行いました。

Rspecではrspec --profile example数とする事で実行時間が長い上位exampleを抽出する事ができます。

原因1: 毎回マスタ投入していた

まず、シンプルに全てのspecファイルの実行時間を計測してみました。

テストファイルごとにexample数に隔たりがあると比較できないので

テストファイルごとの平均example実行時間を箱ひげ図にプロットしてみました。

f:id:bst-tech:20201212160737p:plain
全specファイルの平均実行時間

箱が潰れています(オレンジの線の前後が箱ですw)

異常に時間が掛かっているspecファイルがある事がすぐに分かります。

該当specファイルを見てみると共通してshared contextによって毎回マスタが全投入されている事が分かりました。

shared contextを含むRspecの詳細については弊社テックブログにも説明があるので参考にして頂ければと思います。

Rspecの実装について - バイセル Tech Blog

これを一回だけ投入するようにすれば大幅は改善が図れそうな事が分かりました!

方法は後述します。

原因2: DBをcleanする時に全てのテーブルを探索していた

仮にこの外れ値を取り除けた場合の箱ひげ図もプロットしてみます。

f:id:bst-tech:20201212155008p:plain
外れ値を除いた場合

お気づきの方も多いかと思いますが、

全体的に遅いです。

全てのspecファイルの平均実行時間が1秒以上掛かっており、これはほとんどのitブロックの実行に1秒以上掛かっている事になります。

テスト実行時のデータベースとのやり取りを監視してみるとデータベースをCleanする方法に問題がある事が分かりました。

簡単に説明すると、itブロック実行後に毎回全てのテーブルを探索してレコードを削除する挙動になっていました。

これはinsertがあったテーブルを覚えておき、該当デーブルだけレコードの削除を行うようできれば改善ができそうです!

改善方法

具体的にはDatabaseRewinder導入と設定の変更を行いました。

DatabaseRewinderの導入

CASHでは既に導入されているが設定ファイルが整っておらず一部でしか使っていない状態でした。

github.com

原因2に対する対応方法

insertがあったテーブルを覚えておき、該当デーブルだけレコードを削除

をやってくれるgemです。導入は基本的にReadmeに従えばOKです。

今回の設定ファイル(spec_helper.rb)は以下のような感じにしています。

RSpec.configure do |config|
  ....
  # rspec hoge_spec.rb コマンド実行前に呼ばれる
  config.before(:suite) do
    DatabaseRewinder.clean_all
  end

  config.after(:each) do
    # 「insertがあったデーブルだけレコードを削除」をやってくれる
    DatabaseRewinder.clean
  end

  config.after(:suite) do
    DatabaseRewinder.cleaners.each do |cleaner|
      # 削除対象外のテーブルはexceptに入っている
      # コマンド実行後はテストDBがきれいになって欲しかったので例外を無しにする
      cleaner.except = []
    end
 # 全員消す
    DatabaseRewinder.clean_all
  end
end

この辺は場合に応じてよしなに設定すればいいと思います。

before,afterの設定は以下を覚えておくと便利です!

  • suite: rspecコマンド実行前後
  • context: contextブロック呼び出し前後
  • each: itブロック呼び出し前後

cleaner.exceptによる例外の設定については次に説明します!

マスタを一度だけ投入するように設定を変更

shared contextの該当ファイル部分に以下のようなイメージで設定を行います。

RSpec.shared_context 'hoge hoge' do
  
if 「投入したいtableにレコードが存在してない時(マスタ投入してない時)」
  before(:context) do
    # 例外を設定する
    DatabaseRewinder.cleaners.each do |cleaner|
      cleaner.except = 投入されるtable名の配列
    end

 # マスタ投入を実行する.seed_fuの場合は以下
    SeedFu.quiet = true
    SeedFu.seed
  end
end

大まかな流れ

  1. shared contextが呼ばれる
  2. cleaner.exceptにマスタ管理しているtable名配列が入る
  3. マスタ投入
  4. 例外に入ったマスタtableはこれ以降は消えない

これでマスタ投入1回だけにできるようになりました!

結果

CIの実行時間を10分以下に抑える事ができました!!

f:id:bst-tech:20201212180902p:plain

この方法が良い方法かどうか

あまり良い方法ではないと思います。

今回は紹介できませんでしたが、実際には以下の2種類のテストデータを両立させる事ができませんでした。(idがぶつかるなど)

  • Factory botによるマスタデータの作成
  • マスタ一括投入によるレコード作成

全てをリファクタリングするのは時間的に現実的ではなかったので、恣意的にテストの実行順序をfixさせマスタ投入のタイミングを調整する必要がありました。

本来はテストの実行順序はランダムにしても通る事が理想だと思います。

新しくプロジェクトを立ち上げる場合、マスタ系のテストデータは初回に一括投入される前提でテストを書けると速度的な意味では理想的だと思いました!

この辺はCASHがかつて別の会社によって運営されていた事が少し関係あったりします!

tech.buysell-technologies.com

tech.buysell-technologies.com

おわりに

長くなってしまいましたが最後までお読み頂きありがとうございました!

特殊な方法ではありますが大幅に時間を短縮させる事ができました。

バイセルテクノロジーズではエンジニアを募集しています。

エンジニア歴1年に満たない私でも声を上げればチャレンジさせて貰える環境が揃っていると思います。

ご興味のある方は是非ご連絡をお待ちしております!