RubyのBenchmarkを使ってOctopressのgenerateでどれ位時間がかかってるか測ってみる

Octopressで記事数が増えてきてgenerateするのが結構辛くなってきたので 取り敢えずどれ位時間がかかってるのか測ってみました。

その際にRubyのBenchmarkというモジュールが便利だったのでそれについて。

• Benchmark
  • measure
  • bm
• Octopressの基本的なgenerateの時間を測ってみる
• まとめ

Benchmark

RubyでBenchmarkというモジュールを使うと簡単に 関数等の実行時間を計測して表示することが出来ます。

Benchmark

measure

基本的な使い方は

1
2

require 'benchmark'
ret = Benchmark.measure{cmd}

みたいな形でcmdとういうコマンドでどれだけ時間がかかったか取得できます。 複数行コマンドの場合は;で繋げて入れる事が出来ます。

出力にはtimeコマンドの様にuser、system、total、realの項目があります。

1

puts Benchmark.measure{n=1;for i in 1..10000000; n+=1;end}

とか直接出力すれば

0.620000   0.010000   0.630000 (  0.640026)

みたいな表示が得られます。

Benchmark::CAPTIONという値が

user     system      total        real

となってるので

1
2

puts   Benchmark::CAPTION
puts   Benchmark.measure{n=1;for i in 1..10000000; n+=1;end;}

とかすると

      user     system      total        real
  0.620000   0.010000   0.630000 (  0.640026)

みたいに表示できます。

bm

複数のコマンドを順次計測して表示したい場合には Benchmark.bmが使えます。

使い方はこんな感じ:

1
2
3
4
5

Benchmark.bm(10) do |x|
  x.report("command 1"){cmd1}
  x.report("command 2"){cmd2}
  x.report("command 3"){cmd3}
end

bmの引数の数字はレポート時に表示されるコマンドの名前の長さを整えるのに使われる数字です。 (この数だけ繰り返される、とか、実行するコマンドの数、とかではありません。)

ブロックの中ではreportという関数を使って、()中にコマンド名(レポート表示用)、 {}の中に実際に行うコマンドを入れます。

結果は直接こんな感じでまとめて表示されます。

                 user     system      total        real
command 1    0.000000   0.000000   0.000000 (  0.000005)
command 2    0.000000   0.000000   0.000000 (  0.000005)
command 3    0.000000   0.000000   0.000000 (  0.000005)

ただし、cmd2とかが標準出力を出す様なものだとこの表の途中に紛れ込んだりするので、 適時出力先を変えるか、 もしくは上のmeasureで一つ一つ結果を保存しておいてあとで表示、みたいな 事をした方が良い時もあります。

Octopressの基本的なgenerateの時間を測ってみる

Octopressのgenerateタスクではjekyll buildを呼んでるわけですが、 実際jekyllコマンドの中で行われてる作業を幾つかに区切って時間を測ってみました。

まず、jekyllのモジュールの中身を見て見るために

$ gem which jekyll
/Library/Ruby/Gems/2.0.0/gems/jekyll-2.5.3/lib/jekyll.rb

でインストール場所を確認。 この付近で/Library/Ruby/Gems/2.0.0/gems/jekyll-2.5.3/lib/jekyll/commands/build.rb を見つけたので中をみてみると

1
2
3
4
5
6
7
8
9
10

# Returns nothing.
def build(site, options)
  source      = options['source']
  destination = options['destination']
  Jekyll.logger.info "Source:", source
  Jekyll.logger.info "Destination:", destination
  Jekyll.logger.info "Generating..."
  process_site(site)
  Jekyll.logger.info "", "done."
end

という箇所があって、このprocess_siteという関数は /Library/Ruby/Gems/2.0.0/gems/jekyll-2.5.3/lib/jekyll/command.rbの中で

1
2
3
4
5

def process_site(site)
  site.process
rescue Jekyll::Errors::FatalException => e
...
end

と言った形で定義されてます。 最後に /Library/Ruby/Gems/2.0.0/gems/jekyll-2.5.3/lib/jekyll/site.rb を見ると

1
2
3
4
5
6
7
8
9
10
11

# Public: Read, process, and write this Site to output.
#
# Returns nothing.
def process
  reset
  read
  generate
  render
  cleanup
  write
end

という箇所があるので、取り敢えずここで実行されてる関数ごとに時間を測ってみたいと思います。

こういう時に、Rubyではこういった定義されてる関数を直接いじらずに外から オーバーライドすることが出来るので便利です。

plugins/jekyll_patch.rbというファイルを作って、

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15

require 'benchmark'
module Jekyll
  class Site
    def process
      Benchmark.bm(10) do |x|
        x.report("reset"){reset}
        x.report("read"){read}
        x.report("generate"){generate}
        x.report("render"){render}
        x.report("cleanup"){cleanup}
        x.report("write"){write}
      end
    end
  end
end

こんな感じでprocessを書き換えてあげます。

これでrake generateすると

                 user     system      total        real
reset        0.010000   0.000000   0.010000 (  0.018111)
read         0.430000   0.110000   0.540000 (  0.596607)
generate    61.080000   2.180000  63.260000 ( 70.209942)
render     235.300000   8.080000 243.380000 (251.566731)
cleanup      0.390000   0.040000   0.430000 (  0.460767)
write        0.620000   1.250000   1.870000 (  2.747295)

こんな感じの表示が得られます。 renderの部分が実際に書くページのhtmlを作成してる所です。 ここでだいたい4分位かかってgenerateと合わせて5分もかかっています。。。

さらにgenerateを追っていってどのGeneratorモジュールが時間使ってるのかを見ると GenerateTagsが40秒位で一番時間を使っていました。 (GenerateCategoriesが10秒くらい。)

renderの方は各ページ1秒未満程度で、さらに細かく何が時間かかってるか、 をBenchmarkで追うのは無理なので取り敢えずこんな所で。

まとめ

測ってみたところでここまでだと余りどうしようもないですが、 取り敢えずRubyでのBenchmarkの使い方と、 適当なモジュールの中を探ってBenchmarkを埋め込む方法のまとめ、というメモ。