= Ruby Unroller -- a code tracing tool for Ruby
[Home page:] http://unroller.rubyforge.org/ [Project site:] http://rubyforge.org/projects/unroller/ [Gem install:] gem install unroller [Wiki:] http://whynotwiki.com/Ruby_Unroller [Author:] Tyler Rick [Copyright:] 2007 QualitySmith, Inc. [License:] {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 caller() 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 Unroller::trace 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 'unroller/tron' ...
Or, for the interactive debugger: require 'unroller/debug' ...
===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 :display_style => :concise.)
This is much more efficient and reliable than manually tracing through the execution yourself! (Which would involve trying to guess which file the save! method would be defined in, searching for the file in the depths of /usr/lib/ruby/gems, 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 :display_style => :show_entire_method_body.)
===Interactive debugger
Currently there are two basic modes: non-interactive trace mode and interactive debugger mode. To enable the latter, just call Unroller::debug, 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:
The interactive debugger is still pretty experimental and is sure to still have some bugs in it!
===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 :show_args => true 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 :show_locals => true option.
Not implemented:
===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 during certain iterations 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:
:file_match => file_match :: Unroller will only show a trace for code whose filename matches file_match. If file_match is not already a regular expression it will be escaped and turned into one (/file_match/). :dir_match => dir_match :: Unroller will only show a trace for code whose filename matches dir_match. If dir_match is not already a regular expression it will be escaped and turned into one (/^dir_match/). Tip: You can simply pass in FILE and it will automatically turn that into File.expand_path(File.dirname(FILE)) for you. :exclude_classes :: 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. :exclude_methods (not implementd) :: Like :exclude_classes 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., ThatOneClass#format if you still want to include calls to other methods named format).
These options are for more general overall control:
:max_depth => depth :: Use this to prevent from going more than depth levels deep (relative to starting depth) if you find that the trace is cluttered by a bunch of really deep calls. :max_lines :: 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 :max_depth 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 p caller(0) 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.
Requires a terminal
. Keep in mind that it requires a terminal onto which to output, so it will work if you've started your server with ./script/server; it will not work if the server is detached from the terminal using ./script/server -d, for example, or if it's being executed via FastCGI... Don't worry, it will gently remind you of this with a happy can't get terminal parameters (Inappropriate ioctl for device) 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 :exclude_classes, to reduce the verbosity of the output.
Unrolling an action in your controller:
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!
==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 :depth => caller(0).size 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...
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.
===Presets
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...
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