public
Last active

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.

  • Download Gist
rails_trace.rb
Ruby
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115
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.

Please sign in to comment on this gist.

Something went wrong with that request. Please try again.