From: Robert Klemme <bob.news@...>
Date: 2005-12-21T19:07:49+09:00
Subject: Re: ruby -r profile gives wrong percentage?

Eero Saynatkari wrote:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA1
>
> On 2005.12.21 01:17, "Robert Klemme" <bob.news@gmx.net> wrote:
>> javachallenge@gmail.com wrote:
>>> I am using Windows, and I was testing the profiler with the simple
>>> sieve.rb program.
>>>
>>> I may not have a good understanding of Ruby's profiler but It seems
>>> that it gives me wrong percentages... I guess it is due to the
>>> overhead of the profiler while the process is not too much cpu
>>> bound. However if it shows wrong percentages, to me it's still a
>>> bug.
>>>
>>> So according to the output below, 100% of the time is gone with
>>> Profiler__.start_profile, while 51.61% is gone with Numeric#step.
>>> All this totaling 151.61%!
>>> Am I missing something?
>>
>> Yes.  Some figures are cumulative.  This confused me in the
>> beginning, too.  I guess the rest of the confusion is caused by
>> rounding errors - your figures are quite smallish.  HTH
>
> Specifically it is taking nesting of method calls into account.
> It is basically telling you this:
>
>   # Quite pseudo here
>   def Profiler__.start_profile()
>     loop { foo(bar); Numeric.step(); bar(baz) + quux; }
>   end
>
> So, you are spending all of your time inside start_profile()
> because everything else is executing while you are inside that
> method. If you just did this:
>
>   def foo()
>     5000.times { puts 'foo!' }
>   end
>
>   foo
>
> You would see Kernel.puts consuming x amount, Integer#times
> consuming the total amount of all Kernel.puts calls plus its
> own overhead and foo consuming the amount of all Integer#times
> plus its own overhead. foo should come up to 100% (more or less).

Sample:

ruby -r profile -e 'def foo() 5000.times { puts "x" } end; foo'
x
....
  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 54.21     1.48      1.48     5000     0.30     0.48  Kernel.puts
 27.94     2.25      0.76    10000     0.08     0.08  IO#write
 12.69     2.59      0.35        1   347.00  2734.00  Integer#times
  5.16     2.73      0.14     5000     0.03     0.03  Kernel.respond_to?
  0.00     2.73      0.00        1     0.00     0.00  Module#method_added
  0.00     2.73      0.00        1     0.00  2734.00  Object#foo
  0.00     2.73      0.00        1     0.00  2734.00  #toplevel

First column is percentage of "self seconds".  "cumulative seconds" is the
sum of all "self seconds" up to that line.  "self seconds" is the time
spent in a method while "total" includes methods invoked from there.

Kind regards

    robert