ruby-prof

railsアプリのレスポンスがたまに物凄く悪くなることがあり、ruby-profを試してみました。
ruby-profのバージョンは現在0.7.3なのですが、railsアプリをプロファイルする際に、従来のproductionモードで実行した結果をログに出すアプローチから、プロファイリングしたい部分をtestで実行するアプローチに変わっているようです。今回はログに実行結果を出力する0.6.0を使うことにしました。

ruby-profをインストールします。

$ sudo gem install ruby-prof --version=0.6.0

インストールされたgemにrails-pluginというフォルダがあるので、それをプロファイリングしたいrailsアプリのvendor/pluginsの下に置きます。

$ cd /opt/shrimp/current/vendor/plugins/
$ cp -ipr /usr/local/lib/ruby/gems/1.8/gems/ruby-prof-0.6.0/rails_plugin/ruby-prof .

アプリケーションをproductionモードで再起動後、リクエスト毎にlog/production.logに計測結果が出力されます。

Processing TicketsController#index (for 59.156.119.10 at 2009-06-21 02:05:52) [GET]
  Session ID: BAh7CDoLZmlsdGVybzoQUXVlcnlGaWx0ZXIJOgxAZXJyb3JzbzoZQWN0aXZl
UmVjb3JkOjpFcnJvcnMHOwd7ADoKQGJhc2VABjoWQGF0dHJpYnV0ZXNfY2Fj
aGV7ADoYQGNoYW5nZWRfYXR0cmlidXRlc3sAOhBAYXR0cmlidXRlc3sOIg9j
cmVhdGVkX2F0IhgyMDA4LTA5LTI4IDIzOjI0OjUzIhBwcmlvcml0eV9pZCIG
MyIPdXBkYXRlZF9hdEl1OglUaW1lDZFWG4D3ZcgWBjofQG1hcnNoYWxfd2l0
aF91dGNfY29lcmNpb25GIgl3b3JkIgAiDW93bmVyX2lkIgYxIgdpZCIGMSIQ
Y2F0ZWdvcnlfaWRpBiIMdXNlcl9pZCIGMSIOc3RhdHVzX2lkIgctMzoJdXNl
cmkGIgpmbGFzaElDOidBY3Rpb25Db250cm9sbGVyOjpGbGFzaDo6Rmxhc2hI
YXNoewAGOgpAdXNlZHsA--ec1abaf426ea3d2f998bd9de5c10852c8499891a
  Parameters: {"action"=>"index", "controller"=>"tickets"}
Rendering template within layouts/application
Rendering tickets/index
Completed in 0.36246 (2 reqs/sec) | Rendering: 0.05925 (16%) | DB: 0.03879 (10%) |
 200 OK [http://xxxxx.wrap-trap.net/tickets]
 [http://xxxxx.wrap-trap.net/tickets]

Thread ID: 3084116400
Total: 0.140000

 %self     total     self     wait    child    calls  name
  7.14      0.05     0.01     0.00     0.04       26  <Class::ActiveRecord::Base>#find_every
  7.14      0.01     0.01     0.00     0.00        1  ActiveRecord::Transactions::ClassMethods#…
  7.14      0.01     0.01     0.00     0.00      140  ActiveRecord::Associations::AssociationProxy#…
  7.14      0.03     0.01     0.00     0.02      251  Hash#each
  7.14      0.01     0.01     0.00     0.00      140  Ticket(id: integer, name: string, owner_id: integer,…
  7.14      0.01     0.01     0.00     0.00      793  SQLite3::Driver::Native::Driver#column_type
  7.14      0.01     0.01     0.00     0.00      212  ActionController::AbstractRequest#relative_url_root
  7.14      0.01     0.01     0.00     0.00       47  Object#to_param
  7.14      0.01     0.01     0.00     0.00       83  <Module::SQLite3::Driver::Native::API>#sqlite3…
  7.14      0.01     0.01     0.00     0.00     2094  Kernel#is_a?
  7.14      0.01     0.01     0.00     0.00      164  Symbol#to_sym
  7.14      0.01     0.01     0.00     0.00       28  ActiveSupport::CoreExtensions::Array::Extract…
  7.14      0.03     0.01     0.00     0.02       80  Integer#times
  7.14      0.09     0.01     0.00     0.08      681  Kernel#send-2

なかなか便利なので、暫く仕込んだままにしておこうかと。