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