The Ruby Interpreter includes a profiling tool which is invoked with the -rprofile option on the command line. Below is an example running the Ruby Fibonacci program (fib.rb) included in Ruby documentation samples. The list of functions is sorted from most to least time spent exclusively in the function (self seconds). The first column provides the percentage of self seconds for each function. The cumulative seconds indicates the amount of time spent in that function and the functions it calls directly and indirectly. The calls, self ms/call, and total ms/call provide some indication whether the function is called frequently and the average cost of each call to a function.
The output below shows that most of the runtime is spent in the Object#fib function which is called many times due to the code implementing the computation of Fibanoccia numbers via recursion. The Fixnum#- and Fixnum#< are called as many times time as Object#fib is called because the argument needs to be adjusted (Fixnum#-) and tested (Fixnum#<) for each call of Object#fib. The Fixnum#+ is a binary addition and is only called once for pair of calls to Object#fib.
$ ruby -rprofile fib.rb 6765 % cumulative self self total time seconds seconds calls ms/call ms/call name 78.30 1.66 1.66 21891 0.08 1.30 Object#fib 9.91 1.87 0.21 21890 0.01 0.01 Fixnum#- 8.02 2.04 0.17 21891 0.01 0.01 Fixnum#< 3.77 2.12 0.08 10945 0.01 0.01 Fixnum#+ 0.00 2.12 0.00 1 0.00 0.00 Kernel.print 0.00 2.12 0.00 2 0.00 0.00 IO#write 0.00 2.12 0.00 1 0.00 0.00 Module#method_added 0.00 2.12 0.00 1 0.00 0.00 Fixnum#to_s 0.00 2.12 0.00 1 0.00 2120.00 #toplevel
