Interpretation of Profiler Results

ruby-talk
1

Hi,

I’m a bit confused by a profiler printout. Please could someone enligthen
me? Unfortunately I did not find documentation that ultimately clarified
this. I have a simple test (see attachment) which essentially does three
loops calling three different methods. When run with ruby -r profile I
get these results

Administrator@BOND ~/bin/test
$ ruby -r profile rx-test.rb
% cumulative self self total
time seconds seconds calls ms/call ms/call name
33.74 1.65 1.65 3 550.00 1630.33 Fixnum#times
21.80 2.72 1.07 10000 0.11 0.14 Object#testGlobal
19.59 3.67 0.96 10000 0.10 0.13 Object#testConstant
12.72 4.30 0.62 20000 0.03 0.03 Regexp#=~
12.17 4.89 0.60 10000 0.06 0.06 Object#testDirect
0.00 4.89 0.00 1 0.00 4891.00 #toplevel
0.00 4.89 0.00 1 0.00 0.00 Array#shift
0.00 4.89 0.00 3 0.00 0.00 Module#method_added
0.00 4.89 0.00 1 0.00 0.00 Integer#to_i

Administrator@BOND ~/bin/test
$ ruby --version
ruby 1.6.7 (2002-03-01) [i586-mswin32]

Apparently this holds:

self seconds(m) * 100 / sum(self seconds) = %(m)
self seconds(m) / calls(m) = self ms per call(m)

What bugs me is that “cumulative seconds” of Fixnum#times is the same as
“self seconds”. I’d think that cumulative should differ since the blocks
are called from the body of times. In this case I’d expect something like
4,89099 seconds for cumulative of Fixnum#times.

Regards

robert

rx-test.rb (319 Bytes)

2

I think that ‘self seconds’ and ‘cumulative seconds’ are equal for
the first item in the list because before that (not shown) ‘cumulative seconds’
is equal to zero. Adding 1.07 to 1.65 yields 2.72, the value for
‘cumulative seconds’ on the second line.

···

On Tuesday, 22 April 2003 at 18:12:34 +0900, Robert Klemme wrote:

Hi,

Administrator@BOND ~/bin/test
$ ruby -r profile rx-test.rb
% cumulative self self total
time seconds seconds calls ms/call ms/call name
33.74 1.65 1.65 3 550.00 1630.33 Fixnum#times
21.80 2.72 1.07 10000 0.11 0.14 Object#testGlobal
19.59 3.67 0.96 10000 0.10 0.13 Object#testConstant
12.72 4.30 0.62 20000 0.03 0.03 Regexp#=~
12.17 4.89 0.60 10000 0.06 0.06 Object#testDirect

What bugs me is that “cumulative seconds” of Fixnum#times is the same as
“self seconds”. I’d think that cumulative should differ since the blocks
are called from the body of times. In this case I’d expect something like
4,89099 seconds for cumulative of Fixnum#times.

–
Jim Freeze

There is nothing wrong with Southern California that a rise in the
ocean level wouldn’t cure.
– Ross MacDonald

3

“Jim Freeze” jim@freeze.org schrieb im Newsbeitrag
news:20030422060323.B40269@freeze.org…

Administrator@BOND ~/bin/test
$ ruby -r profile rx-test.rb
% cumulative self self total
time seconds seconds calls ms/call ms/call name
33.74 1.65 1.65 3 550.00 1630.33 Fixnum#times
21.80 2.72 1.07 10000 0.11 0.14
Object#testGlobal
19.59 3.67 0.96 10000 0.10 0.13
Object#testConstant
12.72 4.30 0.62 20000 0.03 0.03 Regexp#=~
12.17 4.89 0.60 10000 0.06 0.06
Object#testDirect

What bugs me is that “cumulative seconds” of Fixnum#times is the same
as
“self seconds”. I’d think that cumulative should differ since the
blocks
are called from the body of times. In this case I’d expect something
like
4,89099 seconds for cumulative of Fixnum#times.

I think that ‘self seconds’ and ‘cumulative seconds’ are equal for
the first item in the list because before that (not shown) ‘cumulative
seconds’
is equal to zero. Adding 1.07 to 1.65 yields 2.72, the value for
‘cumulative seconds’ on the second line.

Ah, I see. So times from the third column are cumulated through the
printout list and not along the call chain - which is what I suspected.
Thanks a lot!

Regards

robert
···

On Tuesday, 22 April 2003 at 18:12:34 +0900, Robert Klemme wrote: