Ruby
Rails

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

More than 3 years have passed since last update.

Webアプリケーションのボトルネック解消を経験や勘に頼らずやりたいので、

Railsで使えそうなプロファイリングツールについて調べてみた。


rack-mini-profiler

MiniProfiler/rack-mini-profiler

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


導入

Gemfileに gem 'rack-mini-profiler' を追加するだけでOK。

下記のような形で、ページ上に表示される。

Kobito.gUkXZf.png


TIPS


表示/非表示の切り替え

表示をトグルしたい場合は Option + P

現在のセッション中表示を止めたい場合はURLの末尾に ?pp=disable をつけてアクセス。

再度表示させたい場合は ?pp=enable で有効になる。


flamegraphとの併用

flamegraph のgemを導入してからURLの末尾に ?pp=flamegraph を付けると

Flame Graphを表示することができる。

Flame Graphはプロファイルを可視化したもので、

どのコードでCPU時間を消費していて、それがどこから呼ばれているかを追跡できる。

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

Kobito.hOfJ2E.png

参考: CPU Flame Graphs


bullet

flyerhzm/bullet

N+1問題を検出する。


導入

Gemfileに gem 'bullet' を追加。

Bulletは設定を追加しない限り何もしないので、

config/environments/development.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問題が発生していることは把握しているが、

修正の必要がない箇所についてはホワイトリストを指定することで、

通知の対象外とすることができる。


config/environments/development.rb

  Bullet.add_whitelist type: :n_plus_one_query, class_name: 'Reservation', association: :book



Slackに通知

bulletは通知のハンドリングにuniform_notifierを使用しているので、

Slackに通知を送ることもできる。

Gemfileに slack-notifier を追加して、development.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


stackprof

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サーバを起動。


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