Forum: Ruby ruby -r profile gives wrong percentage?

Announcement (2017-05-07): www.ruby-forum.com is now read-only since I unfortunately do not have the time to support and maintain the forum any more. Please see rubyonrails.org/community and ruby-lang.org/en/community for other Rails- und Ruby-related community platforms.
unknown (Guest)
on 2005-12-20 17:30
(Received via mailing list)
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?

Thanks in advance. I am such a newbie :-) JC

C:\code\ruby>ruby -r profile sieve.rb
2, 3, 5, 7, 11, 13, 17, 19, 23, 29, 31, 37, 41, 43, 47, 53, 59, 61, 67,
71, 73,
79, 83, 89, 97
  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
100.00     0.03      0.03        1    31.00    31.00
Profiler__.start_profile
 51.61     0.05      0.02        4     4.00     4.00  Numeric#step
  0.00     0.05      0.00        1     0.00     0.00  Kernel.Integer
  0.00     0.05      0.00        2     0.00     8.00  Range#each
  0.00     0.05      0.00        1     0.00    31.00  #toplevel
  0.00     0.05      0.00        9     0.00     0.00  Array#[]
  0.00     0.05      0.00        2     0.00     0.00  IO#write
  0.00     0.05      0.00       26     0.00     0.00
Kernel.respond_to?
  0.00     0.05      0.00        8     0.00     0.00  Integer#succ
  0.00     0.05      0.00        4     0.00     0.00  Fixnum#*
  0.00     0.05      0.00       10     0.00     0.00  Float#<=>
  0.00     0.05      0.00        1     0.00     0.00  Kernel.puts
  0.00     0.05      0.00       25     0.00     0.00  Fixnum#to_s
  0.00     0.05      0.00       10     0.00     0.00  Float#coerce
  0.00     0.05      0.00        1     0.00     0.00  Array#shift
  0.00     0.05      0.00        1     0.00     0.00  Array#compact
  0.00     0.05      0.00        4     0.00     0.00  Fixnum#==
  0.00     0.05      0.00       10     0.00     0.00  Fixnum#<=>
  0.00     0.05      0.00        1     0.00     0.00  Array#join
  0.00     0.05      0.00        1     0.00     0.00  Math.sqrt
  0.00     0.05      0.00      203     0.00     0.00  Array#[]=
Robert K. (Guest)
on 2005-12-20 18:18
(Received via mailing list)
removed_email_address@domain.invalid wrote:
> 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

> Thanks in advance. I am such a newbie :-) JC

We all were once. :-)

Kind regards

    robert
Eero S. (Guest)
on 2005-12-20 21:23
(Received via mailing list)
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 2005.12.21 01:17, "Robert K." <removed_email_address@domain.invalid> wrote:
> > 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).

> > Thanks in advance. I am such a newbie :-) JC
>
> We all were once. :-)
>
> Kind regards
>
>     robert


E
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.1 (GNU/Linux)

iD8DBQFDqGLPxvA1l6h+MUMRAn94AKCO4pKbgCYw8ufjeHxOIlreachskQCfX9ao
iLH8VP2v5roGX6DkSUWKvFY=
=if5t
-----END PGP SIGNATURE-----
Robert K. (Guest)
on 2005-12-21 12:08
(Received via mailing list)
Eero S. wrote:
>>> overhead of the profiler while the process is not too much cpu
>> rounding errors - your figures are quite smallish.  HTH
> because everything else is executing while you are inside that
> 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
This topic is locked and can not be replied to.