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を上書きしてしまうのがよいかなーと思ってこうしました。