About a year ago we released a MiniProfiler for .Net. Ever since, I have been wishing for a Ruby port.

It seems I was not alone as this Stack Overflow question attests.

I am very happy to now announce our first release of MiniProfiler for Ruby. This has been made possible thanks to a large amount of effort by Aleks Totic, Robin Ward and myself. It reuses the UI created by Jarrod Dixon.

Why do you care, what does it do?

MiniProfiler is a ubiquitous production and development profiler, it allows you to quickly isolate performance bottlenecks, both on the server and client.

example of production profiling on this blog

In the example above it is clear there is an N+1 query executing for my comments on this blog. This could also be gleaned using bullet, New Relic or the traditional Rails log, however having this clearly visible on the page you are are navigating makes a very big difference.

MiniProfiler will display timings for POST requests, failed requests, json requests and so on. It keeps track of a list of “sessions” you have not seen and displays them all to you next time you have access to a UI. It allows you to easily tell how much time is spent in SQL and how much time outside of SQL.

Additionally, MiniProfiler makes it VERY easy for you to share profiling sessions with other members of your team, just send them the share link.

As an extra added bonus, MiniProfiler allows you to add probes to your html so you can tell when the client started rendering the BODY and so on (out there, scripts are usually a big cause of slow pages)

Installation and help

We will be keeping the documentation at GitHub up to date, there is also a support site at http://community.miniprofiler.com

Installation on Rails is fairly trivial, all you need to do is add the following to your Gemfile:

gem 'rack-mini-profiler'

We have a robust railtie that takes care of hooking stuff up.

In production, you are going to need to white list requests you would like to enable profiling on, for example this blog uses:

before_filter :admin_check

protected 

def admin_check
   # required only in production
   if is_admin? 
      Rack::MiniProfiler.authorize_request
   end
end

Current impact of production profiling

MiniProfiler is designed to be minimally invasive in production. However, in Ruby, method calls can get rather expensive and a few are needed to determine if profiling is allowed or not. For Rails, MiniProfiler inserts itself first in the Rack chain even before Rack::Lock, the middleware then determines if profiling is required or not. In production - it uses a cookie to determine if it is going to even try profiling, if the application whitelists the request the results are displayed, if not, the cookie is reset.

Additionally, we need to intercept the db calls with a method chain and a few checks are performed there as well.

I have tested this and am running a few sites with production profiling on, I am not able to detect any noticeable impact for unauthorized users. We are open to patches that make this area have even less impact.

If you are worried you can always only load the gem in development.

Enough chatter, show me an example

Recently, I upgraded my sites to Rails 3. I had an admin user page that displays a few fields of all 6,000 users in the system on one page. I was a bit surprised to see that rendering this page now takes about 1 second in production. Digging in to this problem was quite interesting.

Looking at the initial trace I could see that the time in SQL - about 280ms or so was spent in SQL. The first surprise I had was that Active Record was reporting a far lower number, 51ms only.

Started GET "/admin/users" for 10.0.0.6 at 2012-07-12 19:52:12 +1000
Processing by Admin::UsersController#index as HTML
  Rendered admin/users/index.haml within layouts/default (228.9ms)
["MB Store", "http://www.mediabrowser.tv/store", false]
  Rendered default/_navbar.haml (4.4ms)
Completed 200 OK in 955ms (Views: 242.2ms | ActiveRecord: 51.1ms)

Which makes one wonder, who is telling the truth.

Well, we can use MiniProfiler to figure this out, I attempted to query the data raw:

def index

  step("Raw") do
    a = []
    users = nil

    step("All") do 
      users = ActiveRecord::Base.connection.raw_connection
        .query('select email from users')
    end
    step("Iteration") do 
      users.each do |u|
        a << u
      end
    end
  end
  @users = User.all
end

protected 
def step(name, &blk)
  Rack::MiniProfiler.step(name, &blk)
end

This produced:

Aha, so even though the query is quite cheap, streaming it from the DB is NOT being measured in the Rails logs. Browsing through my site I have noticed that quite consistently the time to iterate through the results quite often exceeds the initial execution. This is, in fact, by design.

MiniProfiler is smart enough to intercept both pg and mysql2 for these cases. If you are using another DB it has fall-backs for ActiveRecord and Sequel interceptions.

However, we are not done.

I was still a bit confused here, where can the rest of the time be hiding, so I added the ?pp=sample option to the page to gather some call stacks. This option attempts to gather call stacks from the thread running the page (one every millisecond). The reality is that the Ruby VM will not schedule it that aggressively and you only get 120 or so stack for a 1 second operation.

Anyway, I could see that a whole bunch of stacks looked like this:

 block in execute
 block in log
ActiveSupport::Notifications::Instrumenter instrument
ActiveRecord::ConnectionAdapters::AbstractAdapter log
Rack::MiniProfiler::ActiveRecordInstrumentation log_with_miniprofiler
ActiveRecord::ConnectionAdapters::AbstractMysqlAdapter execute
ActiveRecord::ConnectionAdapters::Mysql2Adapter execute
ActiveRecord::ConnectionAdapters::Mysql2Adapter exec_query
ActiveRecord::ConnectionAdapters::Mysql2Adapter select
ActiveRecord::ConnectionAdapters::DatabaseStatements select_all
 block in select_all
ActiveRecord::ConnectionAdapters::QueryCache cache_sql
ActiveRecord::ConnectionAdapters::QueryCache select_all
 block in find_by_sql
ActiveRecord::Explain logging_query_plan
ActiveRecord::Querying find_by_sql
ActiveRecord::Relation exec_queries
 block in to_a
ActiveRecord::Explain logging_query_plan
ActiveRecord::Relation to_a
ActiveRecord::FinderMethods all
ActiveRecord::Querying all

So I added this line to app/config/initializers/mini_profiler.rb (you will need to create it)

Rack::MiniProfiler.profile_method(ActiveRecord::Querying, "all")

The I ran the page again:

Interesting, time in ActiveRecord and SQL is actually responsible for at least 700ms here, the logs are WAY off.

You may claim that this example is ridiculous.

• You should only be selecting the fields you need (which is true).
• You should be paging for that much date (sometimes can be true).
• If you are displaying that much data and use link_to on each row that will take up more time than your db time (also true)
• You should be caching (sure)
• Server time is usually negligible compared to client time (MiniProfiler also display client time so you can answer that yourself)

My point here is that, more often than not, the amount of time spent in ActiveRecord is way higher than the number displayed in the logs. MiniProfiler can help you dig in to this and give you nice stack traces to explain what is happening and where it is happening.

Further more, this is low impact, ready to go in dev and easily added to production.

---

Start profiling your apps, in production, you will be amazed at the improvements you can make. Use MiniProfiler, use Google PageSpeed, use WebPageTest. Most of the performance tools out there are complimentary.

PS. The website http://miniprofiler.com is very .NET centric, we would love a new design that integrates the Ruby port. If you feel like making that site better - fork it - and send a pull request. Any contributions to MiniProfiler are more than welcome.