Rails におけるパフォーマンス検証パターン: action 抜けた後が遅いケース

TL; DR

  • アクション抜けたあとは action の callback, rendering, rack middleware の世界
  • おもそうなものを特定して抜こう
  • bullet は重いぞ

事象

新機能開発中に、大量データ突っ込むか〜と思って突っ込んで開いたらまあ全然返ってこない。
はあ、まあそういうこともありますわよねと思って見ていたら、実はアクションから抜けるところまではそこそこの速度で終わることがわかった。1

調査

とゆーことは action 後に呼ばれる処理があやしい。 after_action はざっと確認した感じあんまりなさそうだった。2

ていうかそもそも rails log でも rendering xx sec と出ているのでレンダリングも終わっていることがわかった。

というわけでレスポンスを書き終わったはずなのにまだナニカをする層、つまり middleware があやしいということがわかる。

以下を参考に middleware ごとの経過時間を見ておく

http://blog.mirakui.com/entry/2012/04/03/slow-middleware

元コードは alias_method_chain を使っているので prepend に書き直してみた

gist.github.com

増加時間が長いやつを探す。今回は bullet が悪そうだった。業務アプリなのでログは載せないでおく。

とりあえず disable すればいいかなと思って設定変更したらはやくなったことを確認。
bullet は本番ではオフになるので特に問題にならないはずだなーというところまで考えて調査終了。


  1. このへんは愚直にメモ化されるところをまとめて評価したりしてログにぽこぽこ吐いて確認した

  2. これは目視で確認した。