Analyze ruby execution stack with #caller

Sometimes you may need (or just want) to see the current execution stack of your ruby code for inspection: for this very purpose Ruby core library provides a method named caller. Its output is similar to the one of error backtraces, so you should be able to get very familiar with it quite soon.

caller provides some very useful debugging capability, is defined inside the Kernel module, which in turn is included into Object making it available anywhere. Let’s start with the simplest example, create a file and save it with the following content:

def a
  puts 'Your code execution stack:'
  puts caller(0)
end

def b
  a
end

b

When executed, the file output is:


$ ruby example.rb 

Your code execution stack:
example.rb:3:in `a'
example.rb:7:in `b'
example.rb:10:in `'

As you can see this is pretty informative, as it shows every step involved in the code execution, listing the filename, the method and the line number where execution passed to each next method. When you’re dealing with a complex application this can become a lifesaver. We’re seeing the result printed on the screen, but actually caller returns an array of strings (i.e. the lines).

What about that 0 param? It tells how many initial entries from the stack are to be omitted, it is optional and the default is 1. If you remove the zero then you will see that the first line example.rb:3:in `a' disappears from output.

caller accepts a second parameter, which represents how many lines are to be collected in the array. If you change the code to caller(0, 2) then the last line of the output will disappear, listing only the first 2 lines.

Now, let’s see a real use case when caller comes handy. I’ve created a simple rails app with the only purpose of listing all the rails source files involved in a simple request, plus the ability of showing the files content directly in the browser. The application can be downloaded here: read_rails.

Most of my code is in application_controller.rb, routes.rb and views/application/index.html.erb, you can look at those files if you’re interested in how it works, but most of the interesting code is in the erb view listed below:

<pre>
  <% caller(0).each_with_index do |line, i| %>
    <% filename, line_number = line.split(':') %>
    <%= i+1 %> <%= link_to line, "#{filename}#n#{line_number}", target: '_blank' %>
  <% end %>
</pre>

Bundle the gems, start the server and head to http://localhost:3000 to see the list of the files and methods involved in the request cycle. Each line, if clicked, will show the actual rails source code installed on your machine and used by the application.

image

What can we learn from this backtrace?

First, rails is a complex beast: about 110 different method calls (and about the same size in files) are involved to complete the request.

Second: we hit the whole rails MVC stack, plus routing, rack and webrick.

Third: this simple request hits only one single file inside the real app (the index view), the rest is library code. Of course, when you add database queries, assets and javascripts the count increases.

At this point, you may want to pry into rails guts and see what’s really happening at each point, so have fun!

Leave a Reply

wpDiscuz