cfis

edit

Porting ruby-prof to Windows

Posted by Charlie Fri, 09 Jun 2006 19:14:00 GMT

Yesterday I wanted to profile some methods I'm using on a Rails controller. To get a feel for profiling Ruby code I put together a test case, added a "require 'prof'" to the top of the file and eagerly waited for the results. And waited, and waited, and waited. Thinking I did something wrong, I ran the code without a profiler - it took about 2 seconds. With the profiler it took so long I gave up. And this was on a dual core pentium D processor with 1 Gig of memory running Fedora Core 5.

Time for some investigation. It turns out this is a well known problem - the built-in Ruby profiler, which is written in Ruby, is so slow as to be useless. I came across two alternatives - ruby-prof, a C extension written by Shugo Maeda, and ZenProfile, an inline C exension done by Ryan Davis.

I went with ruby-prof. On Linux it was easy enough to download, build and install and it worked like a charm. But I do most of my work on my laptop which runs Windows XP. So I opened up MingW and built and installed the extension on Windows (that's not quite true, I had to hack the C a bit, more info below). But when I ran the test script I was met with a program fail message saying that the stack was empty. Ugh.

Since I find it impossible to debug extensions on Windows with MingW I fired up Visual Studio 2005, rebuilt the extension, and tried again. Same issue.

Digging deeper, it turns out the profilers (as well as the wonderful rcov project) work by registering a callback with Kernel::set_trace_func. When Ruby executes a line of code, enters a new Ruby or C method, or exists a Ruby or C method, the callback is activated.

The problem is that ruby-prof assumes that each call into a method is matched by a return - and if its not then the failure I see is triggered. To understand the problem, let's look at a super simple test case:

require 'profiler'

I said it was simple - didn't I! Here's the trace from Linux:

return start_profile
call print_profile
call stop_profile
c-call set_trace_func

Start_profile is the method that installs the set_trace callback - so it makes sens that the first thing we see is returning from that method. Once the program is done, the profiler calls print_profile, which calls stop_profile, which calls set_trac_func which uninstalls the callback. So the method enters and returns do not balance.

Although the method names ruby-prof uses are slightly different, the problem remains the same. ruby-prof hacks through it by pushing and popping extra items on its stack to counterweigh the imbalanced method calls. Thus its hard-coded to a specific sequence of method calls. So why doesn't it work on Windows?

A quick trace running our test program on Windows shows the problem:

return start_profile
return require
call print_profile
call stop_profile
c-call set_trace_func

There is an extra "return require" which is being generated by Ruby gems. And if you run the program in Arachno, which uses a modified version of Ruby to supports its fantastic debugger (its fast enough that I always run Rails under the debugger so I can set breakpoints at key places - definitely go check it out).

c-return set_trace_func 
return start_profile 
c-return require__ 
return require 
c-return require__ 
return require 
call print_profile 
call stop_profile 
c-call set_trace_func 

It quickly becomes clear that assuming a balanced stack is a bad idea. If you look at the built in Ruby profile it doesn't make such an assumption.

These changes have been merged into ruby-prof-0.4.0 which is now available as a RubyGem.

So, I've patched ruby-prof to remove this assumption and to make it compile on Windows. I'll submit the patch to Shugo Maeda, but in the meantime, I've provided windows binaries for anyone who wants to use the profiler on windows. To install:

1. Download the windows extension, prof.xo, and put it in your ruby\lib\ruby\site_ruby\1.8\i386-msvcrt directory.

2. Download unprof.rb and put it in your ruby\lib\ruby\site_ruby\1.8 directory.

3. To use the profiler simply require 'unprof' at the top of the file

One thing to note about my changes. The self-time for the "toplevel" method will always show "0". Its looks like the Ruby profiler does the same thing, so I think this is ok.

Assembly Hacking

This section is for anyone who's interested in some lower level details - feel free to skip it.

Getting ruby-prof to compile on windows required a few of the usual changes. For example, making sure that the extension's initialization method is property exported using __declspec(dllexport), etc.

However, ruby-prof provides an extra twist. It can measure time in several ways including using some low-level functionality provided by more recent Pentium and PowerPC processors. To access this information it uses this inline assembly call:

static prof_clock_t
cpu_get_clock()
{
#if defined(__i386__)
    unsigned long long x;
    __asm__ __volatile__ ("rdtsc" : "=A" (x));
    return x;
#elif defined(__powerpc__) || defined(__ppc__)
    unsigned long long x, y;

    __asm__ __volatile__ ("\n\
1:	mftbu   %1\n\
	mftb    %L0\n\
	mftbu   %0\n\
	cmpw    %0,%1\n\
	bne-    1b"
	: "=r" (x), "=r" (y));
    return x;
#endif
}

For x86 chips, what it does is call the rdtsc assembly function which returns the number of clock cycles that have been executed. So if you call get_cpu_clock, wait 1 second, and call get_cpu_clock again, you can calculate the chip's clock frequency. Using this information, you can time method calls. For instance, if the chip's frequency is 500Mhz and a method takes 250,000,000 cycles to complete, you can calculate it took 0.5 seconds.

This of course won't work with Visual C++ because it uses its own syntax for inline assembly calls. In this case there are couple ways of porting this code. Newer versions of Visual C++ support compiler intrinsics, and there is one for rdtsc. However, I thought it would be better to use inline assembly to support older versions. Here's the code:

static prof_clock_t
cpu_get_clock()
{
    prof_clock_t cycles = 0;

    __asm
    {
        rdtsc
        mov DWORD PTR cycles, eax
        mov DWORD PTR [cycles + 4], edx
    }
    return cycles;
}

To use this timing method you have to specifically enable it by including the following line in your ruby code.

ENV["RUBY_PROF_CLOCK_MODE"] = "cpu"
require 'unprof'

However, I can't say this works very well. The calculated frequency for my chip is always different. I don't know why - my best guess is that its a Pentium M with Intel's speed step technology so the clock frequency varies to save power. However, I'm usually plugged in so I don't think that's it. Note you can tell ruby-prof your click frequency like this:

ENV["RUBY_PROF_CLOCK_MODE"] = "cpu"
ENV["RUBY_PROF_CPU_FREQUENCY"]= "466000000"
require 'unprof'

So my recommendation is just use the default ruby-prof timing method - it does the job perfectly well.