This Rack middleware for Rails3 lets you see a call-trace of the lines of ruby code in your application invoked during a single request. Only code within your app is considered (i.e. in the /app folder). This expands on my previous attempt (https://gist.github.com/3077744). Example of output in comments below.

rails_trace.rb

require 'singleton'

# outputs a colored call-trace graph to the Rails logger of the lines of ruby code
# invoked during a single request.
#
# Example:
#
# 1) Make sure this file is loaded in an initializer
#
# 2) Add the following to your application.rb in Rails3:
#   if ENV["TRACE"] == "on"
#     config.middleware.use 'RailsTrace'
#   end
#
# 3) then invoke webrick: 
#   $ TRACE=on rails s
#
class RailsTrace

  def initialize(app)
    @app = app
  end
  
  def call(env)
    dup._call(env)
  end
  
  def _call(env)
    t = Tracer.instance
    t.record
    status, headers, response = @app.call(env)
    t.stop
    t.dump
    [status, headers, response]
  end

  class Tracer  
    include Singleton

    def initialize
      @recording = false
      set_trace_func proc { |event, file, line, id, binding, classname|
        if event != "c-call" && event != "c-return" && file =~ /(app\/.*)/
          store_trace(event, $1, file, line)
        end
      }
      log "TRACER: initialized."
    end

    def log(msg, comment = "")
      Rails.logger.debug("\033[1;32m%s\033[0m\033[1;30m%s\033[0m" % [msg, comment])
    end

    def record
      log "TRACER: (recording)"
      @trace_lines = []
      @recording = true
    end

    def recording?
      @recording 
    end
    
    def stop
      @recording = false
      log "TRACER: (stopped)"
    end
    
    def store_trace(event, rel_path, full_path, line)
      @trace_lines << [event, rel_path, full_path, line] if recording?
    end

    def dump
      log "TRACER: dumping trace:"
      indent = 0
      @trace_lines.each do |arr|
        event, rel_path, full_path, line = arr
        source_line = get_line(full_path,line)
        case event
        when /return/
          log( "%s. %s" % ["| "*indent, source_line.chop], " # TRACE %s:%-2d" % [rel_path, line] )
          indent -= 1
        when /call/
          indent += 1
          log( "%s %s" % ["|-"*indent, source_line.chop], " # TRACE %s:%-2d" % [rel_path, line] )
        else
            log( "%s| %s" % ["| "*indent, source_line.chop], " # TRACE %s:%-2d" % [rel_path, line] )
        end
      end
    end

    def get_line(file, line)
      @script_lines ||= {}
      unless list = @script_lines[file]
        begin
          f = ::File::open(file)
          begin
            @script_lines[file] = list = f.readlines
          ensure
            f.close
          end
        rescue Exception => e
          @script_lines[file] = list = []
        end
      end

      if l = list[line - 1]
        l
      else
        "\n"
      end
    end
  end

end

What is it?

Have you ever wanted to see what Ruby lines are executed while processing a request in Rails or other Rack-based app? This simple gist shows how to gather trace information so that you can see every line of code that was executed without having to manually browse source files and "play computer".

Based on my previous experiment in this direction.

Example

Here's an example of the output.

Features

• hierarchical code-trace - the level of nesting is shown with a pipe and dash tree diagram next to the lines of code called.
• limits trace to code within the "/app" directory, but could be adjusted to taste.
• great for debugging other people's Rails code!

Limitations

• doesn't trace through blocks/closures?
• similar to Ruby Tracer implementation, however uses deferred and customized output.

Motivation

The pry gem is good, but there's only so much information you can get from setting a breakpoint and looking at a backtrace. In particular, a backtrace doesn't show you deeply nested context that has already executed and then bubbled up a few levels before descending to the branch of code where your breakpoint is set.

Code profiling tools like the ruby-prof gem show a coarse-grained trace of execution, but you can't see the individual branch points and statements that were executed.

This gist goes deeper by combining the "show_source" feature of Pry with a finer-grained code-trace than ruby-prof. The result is you can see in exact detail what lines of Ruby code execute during a request, including filters, procs, helpers, renderers.