«前の日記(2010-06-09) 最新 次の日記(2010-06-12)» 編集

会長@腹部日記


2010-06-11 [長年日記]

_ Railsが出力するログの計測時間は何か調べてみた

職場でさらっと調べたのでメモしておきます*1。性能を追求するときに他人の説得材料として必要な気配が濃厚です。

Processing HogesController#index (for 127.0.0.1 at 2010-06-11 14:09:36) [GET]
Rendering template within layouts/hoges
Rendering hoges/index
Completed in 453ms (View: 437, DB: 0) | 200 OK [http://localhost/hoges/]

ここで View: 整数, DB: 整数 が出てきています。

きっとどこかに説明があるんでしょうが、さっさとソースを見てみます。

環境

actionmailer (2.3.8)
actionpack (2.3.8)
activerecord (2.3.8)
activeresource (2.3.8)
activesupport (2.3.8)
rails (2.3.8)

出力文字列生成箇所

  • actionpack-2.3.8/lib/action_controller/benchmarking.rb

   def perform_action_with_benchmark
     if logger
       ms = [Benchmark.ms { perform_action_without_benchmark }, 0.01].max
       logging_view          = defined?(@view_runtime)
       logging_active_record = Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected?
       
       log_message  = 'Completed in %.0fms' % ms
       
       if logging_view || logging_active_record
         log_message << " ("
         log_message << view_runtime if logging_view
         
         if logging_active_record
           log_message << ", " if logging_view
           log_message << active_record_runtime + ")"
         else
           ")"
         end
       end
       
       log_message << " | #{response.status}"
       log_message << " [#{complete_request_uri rescue "unknown"}]"
       
       logger.info(log_message)
       response.headers["X-Runtime"] = "%.0f" % ms
     else
       perform_action_without_benchmark
     end
   end
   
   #
   # Viewの処理時間
   #
   def view_runtime
     "View: %.0f" % @view_runtime
   end
   
   #
   # ActiveRecordの処理時間
   #
   def active_record_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: %.0f" % db_runtime
   end

まずは Viewの処理時間と思わしき、@view_runtime から追跡します

@view_runtimeの更新場所は・・・

  • actionpack-2.3.8/lib/action_controller/benchmarking.rb

   def render_with_benchmark(options = nil, extra_options = {}, &block)
     if logger
       if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected?
         db_runtime = ActiveRecord::Base.connection.reset_runtime
       end
       
       render_output = nil
       @view_runtime = Benchmark.ms { render_output = render_without_benchmark(options, extra_options, &block) }
       
       if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected?
         @db_rt_before_render = db_runtime
         @db_rt_after_render = ActiveRecord::Base.connection.reset_runtime
         @view_runtime -= @db_rt_after_render # ここの減算
       end
       
       render_output
     else
       render_without_benchmark(options, extra_options, &block)
     end
   end

alias_method_chainによって、benchmark機能が追加されていました。loggerが environment.rbで設定されていない場合は、計測処理がスキップされるようになっています。

View側のrenderに用いた時間から、ActiveRecordで計測したDBアクセス時間を引いたものが @view_runtime になっています。active_supportで下記のように定義されているBenchmark.msの結果ですから、単位はmsecです。

  • activesupport-2.3.8/lib/active_support/core_ext/benchmark.rb

   require 'benchmark'
   
   class << Benchmark
     # Earlier Ruby had a slower implementation.
     if RUBY_VERSION < '1.8.7'
       remove_method :realtime
   
       def realtime
         r0 = Time.now
         yield
         r1 = Time.now
         r1.to_f - r0.to_f
       end
     end
   
     def ms
       1000 * realtime { yield }
     end
   end

db_runtime も追跡

render前、後のDBアクセス時間と、render中のアクセス時間を足したものになっています。

計測はこーやってます

単位は先と同じ msec です。ActiveRecordのクエリが走るたびに計測されているということが、わかります。

   def log(sql, name)
     if block_given?
       result = nil
       ms = Benchmark.ms { result = yield }
       @runtime += ms # ここで足しこまれている
       log_info(sql, name, ms)
       result
     else
       log_info(sql, name, 0)
       nil
     end
   rescue Exception => e
     # Log message and raise exception.
     # Set last_verification to 0, so that connection gets verified
     # upon reentering the request loop
     @last_verification = 0
     message = "#{e.class.name}: #{e.message}: #{sql}"
     log_info(message, name, 0)
     raise ActiveRecord::StatementInvalid, message
   end

使われ方 - sqlite_adapter.rb

   def execute(sql, name = nil) #:nodoc:
     catch_schema_changes { log(sql, name) { @connection.execute(sql) } }
   end

使われ方 - postgresql_adapter.rb

   def query(sql, name = nil) #:nodoc:
     log(sql, name) do
       if @async
         res = @connection.async_exec(sql)
       else
         res = @connection.exec(sql)
       end
       return result_as_array(res)
     end
   end

使われ方 - mysql_adapter.rb

   def execute(sql, name = nil) #:nodoc:
     log(sql, name) { @connection.query(sql) }
   rescue ActiveRecord::StatementInvalid => exception
     #略
   end

どこから呼ばれてるのか

を書いて終わりにします。

と思いましたが、あまりにもActionController::Baseの処理が複雑なので省略します。

*1 出張準備が終わって手持ちぶさた

_ きょうのつぶやき : 66回