From: Robert Klemme <bob.news@...>
Date: 2003-04-22T18:12:34+09:00
Subject: Interpretation of Profiler Results

This is a multi-part message in MIME format.

------=_NextPart_000_0019_01C308BA.D596B970
Content-Type: text/plain;
	charset="iso-8859-1"
Content-Transfer-Encoding: 7bit


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

------=_NextPart_000_0019_01C308BA.D596B970
Content-Type: application/octet-stream;
	name="rx-test.rb"
Content-Transfer-Encoding: 7bit
Content-Disposition: attachment;
	filename="rx-test.rb"


RX = /^.*%/
$GRX = /^.*%/

def testDirect(str)
  /^.*%/ =~ str
end

def testConstant(str)
  RX =~ str
end

def testGlobal(str)
  $GRX =~ str
end

count = ( ARGV.shift || 10000 ).to_i

# test run

count.times do
  testDirect "foo%"
end

count.times do
  testConstant "foo%"
end

count.times do
  testGlobal "foo%"
end


------=_NextPart_000_0019_01C308BA.D596B970--