Measure with Ruby-Prof

ruby-prof is a Ruby gem that comes with both an API and a command-line tool. In most cases you’ll probably want use the API to profile just that isolated part of the code that you suspect to be slow. But the command-line tool is what you want for profiling application startup, especially if you’re interested in rubygems startup costs. In Rails applications you can get the complete request profile by inserting ruby-prof into the middleware stack.

1. ruby-prof API

In this example we’ll use the ruby-prof API to profile a specific part of your code.

Alternatively, you can pass a block to ruby-prof.

The idea is to wrap the code, in our example the Date#parse call, between RubyProf.start and RubyProf.stop and then print the report.

There are several types of reports ruby-prof can print, but for now we’ll use just one of them, called FlatPrinter, that shows the overall time spent in each function. The output is sorted by time, with functions that take the most time printed first, so you can easily see which functions are the CPU hogs.

Make sure you have the ruby-prof gem installed and run the program.

Let’s briefly take a look at the profile.

Our code spends more than 60% of its time matching the date I passed to the regular expression. Most of the remaining time is taken up by the Date#parse function itself, probably for Date instantiation.

Now let’s see how to use the command-line tool.

2. ruby-prof Command-Line Tool

You don’t have to add any instrumentation to the program itself in order to use the command-line tool. So the program can simply be this:

Run the ruby-prof command to profile it.

Here the -p option tells which printer to use to output the report (flat printer again in our case). And -m limits the outputs by suppressing all functions that took less than a specified percentage of time to execute. In this case I don’t care about places where the code spends less than 1% of its time.

You should get a profile like this one:

With this profile you can see what took the most time during the whole program run. In this case it’s Kernel#gem_original_require—the line that we didn’t see when we profiled only date parsing. We can see the time spent in require ’date’. Other things like class and object initialization functions also appear in the profile. Unsurprisingly, our profile confirms that such a simple program spends more time on startup than on actual code execution.

Your profile may be a bit different, and sometimes GC#disable can appear at the top because it performs a lazy GC sweep before disabling. That may or may not take noticeable time depending on how many objects are currently marked for deletion in the memory heap. In case you’re wondering what that GC sweep is that I’m talking about, take a peek at Chapter 10, ​Tune Up the Garbage Collector​. But don’t think too much about GC#disable if you spot it here, as we have it in the source code only for profiling.

As I mentioned, a profile generated by the ruby-prof command-line tool is very useful if you’re interested in the efficiency of application startup and gem loading. For other cases it adds too much data to the report, and you are much better off using the ruby-prof API.

3. Rails Middleware

The ruby-prof API works best if all you want is to profile a part of the Rails application—for example, controller action or template rendering. But to get insight into middleware, routing, and controller initialization, you need to insert ruby-prof as middleware.

To do that, add the ruby-prof gem into the Gemfile:

Also, insert the ruby-prof Rack adapter into the middleware stack in, for example, config/applilcation.rb:

The use call will insert the profiler into the bottom of the middleware stack. So the profile will include Rails initialization code, skipping the middleware. If you want to profile the middleware, insert the profiler before Rack::Runtime:

With Rack::RubyProf middleware loaded, you will get flat and HTML reports saved in the path you provide.

Don’t forget to disable GC before Rack::RubyProf starts. The best way to do it is to write one more middleware and insert it before the profiler into the stack: