Rails2.3ではログのレスポンスタイムからRackの処理時間が抜けている

Rails2.3からwebサーバとのmiddlewareとしてRackが使われていますが、Rackでの処理時間はRailsのログには記録されません。

class RealLog  
  def initialize(app)  
    @app = app  
    @logger = Logger.new("realtime.log")  
  end  

  def call(env)  
    start_time = Time.now  
    ret = @app.call(env)  
    @logger.info "[#{Time.now - start_time}] #{env["PATH_INFO"] || env["REQUEST_URI"]}"  
    ret  
  end  
end  

こんな計測ツールをRackの一番上に積んでみます。
config/environment.rb

ActionController::Dispatcher.middleware.insert 0, RealLog  

適当なページにアクセスして、Railsログの時間とrealtime.logに記録された時間を比べると、500msくらいの差がありました。
Railsのログだけみて、レスポンスが早くなったと考えるのは早計のようです。

もともとRailsのログはアクションの処理時間を計測したものなので、それより上の話はあまり関係ないといえばないのですが。

おおいしつかさ

Rails2.3ではログのレスポンスタイムからRackの処理時間が抜けている