skip navigation

Here you will find ideas and code straight from the Software Development Team at SportsEngine. Our focus is on building great software products for the world of youth and amateur sports. We are fortunate to be able to combine our love of sports with our passion for writing code.

The SportsEngine application originated in 2006 as a single Ruby on Rails 1.2 application. Today the SportsEngine Platform is composed of more than 20 applications built on Rails and Node.js, forming a service oriented architecture that is poised to scale for the future.

About Us
Home

Rails Middleware Timing with Rack Timer

03/14/2012, 8:45am CDT
By Luke Ludwig

Gain full insight into your middleware performance with Rack Timer!

We use New Relic extensively to give us insight into our NGIN Ruby on Rails application. A few weeks back we started tracking what New Relic calls request queuing time. The header HTTP_X_REQUEST_START is set within Nginx which New Relic uses to show how much time has elapsed between Nginx and when the Rails application starts serving the request. We were shocked to see that on average each request was allotting 200 ms to the request queue! 

We use Nginx with Passenger, and Passenger has an actual queue that it uses as it balances the load between multiple Rails processes. By running passenger-status we can see how many requests are currently queued. If requests are queued then all available Rails processes are busy and the request is waiting for a Rails process to become free.


New Relic graph showing 200 ms of request queuing!

Even though 200 ms was allotted to request queuing, passenger-status was reporting that there was nothing in the queue. What was going on! At this point we suspected middleware as the culprit, which caused me to write the Rack Timer gem to get more insight into our middleware behavior.

Rack Timer is a gem that will tell you how much time is spent within each piece of Rack middleware in your Rails application. Rack Timer provides timing around time taken "on the way in" and "on the way out", meaning before and after the request has been processed by the Rails action. It will also print out the time elapsed by the actual application's action, which is combined with Rails routing, the final piece of middleware. It can also tell you how much time has elapsed from your upstream web server and your first piece of middleware. This requires setting the HTTP_X_REQUEST_START or HTTP_X_QUEUE_START headers in your upstream web server. 

Rack is a simple concept which I didn't fully understand until writing this gem. All Rack classes have a call method which takes a hash argument representing the request and returns an array with the status, headers, and body of the response. You can run rake middleware in any Rails project and it will output the Rack middleware in your Rails app. I was surprised to find around seventeen built-in Rails Rack middleware classes.

Example output of an NGIN rake middleware run: 

~/tstmedia/ngin $ rake middleware
use Rack::Lock
use ActiveSupport::Cache::Strategy::LocalCache
use Rack::Runtime
use Rails::Rack::Logger
use ActionDispatch::ShowExceptions
use ActionDispatch::RemoteIp
use Rack::Sendfile
use ActionDispatch::Callbacks
use ActiveRecord::ConnectionAdapters::ConnectionManagement
use ActiveRecord::QueryCache
use ActionDispatch::Cookies
use ActionDispatch::Session::CookieStore
use ActionDispatch::Flash
use ActionDispatch::ParamsParser
use Rack::MethodOverride
use ActionDispatch::Head
use ActionDispatch::BestStandardsSupport
use Warden::Manager
run Ngin::Application.routes

When I first set out to get timestamps around each of these middleware classes, I thought I would find a loop in Rails that iterated over an array of these classes and called each in turn. Instead each middleware class calls the next one in the chain. The final one executes the route dispatching portion of Rails which then calls the controller and action for the request. Once the application's action completes the response is returned back up the chain of middleware classes. Each Rack middleware class can modify the outgoing response although most just return the response unmodified up the chain.

To produce timestamps, RackTimer wraps each middleware class in a new RackTimer class. The RackTimer class is Rack compatible, meaning it implements a call method. It inserts a header timestamp and calls the middleware class that it is wrapping. The header timestamp is then compared against Time.now within the next middleware class and printed to the log.

Example output from Rack Timer is shown here, with the RACK_TIMER_LOG_THRESHOLD set to 0.

Rack Timer -- Queuing time: 1723 microseconds
Rack Timer (incoming) -- Rack::Lock: 0.019073486328125 ms
Rack Timer (incoming) -- ActiveSupport::Cache::Strategy::LocalCache: 0.0209808349609375 ms
Rack Timer (incoming) -- Rack::Runtime: 0.0140666961669922 ms


Started GET "/page/show/298883-home" for 75.146.189.233 at Tue Mar 13 05:55:20 -0700 2012
Rack Timer (incoming) -- Rails::Rack::Logger: 0.123023986816406 ms
Rack Timer (incoming) -- ActionDispatch::ShowExceptions: 0.00905990600585938 ms
Rack Timer (incoming) -- ActionDispatch::RemoteIp: 0.0140666961669922 ms
Rack Timer (incoming) -- Rack::Sendfile: 0.0119209289550781 ms
Rack Timer (incoming) -- ActionDispatch::Callbacks: 0.0219345092773438 ms
Rack Timer (incoming) -- ActiveRecord::ConnectionAdapters::ConnectionManagement: 0.00905990600585938 ms
Rack Timer (incoming) -- ActiveRecord::QueryCache: 0.0360012054443359 ms
Rack Timer (incoming) -- ActionDispatch::Cookies: 0.00905990600585938 ms
Rack Timer (incoming) -- ActionDispatch::Session::CookieStore: 0.0269412994384766 ms
Rack Timer (incoming) -- ActionDispatch::Flash: 0.581979751586914 ms
Rack Timer (incoming) -- ActionDispatch::ParamsParser: 0.019073486328125 ms
Rack Timer (incoming) -- Rack::MethodOverride: 0.0100135803222656 ms
Rack Timer (incoming) -- ActionDispatch::Head: 0.00905990600585938 ms
Rack Timer (incoming) -- ActionDispatch::BestStandardsSupport: 0.00786781311035156 ms
Rack Timer (incoming) -- Warden::Manager: 0.0669956207275391 ms
Rack Timer (incoming) -- NewRelic::Rack::BrowserMonitoring: 0.00882148742675781 ms
Rack Timer (incoming) -- OmniAuth::Strategies::Facebook: 0.0569820404052734 ms
  Processing by PageController#show as HTML
  Parameters: {"id"=>"298883-home"}
Completed 200 OK in 1552ms (Views: 648.2ms | ActiveRecord: 446.4ms)
Rack Timer (Application Action) -- ActionDispatch::Routing::RouteSet: 1575.03509521484 ms
Rack Timer (outgoing) -- OmniAuth::Strategies::Facebook: 0.0109672546386719 ms
Rack Timer (outgoing) -- NewRelic::Rack::BrowserMonitoring: 0.0259876251220703 ms
Rack Timer (outgoing) -- Warden::Manager: 0.0150203704833984 ms
Rack Timer (outgoing) -- ActionDispatch::BestStandardsSupport: 0.0100135803222656 ms
Rack Timer (outgoing) -- ActionDispatch::Head: 0.00905990600585938 ms
Rack Timer (outgoing) -- Rack::MethodOverride: 0.00905990600585938 ms
Rack Timer (outgoing) -- ActionDispatch::ParamsParser: 0.0100135803222656 ms
Rack Timer (outgoing) -- ActionDispatch::Flash: 0.0138282775878906 ms
Rack Timer (outgoing) -- ActionDispatch::Session::CookieStore: 0.223159790039062 ms
Rack Timer (outgoing) -- ActionDispatch::Cookies: 0.0920295715332031 ms
Rack Timer (outgoing) -- ActiveRecord::QueryCache: 0.0140666961669922 ms
Rack Timer (outgoing) -- ActiveRecord::ConnectionAdapters::ConnectionManagement: 0.113010406494141 ms
Rack Timer (outgoing) -- ActionDispatch::Callbacks: 0.0121593475341797 ms
Rack Timer (outgoing) -- Rack::Sendfile: 0.0138282775878906 ms
Rack Timer (outgoing) -- ActionDispatch::RemoteIp: 0.00786781311035156 ms
Rack Timer (outgoing) -- ActionDispatch::ShowExceptions: 0.0131130218505859 ms
Rack Timer (outgoing) -- Rails::Rack::Logger: 1.23691558837891 ms
Rack Timer (outgoing) -- Rack::Runtime: 0.0350475311279297 ms
Rack Timer (outgoing) -- ActiveSupport::Cache::Strategy::LocalCache: 0.0121593475341797 ms
Rack Timer (outgoing) -- Rack::Lock: 0.0231266021728516 ms

Turns out that all of the default Rails middleware classes are quite fast, which is a good thing! The slowest one, at least for our NGIN application, is ActionDispatch::Flash, which seems to range from 1 ms to 10 ms per request.

Using Rack Timer I was able to see that all of our middleware classes were fast and were not contributing in any significant way to the 200 ms of request queuing. The request queuing timestamps output by Rack Timer were showing as unusually high and unexplainable, which validated New Relic's report of high request queuing time.

At this point I knew the elapsed time being reported in New Relic as request queuing was happening somewhere between when Nginx sets its timestamp and when the first piece of Rails middleware executes. Now that I had narrowed it down, I focused in on a custom modification to Passenger we had made, which makes Passenger garbage collect at the end of every third request. By removing this behavior we are now down to 100 ms request queuing time. More detailed information regarding this tweak will appear in a future post.

 

We first ran across this idea of garbage collecting in between requests in William Harding’s excellent post and had patched Passenger in the same manner as shown here https://github.com/wbharding/passenger. Turns out that Passenger will treat the Rails process as ready to handle additional requests when it is actually busy collecting garbage. This became apparent through the use of New Relic’s request queuing metric. We were getting a large amount of time reported as request queuing and upon investigation discovered that 100 ms per request on average was due to garbage collecting in between requests. We removed this garbage collecting in between requests entirely.


New Relic graph showing an improved 100 ms of request queuing.

We still need to understand the remaining 100ms of "request queuing" time, which occurs sometime between when Nginx sets the timestamp and when the first piece of Rails middleware executes. Passenger is a likely culprit, but this will take more investigation. Rack Timer was useful to gain insight into our middleware and upstream web server performance.

Sport Ngin Pulse Subscribeto our newsletter

Tag(s): Home  Ruby  Performance