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

前回RubyのBenchmarkを使ってOctopressのgenerateでどれ位時間がかかってるか測ってみる とBenchmarkと言うモジュールを使って計測してみましたが、 これだと個々の箇所で一つ一つ計測を行う必要があって 実際中身を細かく知りたい場合にはちょっと面倒です。

ruby-prof というモジュールを使うと簡単に色々と中身をプロファイル出来そうだったので ruby-profでOctopressの中身を測ってみました。

• ruby-prof

ruby-prof

ruby-prof はRubyのコードプロファイラーです。

Rubyには標準で profile というライブラリが入っていますが これはかなり遅いので ¹、 それに変わってruby-profが好まれて使われている様。

また、色々なタイプのアウトプットが指定できるので好きな様に解析しやすいというのも あるかと思います。

取り敢えずインストールは

$ gem install ruby-prof

等で。

使い方はruby-profのREADMEを読むとわかると思いますが、 前回 でやったのと同じ様にはかってみるためには こんな感じのplugins/jekyll_patch.rbを用意してあげます。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25

require 'benchmark'
require 'ruby-prof'
module Jekyll
  class Site
    def process

      # Profile the code
      result = RubyProf.profile do
        reset
        read
        generate
        render
        cleanup
        write
      end

      # Print profile to text
      out='./rubyprof.out'
      puts "Print rubyprof flat to #{out}"
      File.open(out, 'w') {|f|
        RubyProf::FlatPrinter.new(result).print(f)
      }
    end
  end
end

基本はRubyProf.profileの文で囲って(もしくはRubyProf.start/RubyProf.stopを使って)、 その結果をプリンターで出力する、と言う形。

これで

Measure Mode: wall_time
Thread ID: 70192336331880
Fiber ID: 70192341148120
Total: 34.417862
Sort by: self_time

 %self      total      self      wait     child     calls  name
 58.60     20.169    20.169     0.000     0.000     4992   File#initialize 
 10.98      3.777     3.777     0.000     0.000       23   <Class::IO>#select 
  5.66      1.948     1.948     0.000     0.000     1668   IO#read 
  3.09      1.062     1.062     0.000     0.000        7   TCPSocket#initialize 
  1.07      0.368     0.368     0.000     0.000     1652   <Class::IO>#copy_stream 
  1.00      0.623     0.344     0.000     0.279     5008   RubyPants#educate_quotes 
  0.99      0.341     0.340     0.000     0.001    91677   String#gsub 
  0.87      0.299     0.298     0.000     0.001    72635   String#gsub! 
  0.66      0.227     0.227     0.000     0.000    21337   String#sub! 

こんな感じのアウトプットが得られます。 (上の例では./rubyprof.outというファイルへ出力。)

プリンターには

* RubyProf::FlatPrinter - Creates a flat report in text format
* RubyProf::FlatPrinterWithLineNumbers - same as above but more verbose
* RubyProf::GraphPrinter - Creates a call graph report in text format
* RubyProf::GraphHtmlPrinter - Creates a call graph report in HTML (separate files per thread)
* RubyProf::DotPrinter - Creates a call graph report in GraphViz's DOT format which can be converted to an image
* RubyProf::CallTreePrinter - Creates a call tree report compatible with KCachegrind.
* RubyProf::CallStackPrinter - Creates a HTML visualization of the Ruby stack
* RubyProf::MultiPrinter - Uses the other printers to create several reports in one profiling run
* More!

の様な種類があり、上で使ってるFlatPrinterは一番シンプルなものです。

GraphHtmlPrinterとか使うとHTMLで見れますが、HTMLでソートとかが出来るわけではないので ちょっと見づらかったです。

CallTreePrinterを使って結果を KCachegrind というツールを使って表示するとGUIで色々詳しく調べられそう² ですが、 出力を作るのに大量に情報がありすぎるとうまく居ないのか、 このプリンターを使うとフリーズしてしまいました。 本気で色々見ようと思った時には上手く使えば面白そうではあります。

ということで色々測ってみましたが、 やはりどれが問題というわけではなくて全体的に時間がかかるなーというのが印象。

Octopress(というかJekyll)を使う以上は仕方ない状態なのかな、と。 この遅さに嫌気が差して他に移ってる人が結構発生してるみたいですが、 ちょっと他を見てみたいのもありつつ移行するのも面倒だな、というのもありつつ、な感じ。