ruby -r profile gives wrong percentage?

[javachallenge]

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

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 JC

We all were once.

Kind regards

robert

 

[Robert Klemme]

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



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