Railsアプリのパフォーマンス調査をしよう

はじめに

Webサイトのレスポンスタイムが悪化している。なんとか改善したい！
改善するためには、まずボトルネックとなっている箇所を見つけることからはじめると思います。
そこで、今回はボトルネックとなっている箇所を調査する際に役に立つものたちを紹介します。

Benchmark

ある程度ボトルネックとなっている箇所の目処がついている場合は、Benchmarkを使用して改修前後の実行時間を計測できます。

下記の方法で、実行時間計測とログの出力をすることができます。

RubyのBenchmarkライブラリを使用する

ブロックで囲んだ箇所の実行時間を計測して返却してくれるので、それをログに出力して、改修前後の時間を確認します。

articles_controller.rb

require 'benchmark'

def index
  time = Benchmark.realtime do
    @articles = Article.all
    sleep(1)
  end
  logger.debug "計測結果：#{time}s"
end

development.log

計測結果: 1.0132758999970974s

Railsのcontroller,viewで使用できるbenchmarkメソッド

controller,viewだとbenchmarkメソッドを使用できるので、それを使うと便利です。下記のようにするだけでブロック内の実行時間計測と結果をログに出力してくれます。

articles_controller.rb

def index
  benchmark("計測結果") do
    @articles = Article.all
    sleep(1)
  end
end

development.log

計測結果 (1009.6ms)

bullet

パフォーマンス悪化の原因としてよく挙げられるのがN+1問題です。
bulletというGemがあるので、これを使用してN+1が起きていないかを探すことができます。

Gemfileに追加。開発環境でしか使用しないので、development指定します。

Gemfile

group :development do
  gem 'bullet'
end

Bulletを有効にするよう下記のように設定します。

config/environments/development.rb

config.after_initialize do
  Bullet.enable = true        # Bulletを有効にする
  Bullet.bullet_logger = true # ログに書き出す
  Bullet.alert = true         # ブラウザにポップアップ表示する
end

ページ読み込み時にN+1が発生していた場合はログに出力して教えてくれます。

log/bullet.log

GET /articles/
USE eager loading detected
  Article => [:user]
  Add to your query: .includes([:user])
Call stack
  /myapp/app/views/articles/index.html.slim:14:in `block in _app_views_articles_index_html_slim__3756776137332911182_70303078320700'
  /myapp/app/views/articles/index.html.slim:11:in `_app_views_articles_index_html_slim__3756776137332911182_70303078320700'

Bullet.alert = trueオプションだとブラウザでポップアップを表示してくれます。

peek-rblineprof

peek-rblineprofを使うとソースコードの行ごとにどれくらいの実行時間がかかっているのかを調査することができます。
https://github.com/peek/peek-rblineprof

Gemfileに追加します。

Gemfile

group :development do
  gem 'peek'
  gem 'peek-rblineprof'
  gem 'pygments.rb', :require => false # シンタックスハイライトさせたい場合追加
end

初期化用にファイルを作成します。

config/initializers/peek.rb

Peek.into Peek::Views::Rblineprof

CSSとJSファイルを読み込ませます。今回はとりあえず下記ファイルへ記載しました。

app/assets/javascripts/application.js

//= require peek
//= require peek/views/rblineprof
// コードにシンタックスハイライトさせたい場合、下記も追加
//= require peek/views/rblineprof/pygments

app/assets/stylesheets/application.css

//= require peek
//= require peek/views/rblineprof

いざ計測！
計測するURLにlineprofiler=appパラメータを付与してアクセスします。

http://localhost:3000/articles?lineprofiler=app

するとブラウザに下記のように表示され、どの行で時間がかかっているかを確認することができます。

controllerのsleep入れた箇所で約1000ms時間がかかっていることもわかりますね。
viewでは、タイトルを表示している箇所では時間かかっていないですが、ユーザー名を取得する箇所で時間かかっていることがわかり、改善への手がかりを掴むこともできます。便利...!(ここで実際N+1問題が起きています。)

N+1改善&sleep削除後

改善されていることが確認できました!

最後に

今回は簡単な例で紹介しました。すぐに使えて便利なので、パフォーマンス調査する際に活用できると思います。

明日は、@mamiyanさんの「食べログスタイルガイドを使ったカード型UIの汎用モジュール作成」です。お楽しみに!!