Ruby -r profile gives wrong percentage?

ruby-talk
1

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 :slight_smile: 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#[]=

2

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

Thanks in advance. I am such a newbie :slight_smile: JC

We all were once. :slight_smile:

Kind regards

    robert

3

> 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 :slight_smile: JC

We all were once. :slight_smile:

Kind regards

    robert

E

···

On 2005.12.21 01:17, "Robert Klemme" <bob.news@gmx.net> wrote:

javachallenge@gmail.com wrote:

4

Eero Saynatkari wrote:

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

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

···

On 2005.12.21 01:17, "Robert Klemme" <bob.news@gmx.net> wrote:

javachallenge@gmail.com wrote: