[ruby-list:35822] profile.rb の使い方

こんにちは、高石です。

自作スクリプトのどこで時間がかかっているのか調べようと
profile.rbを使ってみたのですが、不可解な結果になりました。

もともと処理の前後で Time.now を使って所要時間を計っていたの
ですが、プロファイルをとらない時には、処理Aより処理Bの方が速
かったのが、プロファイルをとると、処理Bの方が遅くなってしま
うのです。

プロファイラの使い方が間違っているのでしょうか。

% cat hoge.rb
#!/usr/local/bin/ruby

def foo(str)
  str.gsub!(/./) {|a| a.upcase}
end

def bar(str)
  str.gsub!(/a/,'A')
  str.gsub!(/b/,'B')
  ... 中略 ...
  str.gsub!(/y/,'Y')
  str.gsub!(/z/,'Z')
end

# 処理A
str = 'abcdefghijklmn'
start = Time.now
for i in 1..1000
  foo(str)
end
puts Time.now - start

# 処理B
str = 'abcdefghijklmn'
start = Time.now
for i in 1..1000
  bar(str)
end
puts Time.now - start
-----

%ruby -v hoge.rb
ruby 1.6.7 (2002-03-01) [i686-cygwin]
0.130908
0.029169

%ruby -vr profile hoge.rb
ruby 1.6.7 (2002-03-01) [i686-cygwin]
2.660891
3.935797
  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 41.31     2.63      2.63     1000     2.63     3.66  Object#bar
 39.58     5.14      2.52    27000     0.09     0.12  String#gsub!
 11.98     5.91      0.76    14000     0.05     0.05  String#upcase
  4.67     6.20      0.30        2   148.50  3180.00  Range#each
  2.47     6.36      0.16     1000     0.16     2.41  Object#foo
  0.00     6.36      0.00        4     0.00     0.00  IO#write
  0.00     6.36      0.00        2     0.00     0.00  Time#-
  0.00     6.36      0.00        1     0.00  6360.00  #toplevel
  0.00     6.36      0.00        2     0.00     0.00  Kernel.puts
  0.00     6.36      0.00        2     0.00     0.00  Module#method_added
  0.00     6.36      0.00        4     0.00     0.00  Time#now
  0.00     6.36      0.00        2     0.00     0.00  Float#to_s

/--------------------------------------------------------/
  高石 勇人 < [e-mail] >
  PGP Key(RSA): http://rio-t.presen.to/pgp/mykey.asc
         (DSS): http://rio-t.presen.to/pgp/mykey-dss.asc
/--------------------------------------------------------/