ruby-prof

Overview

ruby-prof is a fast code profiler for MRI Ruby. Its features include:

Speed - it is a C extension and therefore many times faster than the standard Ruby profiler.
Modes - Ruby prof can measure a number of different parameters, including call times, memory usage and object allocations.
Reports - can generate text and cross-referenced html reports
- Flat Profiles - similar to the reports generated by the standard Ruby profiler
- Graph profiles - similar to GProf, these show how long a method runs, which methods call it and which methods it calls.
- Call tree profiles - outputs results in the calltree format suitable for the KCacheGrind profiling tool.
- Many more – see reports section of this README.
Threads - supports profiling multiple threads simultaneously

Requirements

ruby-prof requires Ruby 1.9.3 or higher. Please note some ruby releases have known bugs which cause ruby-prof problems, like incorrect measurements. We suggest to use the latest minor patch level release if possible. In particular, on the 2.1 branch of ruby you should use at least 2.1.7.

If you are running Linux or Unix you’ll need a C compiler so the extension can be compiled when it is installed.

If you are running Windows, then you may need to install the Windows specific RubyGem which includes an already built extension (see Install section).

Install

The easiest way to install ruby-prof is by using Ruby Gems. To install:

gem install ruby-prof

If you’re on windows then please install the devkit first so that it can compile.

Usage

There are three major options for running ruby-prof: via the command line, via its convenience API or via its core API.

ruby-prof Executable

The first is to use ruby-prof to run the Ruby program you want to profile. For more information refer to the documentation of the ruby-prof command: ‘$ ruby-prof -h.`

ruby-prof Convenience API

The second way is to use the ruby-prof convenience API to profile particular segments of code.

require 'ruby-prof'

# profile the code
RubyProf.start
# ... code to profile ...
result = RubyProf.stop

# print a flat profile to text
printer = RubyProf::FlatPrinter.new(result)
printer.print(STDOUT)

Alternatively, you can use a block to tell ruby-prof what to profile:

require 'ruby-prof'

# profile the code
result = RubyProf.profile do
  # ... code to profile ...
end

# print a graph profile to text
printer = RubyProf::GraphPrinter.new(result)
printer.print(STDOUT, {})

ruby-prof also supports pausing and resuming profiling runs.

require 'ruby-prof'

# profile the code
RubyProf.start
# ... code to profile ...

RubyProf.pause
# ... other code ...

RubyProf.resume
# ... code to profile ...
result = RubyProf.stop

Note that resume will only work if start has been called previously. In addition, resume can also take a block:

require 'ruby-prof'

RubyProf.resume do
  # ... code to profile...
end

result = RubyProf.stop

With this usage, resume will automatically call pause at the end of the block.

Profiling Selected Threads (Core API)

The convenience API does not support running multiple profiles in separate threads concurrently, but the RubyProf::Profile API does. In fact, the convenience layer uses the Profile API internally. It all revolves around Profile objects:

RubyProf::Profile.new

Create a profile object given an options hash (see below)

The following options are available when creating Profile instances:

measure_mode: One of the defined measure modes
exclude_threads: Array of threads which should not be profiled.
include_threads: Array of threads which should be profiled. All other threads will be ignored.
merge_fibers: Whether profiling data for a given thread’s fibers should all be subsumed under a single entry. Basically only useful to produce callgrind profiles.

RubyProf::Profile#start

Start profiling

RubyProf::Profile#pause

Pause profiling

RubyProf::Profile#resume

Resume profiling

RubyProf::Profile#stop

Stop profiling and return self

RubyProf::Profile#profile

Perform a profile run and return result. Accepts the same arguments as RubyProf::Profile.new.

Method Elimination (Deprecated)

ruby-prof supports eliminating specific methods and threads from profiling results. This is useful for reducing connectivity in the call graph, making it easier to identify the source of performance problems when using a graph printer.

For example, consider Integer#times: it’s hardly ever useful to know how much time is spent in the method itself. We’re much more interested in how much the passed in block contributes to the time spent in the method which contains the Integer#times call.

Methods are eliminated from the collected data by calling eliminate_methods! on the profiling result, before submitting it to a printer.

result = RubyProf.stop
result.eliminate_methods!([/Integer#times/])

The argument given to eliminate_methods! is either an array of regular expressions, or the name of a file containing a list of regular expressions (line separated text).

After eliminating methods the resulting profile will appear exactly as if those methods had been inlined at their call sites.

Method Exclusion

ruby-prof supports exluding methods from profiling. The effect on collected metrics are identical to eliminating methods from the profiling result in a prost process step. The interface is slightly different though:

profile = RubyProf.new(...)
profile.exclude_methods!(Integer, :times, ...)
profile.start

A convenience method is provided to exclude a large number of methods which usually clutter up profiles:

profile.exclude_common_methods!

However, this is a somewhat opinionated method collection. It’s usually better to view it as an inspiration instead of using it directly (see github.com/ruby-prof/ruby-prof/blob/e087b7d7ca11eecf1717d95a5c5fea1e36ea3136/lib/ruby-prof/profile/exclude_common_methods.rb).

Profiling Rails

To profile a Rails application it is vital to run it using production like settings (cache classes, cache view lookups, etc.). Otherwise, Rail’s dependency loading code will overwhelm any time spent in the application itself (our tests show that Rails dependency loading causes a roughly 6x slowdown). The best way to do this is create a new Rails environment, profile.rb.

So to profile Rails:

Create a new profile.rb environment. Make sure to turn on cache_classes and cache_template_loading. Otherwise your profiling results will be overwhelmed by the time Rails spends loading required files. You should likely turn off caching.

Add the ruby-prof to your gemfile:

group :profile do
  gem 'ruby-prof'
end

Add the ruby prof rack adapter to your middleware stack. One way to do this is by adding the following code to config.ru:
```
if Rails.env.profile?
  use Rack::RubyProf, :path => '/temp/profile'
end
```
The path is where you want profiling results to be stored. By default the rack adapter will generate a html call graph report and flat text report.
Now make a request to your running server. New profiling information will be generated for each request. Note that each request will overwrite the profiling reports created by the previous request!

Reports

ruby-prof can generate a number of different reports:

Flat Reports
Graph Reports
HTML Graph Reports
Call graphs
Call stack reports
More!

Flat profiles show the overall time spent in each method. They are a good way of quickly identifying which methods take the most time. An example of a flat profile and an explanation can be found in examples/flat.txt.

There are several varieties of these - run ruby-prof --help

Graph profiles also show the overall time spent in each method. In addition, they also show which methods call the current method and which methods its calls. Thus they are good for understanding how methods gets called and provide insight into the flow of your program. An example text graph profile is located at examples/graph.txt.

HTML Graph profiles are the same as graph profiles, except output is generated in hyper-linked HTML. Since graph profiles can be quite large, the embedded links make it much easier to navigate the results. An example html graph profile is located at examples/graph.html.

Call graphs output results in the calltree profile format which is used by KCachegrind. Call graph support was generously donated by Carl Shimer. More information about the format can be found at the KCachegrind site.

Call stack reports produce a HTML visualization of the time spent in each execution path of the profiled code. An example can be found at examples/stack.html.

Another good example: twitpic.com/28z94a

Finally, there’s a so called MultiPrinter which can generate several reports in one profiling run. See examples/multi.stack.html.

There is also a graphviz .dot visualiser.

Printers

Reports are created by printers. Supported printers include:

RubyProf::FlatPrinter: Creates a flat report in text format
RubyProf::FlatPrinterWithLineNumbers: Same as above but more verbose
RubyProf::GraphPrinter: Creates a call graph report in text format
RubyProf::GraphHtmlPrinter: Creates a call graph report in HTML (separate files per thread)
RubyProf::DotPrinter: Creates a call graph report in GraphViz’s DOT format which can be converted to an image
RubyProf::CallTreePrinter: Creates a call tree report compatible with KCachegrind
RubyProf::CallStackPrinter: Creates a HTML visualization of the Ruby stack
RubyProf::MultiPrinter: Uses the other printers to create several reports in one profiling run

Most printers are used in the following way:

result = RubyProf.stop
printer = RubyProf::GraphPrinter.new(result)
printer.print(STDOUT, :min_percent => 2)

The first parameter is any writable IO object such as STDOUT or a file. The second parameter, specifies the minimum percentage a method must take to be printed. Percentages should be specified as integers in the range 0 to 100. For more information please see the documentation for the different printers.

The other option is :print_file => true (default false), which adds the filename to the output (GraphPrinter only).

MultiPrinter and CallTreePrinterdiffer from the other printers in that they require a directory path and a profile basename for the files they produce:

printer = RubyProf::MultiPrinter.new(result)
printer.print(:path => ".", :profile => "profile")

The values given in the example above are the defaults.

Measurements

Depending on the mode and platform, ruby-prof can measure various aspects of a Ruby program. Supported measurements include:

RubyProf::WALL_TIME: Wall time measures the real-world time elapsed between any two moments. If there are other processes concurrently running on the system that use significant CPU or disk time during a profiling run then the reported results will be larger than expected.
RubyProf::PROCESS_TIME: Process time measures the time used by a process between any two moments. It is unaffected by other processes concurrently running on the system. Note that Windows does not support measuring process times.
RubyProf::CPU_TIME: CPU time uses the CPU clock counter to measure time. The returned values are dependent on the correctly setting the CPU’s frequency. This mode is only supported on Pentium or PowerPC platforms (linux only).
RubyProf::ALLOCATIONS: Object allocation reports show how many objects each method in a program allocates. This support was added by Sylvain Joyeux and requires a patched Ruby interpreter. See below.
RubyProf::MEMORY: Memory usage reports show how much memory each method in a program uses. This support was added by Alexander Dymo and requires a patched Ruby interpreter. See below.
RubyProf::GC_TIME: Garbage collection time reports how much time is spent in Ruby’s garbage collector during a profiling session. This support was added by Jeremy Kemper and requires a patched Ruby interpreter. See below.
RubyProf::GC_RUNS: Garbage collection runs report how many times Ruby’s garbage collector is invoked during a profiling session. This support was added by Jeremy Kemper and requires a patched Ruby interpreter. See below.

Patching ruby

All of the patches to Ruby are included in the railsexpress patchsets for rvm, see github.com/skaes/rvm-patchsets. You can also use these patches manually with other ruby managers (ruby-install, ruby-build, etc.).

Note if you rebuild your ruby with patches you must uninstall and reinstall the ruby-prof gem to take advantage of the new capabilities.

Measure modes

To set the measurement:

RubyProf.measure_mode = RubyProf::WALL_TIME
RubyProf.measure_mode = RubyProf::PROCESS_TIME
RubyProf.measure_mode = RubyProf::CPU_TIME
RubyProf.measure_mode = RubyProf::ALLOCATIONS
RubyProf.measure_mode = RubyProf::MEMORY
RubyProf.measure_mode = RubyProf::GC_TIME
RubyProf.measure_mode = RubyProf::GC_RUNS

The default value is RubyProf::WALL_TIME.

You may also specify the measure mode by using the RUBY_PROF_MEASURE_MODE environment variable:

export RUBY_PROF_MEASURE_MODE=wall
export RUBY_PROF_MEASURE_MODE=process
export RUBY_PROF_MEASURE_MODE=cpu
export RUBY_PROF_MEASURE_MODE=allocations
export RUBY_PROF_MEASURE_MODE=memory
export RUBY_PROF_MEASURE_MODE=gc_time
export RUBY_PROF_MEASURE_MODE=gc_runs

On Linux, process time is measured using the clock method provided by the C runtime library. Note that the clock method does not report time spent in the kernel or child processes and therefore does not measure time spent in methods such as Kernel.sleep method. If you need to measure these values, then use wall time. Wall time is measured using the gettimeofday kernel method.

If you set the clock mode to PROCESS_TIME, then timings are read using the clock method provided by the C runtime library. Note though, these values are wall times on Windows and not process times like on Linux. Wall time is measured using the GetLocalTime API.

If you use wall time, the results will be affected by other processes running on your computer, network delays, disk access, etc. As result, for the best results, try to make sure your computer is only performing your profiling run and is otherwise quiescent.

Multi-threaded Applications

Unfortunately, Ruby does not provide an internal API for detecting thread context switches. As a result, the timings ruby-prof reports for each thread may be slightly inaccurate. In particular, this will happen for newly spawned threads that go to sleep immediately (their first call). For instance, if you use Ruby’s timeout library to wait for 2 seconds, the 2 seconds will be assigned to the foreground thread and not the newly created background thread. These errors can largely be avoided if the background thread performs any operation before going to sleep.

Performance

Significant effort has been put into reducing ruby-prof’s overhead as much as possible. Our tests show that the overhead associated with profiling code varies considerably with the code being profiled. Most programs will run approximately twice as slow while highly recursive programs (like the fibonacci series test) will run three times slower.

Editing links

Use RUBY_PROF_EDITOR_URI environment variable to open source code files in your favorite text editor. For example, RUBY_PROF_EDITOR_URI=atm will produce links for Atom text editor.

License

See LICENSE for license information.

API Documentation

The ruby-prof API documentation for the latest released gem version can be found here: www.rubydoc.info/gems/ruby-prof/

The ruby-prof API documentation for the master branch is available here: www.rubydoc.info/github/ruby-prof/ruby-prof/

Development

Code is located at github.com/ruby-prof/ruby-prof

Google group/mailing list: groups.google.com/group/ruby-optimization or open a github issue.