Rails / Performance / Dissection of performance-/benchmarking-related code

This is a [source code dissection (category)] of Rails performance-/benchmarking-related sections of request processing code

Aspect of Rails: Performance

Database query benchmarking/logging

• activerecord/lib/active_record/connection_adapters/*_adapter.rb
  • In each adapter, execute(sql, name = nil) wraps the actual query execution in log(sql, name) { @connection.query(sql) }
• AbstractAdapter#log(sql, name) takes care of:
  • logging the individual query
  • benchmarking the individual query
  • adding the benchmark for the individual query to the running total for database runtime (AbstractAdapter#@runtime).
• AbstractAdapter#@runtime gets reset when the adapter is initialized and at the following times:
  • At various times during render_with_benchmark: But don't worry! These "subtotals" are recorded in variables such as @db_rt_before_render and @db_rt_before_render, which are then added back together in active_record_runtime in order to get a total elapsed time for ActiveRecord during the course of performing "this" action/request.
  • One "final" time when we output the totals in the log: in perform_action_with_benchmark (in active_record_runtime)

Interesting methods...

./vendor/rails/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb

    class AbstractAdapter

      def initialize(connection, logger = nil) #:nodoc:
        @runtime = 0
        ...
      end

      def reset_runtime
        rt, @runtime = @runtime, 0
        rt
      end

      protected
        def log(sql, name)
          if block_given?
            if @logger and @logger.level <= Logger::INFO
              result = nil
              seconds = Benchmark.realtime { result = yield }
              @runtime += seconds
              log_info(sql, name, seconds)
              result
            else
              yield
            end
          else
            log_info(sql, name, 0)
            nil
          end
        end

        def log_info(sql, name, runtime)
          return unless @logger

          @logger.debug(
            format_log_entry(
              "#{name.nil? ? "SQL" : name} (#{sprintf("%f", runtime)})",
              sql.gsub(/ +/, " ")
            )
          )
        end

Controller/view benchmarking/logging

(with some ActiveRecord benchmarking/logging thrown in there just for bad measure)

./vendor/rails/actionpack/lib/action_controller/benchmarking.rb

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

The database logging (and adding up of run times) is mixed in there as well...

./vendor/rails/actionpack/lib/action_controller/benchmarking.rb

    def perform_action_with_benchmark
        ...
        log_message << rendering_runtime(runtime) if defined?(@rendering_runtime)
        log_message << active_record_runtime(runtime) if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected?
        ...
        logger.info(log_message)
    end



    def render_with_benchmark(options = nil, deprecated_status = nil, &block)
        ...
        db_runtime = ActiveRecord::Base.connection.reset_runtime     # "start DB timer"
        @db_rt_before_render = db_runtime

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

        @db_rt_after_render = ActiveRecord::Base.connection.reset_runtime          # "stop DB timer"
        # @db_rt_after_render is set to the elapsed DB time that occurred *during* render_without_benchmark
        # We don't want *DB* time to count against the total *rendering* time, so we exclude/subtract it now...
        @rendering_runtime -= @db_rt_after_render

        render_output
    end



      def active_record_runtime(runtime)      # [simplified]
        # Add up run times
        db_runtime = @db_rt_before_render +   # All ActiveRecord time *before* the render
                     @db_rt_after_render  +   # All ActiveRecord time *during* the render (should call it @db_rt_during_render)
                     ActiveRecord::Base.connection.reset_runtime  # All ActiveRecord time *after* the render
        db_percentage = (db_runtime * 100) / runtime
        " | DB: #{sprintf("%.5f", db_runtime)} (#{sprintf("%d", db_percentage)}%)"
      end

This is where it puts the pieces of the output (Completed in 0.00480 (208 reqs/sec) | Rendering: 0.00291 (60%)) together into one piece before writing them to the logger:

./vendor/rails/actionpack/lib/action_controller/benchmarking.rb

    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

Notice that this is used as the denominator for the percentages:

        runtime = [Benchmark::measure{ perform_action_without_benchmark }.real, 0.0001].max

cgrep def.*perform_action

I assume perform_action_without_benchmark is the one defined here:

./vendor/rails/actionpack/lib/action_controller/base.rb

      def perform_action
        if self.class.action_methods.include?(action_name)
          send(action_name)
          render unless performed?
        elsif respond_to? :method_missing
          send(:method_missing, action_name)
          render unless performed?
        elsif template_exists? && template_public?
          render
        else
          raise UnknownAction, "No action responded to #{action_name}", caller
        end
      end

So the "total" time is actually the total time taken to perform the action and render the template. The Rails log output shows what percentage of this total is taken up by the rendering itself and by the database. It is easy to see that those are not required to add up to 100%. The rest of that 100% could be taken up by (non-DB) statements in the controller action itself.