Rails4で性能ログを出力する

ローカルで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のどちらでも動作するかと思います。