Thursday, January 31, 2008

The Rubinius Debugger

When I read the posting about Cylon, the Ruby debugger for Visual Studio by SapphireSteel, I immediately thought about the Rubinius debugger highlighted in InfoQ recently. I decided to give it a try and see what I came up with. I wasn’t able to replicate Dermot’s tests exactly (I don’t know where he set his breakpoints, and Rubinius doesn’t support everything he tested), but here are my initial results:

Line Based
Rubinius no debugger Rubinius w/debugger no breakpoints Ruby
2.039 seconds 2.399 seconds 0.898 seconds
Call Based
Rubinius no debugger Rubinius w/debugger no breakpoints Ruby
13.441 second 13.999 seconds 4.171 seconds

Rubinius still has a long performance road ahead of them in terms of general execution, but it’s pretty exciting to see that their debugger is so fast. The cylon debugger (which smoked the other options in their testing) was 25% slower for line based debugging, and 306% slower for call based. By comparison, Rubinius’ debugger only added 17% for line based and 4% for call based (actually, I’m guessing that had the line based run through more iterations, the Rubinius debugger would have done better, I think most of its time is spent in set up).

Using the Rubinius debugger requires that you add a call to the debugger to the program:

debugger

def fac(n)
  lvar = n
  n == 1 ? 1 : n * fac(n-1)
  return n
end

count = 0

tstart = Time.new
0.upto(1000000) {fac(5)}               # 1ine based
#0.upto(30000000) {count += 1}         # call based
tend = Time.new  
puts "%10.3f" % tstart
puts "%10.3f" % tend.to_f
diff = tend - tstart
puts "%10.3f" % diff.to_f

When you run this, you’ll get something like this:

$ ../shotgun/rubinius debug_fac.rb
[Debugger activated]

debug_fac.rb:1 [IP:5]

rbx:debug> c
[Resuming program]
1201801369.694
1201801372.001
     2.307

There are several commands available:

command explanation
h get a listing of commands
b list breakpoints
b set a breakpoint at the start of the method
n Step to the next line
ni step to the next VM instruction
c continue execution until the next breakpoint
l list source code around the current breakpoint
d decode VM bytecode around the current breakpoint
v display local variables and their values
vs display the contents of the VM stack

Some of these are pretty cool, take a look at these examples:

rbx:debug> vs
     VM stack [0-5]:
  sp => 0: TrueClass  true
  fp => 1: Class      Rubinius::VM
        2: String     "" 
        3: String     "debug_fac.rb" 
        4: String     "debug_fac.rbc" 
        5: NilClass   nil
           ...

or:

rbx:debug> d
   Bytecode instructions [5-25] in compiled method script:
           ...
           # line 1
     0005: pop
           # line 3
     0006: push_literal  #
     0008: push_literal  :fac
     0010: push_self
     0011: send_stack    :add_method, 2
     0014: pop
           # line 9
  => 0015: meta_push_0
     0016: set_local     :count
     0018: pop
           # line 11
     0019: push_const    :Time
     0021: send_method   :new
     0023: set_local     :tstart
     0025: pop
           ...

which compares to:

rbx:debug> l
   Source lines [1-18] in debug_fac.rb:
      1: debugger
      2:
      3: def fac(n)
      4:   lvar = n
      5:   n == 1 ? 1 : n * fac(n-1)
      6:   return n
      7: end
      8:
  =>  9: count = 0
     10:
     11: tstart = Time.new
     12: 0.upto(1000000) {fac(5)}               # $-1òølineòù based
     13: #0.upto(30000000) {count += 1}     #$-1òùcallòù based
     14: tend = Time.new
     15: puts "%10.3f" % tstart
     16: puts "%10.3f" % tend.to_f
     17: diff = tend - tstart
     18: puts "%10.3f" % diff.to_f

Like a lot of things in Rubinius, the debugger isn’t quite ready for primetime but it sure shows a lot of promise.

4 comments:

agardiner said...

Hi Pate,

Hehe... the Rubinius debugger is not even half complete yet, but thanks for the write-up!

If you are interested, I've just addeed support for setting breakpoints at a particular line number in a method.

Cheers,

agardiner

pate said...

agardiner,

that's awesome news. I needed that to get a better comparison, so I'll run of and try to get it going for another post.

Rocky said...

I've seen a number of comparisons regarding the speeds of various debuggers, usually in regard to touting some new debugger as the fastest.

Although most of the comparisons I've read are well-intentioned and may give some representative idea, the real story however is a little bit more complicated.

There are several kinds of ways a debugger can get called into action initially, and get used subsequently; the fact that a number of the comparisons gloss over this suggests that those doing the comparisons might not even be aware of what's going on. For example consider this statement from the cited article:

The full speed debugger gives Rubinius a big edge versus Ruby implementations that need to rely on tracing based debuggers (no matter how fast these implementations are).

I'll come back to this comment a little later.

In the early days of debugging, one invoked the debugger at the outset. Perhaps one set up some breakpoints or started stepping through the program. It is for that kind of behavior that the debugger speed comparisons are most relevant.

Nowadays however it is not uncommon to bring in the program sometime after the program has started executing. In Ruby and Python (and even Bash ;-) you can "require", "import", or "source" the debugger anywhere in the code. And when this is done there is no overhead, until the debugger is pulled in. In fact, it's possible to set up an interrupt handler so that when the program gets a signal, that's when the debugger is loaded. (I can't remember, but I think I did this in a Python debugger I worked on.)

Debugging in Ruby is a little bit weird, different, good, and bad. (And in 1.9 I suspect it's going to get weirder, more different, better and worse). In contrast to say Perl, Ruby has less debugging support built in, and no Ruby primitives for accessing stack frames. Part of what made the default Ruby debugger "debug.rb" particularly slow is creating and saving frame information along with a "binding" to access variables. I think it has been noted in ruby-core and perhaps by Evan Phoenix that saving bindings can be particular slow.

In ruby-debug, Kent Sibilev's solution to debugging is particularly interesting and unique. There are three steps one must go through. First you bring in the debugger (e.g. require "ruby-debug"). Second you start recording frame information (e.g. Debugger.start), and third you add a trace hook (e.g. Debugger.debugger) which goes into the debugger proper. The interesting step is the second step, somewhat necessitated by Ruby's lack of built-in support. So not only is there a Debug.start, but there is also a Debugger.stop which removes the trace hook.

Therefore a savvy programmer who runs into debugger speed performance issues can speed up debugging by a judicious use of start/stop. In practice people like to put ruby-debug's start somewhere towards the beginning of execution, but it need not be done that way. If there's a place that you want go into the debugger at, you could but the start right before the call to debugger. In fact I think a call to debugger without a start will run it for you. The downside of this is just that you won't get call stack information lower than where the start was issued. However in terms of performance, you in fact have zero any debugger overhead before the first start and after any subsequent stop. (Sort of, it's possible to nest starts and stops; so I really mean stopping out of the the first-level.)

Ruby is not unique here. In Python debuggers (e.g. pdb and pydb) which a trace hook as well, there is a little hack that has been added to reduce overhead: if there are no line breakpoints set and one is not "stepping", the line event handler is not called. Python has the ability to set a break on a return frame call to a routine.

But having written all this, I admit that most people don't really know what's going on in the various debuggers so timing tests may be helpful here. In Rails 2.0 debug support was added; but it is done by issuing a Debugger.start early on. My take is that it was deemed that the performance degradation of ruby-debug not significant that it caused people to give it a second thought.

Don't get me wrong. I really like a VM trap instruction or instruction replacement (which I believe goes back to the days of debugging assembler on the IBM System/370 because in fact there wasn't a TRAP instruction like the PDP/11 had). And I think instruction replacement on the VM will have a big and bright future on Ruby as well.

I'm just saying the trace-hook versus trap thing might not necessarily be black and white as folks make it out to be.

Rocky said...

I wrote the above after a long tiring day at work. There are a couple of small errors I'd like to correct. Debugger.start is what installs a trace hook and that's when there starts to be overhead until Debugger.stop (level 1) is executed; "debugger" calls the debugger read loop.

Although "import"ing a Python debugger had been discussed in pydb, the code to do this isn't part of the code base; however there is a little used (and I'm not even sure if it works) "server" mode in pydb which does install a trap handler to pull in the debugger. However the bash debugger does allow one to set up a signal handler to bring in the debugger.

Finally, to elaborate on why debugging in 1.9 may get weirder is the fact that there may be mixed levels of debugging: there may be instruction replacement of VM code as well as trace hook debugging