ruby-prof 0.4.0 with call graphs

Update: ruby-prof 0.5.0 is now available and has significantly more features than 0.4.0, including better threading support, rails support, call tree output, etc.

After porting ruby-prof to Windows a couple of weeks ago, Shugo
, ruby-prof’s author, and I started working together. We’re
happy to announce the release of ruby-prof 0.4.0, which is chock
full of new features:

  • Addition of call graph profiles similar to GProf
  • Improved speed – overhead is now as low as 15% for some code, although
    you should generally expect around 50%
  • Full support for multiple threads
  • New cross-referenced html reports
  • New ruby-prof script that makes it easy to profile your programs
    without modifying them
  • Vastly improved documentation
  • Detection of recursive calls and
    call cycles
  • Support for windows

Best of all, ruby-prof is now distributed as a gem so it’s as easy to
install as:

gem install ruby-prof

If you’re on Windows, the gem includes a pre-built windows binary. If
you’re on Linux or Unix, the binary will be automatically built on intallation.

Graph Profiles

My favorite new feature – and the raison d’être for this
release, is the addition of call graphs. Here is the source code for the following examples.

Most profiling tools for Ruby1
output flat profiles, which are useful for identifying which methods
take the longest. They are concise and easy to understand.
Let’s take a look at an example to
see what I mean.

For short programs, flat profiles work well. But for
long programs, it’s really helpful to understand more about the context
in which a method is called. For example, which methods called the one
we’re interested in? Which methods did it call?

A quick word of warning – call graphs can be overwhelming if you haven’t
seen one before. Let’s venture forth and take a look at one that
shows the same results as the flat profile above.
Quite a bit different, isn’t it? If you haven’t used a call graph before
I’ve put together a little tutorial here.
There are also a number of excellent examples on the Web – search Google
for “gprof call graph tutorial.”


The thing that got me started working on ruby-prof was that the
built in Ruby profiler is beyond slow (and doesn’t support call graphs).
So how does ruby-prof compare?

We spent a good deal of time profiling ruby-prof, using oprofile on
Linux and Rational PurifyPlus on
Windows. When we started, ruby-prof added over 100% overhead to a program.
Thus, if a program took 10 seconds to run the profile run would take at
least 20. That’s not too bad, but there was clearly room for improvement.

Internally ruby-prof maintains two main data structures. The first is
a stack that keeps track of the current call sequence. The second is a
hash table with one entry per method profiled per thread.
The slowest part was looking up the method information in the hash table.
This happens each time a method is entered or exited.

To give you some idea of the number of times this happens, take a look
at the the Fixnum# method
in the graph profile above. For a program that lasted only 8 seconds, Fixnum#
got called a whopping 250,000 times (and these results are from last week
before our optimization work, so the program really only takes around 3
or 4 seconds to run).

The key to speeding up ruby-prof was to reduce these lookups as much as
possible. This was done by a combination of caching to avoid lookups,
simplyifing the hash key to make lookups faster,
and making the method tracking logic as simple as possible.

The result are quite encouraging. On “normal” programs, like Rails
apps, ruby-prof’s overhead is now less than 50% (and in fact, when I profile
our unit tests it is more in the range of 10% to 20%). For
programs that stress profilers, like the prime test above or a
factorial method, the overhead is somewhere in the 50% to 80% range.

Next time – some results from profiling Rails.

1The latest release of Mauricio Fernandez excellent rcov extension looks like it now has this functionality

  1. June 22, 2006

    Very cool! Thanks for this.

  2. Charlie Savage –
    June 22, 2006

    No problem Paul, it was fun to do. All feedback and comments are welcome….

  3. Jonathan
    June 22, 2006

    This looks like a very very useful utility and I’d like to thank you guys for all the effort you already put in.

    However I can’t find a way to use the Ruby cmd-line arguments to, for example, add a directory to the loading-list: -I . Or to require a library beforehand with -r

    Do you have any plans to add this ruby-prof?

  4. Charlie
    June 22, 2006

    Hi Jonathon,

    ruby-prof right now uses Ruby’s load method to run the specified scripts.

    So, not sure if this would work, but you could try:

    ruby -S ruby-prof -r(add your stuff) (scripts_to_run)

    If that doesn’t work, then check out the profiletask in the lib/ruby-prof directory. You could create a little rake file that would call RubyProf the way you mention.

    Let us know what works – and we’d be happy to accept a patch to make this work better with ruby-prof.

  5. June 23, 2006

    I seem to be having problems installing the gem. I’m running Ruby 1.8.2, and it tells me it’s too old. What version does it require?

    Btw, what about the 0.4.1 version that shows up, is that stable?

  6. Charlie
    June 23, 2006

    Haris – We’ve only tested on Ruby 1.8.4. Its plausible it works on 1.8.2 but we didn’t test it so we required 1.8.4. You could try gem install –force ruby-prof and give it a try.

    0.4.1 fixes a bug in 0.4.0 that you probably wouldn’t run into, as well as an obvious documentation error. Hopefully is stable.

  7. June 23, 2006

    Thanks for the quick feedback. When I try even with the –force, I get:

    Ruby version is too old
    ERROR: While executing gem … (RuntimeError)
    ERROR: Failed to build gem native extension.

    I’m basically using the ruby that ships with MacOSX.

    I guess I’ll have to wait until I decide to update. Darn though, it looks really cool!

    You might want to update the documentation in though, it says that it requires simply 1.8.2 or higher.

  8. Charlie Savage –
    June 23, 2006

    Bummer. If you feel like doing a little more work try a manual install. Download the zip or tar archive and unzip it. Then copy ruby-prof.rb, ruby-prof, and the lib directory to your ruby_site directory. Then copy the extension to site_ruby i386-msvcrt (or whatever it is on your platform).

    That should do the trick, you can then see it works. Thanks for the tip on the documentation, if I get a chance I’ll install Ruby 1.8.2 and see what happens.

  9. June 23, 2006

    I’m with you until the file. I downloaded and unziped it, but I can’t find a .so file. There is a ruby-prof file with no extension on the root directory, and a ruby_prof.c file in the ext folder. Is that the one that’s supposed to give me the .so? I’m not sure how I am supposed to compile it. Also not clear where to place the .so file, what is this directory supposed to be? I’m guessing it should be: /usr/lib/ruby/1.8/powerpc-darwin8.0/ this contains a lot of .bundle items, but no .so items.

    Thanks for the help.

  10. Charlie Savage –
    June 23, 2006

    Right, you’re on Linux/unix. Here’s how to compile it:

    $ cd ruby-prof/ext

    $ gcc -c ruby_prof.o -I/usr/lib/ruby/1.8/i386-linux (that’s a capital i not l)

    $ gcc -shared -o -lruby (and that’s a lowercase l not an i)

    That should do the trick. Thanks for your patience.

  11. June 23, 2006

    Thanks for helping out, my compiling skills are I’m afraid limited to ./configure, make, make install.

    I am running on MacOSX btw.

    I tried to run this command:

    gcc -c ruby_prof.o -I/usr/lib/ruby/1.8/powerpc-darwin8.0

    which I’m assuming is what you meant, and I got:

    powerpc-apple-darwin8-gcc-4.0.0: ruby_prof.o: No such file or directory

    In fact the ext directory has only ruby_prof.c

    When I tried to run:

    gcc -c ruby_prof.c -I/usr/lib/ruby/1.8/powerpc-darwin8.0

    instead, I got a whole list of errors starting with:

    ruby_prof.c:1027: error: parse error before ‘event’

    Btw, my gcc doesn’t seem to have the -I option.

  12. June 23, 2006

    Upon further examination, gcc seems to understand the -I option, even though it doesn’t say so when I do gcc –help.
    So I decided to search in the directory
    /usr/lib/ruby/1.8/powerpc-darwin8.0 for the string rb_event_t, and it can’t be found anywhere.

  13. Charlie
    June 23, 2006

    This was the correct form:

    gcc -c ruby_prof.c -I/usr/lib/ruby/1.8/powerpc-darwin8.0

    Basically, compile ruby_prof.c to ruby_prof.o. The -I (uppercase i) tells gcc where the Ruby header files are. If it can’t find them, then you’ll get a bunch of errors.

    Let me see if this works with Ruby 1.8.2 today….

  14. Charlie
    June 23, 2006

    Ok – looks like it doesn’t work. I get errors about prof_event_hook not working – which is the main way ruby-prof hooks into Ruby.

    After some investigation, I found this:

    Looks to me that Shugo requested that this function be added to Ruby. In the ruby-prof-0.3.0 build scripts, they require a version of 1.8.2 newer than March 22, 2005. However, Ruby 1.8.2 was released in December 2004.

    So it looks to me you’d have to upgrade to 1.8.4. Sorry about that, I’ll fix up the documentation to make that more clear.

  15. June 23, 2006

    Oh well, thanks for all the help anyway. I have had other reasons to move up to 1.8.4 anyway, it’s just a question of taking the plunge… Since I didn’t install Ruby in the first place, it just came with the OS, i’m a bit hesitant to install it now. 🙂

    Thanks again and congrats on an awesome tool. It looks great even without using it 😉