Creating a simple but powerful profiler for Ruby on Rails

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.

Dmytro Shteflyuk's Home

Creating a simple but powerful profiler for Ruby on Rails

One Response to this entry

Comments are closed