Railsで遅いMiddlewareを探す

AさんはRailsで書かれたある遅いコードの検証をしていました。
X-Runtimeヘッダを見ると

$ curl -Is localhost:3000/hello | grep X-Runtime
X-Runtime: 5.008580

5秒もかかってる。
しかしRailsのログを見ると

Started HEAD "/hello" for 127.0.0.1 at Tue Apr 03 13:04:11 +0900 2012
Processing by HelloController#index as */*
  Rendered text template (0.0ms)
Completed 200 OK in 10ms (Views: 9.7ms)

こんな感じで10msで返していることになっている。なんだこれは？

こういう状況で疑わしいことの一つとして、Rack等のMiddlewareのどれかが重いのではという懸念があります。そこで、今日は各Middlewareの速度を測ってみようと思います。

測り方

ActionDispatch::MiddlewareStack::Middleware.class_eval do
  def build_with_benchmarker(app)
    app.class_eval do
      def call_with_benchmark(env)
        result = nil 
        ms = Benchmark.ms { result = call_without_benchmark(env) }
        puts "MIDDLEWARE END #{self.class.to_s} (#{ms.to_i}ms)"
        result
      end 
      alias_method_chain :call, :benchmark
    end 
    build_without_benchmarker(app)
  end 
  alias_method_chain :build, :benchmarker
end

こんな感じのコードを environment.rb のロードの前あたりに入れます。で、リクエストをしてみると

MIDDLEWARE END ActionDispatch::Routing::RouteSet (2ms)
MIDDLEWARE END SlowMiddleware (5003ms)
MIDDLEWARE END ActionDispatch::BestStandardsSupport (5003ms)
MIDDLEWARE END Rack::ETag (5004ms)
MIDDLEWARE END Rack::ConditionalGet (5004ms)
MIDDLEWARE END ActionDispatch::Head (5004ms)
MIDDLEWARE END ActionDispatch::ParamsParser (5005ms)
MIDDLEWARE END ActionDispatch::Flash (5006ms)
MIDDLEWARE END ActionDispatch::Session::CookieStore (5006ms)
MIDDLEWARE END ActionDispatch::Cookies (5006ms)
MIDDLEWARE END ActionDispatch::Callbacks (5006ms)
MIDDLEWARE END ActionDispatch::Reloader (5007ms)
MIDDLEWARE END ActionDispatch::RemoteIp (5007ms)
MIDDLEWARE END ActionDispatch::DebugExceptions (5007ms)
MIDDLEWARE END ActionDispatch::ShowExceptions (5007ms)
MIDDLEWARE END Rails::Rack::Logger (5008ms)
MIDDLEWARE END ActionDispatch::RequestId (5008ms)
MIDDLEWARE END Rack::MethodOverride (5008ms)
MIDDLEWARE END Rack::Runtime (5008ms)
MIDDLEWARE END ActiveSupport::Cache::Strategy::LocalCache::Middleware (5008ms)
MIDDLEWARE END Rack::Lock (5008ms)

こういう感じで出力されます。

  :
MIDDLEWARE END ActionDispatch::Routing::RouteSet (2ms)
MIDDLEWARE END SlowMiddleware (5003ms)
  :

となっており、このSlowMiddlewareが遅そうというのが分かりました。よかったね。

補足

Middlewareは共通の親クラスがなくて、callメソッドをダックタイピングしているだけなので、全部のMiddlewareのcallに共通の処理を差し込むのはちょっと面倒でした。で、Middlewareの追加（build）時にcallを上書きしてしまうのがよいかなーと思ってこうしました。