Tracing Ruby Code

I'm not a big fan of using debugging tools with Ruby. When I want to check something I'll often just use puts (or even raise when debugging controller actions/views because it's easier to see the result in browser instead of looking in the logs).

However, there are times when I want to look deeper in the source code and understand how an external library call works. And, when it's some complex code, it becomes difficult to quickly familiarize and get a sense of where things are placed. In such situation, having a trace log with all execution calls in a file:line format is quite handy to give me the big picture.

Thanks to Ruby's dynamic nature, we can inspect what's going on during execution. In the old Ruby days, set_trace_func was the real thing, but since Ruby 2.0 it is the OO equivalent TracePoint.

Here's a simple trace method that will write the line:file trace points to /tmp/trace.txt file.

def trace(event_type = :call, *matchers)
  points = []

  tracer = TracePoint.new(event_type) do |trace_point|
    if matchers.all? { |match| trace_point.path.match(match) }
      points << { file: trace_point.path, line: trace_point.lineno, }
    end
  end

  result = tracer.enable { yield }

  File.open('/tmp/trace.txt', 'w') do |file|
    points.each do |point|
      file.puts "#{point[:file]}:#{point[:line]}"
    end
  end

  result
end

Once I have the /tmp/trace.txt trace log, I would use Vim to navigate the files and get a sense of how code is structured in the library (using gF to navigate files and go to the specific line or using file-line plugin for opening files at specific line).

By default it will trace events of type :call:

trace(:call) do
  FactoryGirl.create(:account) # call we want to trace
end

event_type can be any of the following:

 :line,                      # line of code
 :call, :return              # ruby method
 :class, :end                # start/end of class/module
 :c_call, :c_return          # MRI itself
 :raise                      # exception
 :b_call, :b_return          # ruby block
 :thread_begin, :thread_end  # thread

As optional arguments, trace method accepts file name matchers that I find useful to filter out the trace points to what might be of my interest. For example, if I want to focus on the code in FactoryGirl gem (but not ActiveRecord and such), I'll just filter out by file names matching factory_girl.

trace(:call, 'factory_girl') do
  FactoryGirl.create(:account) # call we want to trace
end

TracePoint is capable of much more that this and debuggers such as ByeBug use it, so be sure to check the docs.

One final tip for the end. If you just want to identify the source location of a method call and start looking at the source code from there, you can just do:

FactoryGirl.method(:create).source_location

Posted by Dalibor Nasevic on and tagged with: and .