perftools.rb - revamping

前回、ruby-profを使ってみたのですが、今回はperftools.rbというプロファイラを使ってみました。

もともと、google-perftoolsというプロファイリングツールがあり、それをRubyで使用できるようにしたのがperftools.rb。現在はCpuProfilerのみですが、TODOにはHeapProfilerと記述されています。
まずはインストール。

gem install -s http://gems.github.com tmm1-perftools.rb

サンプルコードで試してみます。

require 'rubygems'
require 'perftools'
PerfTools::CpuProfiler.start("/tmp/add_numbers_profile") do
  5_000_000.times{ 1+2+3+4+5 }
end

/tmpの下に、add_numbers_profile、add_numbers_profile.symbolの2ファイルが生成されます。これが結果ファイルになるので、pprof.rbというレポートツールを使用して内容を確認します。

Total: 134 samples
     116  86.6%  86.6%      134 100.0% Integer#times
      18  13.4% 100.0%       18  13.4% Fixnum#+
       0   0.0% 100.0%      134 100.0% PerfTools::CpuProfiler.start

これをrailsのアプリケーションに適用してみます。今回は、railsの初期化後からプロファイルを開始してみました。まず、RAILS_ROOT/config/environments/(実行するモード).rbに、以下を追記します。

config.after_initialize do
  require 'perftools'
  PerfTools::CpuProfiler.start("/tmp/shrimp_profile")
end

あとはscript/server -e (実行モード)でサーバを起動し、アプリケーションを適当に操作した後、サーバを停止します。今回試してみた結果、以下のように出力されました。

$ pprof.rb --text /tmp/shrimp_profile
Total: 73 samples
      22  30.1%  30.1%       26  35.6% Thread.start
      15  20.5%  50.7%       15  20.5% IO.select
       4   5.5%  56.2%        4   5.5% Module#constants
       3   4.1%  60.3%        3   4.1% garbage_collector
       2   2.7%  63.0%        2   2.7% SQLite3::Driver::Native::API.sqlite3_prepare
       2   2.7%  65.8%        2   2.7% SQLite3::Driver::Native::API.sqlite3_step
       1   1.4%  67.1%        1   1.4% String#sub
       1   1.4%  68.5%        1   1.4% WEBrick::Cookie.parse
       1   1.4%  69.9%        2   2.7% Array#map
       1   1.4%  71.2%        1   1.4% ActiveRecord::Associations::AssociationProxy#initialize
       1   1.4%  72.6%        1   1.4% Regexp#===
       1   1.4%  74.0%        1   1.4% Proc.new
       1   1.4%  75.3%        1   1.4% ActionController::Routing::RouteSet::NamedRouteCollection#define_url_helper
       1   1.4%  76.7%        1   1.4% IO#write
       1   1.4%  78.1%        1   1.4% Array#-
       1   1.4%  79.5%        1   1.4% ActiveSupport::Callbacks::CallbackChain#find
       1   1.4%  80.8%        1   1.4% Object#ticket_path
       1   1.4%  82.2%        1   1.4% Object#detect
       1   1.4%  83.6%        1   1.4% Object#options_for_select
       1   1.4%  84.9%        1   1.4% ActiveRecord::Associations::AssociationProxy#load_target
       1   1.4%  86.3%       49  67.1% Kernel#gem_original_require
       1   1.4%  87.7%        1   1.4% Object#instance_variable_set
       1   1.4%  89.0%        1   1.4% Time#initialize
       1   1.4%  90.4%        1   1.4% ActionController::Routing::RouteBuilder#separator_pattern
       1   1.4%  91.8%        1   1.4% Hash#[]
       1   1.4%  93.2%        6   8.2% Module#local_constants
       1   1.4%  94.5%        1   1.4% Hash#key?
       1   1.4%  95.9%        1   1.4% Object#kind_of?
       1   1.4%  97.3%        3   4.1% TicketsController#search_tickets
       1   1.4%  98.6%        1   1.4% ActionController::AbstractRequest#ssl?
       1   1.4% 100.0%        1   1.4% ActiveRecord::Base#column_for_attribute

pprof.rbでは、結果からコールグラフをgif画像等で出力されることができます。今回、gif画像を生成するにたりGraphvizが必要ということで、別途インストールしました。

pprof.rb --gif /tmp/shrimp_profile > /tmp/shrimp_profile.gif

上記コマンドを実行後、以下のgifが生成されました。

今回は初期化後から終了までの間をプロファイルしましたが、最初のサンプルコードのようにコードの一部をプロファイリングすることも可能なはずです。これは別の機会に試してみたいと思います。