Ruby
Rails
RubyOnRails
Rails4

Rails4で性能ログを出力する

More than 3 years have passed since last update.

ローカルでRailsで動かしているとき、コンソールからはViewのレンダリングとActiveRecordのそれぞれで何msかかったが表示されますよね。

Completed 200 OK in 309ms (Views: 247.3ms | ActiveRecord: 40.8ms)

このレスポンスタイムの部分を性能ログとして切り出して、解析などに利用したいときには、ActiveSupport::Notificationsを利用します。

config/application.rb
config.perf_logger = ActiveSupport::Logger.new(Rails.root.join('log', 'perf.log'), 'daily')
config/initializers/notifications
ActiveSupport::Notifications.subscribe "process_action.action_controller" do |name, start, finish, id, payload|
  Rails.application.config.perf_logger.info(
    "#{Time.now} [#{payload[:controller]}##{payload[:action]}] #{payload[:method]} #{payload[:status]} #{payload[:path]} #{((finish - start) * 1000).round}ms(V:#{payload[:view_runtime].to_f.round(1)}ms,A:#{payload[:db_runtime].to_f.round(1)}ms)")
end

これでperf.logには、下記のようにローカル開発時に出力されるものと同じ値でログ出力することができます。

log/perf.log
2015-06-18 22:44:55.777  [WelcomeController#index] GET 200 / 309ms(V:247.3ms,A:40.8ms)

なお、ActiveSupport::NotificationsはRails3から導入されてますので、Rails3,4のどちらでも動作するかと思います。