profile icon indicating copy to clipboard operation
profile copied to clipboard

Fix calls count probrem - I want to use profile.rb

Open 284km opened this issue 6 years ago • 0 comments

I want to use profile.rb. Because it is convenient to be able to profile only by specifying -rprofile.

When executed with such sample code

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 this result.

$ ruby -rprofile example.rb

 %   cumulative   self              self     total
time   seconds   seconds    calls  ms/call  ms/call  name
38.72     0.00      0.00        1     1.86     1.86  TracePoint#__enable
12.47     0.00      0.00        2     0.30     0.30  Integer#times
 0.73     0.00      0.00        1     0.04     0.42  Object#slow_method
 0.63     0.00      0.00        1     0.03     1.89  TracePoint#enable
 0.50     0.00      0.00        1     0.02     0.24  Object#fast_method
 0.13     0.00      0.00        2     0.00     0.00  Module#method_added
 0.08     0.00      0.00        1     0.00     0.00  TracePoint#disable
 0.00     0.00      0.00        1     0.00     4.79  #toplevel

I removed :b_call and :b_return event hook. :b_call and :b_return are small or ambiguous in profiling with ruby/profile, and I think it is sometimes difficult to read the profile results. We should use tools such as perf if we want profile results that require very high accuracy. ruby/profile is an accuracy that traces method calls and returns, and I think it is a convenient library in most cases if it can be used simply by -rprofile So I removed :b_call and :b_return event. And I want to use this ruby/profile.

By this change, we can prevent the user from being confused by seeing the output of the number of calls as reported here.

https://bugs.ruby-lang.org/issues/15652

The reason why the number of calls is output as 5001 in reported sample is: First, in the case of arithmetic operations, opt_* instruction is executed, so :c_call event does not occur.

In the following example, 9999999999999999*999999999 or 9999999999999999+999999999 will be detected in :b_return event. And since method_id at that time is Object#slow_method or Object#fast_method, it results in calls 5001.

284km avatar Apr 06 '19 04:04 284km