rack-timer-statsd

rack-timer

Are you spending too much time in Rack middlewares?

Is one of your Rack middlewares misbehaving in production?

Add RackTimer::Middleware to the to of your middleware stack and figure out.

Installation

Add this line to your application's Gemfile:

gem 'rack-timer'

Add the middleware to your stack. In your config.ru, add this before any other middleware:

require 'rack-timer'
use RackTimer::Middleware

When your app runs, it will output timing information to standard error. If you want to change that, you can tell rack-timer to send data to another file-y object, for instance:

RackTimer.output = $stdout

If you want to send execution time to StatsD as well, you can specify a client:

RackTimer.statsd = $statsd

Usage

Run your app normally after installation, wait a while, and download your logs.

They will report the middleware starting up:

[rack-timer] assimilating: Rack::MiddlewareTimer
[rack-timer] assimilating: Rack::Lock
[rack-timer] assimilating: Airbrake::UserInformer
[rack-timer] assimilating: Rack::DetectCrawler

then timing each request:

[rack-timer] Proc took 3398135 us
[rack-timer] Rack::Cors took 54 us
[rack-timer] Rack::OutOfBandGC took 51 us
...
[rack-timer] Airbrake::UserInformer took 74 us
[rack-timer] Rack::Lock took 78 us
[rack-timer] Rack::MiddlewareTimer took 80 us
[rack-timer] queued for 5256 us

Besides middleware timing, two bits of extra information are reported:

• Proc (the first entry for each request) typically is your app itself (excluding middleware).
• queued for... will be present if your web frontend adds the X-Request-Start HTTP header. If using Nginx+Unicorn or Apache+Passenger, this will report the queueing time in Unicorn or Passenger.

An example

We developed this because of wierd issues with queuing time (was too high without an obvious reason).

We graphed the middleware timings:

And the queueing timings:

(horizontally: log10 of the queuing time in microseconds, ie. 3 is 1ms and 6 is 1 second)

The conlusion was that something what causing queuing in some cases. It turned out our out-of-band garbage colleciton hack was no longer compatible with Passenger, and removing it solved the issue:

Contributing

1. Fork it
2. Create your feature branch (git checkout -b my-new-feature)
3. Commit your changes (git commit -am 'Add some feature')
4. Push to the branch (git push origin my-new-feature)
5. Create new Pull Request