ベンチマークスクリプトの管理

classxではちょっとベンチマークスクリプトを書いてみると、通常のクラスよりも非常に遅いこともあり、定期的にベンチマークを取って、あとからリビジョンも追えるように以下のようにリビジョンを残しつつ、結果をベンチマークスクリプト内にコメントとして残すようにしてました。

require 'benchmark'
$LOAD_PATH.unshift(File.expand_path(File.join(File.dirname(__FILE__), '..', 'lib' )))
require 'classx'

class PointWithClassX
  include ClassX
  has :x, :writable => true
  has :y, :writable => true
  has :z, :writable => true
end

class PointWithoutClassX
  attr_accessor :x, :y, :z

  def initialize hash
    @x = hash[:x]
    @y = hash[:y]
    @z = hash[:z]
  end
end

COUNT = 1000

point_with_classx = PointWithClassX.new({ :x => 0, :y => 0, :z => 0 })
point_without_classx = PointWithoutClassX.new({ :x => 0, :y => 0, :z => 0 })

def do_bench klass, style=:equal
  GC.disable
  COUNT.times do
    if style == :equal
      klass.__send__ :x=, rand(10)
      klass.__send__ :y=, rand(10)
      klass.__send__ :z=, rand(10)
    elsif style == :getter_with_arg
      klass.__send__ :x, rand(10)
      klass.__send__ :y, rand(10)
      klass.__send__ :z, rand(10)
    end
  end
  GC.enable
end


Benchmark.bm do |x|
  x.report 'classx with attr_name = val' do
    do_bench point_with_classx
  end
  x.report 'classx with attr_name(val)' do
    do_bench point_with_classx, :getter_with_arg
  end
  x.report 'normal class' do
    do_bench point_without_classx
  end
end

# On my environment( MacBook1.1 Intel Core Duo 1.83 GHz, 2GB), result is like that. TOOOOO SLOOOW classX!!!!.
#-
# ----------------------------------------------------------
# result after 0171feab
# classx with attr_name = val   0.030000   0.000000   0.030000 (  0.035114)
# classx with attr_name(val)    0.040000   0.000000   0.040000 (  0.053949)
# normal class                  0.010000   0.000000   0.010000 (  0.001969)
# ----------------------------------------------------------
# result after d85fa7ded
# classx with attr_name = val   0.020000   0.010000   0.030000 (  0.031880)
# classx with attr_name(val)    0.040000   0.000000   0.040000 (  0.049979)
# normal class                  0.000000   0.000000   0.000000 (  0.002021)
# ----------------------------------------------------------
# result after 92ed088b ( before 0.0.4 )
#                                 user     system      total        real
# classx with attr_name = val   0.020000   0.010000   0.030000 (  0.029100)
# classx with attr_name(val)    0.040000   0.000000   0.040000 (  0.050599)
# normal class                  0.000000   0.000000   0.000000 (  0.002188)
# ----------------------------------------------------------
# result after 3e97a758
#                                 user     system      total        real
# classx with attr_name = val   0.020000   0.000000   0.020000 (  0.026784)
# classx with attr_name(val)    0.030000   0.010000   0.040000 (  0.051044)
# normal class                  0.010000   0.000000   0.010000 (  0.002661)

ただ先月のあたりから、MacBookが不調になり、MacBookProに乗りかえたので、元々のベンチマーク結果があてにならなくなったので、もとの結果を消して、あらかじめ記録しておいたsha1(正確にはgit rev-parseで解釈できるもの)の順にベンチマークを記録して結果をファイルにするようなRakeタスクを書いてみた。

desc 'run generate benchmark history'
task :benchmark_all do
  require 'pathname'
  require 'yaml'

  base_dir = Pathname(File.expand_path(File.join(File.dirname(__FILE__), 'bench')))

  base_dir.children.each do |script|
    next unless script.to_s =~ /\.rb$/

    # extract DATA section from script
    yaml = ""
    File.open(script) do |f|
      rev_fg = false
      f.each do |line|
        if  /^__END__$/ =~ line
          rev_fg = true
          next
        end

        next unless rev_fg
        yaml << line
      end
    end


    unless yaml == ""
      outfile = "#{script}.result.txt"

      rm outfile if File.exist? outfile

      revisions = YAML.load(yaml)

      tmp_script = "#{base_dir}/.backup.rb"
      begin
        cp script, tmp_script
        system("echo '--------------' >> #{outfile}")
        system("echo 'system infomation' >> #{outfile}")
        system("echo '--------------' >> #{outfile}")
        system("uname -a >> #{outfile}")
        system("echo '--------------' >> #{outfile}")
        system("vm_stat >> #{outfile}")
        system("echo '--------------' >> #{outfile}")
        system("ruby -v >> #{outfile}")
        system("echo '--------------' >> #{outfile}")
        revisions.each do |rev|
          system("git checkout #{rev['sha1']}") or raise "git checkout failed!!"
          system("echo '--------------' >> #{outfile}")
          system("git show HEAD --pretty=oneline --stat | head -n 1 >> #{outfile}")
          system("echo '--------------' >> #{outfile}")
          system("ruby #{tmp_script} >> #{outfile}")
        end
      ensure
        rm tmp_script
        system("git checkout master")
      end
    end
  end
end

def system str
  warn "executed: #{str}"
  super
end

スクリプトはsystem使いまくりでろくに例外処理もしてない手抜きですが、もうちょっと汎用的にできないかと思いつつ、使いながら改良していこうかと思う。

ポイントはgit checkoutする前にベンチマークスクリプトをコピーしてリポジトリの管理対象外に用意しておくこと。あと結果のページに比較の邪魔にならないくらいシンプルかつコミットの概要を表示させる方法は模索した結果"git show HEAD --pretty=oneline --stat | hean -n 1"だった。symbolic-refとかもあわせて表示できるとなお素敵かもしれない。

いつもやるには重いんで、主にrelease前にパフォーマンスを落とすような変更が入ってないかチェックするのに使うのを想定している。

結果はこんな感じ。

--------------
system infomation
--------------
Darwin robin 9.6.0 Darwin Kernel Version 9.6.0: Mon Nov 24 17:37:00 PST 2008; root:xnu-1228.9.59~1/RELEASE_I386 i386
--------------
Mach Virtual Memory Statistics: (page size of 4096 bytes)
Pages free:                   107591.
Pages active:                 154412.
Pages inactive:               128948.
Pages wired down:              66279.
"Translation faults":     1204303202.
Pages copy-on-write:        16606839.
Pages zero filled:         136515961.
Pages reactivated:            335522.
Pageins:                      516980.
Pageouts:                     216625.
Object cache: 2169509 hits of 3871701 lookups (56% hit rate)
--------------
ruby 1.8.7 (2008-08-11 patchlevel 72) [i686-darwin9]
--------------
--------------
53ca6f5904e013ce2add078c363ccae15396228d Released 0.0.7
--------------
classx            0.020000>-  0.000000>-  0.020000>-(  0.012758)
normal class      0.000000>-  0.000000>-  0.000000>-(  0.001166)
--------------
1cd4943cf71c96d09d6aef15afaf79ec86cd0b5b release 0.0.6
--------------
classx            0.020000>-  0.000000>-  0.020000>-(  0.013466)
normal class      0.000000>-  0.000000>-  0.000000>-(  0.001193)
--------------
17a7717af41d9c55ff3b43a21bab445c3f78d2eb release 0.0.5
--------------
classx            0.020000>-  0.000000>-  0.020000>-(  0.016890)
normal class      0.000000>-  0.000000>-  0.000000>-(  0.001190)
--------------
723cffd4439723f9533c8e681a9202ca5836d3c5 released 0.0.4
--------------
classx            0.010000>-  0.000000>-  0.010000>-(  0.013143)
normal class      0.000000>-  0.000000>-  0.000000>-(  0.001428)
--------------
3e97a758c8f421b5089d44abe399ab328174afbb fixed revision.
--------------
classx            0.020000>-  0.000000>-  0.020000>-(  0.020661)
normal class      0.000000>-  0.000000>-  0.000000>-(  0.001759)

ベンチマークスクリプトは

require 'benchmark'
$LOAD_PATH.unshift(File.expand_path(File.join(File.dirname(__FILE__), '..', 'lib' )))
require 'classx'

class PointWithClassX
  include ClassX
  has :x
  has :y
  has :z
end

class PointWithoutClassX
  attr_reader :x, :y, :z

  def initialize hash
    @x = hash[:x]
    @y = hash[:y]
    @z = hash[:z]
  end
end

COUNT = 1000

point_with_classx = PointWithClassX.new({ :x => 0, :y => 0, :z => 0 })
point_without_classx = PointWithoutClassX.new({ :x => 0, :y => 0, :z => 0 })

def do_bench klass
  GC.disable
  COUNT.times do
    klass.__send__ :x
    klass.__send__ :y
    klass.__send__ :z
  end
  GC.enable
end

Benchmark.benchmark '', 16, "%10.6u\t%10.6y\t%10.6t\t%10.6r\n" do |x|
  x.report 'classx', "\t%t" do
    do_bench point_with_classx
  end
  x.report 'normal class', "\t%t" do
    do_bench point_without_classx
  end
end

__END__
--
  sha1: 0.0.7
--
  sha1: 0.0.6
--
  sha1: 0.0.5
--
  sha1: 0.0.4
--
  sha1: 3e97a758
--
  sha1: 83519953e
--
  sha1: 1f4c448b
--
  sha1: 283903a

こんな感じで、__END__以下に書いたところをYAMLでパースして、この順番にベンチマークを測定していくようになっている。

今困っているのが、CPUとメモリサイズでプラットフォーム互換で表示するうまい方法がわからないことだったりします。まぁ割合でみるべきだと思うので、そこまで重視する項目でもないかもですが、参考までに出すようにしたいなぁと思ったり。

rubyも1.8と1.9両方の結果を出せる方が望ましいですね。