Pennysmalls

Stephen Sykes's tech blog

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) 
          logger.info("*=*=*=*=*=*=*=*=* #{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.