In Progress
Unit 1, Lesson 1
In Progress

Tracepoint

Video transcript & code

Ruby is a dynamic programming language. "Dynamic" can mean a lot of things. But one of the things it means is that it puts most of its decisions off until as late as possible.

Let's look at an example of what this can mean, and where it sometimes give us trouble.

When we require the "rake" library, it doesn't just load code in the Rake namespace. It adds some goodies to other classes as well. For instance, if we include the FileUtils module, we can now run subsidiary Ruby processes just by using the ruby method. This method only exists if we require rake. We can't get it just by requiring fileutils.

require "rake"

include FileUtils

ruby "-v"

# >> ruby 2.2.0p0 (2014-12-25 revision 49005) [x86_64-linux]

# !> /home/avdi/.rubies/ruby-2.2.0/bin/ruby -v

We might like to discover where this added method is defined, and how it works. How does this method determine how to find the currently-running Ruby executable? That might be some useful knowledge.

But where can we find the code for this add-on method? Obviously it's not in the fileutils.rb file, since requiring that file doesn't provide it. We might look around in the rake source code, but we're not really sure where to start.

And anyway, even if we find the method we're looking for in here, do we really know that it's the one being called? After all, the whole point of a dynamic language is that it doesn't decide which actual implementation of a method is called until the last possible moment, when the message is actually sent. We can poke around the code all we want, making up stories about how it runs. But the only way to know if our stories are true is to run the code and see.

The trouble with running the code is that Ruby doesn't normally tell us what its up to. It just does it. We need a way to run the code and get ruby to report what it's doing as it does it.

Enter the TracePoint API. TracePoints are a way to have Ruby tell us all about what its doing, as it does it.

Let's set up a simple trace. We'll instantiate a new TracePoint, and pass it a block. The block receives TracePoint objects. Inside, we'll just print out the object.

Then we'll enable the trace. After it's enables, we'll execute a single, very simple line of code. All it does is sort an array. Once we're done with this line, we'll disable the trace.

trace = TracePoint.new do |tp|
  p tp
end

trace.enable
[1,2,3].sort!
trace.disable

Let's save this code and run it.

 $ ruby trace_sort.rb
#<TracePoint:c_return `enable'@trace_sort.rb:6>
#<TracePoint:line@trace_sort.rb:7>
#<TracePoint:c_call `sort!'@trace_sort.rb:7>
#<TracePoint:c_return `sort!'@trace_sort.rb:7>
#<TracePoint:line@trace_sort.rb:8>
#<TracePoint:c_call `disable'@trace_sort.rb:8>

We can see that just with a one-line trace, several tracepoints were generated. First, we have a :c_return, which is a return from the enable method, defined in C code. Then we have a line event, as the VM moves on to executing the next line of code. Then we have a :c_call and a :c_return for the #sort! method. Next another :line event, and a :c_call into the method that disables tracing.

Now that we have a basic idea of how to use tracepoints, lets apply this knowledge to the method we were wondering about originally.

require "rake"

include FileUtils

trace = TracePoint.new do |tp|
  p tp
end

trace.enable

ruby "-v"

trace.disable

We run this code and… wow, that's a lot of information!

 $ ruby trace_all.rb
#<TracePoint:c_return `enable'@trace_all.rb:10>
#<TracePoint:line@trace_all.rb:12>
#<TracePoint:call `ruby'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:33>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:37 in `ruby'>
#<TracePoint:call `rake_merge_option'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:116>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:117 in `rake_merge_option'>
#<TracePoint:c_call `last'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:117>
#<TracePoint:c_return `last'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:117>
#<TracePoint:c_call `==='@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:117>
#<TracePoint:c_return `==='@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:117>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:121 in `rake_merge_option'>
#<TracePoint:c_call `push'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:121>
#<TracePoint:c_return `push'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:121>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:122 in `rake_merge_option'>
#<TracePoint:return `rake_merge_option'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:123>
#<TracePoint:call `ruby'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:91>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:92 in `ruby'>
#<TracePoint:c_call `last'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:92>
#<TracePoint:c_return `last'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:92>
#<TracePoint:c_call `==='@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:92>
#<TracePoint:c_return `==='@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:92>
#<TracePoint:c_call `pop'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:92>
#<TracePoint:c_return `pop'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:92>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:93 in `ruby'>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:96 in `ruby'>
#<TracePoint:c_call `first'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:96>
#<TracePoint:c_return `first'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:96>
#<TracePoint:call `sh'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:33>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:37 in `sh'>
#<TracePoint:call `rake_merge_option'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:116>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:117 in `rake_merge_option'>
#<TracePoint:c_call `last'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:117>
#<TracePoint:c_return `last'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:117>
#<TracePoint:c_call `==='@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:117>
#<TracePoint:c_return `==='@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:117>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:118 in `rake_merge_option'>
#<TracePoint:c_call `last'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:118>
#<TracePoint:c_return `last'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:118>
#<TracePoint:c_call `update'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:118>
#<TracePoint:c_return `update'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:118>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:119 in `rake_merge_option'>
#<TracePoint:c_call `pop'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:119>
#<TracePoint:c_return `pop'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:119>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:121 in `rake_merge_option'>
#<TracePoint:c_call `push'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:121>
#<TracePoint:c_return `push'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:121>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:122 in `rake_merge_option'>
#<TracePoint:return `rake_merge_option'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:123>
#<TracePoint:call `sh'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:45>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:46 in `sh'>
#<TracePoint:c_call `last'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:46>
#<TracePoint:c_return `last'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:46>
#<TracePoint:c_call `==='@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:46>
#<TracePoint:c_return `==='@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:46>
#<TracePoint:c_call `pop'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:46>
#<TracePoint:c_return `pop'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:46>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:47 in `sh'>
#<TracePoint:c_call `block_given?'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:47>
#<TracePoint:c_return `block_given?'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:47>
#<TracePoint:call `create_shell_runner'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:61>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:62 in `create_shell_runner'>
#<TracePoint:c_call `join'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:62>
#<TracePoint:c_return `join'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:62>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:63 in `create_shell_runner'>
#<TracePoint:c_call `[]'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:63>
#<TracePoint:c_return `[]'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:63>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:64 in `create_shell_runner'>
#<TracePoint:c_call `lambda'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:64>
#<TracePoint:c_return `lambda'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:64>
#<TracePoint:return `create_shell_runner'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:69>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:48 in `sh'>
#<TracePoint:call `set_verbose_option'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:72>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:73 in `set_verbose_option'>
#<TracePoint:c_call `key?'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:73>
#<TracePoint:c_return `key?'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:73>
#<TracePoint:return `set_verbose_option'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:78>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:49 in `sh'>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:50 in `sh'>
#<TracePoint:call `rake_check_options'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:133>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:134 in `rake_check_options'>
#<TracePoint:c_call `dup'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:134>
#<TracePoint:c_call `initialize_dup'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:134>
#<TracePoint:c_call `initialize_copy'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:134>
#<TracePoint:c_return `initialize_copy'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:134>
#<TracePoint:c_return `initialize_dup'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:134>
#<TracePoint:c_return `dup'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:134>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:135 in `rake_check_options'>
#<TracePoint:c_call `each'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:135>
#<TracePoint:b_call@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:135>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:136 in `rake_check_options'>
#<TracePoint:c_call `delete'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:136>
#<TracePoint:c_return `delete'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:136>
#<TracePoint:b_return@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:137>
#<TracePoint:b_call@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:135>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:136 in `rake_check_options'>
#<TracePoint:c_call `delete'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:136>
#<TracePoint:c_return `delete'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:136>
#<TracePoint:b_return@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:137>
#<TracePoint:c_return `each'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:135>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:139 in `rake_check_options'>
#<TracePoint:return `rake_check_options'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:140>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:51 in `sh'>
#<TracePoint:c_call `join'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:51>
#<TracePoint:c_return `join'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:51>
#<TracePoint:call `rake_output_message'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:126>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:127 in `rake_output_message'>
#<TracePoint:c_call `puts'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:127>
#<TracePoint:c_call `write'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:127>
/home/avdi/.rubies/ruby-2.2.0/bin/ruby -v#<TracePoint:c_return `write'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:127>
#<TracePoint:c_call `write'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:127>

#<TracePoint:c_return `write'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:127>
#<TracePoint:c_return `puts'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:127>
#<TracePoint:return `rake_output_message'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:128>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:53 in `sh'>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:54 in `sh'>
#<TracePoint:call `rake_system'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:81>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:82 in `rake_system'>
#<TracePoint:c_call `system'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:82>
ruby 2.2.0p0 (2014-12-25 revision 49005) [x86_64-linux]
#<TracePoint:c_return `system'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:82>
#<TracePoint:return `rake_system'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:83>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:55 in `sh'>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:56 in `sh'>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:57 in `sh'>
#<TracePoint:c_call `call'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:57>
#<TracePoint:b_call@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:64>
#<TracePoint:line@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:67 in `create_shell_runner'>
#<TracePoint:b_return@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:68>
#<TracePoint:c_return `call'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:57>
#<TracePoint:return `sh'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:59>
#<TracePoint:return `sh'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:38>
#<TracePoint:return `ruby'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:98>
#<TracePoint:return `ruby'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:38>
#<TracePoint:line@trace_all.rb:14>
#<TracePoint:c_call `disable'@trace_all.rb:14>
~/Dropbox/rubytapas/327-tracepoint $

The trace output shows us every line of code that was executed, and every method call and return. If we look carefully, we can also see some events for Ruby blocks being executed and returning.

The only thing we can't see in tracing output is what happens inside of code written in C. Unfortunately, that code is opaque to the tracepoint system, because it's executed outside of the Ruby VM.

This is a lot of data to comprehend. Let's filter it a bit. We can tell TracePoint that we're only interested in a subset of event types, by passing a list of symbols to the .new method. Here we tell it that we only care about method calls, whether methods written in Ruby or in C code.

require "rake"

include FileUtils

trace = TracePoint.new(:call, :c_call) do |tp|
  p tp
end

trace.enable

ruby "-v"

trace.disable

This thins out the output considerably, but it's still a little hard to follow.

$ ruby trace_calls.rb
#<TracePoint:call `ruby'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:33>
#<TracePoint:call `rake_merge_option'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:116>
#<TracePoint:c_call `last'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:117>
#<TracePoint:c_call `==='@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:117>
#<TracePoint:c_call `push'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:121>
#<TracePoint:call `ruby'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:91>
#<TracePoint:c_call `last'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:92>
#<TracePoint:c_call `==='@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:92>
#<TracePoint:c_call `pop'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:92>
#<TracePoint:c_call `first'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:96>
#<TracePoint:call `sh'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:33>
#<TracePoint:call `rake_merge_option'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:116>
#<TracePoint:c_call `last'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:117>
#<TracePoint:c_call `==='@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:117>
#<TracePoint:c_call `last'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:118>
#<TracePoint:c_call `update'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:118>
#<TracePoint:c_call `pop'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:119>
#<TracePoint:c_call `push'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:121>
#<TracePoint:call `sh'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:45>
#<TracePoint:c_call `last'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:46>
#<TracePoint:c_call `==='@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:46>
#<TracePoint:c_call `pop'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:46>
#<TracePoint:c_call `block_given?'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:47>
#<TracePoint:call `create_shell_runner'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:61>
#<TracePoint:c_call `join'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:62>
#<TracePoint:c_call `[]'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:63>
#<TracePoint:c_call `lambda'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:64>
#<TracePoint:call `set_verbose_option'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:72>
#<TracePoint:c_call `key?'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:73>
#<TracePoint:call `rake_check_options'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:133>
#<TracePoint:c_call `dup'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:134>
#<TracePoint:c_call `initialize_dup'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:134>
#<TracePoint:c_call `initialize_copy'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:134>
#<TracePoint:c_call `each'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:135>
#<TracePoint:c_call `delete'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:136>
#<TracePoint:c_call `delete'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:136>
#<TracePoint:c_call `join'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:51>
#<TracePoint:call `rake_output_message'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:126>
#<TracePoint:c_call `puts'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:127>
#<TracePoint:c_call `write'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:127>
/home/avdi/.rubies/ruby-2.2.0/bin/ruby -v#<TracePoint:c_call `write'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:127>

#<TracePoint:call `rake_system'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:81>
#<TracePoint:c_call `system'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:82>
ruby 2.2.0p0 (2014-12-25 revision 49005) [x86_64-linux]
#<TracePoint:c_call `call'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:57>
#<TracePoint:c_call `disable'@trace_calls.rb:14>

Let's make this easier to read by adding some indentation. We'll set up an indent level, starting it at 0. We'll add method returns to the list of events we are interested in.

Before printing, we'll check to see if the event was a method return. If so, we'll decrement the indent and then move on. If it was a call, on the other hand, we'll print the indented tracepoint, and then bump up the indent.

require "rake"

include FileUtils

indent = 0
trace = TracePoint.new(:call, :c_call, :return, :c_return) do |tp|
  if [:return, :c_return].include?(tp.event) && indent.nonzero?
    indent -= 1
  else
    puts "#{' ' * indent}#{tp.inspect}"
    indent += 1
  end
end

trace.enable

ruby "-v"

trace.disable

When we run this code, we get a pretty good picture of what method calls go into running a child Ruby process.

$ ruby trace_indent.rb
#<TracePoint:c_return `enable'@trace_indent.rb:16>
 #<TracePoint:call `ruby'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:33>
  #<TracePoint:call `rake_merge_option'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:116>
   #<TracePoint:c_call `last'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:117>
   #<TracePoint:c_call `==='@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:117>
   #<TracePoint:c_call `push'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:121>
  #<TracePoint:call `ruby'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:91>
   #<TracePoint:c_call `last'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:92>
   #<TracePoint:c_call `==='@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:92>
   #<TracePoint:c_call `pop'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:92>
   #<TracePoint:c_call `first'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:96>
   #<TracePoint:call `sh'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:33>
    #<TracePoint:call `rake_merge_option'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:116>
     #<TracePoint:c_call `last'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:117>
     #<TracePoint:c_call `==='@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:117>
     #<TracePoint:c_call `last'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:118>
     #<TracePoint:c_call `update'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:118>
     #<TracePoint:c_call `pop'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:119>
     #<TracePoint:c_call `push'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:121>
    #<TracePoint:call `sh'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:45>
     #<TracePoint:c_call `last'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:46>
     #<TracePoint:c_call `==='@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:46>
     #<TracePoint:c_call `pop'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:46>
     #<TracePoint:c_call `block_given?'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:47>
     #<TracePoint:call `create_shell_runner'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:61>
      #<TracePoint:c_call `join'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:62>
      #<TracePoint:c_call `[]'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:63>
      #<TracePoint:c_call `lambda'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:64>
     #<TracePoint:call `set_verbose_option'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:72>
      #<TracePoint:c_call `key?'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:73>
     #<TracePoint:call `rake_check_options'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:133>
      #<TracePoint:c_call `dup'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:134>
       #<TracePoint:c_call `initialize_dup'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:134>
        #<TracePoint:c_call `initialize_copy'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:134>
      #<TracePoint:c_call `each'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:135>
       #<TracePoint:c_call `delete'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:136>
       #<TracePoint:c_call `delete'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:136>
     #<TracePoint:c_call `join'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:51>
     #<TracePoint:call `rake_output_message'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:126>
      #<TracePoint:c_call `puts'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:127>
       #<TracePoint:c_call `write'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:127>
/home/avdi/.rubies/ruby-2.2.0/bin/ruby -v       #<TracePoint:c_call `write'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils_ext.rb:127>

     #<TracePoint:call `rake_system'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:81>
      #<TracePoint:c_call `system'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:82>
ruby 2.2.0p0 (2014-12-25 revision 49005) [x86_64-linux]
     #<TracePoint:c_call `call'@/home/avdi/.rubies/ruby-2.2.0/lib/ruby/2.2.0/rake/file_utils.rb:57>
 #<TracePoint:c_call `disable'@trace_indent.rb:20>

Let's poke around in here a little bit. We can see that the ruby method is defined inside a file called rake/file_utils_ext.rb. We even have the line number. Latter on, we can see that this method delegates to the sh method, which is Rake's general method for running shell commands.

We now have a detailed guide to exactly where to look if we want to understand how this method works. And none of it is guesswork; it's all hard data from a real run.

There is lots more to know about tracepoints, and lots more we could do. In fact, tracepoints give us the building blocks for lots of interesting code tools. Maybe we'll talk about some of them in other episodes. For now, check out the TracePoint documentation if you want to know more.

And that's all for today. Happy hacking!

Responses