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


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

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

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

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

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

```ruby: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メソッドを使用できるので、それを使うと便利です。下記のようにするだけでブロック内の実行時間計測と結果をログに出力してくれます。

```ruby: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指定します。

```ruby:Gemfile
group :development do
  gem 'bullet'
end
```
Bulletを有効にするよう下記のように設定します。

```ruby: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```オプションだとブラウザでポップアップを表示してくれます。
![スクリーンショット 2020-11-28 18.04.23.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/319369/2c52647e-653d-adf4-720b-0c53fff24c72.png)

## peek-rblineprof


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

Gemfileに追加します。

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

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

```ruby:config/initializers/peek.rb
Peek.into Peek::Views::Rblineprof
```
CSSとJSファイルを読み込ませます。今回はとりあえず下記ファイルへ記載しました。

```javascript:app/assets/javascripts/application.js
//= require peek
//= require peek/views/rblineprof
// コードにシンタックスハイライトさせたい場合、下記も追加
//= require peek/views/rblineprof/pygments
```

```css:app/assets/stylesheets/application.css
//= require peek
//= require peek/views/rblineprof
```

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

```
http://localhost:3000/articles?lineprofiler=app
```
するとブラウザに下記のように表示され、どの行で時間がかかっているかを確認することができます。

![スクリーンショット 2020-12-03 16.07.09.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/319369/34af9225-3158-5a39-ec54-d8b237398a59.png)

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

N+1改善&sleep削除後
![スクリーンショット 2020-12-03 16.11.37.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/319369/5219fef1-d356-785f-b5f0-84db9384c7e9.png)
改善されていることが確認できました!

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

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