= <i>Ruby Unroller</i> -- a code tracing tool for Ruby

[<b>Home page</b>:]        http://unroller.rubyforge.org/
[<b>Project site</b>:]     http://rubyforge.org/projects/unroller/
[<b>Gem install</b>:]      <tt>gem install unroller</tt>
[<b>Wiki</b>:]             http://whynotwiki.com/Ruby_Unroller
[<b>Author</b>:]           Tyler Rick
[<b>Copyright</b>:]        2007 QualitySmith, Inc.
[<b>License</b>:]          {GNU General Public License}[http://www.gnu.org/copyleft/gpl.html]

==Introduction / What it is

Ruby Unroller is a tool for generating human-readable "execution traces".
While it is enabled, it will watch every Ruby statement and method call that gets executed and will display the source code on your screen in real-time as it is being executed.

You can use it for...

===Debugging

A very efficient tool for seeing what code actually gets executed... Add it to your toolbox along with the other tricks you already know, like inspecting <tt>caller()</tt> or printing "got here" at various places in your code.

===Learning/Exploring

It's a great tool for exploring 3rd-party source code that you aren't familiar with. If you've ever found yourself wondering "How was that method implemented?" or "What's going on behind the scenes when I call such-and-such?", then this tool is for you!


==Usage

Just insert these line before the point you want to start tracing:

  require 'unroller'
  Unroller::trace

And if you want the tracing to stop, just add this line somewhere:

  Unroller::trace_off

You can also pass a block to <tt>Unroller::trace</tt> and it will automatically turn off tracing as soon as the block has been executed.

  Unroller::trace do
  	...
  end

If you want really quick and dirty:
  require 'tron'
  ...
  troff

===Example

Say I have an ActiveRecord model and want to know exactly what actually goes on behind the scenes when I call model.save! . All I have to do is wrap the method call in a "trace" block, like this:

  Unroller::trace do
    model.save!
  end

, start the script, and then watch as the source code is unfolded before my very eyes!

Screenshot[link:include/screenshot1.png]

(The above shows <tt>:display_style => :concise</tt>.)

This is much more efficient and reliable than manually tracing through the execution yourself!  (Which would involve trying to guess which file the <tt>save!</tt> method would be defined in, searching for the file in the depths of <tt>/usr/lib/ruby/gems</tt>, scrolling down to the right line number, and repeating a zillion times...)

Here's an example of the interactive debugger mode:

Screenshot[link:include/screenshot_interactive.png]

(The above shows <tt>:display_style => :show_entire_method_body</tt>.)

===Interactive debugger

Currently there are two basic modes: non-interactive trace mode and interactive debugger mode. To enable the latter, just call <tt>Unroller::debug</tt>, kind of like this:

  Unroller::debug do
    whatever()
  end

It will prompt you after every line of code and ask you what to do. Currently the options are:
* <b>step out</b>
* <b>step over</b>
* <b>step into</b>
* <b>show locals</b>: lists all local variables and their variables (using pp pretty printer)
* <b>run</b>: ends interactive mode

<b>The interactive debugger is still pretty experimental and is sure to still have some bugs in it!</b>

===Inspecting variables

If you'd like to see the values of all arguments/parameters that were passed into the method for each method call, just pass in the <tt>:show_args => true</tt> option.

If you'd like to see the values of all local variables as they exist right before executing the current line, just pass in the <tt>:show_locals => true</tt> option.

Not implemented:
* You might like to know that the state of those variables is _after_ executing that line, too, but currently that's not implemented. (Use the interactive debugger instead.)
* Also, I haven't yet figured out a way to show the return value it's going to return with when we hit a 'return' event. That would be nice to have, too, if one can figure out how to implement it...

===Only tracing if a condition is met

For example, a lot of the time you will be in a loop or iterator and you will only be interested in what's going on <i>during certain iterations</i> of that loop.

There are two ways you can accomplish that selectivity:

The good old simple way:

  Unroller::trace if name =~ /interesting/
    code_that_may_or_may_not_be_traced
  Unroller::trace_off

And the somewhat trickier but arguably more elegant way that still uses a block (which always gets executed):

  Unroller::trace :if => { name =~ /interesting/ } do
    code_that_may_or_may_not_be_traced
  end

The other reason that the latter way is preferred is that the return value of the code-being-traced is preserved. With the first method, you could end up breaking things if the trace_off happens to be the last value in your method (because then the value of trace_off will be used as the return value).

Note: The actual application code (the code in the block passed to Unroller::trace, if using the block version) will _always_ get executed, with either of these methods. It is only the tracing that we are toggling, not the execution of the code within the trace(d) block.

===Reducing verbosity

This can generate some really *verbose* output... Not only can be impractical to try to *read* through the reams of pages it can produce, but it can also take an hour just to output it in the first place!

A couple options are available to help things under control. The two main approaches are to only trace a limited section of code or to trace a large section of code but exclude certain types of calls (for example, low-level methods that you don't care about.)

You may find that your trace is cluttered/dominated by calls to a small set of methods and classes that you don't care about. These options help you to exclude the worst offenders in a hurry:

<tt>:file_match => file_match</tt> ::
  Unroller will only show a trace for code whose filename matches <tt>file_match</tt>. If <tt>file_match</tt> is not already a regular expression it will be escaped and turned into one (<tt>/file_match/</tt>).
<tt>:dir_match => dir_match</tt> ::
  Unroller will only show a trace for code whose filename matches <tt>dir_match</tt>. If <tt>dir_match</tt> is not already a regular expression it will be escaped and turned into one (<tt>/^dir_match/</tt>). Tip: You can simply pass in __FILE__ and it will automatically turn that into File.expand_path(File.dirname(__FILE__)) for you.
<tt>:exclude_classes</tt> ::
  Unroller won't show a trace for any calls to methods from the given class or classes (regular expressions).
  Pass [/class_name/, :recursive] to also not show the trace for any calls made *from* those uninteresting methods.
<tt>:exclude_methods</tt> (not implementd) ::
  Like <tt>:exclude_classes</tt> only you give it _method_ names instead of class names. Maybe will have the ability to specify a class name as well as a method name if you want to be more specific (f.e., <tt>ThatOneClass#format</tt> if you still want to include calls to other methods named <tt>format</tt>).

These options are for more general overall control:

<tt>:max_depth => depth</tt> ::
  Use this to prevent from going more than <tt>depth</tt> levels deep (_relative_ to starting depth) if you find that the trace is cluttered by a bunch of really deep calls.
<tt>:max_lines</tt> ::
  If you don't know where to place the trace(false) and you just want it to stop on its own after so many lines, you could use this...

I'd recommend using <tt>:max_depth</tt> option with something sane like 3 or 5 most of the time.

Examples:

  Unroller::trace :max_lines => 100, :exclude_classes => /Boring/ { ... }

  Unroller::trace :if => proc{$tracing_enabled}, :max_depth => 9, :exclude_classes =>
    [
      /Benchmark/,
      /Logger/,
      /MonitorMixin/,
      /Set/,
      /HashWithIndifferentAccess/,
      /ERB/,
      /ActiveRecord/,
      /SQLite3/,
      /Class/,
      /ActiveSupport/,
      /ActiveSupport::Deprecation/,
      /Pathname/
    ] do
      ...
    end

Ignore a section of code that is within the block passed to +trace+:

  Unroller::trace do
	  stuff_you_care_about
    Unroller::exclude do
      stuff_that_you_really_dont_care_about
	  end
	  stuff_you_care_about
  end

===How did that method even get *called*?

Some of the time, you may be trying to answer the question "How did that method even get *called*?" This tool can't directly help answer that question unless you're willing to enable tracing really early and wade through pages and pages of output.

If you enable tracing from within that method, it will only show the calls that came *after* the mysterious call to the mystery function, not what came *before*, which is what you're interested in.

So... you could always <tt>p caller(0)</tt> within your mystery function and then put a trace around one of the calls leading up to this call, a little further up the stack...

I know, wouldn't it be nice if you could just tell it, "Show me the execution traces for the 3 calls leading up to this call"? But alas, Unroller can only affect what happens _after_ it gets called, not before.
*If I ever get around to writing an interactive tree-based UI for this, then I guess we could give the _impression_ of being able to show calls leading up to a certain call. But only by recording *all* calls and then hiding everything except the calls you're interested in...
*If it is completely reproduceable, then we could even do it without the tree-based UI. We could just keep track of the "executed line number" at which the interesting event occured (line_number_of_interest), then subtract however many lines we want to see leading up to that call (introductory_lines_count), re-run the script, and have it stop after (line_number_of_interest - introductory_lines_count) lines are executed.

===When did that constant get set the _first_ time??===

If you start getting errors like "warning: already initialized constant OPTIONS", then you may be wondering when it was first initialized (something the backtrace fails to tell you).

Here's one way you could try to answer that question...
  Unroller::trace :line_matches => 'OPTIONS ='.to_re

===Usage in Rails

Unroller can be useful for debugging in development mode as well as in tests.

<b>Requires a terminal</p>. Keep in mind that it requires a terminal onto which to output, so it will work if you've started your server with <tt>./script/server</tt>; it will _not_ work if the server is detached from the terminal using <tt>./script/server -d</tt>, for example, or if it's being executed via FastCGI... Don't worry, it will gently remind you of this with a happy <tt>can't get terminal parameters (Inappropriate ioctl for device)</tt> error if you forget about it.

Rails has a lot of levels of abstractions, so even a seemingly simple call can generate many, many method calls. You may want to try using some of the filtering options, such as <tt>:exclude_classes</tt>, to reduce the verbosity of the output.

<b>Unrolling an action in your controller:</b>

If you want to see all code that gets executed within a certain action in your controller, you can just add this snippet to your controller, request the page, and watch the console where you have Webrick running as pages and pages of ActionController/ActionRecord code go flying by...

  around_filter do |controller, action|
    Unroller::trace do
      action.call
    end
  end

==Installation

  sudo gem install unroller --include-dependencies

The dependencies include: facets, quality_extensions, colored, and extensions

==Status

It's pretty much fully functional, but may still have a couple rough edges.

Generally it behaves quite reliably and stably.

(Don't even *think* about leaving this in your production code!)

The code isn't really clean and there aren't (m)any automated tests yet because I've kind of thrown this together in a big hurry, but I hope to solve both of those problems eventually.
You might consider this a "prototype" right now -- it works, but it wouldn't hurt at some point to throw it away and re-implement it a bit better.

Also keep in mind that the API as subject to change as I try to think of better design ideas and as I get feedback from people telling me what they want to see.

==About the name

I called it "Ruby Unroller" because it visually "unrolls" a stack trace for you (like a scroll?). (And it sounds cooler than "Ruby Script Execution Tracer".)

If there are method calls (even recursion), it will sort of "unroll" the method definition for you so you can see it.

It also alludes to some ideas from compiler design. Think {"method inlining"}[http://en.wikipedia.org/wiki/Inline_expansion] and {"loop unrolling"}[http://en.wikipedia.org/wiki/Loop_unrolling] in real-time. Not quite the same thing, but close enough.

It takes something that is actually very stack-based (the path that Ruby interpreter takes while executing your source code) and "flattens" it. It still tries to keep things appearing hierarchical (by means of the indent levels), but in essence it takes code from a bunch of different files and merges them into one "flat" output stream.

Phew!

Other name ideas are welcome!
* Unfolder?
* ...

==Similarity to debuggers/profilers / What it is not

It's sort of like a cross between a Ruby debugger and a profiler.

It's like a debugger because it lets you step through code execution one line at time (similar to the "step into" / "next" commands in most debuggers). It's not a debugger, though, because it doesn't let you inspect variables, set breakpoints, etc. It lets you *watch* the execution ... and that's it! So it's not as powerful as a real debugger, but it can be a lot *faster*! Rather than pressing F8 (or whatever the shortcut is for the 'step' command) 1000 times, you can just tell it "trace from here to here" and it will.

And like a profiler, it follows every method call, using Ruby's set_trace_func. Like a profiler, it can be helpful for diagnosing performance bottlenecks in your application -- at least those that involve excessive or unwanted method calls or recursion. It's not a profiler, though, because it doesn't _time_ the method calls like a 'real' profiler would.

It's also sort of like a call stack (caller(0)). But unlike the callstack you usually see, which only shows where you've been, this one doesn't show where you've been; it only shows where you _going_ -- or more accurately, where you *go* after you enable the tracing. So while it works equally well for tracing while the call stack is being unwound (returning from calls, which pops that call off the stack), the most common use of the tracer is to see what happens "within" a method call -- that method will in turn call _other_ methods, and the stack will grow temporarily -- but then it will unwind again and you'll get back to the method where you started the trace (hopefully -- eventually?), with a net change in stack size of 0.

(If you _do_ want to watch the trace as the call stack is unwound completely, be sure to pass <tt>:depth => caller(0).size</tt> to the Unroller so that it can start the indenting at an appropriate level...)

==Possibly related projects

I didn't see any projects out there that did what I was wanting, so I wrote my own (and was surprised by how easy it was!). But if you know of any similar projects out there, let me know and I'll check it out.

Here are the closest projects I've run across so far...
* http://rubyforge.org/projects/dev-utils/ : Collects utilities that aid Ruby development, e.g. testing and debugging. Version 1.0 contains simple debug logging, tracing, and escaping to IRB.
* http://rubyforge.org/projects/ruby-uml/ : Generates uml diagrams by tracing the run of an application for analysation of an existing application and to provide support for refactorisations.

I've also heard rumors that Ruby comes standard with some kind of debugger (?) ... Maybe I wouldn't have written this if I'd known how to use that (is it any good?? is it easy to use??)... but... I still haven't even looked at that.

==To do

You're welcome to submit comments, ideas, and/or patches.

* Make a GUI interface that lets you quickly collapse/nodes nodes of the tree.
* :include_classes option in addition to :exclude_classes?

===Presets

* Have some "presets" for what you might want to exclude if tracing an ActiveRecord request for example. In that case, you probably don't want to see the internals of any support code, like any methods from ActiveSupport.
  * :rails => true
  * :preset => :Rails : Exclude ActiveSupport, Dependencies, etc.
  * :preset => :ActiveSupport : Exclude ActiveRecord, etc.
  * :preset => :'ActiveRecord high level' : excludes the lowel-level database stuff (like the individual adapter (SQLite, MySQL, ...).
  * :preset => :'ActiveRecord low level'

Might be more intuitive to say :exclude => :boring_rails_stuff
(If it's a symbol passed in instead of a string or regexp, we'll assume it's a preset, which will be turned into the strings/regexp's that it defines)

Also :include => :something.

Let them store presets in a ~/.unroller file so they're not limited to my ideas, and don't have to type out a long list of exclusions every time they want to reuse a common set of exclusions.

==="Watch for" conditions

Only traces / shows you when/if a certain condition is met.

You could use it, for example, to answer the question, "When did this method get added?? I don't remember adding that?!"

Useful when you see evidence that something *is* happening but you just can't figure out *where* it's happening or *why*.

You'd just start the tracer at the very beginning of your application and tell it to watch for lines that might have caused it to be added.

It wouldn't be perfect by any means, but it it might be better than nothing...

* You'd kind of have to know a lot about Ruby and the various ways methods can get added. (Normal def statements or alias or alias_method or alias_method_chain, etc.)
* It would be a rather inexact test, as it would probably use string/Regexp matching, which can easily be too broad or too strict
* It wouldn't work for stuff that happens during c-calls or if people don't specify the correct file/line for their evals (because if they don't do that, we can't read the source code)

Might look something like this...

Unroller::trace, :watch_for => proc {|event| event.type =~ /line/ && (event.code =~ /def/ || event.method =~ /method/) }
end

Other name ideas: :match_code, :match_event, :event_match, :only_events