本番環境でRubyのパフォーマンス問題をデバッグする方法 ― rbtrace活用ガイド

パフォーマンスが重要な機能であることは、誰もが理解しているはずです。実際、多くのパフォーマンス問題は開発段階で発見し、修正することができます。

しかし、本番環境でしか発生しない遅延にはどう対処すればよいのでしょうか？すべてのコード行にログ出力を仕込む必要があるでしょうか？そんなことをすれば、かえって動作がさらに遅くなるだけです。あるいは「もしかしたら直るかも」という小さなコミットを大量に積み重ねて、当たりを探すしかないのでしょうか？

実は、コードを汚すことなく解析することは可能です。その鍵となるのが rbtrace です。

実行中のRubyアプリをトレースする

rbtraceを使えば、次のようなことがコードを一行も追加せずに行えます。

• パフォーマンス問題の検出
• 稼働中の別のRubyプロセス内でのコード実行
• メソッド呼び出しのログ記録

導入も簡単で、Gemfile に gem "rbtrace" を追加するだけです。

私がrbtraceを知ったのは、Sam Saffron氏によるRubyのメモリリークデバッグに関する優れた記事でした（まだ読んでいない方は、ぜひ一度目を通してみてください）。

この記事の中でSam氏は、rbtraceを使ってプロセスが使用しているすべてのオブジェクトを可視化していました。

bundle exec rbtrace -p $SIDEKIQ_PID -e 'Thread.new{GC.start;require "objspace";io=File.open("/tmp/ruby-heap.dump", "w"); ObjectSpace.dump_all(output: io); io.close}'

これは本当に強力な機能です。しかし、rbtraceでできることはこれだけではありません。

rbtraceで何ができるのか？

本番環境で実行されているSQLを確認する

本番環境で実際に発行されているSQL文と、その実行時間を確認したくなったことはありませんか？次のように実行するだけで把握できます。

~/Source/testapps/rbtrace jweiss$ rbtrace -p $RAILS_PID --methods "ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#execute_and_clear(sql)"
*** attached to process 7897
ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#execute_and_clear(sql="SELECT  "articles".* FROM "articles" WHERE "articles"."id" = $1 LIMIT 1") <0.002631>

2秒以上かかるメソッド呼び出しを検出する

--slow オプションにミリ秒を指定すれば、指定時間を超えるすべてのメソッド呼び出しを捕捉できます。ボトルネックの特定に非常に役立ちます。

~/Source/testapps/rbtrace jweiss$ rbtrace -p $RAILS_PID --slow 2000
*** attached to process 8154
    Integer#times <2.463761>
        ArticlesController#create <2.558673>

特定のメソッドの呼び出しを追跡する

「このメソッドがいつ呼ばれているのか知りたい」という場面もありますよね。--methods オプションで対象メソッドを指定すれば、呼び出されるたびに記録されます。

~/Source/testapps/rbtrace jweiss$ rbtrace -p $RAILS_PID --methods "ActiveRecord::Persistence#save"
*** attached to process 8154
ActiveRecord::Persistence#save <0.010964>

稼働中のスレッド一覧を表示する

アプリが現在どんなスレッドを動かしているのかを確認することもできます。

~/Source/testapps/rbtrace jweiss$ rbtrace -p $RAILS_PID -e "Thread.list"
*** attached to process 8154
>> Thread.list
=> [#<Thread:0x007ff4fcc9a8a8@/usr/local/lib/ruby/gems/2.2.0/gems/puma-2.6.0/lib/puma/server.rb:269 sleep>, #<Thread:0x007ff4fcc9aa10@/usr/local/lib/ruby/gems/2.2.0/gems/puma-2.6.0/lib/puma/thread_pool.rb:148 sleep>, #<Thread:0x007ff4fcc9ab50@/usr/local/lib/ruby/gems/2.2.0/gems/puma-2.6.0/lib/puma/reactor.rb:104 sleep>, #<Thread:0x007ff4f98c0410 sleep>]

サーバープロセス内でRubyコードを実行する

-e オプションを使えば、稼働中のサーバープロセス内で任意のRubyコードを実行できます。

~/Source/testapps/rbtrace jweiss$ rbtrace -p $RAILS_PID -e "ActiveRecord::Base.connection_config"
*** attached to process 8154
>> ActiveRecord::Base.connection_config
=> {:adapter=>"postgresql", :pool=>5, :timeout=>5000, :database=>"rbtrace_test"}

正直なところ、ここまでできると少し怖気づきますね。とはいえ、非常にクールな機能であることは間違いありません。なお、rbtraceを実行できるのは、そのプロセスを操作する権限を持つユーザーだけなので、セキュリティ上の心配は比較的少ないといえます。

まとめ：rbtraceで本番環境の調査が変わる

rbtraceは、ステージング環境や本番環境でRubyプロセスを調査するための強力なツール群を提供します。プロセスがメモリをどのように使っているのか（あるいは乱用していないか）を確認したり、遅いメソッド呼び出しをトレースしたり、さらにはRubyコードを直接実行したりすることも可能です。

問題を切り分けるために大量のテストコミットやログ出力を用意する必要はもうありません。サーバーに接続してデータを取得し、切断するだけ。それだけで十分な情報が手に入ります。

本番環境での利用にはまだ完全には慣れていないというのが正直なところですが、テスト環境やステージング環境でのトラブルシューティングにおいて、rbtraceは間違いなく大きな助けになるはずです。

あなたなら、rbtraceをどんな用途に活用しますか？ぜひ考えてみてください。