This post originated from an RSS feed registered with Ruby Buzz by . Original Post: ruby-prof 0.4.0 with call graphs Feed Title: cfis Feed URL: http://cfis.savagexi.com/articles.rss Feed Description: Charlie's Blog Latest Ruby Buzz Posts Latest Ruby Buzz Posts by Latest Posts From cfis

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. Most profiling tools for Ruby¹ 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.

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