Rails Appのプロファイリングツール


Webアプリケーションのボトルネック解消を経験や勘に頼らずやりたいので、
Railsで使えそうなプロファイリングツールについて調べてみた。

## rack-mini-profiler

[MiniProfiler/rack-mini-profiler](https://github.com/MiniProfiler/rack-mini-profiler)

レンダリングにかかった時間やDBクエリをページ上に表示する。

### 導入

Gemfileに `gem 'rack-mini-profiler'` を追加するだけでOK。
下記のような形で、ページ上に表示される。

![Kobito.gUkXZf.png](https://qiita-image-store.s3.amazonaws.com/0/82948/65413bf2-df45-8449-85bc-5da2dc76a585.png "Kobito.gUkXZf.png")


### TIPS

#### 表示/非表示の切り替え

表示をトグルしたい場合は `Option + P` 、
現在のセッション中表示を止めたい場合はURLの末尾に `?pp=disable` をつけてアクセス。
再度表示させたい場合は `?pp=enable` で有効になる。

#### flamegraphとの併用

[flamegraph](https://github.com/SamSaffron/flamegraph) のgemを導入してからURLの末尾に `?pp=flamegraph` を付けると
Flame Graphを表示することができる。

Flame Graphはプロファイルを可視化したもので、
どのコードでCPU時間を消費していて、それがどこから呼ばれているかを追跡できる。

インタラクティブに拡大縮小が可能なので、細かく見ていくことでボトルネックの解消に役立つ。

![Kobito.hOfJ2E.png](https://qiita-image-store.s3.amazonaws.com/0/82948/f3af4a27-8b31-0371-5499-c1bb4ff1f6cb.png "Kobito.hOfJ2E.png")


参考: [CPU Flame Graphs](http://www.brendangregg.com/FlameGraphs/cpuflamegraphs.html)

## bullet

[flyerhzm/bullet](https://github.com/flyerhzm/bullet)

N+1問題を検出する。

### 導入

Gemfileに `gem 'bullet'` を追加。

Bulletは設定を追加しない限り何もしないので、
`config/environments/development.rb` に以下を追加。

```rb:config/environments/development.rb
config.after_initialize do
  Bullet.enable = true
  
  # この下は通知先の設定
  Bullet.alert = true
  Bullet.bullet_logger = true
  Bullet.console = true
  Bullet.growl = true
  Bullet.xmpp = { :account  => 'bullets_account@jabber.org',
                  :password => 'bullets_password_for_jabber',
                  :receiver => 'your_account@jabber.org',
                  :show_online_status => true }
  Bullet.rails_logger = true
  Bullet.honeybadger = true
  Bullet.bugsnag = true
  Bullet.airbrake = true
  Bullet.rollbar = true
  Bullet.add_footer = true
  Bullet.stacktrace_includes = [ 'your_gem', 'your_middleware' ]
  Bullet.slack = { webhook_url: 'http://some.slack.url', foo: 'bar' }
end
```

上記の設定をした状態でN+1問題を検出すると、
コンソールに以下のようなログが出力されるので、あとはその箇所について修正を行っていく。

```
Completed 200 OK in 92ms (Views: 86.3ms | ActiveRecord: 4.4ms)
user: username
/reservation/index
N+1 Query detected
  Reservation => [:book]
  Add to your finder: :includes => [:book]
```

### TIPS

#### ホワイトリストの指定

N+1問題が発生していることは把握しているが、
修正の必要がない箇所についてはホワイトリストを指定することで、
通知の対象外とすることができる。

```rb:config/environments/development.rb
  Bullet.add_whitelist type: :n_plus_one_query, class_name: 'Reservation', association: :book
```


#### Slackに通知

bulletは通知のハンドリングに[uniform_notifier](https://github.com/flyerhzm/uniform_notifier)を使用しているので、
Slackに通知を送ることもできる。

Gemfileに `slack-notifier` を追加して、`development.rb` に以下を追加する。

```rb:config/environments/development.rb
config.after_initialize do
  Bullet.enable = true
  Bullet.slack = { webhook_url: 'http://some.slack.url', foo: 'bar' } # これを追加
end
```

![Kobito.j47FdB.png](https://qiita-image-store.s3.amazonaws.com/0/82948/5bf504c9-ead8-9cf0-17ec-6f87d622fe81.png "Kobito.j47FdB.png")


## stackprof

[tmm1/stackprof](https://github.com/tmm1/stackprof)

> stack frames are collected via rb_profile_frames, which provides low-overhead C-API access to the VM's call stack. no object allocations occur in this path, allowing stackprof to collect callstacks in allocation mode.

Ruby2.1から導入された `rb_profile_frames` という
オーバーヘッドの少ないC-APIを使った軽量なプロファイラ。

### 導入

Gemfileに `gem 'stackprof'` を追加し、
有効化の設定を `config.ru` に追記してRailsサーバを起動。

```rb:config.ru
use StackProf::Middleware,
    enabled: ENV['ENABLE_STACKPROF'].to_i.nonzero?,
    mode: :cpu,
    interval: 1000,
    save_every: 5,
    path: 'tmp'
```

```
$ ENABLE_STACKPROF=1 bundle exec rails s
```

プロファイルは `path` で指定したディレクトリに出力され、
stackprofコマンドでレポートが作成できる。

```
$ stackprof tmp/stackprof-cpu-*.dump --text --limit 10
==================================
  Mode: cpu(1000)
  Samples: 72 (7.69% miss rate)
  GC: 11 (15.28%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
        11  (15.3%)           9  (12.5%)     ActiveSupport::FileUpdateChecker#watched
        11  (15.3%)           7   (9.7%)     block in ActiveRecord::Migrator.migrations
         7   (9.7%)           7   (9.7%)     Sprockets::PathUtils#stat
         6   (8.3%)           6   (8.3%)     block in ActiveSupport::FileUpdateChecker#max_mtime
         4   (5.6%)           4   (5.6%)     Time#compare_with_coercion
         5   (6.9%)           4   (5.6%)     Sprockets::PathUtils#entries
         3   (4.2%)           3   (4.2%)     block in Logger::LogDevice#write
         4   (5.6%)           3   (4.2%)     Sprockets::Cache::FileStore#safe_open
         2   (2.8%)           2   (2.8%)     block in ActiveSupport::FileUpdateChecker#watched
         2   (2.8%)           2   (2.8%)     ActiveRecord::MigrationProxy#mtime
```

さらに、各メソッドがどこから呼ばれているか(callers)もわかるようになっている。

```
$ stackprof tmp/stackprof-cpu-*.dump --method 'ActiveSupport::FileUpdateChecker#watched'
ActiveSupport::FileUpdateChecker#watched (/Users/user/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/activesupport-4.2.1/lib/active_support/file_update_checker.rb:93)
  samples:     9 self (12.5%)  /     11 total (15.3%)
  callers:
      11  (  100.0%)  ActiveSupport::FileUpdateChecker#updated?
  callees (2 total):
       2  (  100.0%)  block in ActiveSupport::FileUpdateChecker#watched
  code:
                                  |    93  |     def watched
                                  |    94  |       @watched || begin
    2    (2.8%)                   |    95  |         all = @files.select { |f| File.exist?(f) }
                                  |    96  |         all.concat(Dir[@glob]) if @glob
    9   (12.5%) /     9  (12.5%)  |    97  |         all
                                  |    98  |       end
```


### 参考記事

作者のブログより
[Ruby 2.1: Profiling Ruby · computer talk by @tmm1](http://tmm1.net/ruby21-profiling/)