Webアプリケーションのボトルネック解消を経験や勘に頼らずやりたいので、
Railsで使えそうなプロファイリングツールについて調べてみた。
rack-mini-profiler
MiniProfiler/rack-mini-profiler
レンダリングにかかった時間やDBクエリをページ上に表示する。
導入
Gemfileに gem 'rack-mini-profiler' を追加するだけでOK。
下記のような形で、ページ上に表示される。
TIPS
表示/非表示の切り替え
表示をトグルしたい場合は Option + P 、
現在のセッション中表示を止めたい場合はURLの末尾に ?pp=disable をつけてアクセス。
再度表示させたい場合は ?pp=enable で有効になる。
flamegraphとの併用
flamegraph のgemを導入してからURLの末尾に ?pp=flamegraph を付けると
Flame Graphを表示することができる。
Flame Graphはプロファイルを可視化したもので、
どのコードでCPU時間を消費していて、それがどこから呼ばれているかを追跡できる。
インタラクティブに拡大縮小が可能なので、細かく見ていくことでボトルネックの解消に役立つ。
参考: CPU Flame Graphs
bullet
N+1問題を検出する。
導入
Gemfileに gem 'bullet' を追加。
Bulletは設定を追加しない限り何もしないので、
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問題が発生していることは把握しているが、
修正の必要がない箇所についてはホワイトリストを指定することで、
通知の対象外とすることができる。
Bullet.add_whitelist type: :n_plus_one_query, class_name: 'Reservation', association: :book
Slackに通知
bulletは通知のハンドリングにuniform_notifierを使用しているので、
Slackに通知を送ることもできる。
Gemfileに slack-notifier を追加して、development.rb に以下を追加する。
config.after_initialize do
Bullet.enable = true
Bullet.slack = { webhook_url: 'http://some.slack.url', foo: 'bar' } # これを追加
end
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サーバを起動。
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