ruby-prof

Posted on June 21st, 2009 by masayuki | Filed in tips

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の下に置きます。 
1
2

$ 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に計測結果が出力されます。 
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
26
27
28
29
30
31
32
33
34
35

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
なかなか便利なので、暫く仕込んだままにしておこうかと。

Sorry, comments are closed for this article.