From: Eero Saynatkari <ruby-ml@...>
Date: 2005-12-21T04:22:35+09:00
Subject: Re: ruby -r profile gives wrong percentage?

-----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).

> > 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-----