リクエストの消費時間内訳

Rails のログを見ると、各リクエストの記録の末尾に次のような行がある。

Completed in 1.08156 (0 reqs/sec) | Rendering: 0.25919 (23%) | DB: 0.78924 (72%) | 200 OK [http://foobar.com/entries/show/64343]

今日は、これがどんな意味があるのか調べてみた。

関連するソースコードは以下の通り。ActionController の benchmarking.rb に存在する。

# $GEMSHOME/actionpack-1.13.3/lib/action_controller/benchmarking.rb
def render_with_benchmark(options = nil, deprecated_status = nil, &block)
    unless logger
      render_without_benchmark(options, deprecated_status, &block)
    else
      db_runtime = ActiveRecord::Base.connection.reset_runtime if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected?

      render_output = nil
      @rendering_runtime = Benchmark::measure{ render_output = render_without_benchmark(options, deprecated_status, &block) }.real

      if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected?
        @db_rt_before_render = db_runtime
        @db_rt_after_render = ActiveRecord::Base.connection.reset_runtime
        @rendering_runtime -= @db_rt_after_render
      end

      render_output
    end
  end

  def perform_action_with_benchmark
    unless logger
      perform_action_without_benchmark
    else
      runtime = [Benchmark::measure{ perform_action_without_benchmark }.real, 0.0001].max
      log_message  = "Completed in #{sprintf("%.5f", runtime)} (#{(1 / runtime).floor} reqs/sec)"
      log_message << rendering_runtime(runtime) if defined?(@rendering_runtime)
      log_message << active_record_runtime(runtime) if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected?
      log_message << " | #{headers["Status"]}"
      log_message << " [#{complete_request_uri rescue "unknown"}]"
      logger.info(log_message)
    end
  end

  private
    def rendering_runtime(runtime)
      " | Rendering: #{sprintf("%.5f", @rendering_runtime)} (#{sprintf("%d", (@rendering_runtime * 100) / runtime)}%)"
    end

    def active_record_runtime(runtime)
      db_runtime    = ActiveRecord::Base.connection.reset_runtime
      db_runtime    += @db_rt_before_render if @db_rt_before_render
      db_runtime    += @db_rt_after_render if @db_rt_after_render
      db_percentage = (db_runtime * 100) / runtime
      " | DB: #{sprintf("%.5f", db_runtime)} (#{sprintf("%d", db_percentage)}%)"
    end
end

この中でエントリポイントとなるメソッドは、perform_action_with_benchmark である。perform_action はコントローラのアクションが実行されるときに呼び出される。もういちど例に戻って見ると、

Completed in 1.08156 (0 reqs/sec) | Rendering: 0.25919 (23%) | DB: 0.78924 (72%) | 200 OK [http://foobar.com/entries/show/64343]

Rendering は、テンプレート等のレンダリング処理の所要時間である。単位は秒。パーセンテージはこのアクションの処理全体に占める割合である。
DB は、ActiveRecord 関係の処理の所要時間である。単位は秒。パーセンテージはこのアクションの処理全体に占める割合である。

perform_action は、URL の解析（ルーティング）が終わった後に呼び出されるので、実際の1リクエストに必要な所要時間は、ここで表示される時間より少し長くなるはずだ。