CODEWITHSUNDEEP
rubyprofilingprofiler
x-yuri
x-yuri

Reputation: 18943

How to read ruby profiler's output

Let us take an example from the docs:

require 'profile'

def slow_method
  5000.times do
    9999999999999999*999999999
  end
end

def fast_method
  5000.times do
    9999999999999999+999999999
  end
end

slow_method
fast_method

Output:

  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 68.42     0.13      0.13        2    65.00    95.00  Integer#times
 15.79     0.16      0.03     5000     0.01     0.01  Fixnum#*
 15.79     0.19      0.03     5000     0.01     0.01  Fixnum#+
  0.00     0.19      0.00        2     0.00     0.00  IO#set_encoding
  0.00     0.19      0.00        1     0.00   100.00  Object#slow_method
  0.00     0.19      0.00        2     0.00     0.00  Module#method_added
  0.00     0.19      0.00        1     0.00    90.00  Object#fast_method
  0.00     0.19      0.00        1     0.00   190.00  #toplevel

Upvotes: 3

Views: 1286

Answers (2)

sawa
sawa

Reputation: 168199

A method may spend time on its own, or spend time due to time spent by the methods it calls. self ms/call only counts the former, while total ms/call counts the sum of both. It makes sense to represent self seconds, but not total seconds because that would be cumulate all over the place.

Upvotes: 0

x-yuri
x-yuri

Reputation: 18943

tl;dr self seconds + time spent in called methods

Okay, let us dig into the source. There are two procs, gathering information there: PROFILE_CALL_PROC, PROFILE_RETURN_PROC. The former gets called before stepping into a method, the latter before stepping out.

@@maps[Thread.current] accumulates information about methods, namely calls, total seconds (cost), self seconds and name in this particular order. This very information is served later to the user, in a more wordy fashion. After being aggregated.

@@stacks[Thread.current] stores information about methods being run, in a stack. Namely "when the method was started", and "how much time does called (child) methods took" (tick[1]). This is more of a temporary data structure destined to help gathering data into @@maps.

As one can supposedly see now, self seconds is total seconds minus cost (time spent in called methods). That is, total seconds is a time spent both in the method itself and in the methods it calls.

P.S. Pretty much reminds flat profiles in ruby-prof.

Upvotes: 2

Related Questions