ruby-prof 0.4.0 with call graphs

Posted by Charlie Wed, 21 Jun 2006 19:06:00 GMT

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 Maeda, 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."

Speed

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

Posted in ,  | 15 comments | no trackbacks

Comments

  1. Avatar Paul Findlay said about 8 hours later:

    Very cool! Thanks for this.

  2. Avatar Charlie said about 11 hours later:

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

  3. Avatar Jonathan said about 17 hours later:

    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. Avatar Charlie said 1 day later:

    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. Avatar Haris Skiadas said 1 day later:

    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. Avatar Charlie said 1 day later:

    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. Avatar Haris Skiadas said 1 day later:

    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 http://ruby-prof.rubyforge.org/ though, it says that it requires simply 1.8.2 or higher.

  8. Avatar Charlie said 1 day later:

    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 rubysite directory. Then copy the rubyprof.so 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. Avatar Haris Skiadas said 1 day later:

    I’m with you until the rubyprof.so file. I downloaded http://rubyforge.org/frs/download.php/11223/ruby-prof-0.4.1.tgz 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 rubyprof.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. Avatar Charlie said 1 day later:

    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 rubyprof.so -lruby rubyprof.so (and that’s a lowercase l not an i)

    That should do the trick. Thanks for your patience.

  11. Avatar Haris Skiadas said 1 day later:

    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. Avatar Haris Skiadas said 1 day later:

    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 rbeventt, and it can’t be found anywhere.

  13. Avatar Charlie said 1 day later:

    This was the correct form:

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

    Basically, compile rubyprof.c to rubyprof.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. Avatar Charlie said 1 day later:

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

    After some investigation, I found this:

    http://blade.nagaokaut.ac.jp/cgi-bin/vframe.rb/ruby/ruby-talk/131313?131258-132005+split-mode-vertical.

    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. Avatar Haris Skiadas said 2 days later:

    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 ;)

Trackbacks

Use the following link to trackback from your own site:
http://cfis.savagexi.com/trackbacks?article_id=ruby-prof-0-4-0-with-call-graphs&day=21&month=06&year=2006

RSS feed for this post trackback uri

Comments are disabled