easy-prof

Simple and easy to use Ruby code profiler, which could be used as a Rails plugin.

Installation

Add the "easy-prof" gem to your Gemfile.

gem "easy-prof"

And run bundle install command.

Description

The main idea behind the easy-prof is creating check points and your code and measuring time needed to execute code blocks. Here is the example of easy-prof output:

[home#index] Benchmark results:
[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 s

From this output you can see what checkpoints takes longer to reach, and what code fragments are pretty fast.

Usage

The library extends Kernel with a method easy_profiler. By default profiling is disabled globally, so you should pass :enabled parameter to enable profiling of particular code. Also there is a time :limit option which could be used to skip logging of blocks which are fast enough.

For more details see the options description below.

easy_profiler('sleep', :enabled => true) do |p|
  sleep 1
  p.progress('sleep 1')
  p.debug('checkpoint reached')
  sleep 2
  p.progress('sleep 2')
end

Method accepts two parameters: profiling session name and a hash of options:

• :enabled — value indicating whether profiling is enabled.
• :limit — minimum time period which should be reached to print profiling log.
• :count_ar_instances — indicating whether profiler should log an approximate number of instantiated ActiveRecord objects.
• :count_memory_usage — indicating whether profiler should log an approximate amount of memory used.
• :logger — a Logger instance.

Configuration

There are some global configuration options exists:

EasyProfiler.configure do |config|
  config.enable_profiling   = false
  config.print_limit        = 0.01
  config.count_ar_instances = false
  config.count_memory_usage = false
  config.logger             = nil # or Rails.logger or whatever
  config.colorize_logging   = true
  config.live_logging       = false
end

• enable_profiling — used to enable or disable profiling globalle (false by default).
• print_limit — used to set a minimum time period in seconds which should be reached to dump profile to the log (0.01 by default).
• count_ar_instances — indicating whether profiler should log an approximate number of instantiated ActiveRecord objects.
• count_memory_usage — indicating whether profiler should log an approximate amount of memory used.
• logger — a Logger instance to dump logs to.
• colorize_logging — when true, output will be colorized (useful when dumping profiling information into the Rails log).
• live_logging — when true, every profiling info will be pushed to the log immediately (by default everything will be dumped in the end of profiling session).

Active Record instances number profiling

easy-prof can log a number of instantiated ActiveRecord instances. To enable this kind of profiling, use a :count_ar_instances option or global setting with the same name.

Please note, that easy-prof completely disables garbage collector during this kind of profiling. It could hurt your overall application performance, so do not use it on production boxes. Also I can't guaranty 100% precision, but it is about this value in almost all cases.

Further reading:

• That’s Not a Memory Leak, It’s Bloat

Memory usage profiling

The plugin is able to log an amount of memory used by current Ruby process. To enable this kind of profiling, use a :count_memory_usage option or global setting with the same name.

Please note, that easy-prof completely disables garbage collector during this kind of profiling. It could hurt your overall application performance, so do not use it on production boxes. Also I can't guaranty 100% precision, but it is about this value in almost all cases.

Dumping results to the Firebug console

If you are profiling a Ruby on Rails application, it could be useful to get profiling results from production server sometimes. To achieve this you can use a FirebugLogger, bundled with this plugin. In any controller you have a helper called firebug_logger, so you can pass it to EasyProfiler using :logger option:

easy_profiler('home#index', :logger => firebug_logger, :limit => 2) do |p|
end

The idea behind this logger is pretty simple (as everything in this plugin): there is an after_filter named dump_firebug_profile, which dumps profiling information after your action finished its work. Please note: it will not output any line when profiling session is disabled or time limit is not reached.

Do not forget to protect firebug output: it is a bad idea to allow anyone to see your profiling session dump. You can allow admin users only to use firebug, or restrict this feature by IP address.

BTW, you can use Firebug Console Lite (http://getfirebug.com/lite.html) to get this feature working in any browser! By default it works perfectly in Firefox with Firebug installed, and in Safari 4.

Ruby on Rails application profiling

Here is a complete example of a Rails action profiling:

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 a view:

<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

Who are the authors?

This plugin has been created in Scribd.com for our internal use and then the sources were opened for other people to use. All the code in this package has been developed by Dmytro Shteflyuk for Scribd.com and is released under the MIT license. For more details, see the MIT-LICENSE file.

Credits

• Dmytro Shteflyuk (author) kpumuk@kpumuk.info http://kpumuk.info
• Alexey Kovyrin (contributor) alexey@kovyrin.net http://kovyrin.net