rbtrace で ruby のメソッドコールをトレースする

アプリケーションを運用していると、実行中のrubyプロセスで何が起こっているのか知りたくなることがあります。

例えば、「なんかbugがあって無限ループに陥ってるっぽいが、どの部分か特定できてない」とか「時間が掛かってるメソッドがあるはずなんだけど、どこか分からない」とか。

rbtrace はそのような状況で使える道具の一つかもしれません。

## rbtrace

https://github.com/tmm1/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 プロセス（リクエストを待っている状態）にアタッチしたものです。

```bash
$ 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 オプションを使うとよいです。

```bash
$ 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 の例。

```bash
$ 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日目](http://gihyo.jp/news/report/01/rubykaigi2014/0003)

> 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](http://bit.ly/ruby21-in-production), Ruby Kaigi 2014 発表資料


## まとめ

素晴らしいツールなのに、意外と日本語記事がないので書いてみました。