Creating a simple but powerful profiler for Ruby on Rails

Posted by Dmytro Shteflyuk on under Ruby & Rails (16,035 views)

You are developing a large Web application. Controllers are full of complex data retrieving logic, views contain tons of blocks, partials, loops. One day you will receive an email with user complaints about some of your pages slowness. There are many profiling tools, some of them are easy (ruby-prof), others are large and complex (newrelic), but regardless of this it’s really hard to find the particular place where you have a real bottleneck. So we created really simple, but über-useful tool for ruby code profiling.

First of all, we need to decide what features we need from this tool. Don’t know about you, but all I need is to measure execution time of particular ruby code block. Here is what I mean:

1
2
3
4
5
6
7
8
9
10
11
12
13
[home#index] debug: Logged in user home page
[home#index] progress: 0.7002 s [find top videos]
[home#index] progress: 0.0452 s [build categories list]
[home#index] progress: 0.0019 s [build tag cloud]
[home#index] progress: 0.0032 s [find featured videos]
[home#index] progress: 0.0324 s [find latest videos]
[home#index] debug: VIEW STARTED
[home#index] progress: 0.0649 s [top videos render]
[home#index] progress: 0.0014 s [categories render]
[home#index] progress: 2.5887 s [tag cloud render]
[home#index] progress: 0.0488 s [latest videos render]
[home#index] progress: 0.1053 s [featured video render]
[home#index] results: 3.592 seconds

So what do we see from this output? There are two slow blocks: top videos retrieving and tag cloud rendering. Now we just know what to do to make this page faster.

Let’s write the code:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
module EasyProfiler
  class Profile
    @@profile_results = {}

    cattr_accessor :enable_profiling
    @@enable_profiling = false
   
    cattr_accessor :print_limit
    @@print_limit = 0.01
   
    def self.start(name, options = {})
      options[:enabled] ||= @@enable_profiling
      options[:limit] ||= @@print_limit
      return NoProfileInstance.new unless options[:enabled]

      if @@profile_results[name]
        puts "EasyProfiler::Profile.start() collision! '#{name}' is already started!"
        return NoProfileInstance.new
      end
     
      @@profile_results[name] = ProfileInstance.new(name, options)
    end
   
    def self.stop(name, options = {})
      options[:enabled] ||= @@enable_profiling
      options[:limit] ||= @@print_limit
      return unless options[:enabled]

      unless @@profile_results[name]
        puts "EasyProfiler::Profile.stop() error! '#{name}' is not started yet!"
        return false
      end
     
      total = @@profile_results[name].total
     
      if total > options[:limit]
        @@profile_results[name].buffer_checkpoint("results: %0.4f seconds" % total)
        @@profile_results[name].dump_results
      end
     
      @@profile_results.delete(name)
    end
  end
 
  class ProfileInstance
    def initialize(name, options = {})
      @name = name
      @start = @progress = Time.now.to_f
      @buffer = []
    end
   
    def progress(message)
      progress = (now = Time.now.to_f) - @progress
      @progress = now
      buffer_checkpoint("progress: %0.4f seconds [#{message}]" % progress)
    end
   
    def debug(message)
      @progress = Time.now.to_f
      buffer_checkpoint("debug: #{message}")
    end
   
    def total
      Time.now.to_f - @start
    end
   
    def buffer_checkpoint(message)
      @buffer << message
    end
   
    def dump_results
      profile_logger.info("[#{@name}] Benchmark results:")
      @buffer.each do |message|
        profile_logger.info("[#{@name}] #{message}")
      end
    end

    def profile_logger
      root = Object.const_defined?(:RAILS_ROOT) ? "#{RAILS_ROOT}/log" : File.dirname(__FILE__)
      @profile_logger ||= Logger.new(root + '/profile.log')
    end
  end
 
  class NoProfileInstance
    def progress(message)
    end

    def debug(message)
    end
  end
end

We have defined two class attributes: EasyProfiler::Profile.enable_profiling (to be able to disable or enable profiler globally) and EasyProfiler::Profile.print_limit (to filter out from log code blocks that are fast enough).

Then we defined two methods, which accept name of profile session (for example, “home#index”), and hash of options. Possible options are :enabled (to enable profiling of particular block) and :limit (limit in seconds to filter out fast code fragments).

Method start returns an instance of profiler, which will be used to print check points. It contains two useful methods: debug (to display custom message) and progress (to display a message along with time spent since last checkpoint). Both methods define a new checkpoint.

To simplify usage, let’s create a helper:

1
2
3
4
5
6
7
module Kernel
  def easy_profiler(name, options = {})
    yield EasyProfiler::Profile.start(name, options)
  ensure
    EasyProfiler::Profile.stop(name, options)
  end
end

And now example:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
class HomeController < ApplicationController
  def index
    easy_profiler('home#index', :enabled => profile_request?, :limit => 2) do |p|
      p.progress 'logged in user home page'
     
      @top_videos = Video.top(:limit => 10)
      p.progress 'find top videos'

      @categories = Category.all(:order => 'name DESC')
      p.progress 'build categories list'

      @tag_cloud = Tag.tag_cloud(:limit => 200)
      p.progress 'build tag cloud'
     
      @featured_videos = Video.featured(limit => 5)
      p.progress 'find featured videos'

      @latest_videos = Video.latest(:limit => 5)
      p.progress 'find latest videos'
     
      @profiler = p
      p.debug 'VIEW STARTED'
    end
  end

  private
 
    # Method returns +true+ if current request should ouput profiling information
    def profile_request?
      params['_with_profiling'] == 'yes'
    end
end

and view:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
  <div id="top_videos">
    <%= render :partial => 'top_videos' %>
    <% @profiler.progress 'top videos render' %>
  </div>
 
  <div class="tabs">
    <ul id="taxonomy">
      <li><a href="#" id="categories" class="current">Categories</a></li>
      <li><a href="#" id="tags">Tags</a></li>
    </ul>
    <div class="categories_panel">
      <%= render :partial => 'categories' %>
      <% @profiler.progress 'categories render' %>
    </div>
    <div class="categories_panel hidden">
      <%= render :partial => 'tag_cloud' %>
      <% @profiler.progress 'tag cloud render' %>
    </div>
  </div>
 
  <div class="box">
    <div id="latest">
      <%= render :partial => 'videos', :videos => @latest_videos %>
      <% @profiler.progress 'latest videos render' %>
    </div>
    <div id="featured">
      <%= render :partial => 'videos', :videos => @featured_videos %>
      <% @profiler.progress 'featured video render' %>
    </div>
  </div>

As you can see from this example, profiler will be enabled only when you pass a _with_profiling parameter with value yes: http://example.com/home?_with_profiling=yes.

That’s all. If you have any question, feel free to post a comment or contact me.

Update: I have created a Rails plugin called easy-prof, which is hosted on GitHub. It’s more powerful and feature complete, so feel free to grab sources and play with it by yourself (check the RDoc documentation at rdoc.info). Do not forget to drop me a line about your feelings.

One Response to this entry

Subscribe to comments with RSS

said on September 30, 2009 at 7:13 pm · Permalink

fascinating use of profiler for rails. I like it!

Comments are closed

Comments for this entry are closed for a while. If you have anything to say – use a contact form. Thank you for your patience.