アプリケーションを運用していると、実行中のrubyプロセスで何が起こっているのか知りたくなることがあります。
例えば、「なんかbugがあって無限ループに陥ってるっぽいが、どの部分か特定できてない」とか「時間が掛かってるメソッドがあるはずなんだけど、どこか分からない」とか。
rbtrace はそのような状況で使える道具の一つかもしれません。
rbtrace
rbtrace shows you method calls happening inside another ruby process in real time.
rbtrace works on ruby 1.8 through 2.2 (and beyond), running on linux or mac osx.
rbtrace is designed to have minimal overhead, and should be safe to run in production.
Github からそのまま引用ですが、ruby プロセス中のメソッドコールを表示するツールです。
使ってみた
使い方も README の通りなんですが、Rails であれば Gemfile に
gem 'rbtrace'
と書いておけば ok です。
--firehose オプション
firehose は 全てのメソッドコールを出力するオプションで、下記例は unicorn の worker プロセス（リクエストを待っている状態）にアタッチしたものです。
$ bundle exec rbtrace --pid 123456 --firehose
** attached to process 123456
Thread.current <0.000012>
Thread#[] <0.000009>
Kernel#sleep <10.000179>
Thread.current <0.000011>
Thread#[] <0.000010>
Kernel#sleep <1.467024>
Time.now
Time#initialize
Fixnum#+ <0.000009>
Time#initialize <0.000043>
Time.now <0.000071>
Time#to_i
Fixnum#divmod <0.000012>
Time#to_i <0.000085>
Unicorn::Worker#tick=
Raindrops#[]= <0.000011>
Unicorn::Worker#tick= <0.000139>
--methods オプション
実際に worker プロセスがリクエストを受けると、すごい勢いで出力されるので適宜絞ってあげる必要があります。
例えば、SQL の実行だけに絞りたい時は --methods オプションを使うとよいです。
$ bundle exec rbtrace --pid 123456 -m 'ActiveRecord::ConnectionAdapters::Mysql2Adapter#execute(sql)'
*** attached to process 123456
ActiveRecord::ConnectionAdapters::Mysql2Adapter#execute(sql="SELECT `users`.* FROM `users` WHERE `users`.`id` = 123 LIMIT 1") <0.001091>
ActiveRecord::ConnectionAdapters::Mysql2Adapter#execute(sql="SHOW FULL FIELDS FROM `users`") <0.012188>
ActiveRecord::ConnectionAdapters::Mysql2Adapter#execute(sql="SHOW TABLES ") <0.000827>
ActiveRecord::ConnectionAdapters::Mysql2Adapter#execute(sql="SELECT `resources`.* FROM `resources` WHERE `resources`.`id` = 456 <0.001423>
※ mysql2 アダプタの例なので、利用しているアダプタに応じて適宜読み替えてください。
slow オプション
指定の時間（ミリセカンド単位）を要したメソッドコールに絞り込むことが可能です。以下は 100ms の例。
$ bundle exec rbtrace --pid 123456 --slow=100
ActiveRecord::ConnectionAdapters::Mysql2Adapter#execute(sql="SELECT `users`.* FROM `users` WHERE `users`.`id` = 123 LIMIT 1") <0.001091>
ActiveRecord::ConnectionAdapters::Mysql2Adapter#execute(sql="SHOW FULL FIELDS FROM `users`") <0.012188>
ただし、トレースに表示される時間（例：<0.012188> ）は秒単位であることに注意。
--eval オプション
eval もできます。
$ bundle exec rbtrace --pid 123456 -e 'p Rails.env'
*** attached to process 123456
>> p Rails.env
=> "sandbox"
Production で使って ok ？
rbtrace is designed to have minimal overhead, and should be safe to run in production.
README に書かれている通り、production での利用が想定されてます。
Author の Aman Gupta 氏 は GitHub, Inc 勤務で、Rubyコミッタ でもあるので、safe to run in production は額面通りに受け取って大丈夫でしょう。
Aman Gupta, GitHubでのRubyの使われ方と高速化のテクニックを紹介 ～ RubyKaigi 2014 基調講演 3日目
As a newcomer to a large codebase, I often found myself wondering what was happening inside various ruby processes running in production.
Out of this curiosity was born rbtrace, one of first tools I wrote at github that we continue to use to this day. If you haven’t used retrace I highly highly recommend checking it out. It has a number of features that allow live introspection of running ruby processes.
引用元： Ruby 2.1 in Production, Ruby Kaigi 2014 発表資料
まとめ
素晴らしいツールなのに、意外と日本語記事がないので書いてみました。