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 に書き直してみた
増加時間が長いやつを探す。今回は bullet が悪そうだった。業務アプリなのでログは載せないでおく。
とりあえず disable すればいいかなと思って設定変更したらはやくなったことを確認。
bullet は本番ではオフになるので特に問題にならないはずだなーというところまで考えて調査終了。