Benchmarking at the method level in rails controllers

We have a reasonably complicated set of logic inside our controllers that is able to take an incoming url and serve the right content depending on 3 different parts of the url in various combinations and permutations. There are quite many DB queries required, and sometimes it goes slow.

I wanted to find where the system was spending its time, and the DB query logging provided by ActiveRecord was not enough to show me where the performance needed tuning.

The rails benchmark method to the rescue. And a little meta-programming. I added this to application.rb:

if ENV['EXTRA_BENCHMARKING']    @@added_methods = []    def self.method_added(id)  # wrap a benchmark around all controller method calls      name = id.id2name      if name =~ /^old_(.*)$/        return if @@added_methods.include?($1)      else        return if @@added_methods.include?(name)      end      @@added_methods << name      alias_method "old_#{name}".intern, name.intern      eval %{        def #{name}(*args, &block) "*=*=*=*=*=*=*=*=* #{name} START")          self.class.benchmark("*=*=*=*=*=*=*=*=* #{name}", Logger::DEBUG, false) do            send("old_#{name}", *args, &block)          end        end      }    end  end

It’s important to add this pretty much at the top of application.rb, or at least before all the methods you want to time.

Method_added gets called every time a method is added to the class. As each method is added we make a note of it in our array @@added_methods, and then alias it with the prefix “old_”. Then we define a new method adding the logger calls and the benchmark call.

The output looks like this:

...*=*=*=*=*=*=*=*=* save_url_history START*=*=*=*=*=*=*=*=* save_url_history (0.00004)*=*=*=*=*=*=*=*=* missing_page_catcher START*=*=*=*=*=*=*=*=* get_categories START*=*=*=*=*=*=*=*=* get_categories (0.00028)*=*=*=*=*=*=*=*=* get_continents START*=*=*=*=*=*=*=*=* get_continents (0.00004)...

Also you will get all your regular debug level logging in between these new lines in your log.

Note that the @@added_methods array is important because both alias_method and the eval’d def result in a call to method_added – so we use the array to prevent infinite recursion.

Just run rails up with the EXTRA_BENCHMARKING environment variable set, and you are away:

EXTRA_BENCHMARKING=1 script/server -e production

I like to use production mode so I can see the effect of the fragment caching. But you’ll get valid results in development mode too.


Leave a Reply

Fill in your details below or click an icon to log in: Logo

You are commenting using your account. Log Out /  Change )

Google photo

You are commenting using your Google account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s