CubicLouve

Spring_MTの技術ブログ

プロファイラーについて

この記事はパーフェクトRuby Advent Calendar 2013 - Adventar の21日目です。 前の日のエントリーは パーフェクトRuby の次に読む本 です。

2013/12/24 Array#<<の結果が出ない件追記しました

パーフェクトRuby

パーフェクトRubyをやっと読み終わりました。。。。

パーフェクトRuby (PERFECT SERIES 6)

パーフェクトRuby (PERFECT SERIES 6)

まだまだ知らないことが多いなあと痛感しました。

ObjectSpace#_id2refでobject_idから実際のobjectを取得できたり、gem prinstineでgemパッケージを元に戻せるのとかは知らなかった。。。。

自分の知らなかった部分を紹介しようと思ったのですが既出のものが多かったので、パーフェクトRubyに載っていなかったプロファイラーについて少し紹介しようと思います。

プロファイラー

プロファイラーとは、各メソッドの実行時間を計測するためのツールです。
プロファイラーの結果を見ると、実行したrubyスクリプトで呼ばれる各メソッドの実行時間がわかります。

今回、プロファイルをとるスクリプトは下記です。

sample scriptarray_push_vs_arrows.rb

また、これをプロファイラーを仕込まず実行した結果は下記のとおりです。

プロファイラーなし

profile

Rubyには標準添付ライブラリにprofileというプロファイルを取得できるモジュールが入ってます。
profileを使ったプロファイル結果はこんな感じです。

profileを使った結果

項目の見方は、http://docs.ruby-lang.org/ja/2.0.0/library/profile.htmlに書いてありますが抜き出してみます。

% time cumulative seconds self seconds calls self ms/call total ms/call name
全体時間のパーセンテージ 全体時間の総和(秒) 正味時間の総和(秒) 呼び出された回数 1回の呼び出し当たりの平均正味時間(ミリ秒) 1回の呼び出し当たりの平均全体時間(ミリ秒) メソッド名
  • 全体時間(総時間) : メソッド呼び出しの合計時間
  • 正味時間 : 全体時間から他の全てのメソッドの実行時間を除いた時間

実行時間を見てもらうとわかると思うのですが、profileってめっちゃくちゃ重い!!

これでは、とてもカジュアルには使えません。
ということで、標準添付ではありませんが、もう少し軽量に動作するruby-profというライブラリを紹介しようと思います。

ruby-prof

ruby-profはprofileモジュールよりも軽量に動作するプロファイラーです。

ruby-profは

gem install ruby-prof

でインストールすることができます。

ruby-profをいれると、ruby-profコマンドを使えるようになります。
このruby-profコマンドを使ってサンプルコードのプロファイルを取ってみます。

ruby-profを使った結果

項目の見方は下記の通りです。

%self total self wait child calls name
全体時間のパーセンテージ メソッド呼び出しとそのメソッドから呼び出されたメソッドの合計時間(秒) メソッド呼び出しの時間(秒) スレッドの待機時間(秒) メソッドから更に呼び出されたメソッドの呼び出し時間(秒) 呼び出された回数 メソッド名

実行時間を見てみると、profileよりは早く動作していますが、それでも実行に時間がかかってしまいますね。

あと、Array#<<の結果が何故かでていない。。。。
とりあえす、ruby-profにissueは投げてみました。
今自分でもコード読んで確認しているところです。。。

まとめ

重いスクリプトがある場合は、プロファイルを取ってボトルネックを探してみると良いと思います。
実際にプロファイルを取るときは、動作が重くなっても問題ないか確認してから仕込んでください!

追記

ruby-profのissueでArray#<<の結果がでないことを聞いてみたら、コンパイルオプションの問題だよって返答頂きまた。

https://github.com/ruby-prof/ruby-prof/issues/132

bin/ruby-profに

RubyVM::InstructionSequence.compile_option = {
  :trace_instruction => true,
  :specialized_instruction => false
}

を書いて、実行したところ、

ruby-prof with option settings

ちゃんと出るようになりました!