rbtraceで実行中のRubyプロセスをリアルタイムにトレース・解析する方法

実行中のプロセスで発生するすべてのメソッド呼び出しをリアルタイムに記録できることをご存知でしょうか。さらに驚くことに、稼働中のプロセス内部へコードを注入して実行させることさえ可能です。これらを実現してくれるのが、rbtraceというgemの魔法です。

rbtraceの構成要素

rbtrace gemは、大きく2つの部分から構成されています。

• ライブラリ部分:トレースしたいコードに組み込んで使用します
• コマンドラインユーティリティ:トレースデータの照会や表示に使用します

基本例:シンプルなスクリプトをトレースする

まずは簡単な例から見ていきましょう。トレース対象となるコードは非常にシンプルで、必要なのはrbtrace gemをrequireすることだけです。

require 'rbtrace'
require 'digest'
require 'securerandom'

# 無限ループ
while true

  # 何らかの処理を実行
  Digest::SHA256.digest SecureRandom.random_bytes(2**8)

  # 各イテレーションで1秒間スリープ
  sleep 1
end

それでは、このプログラムをバックグラウンドで起動してみましょう。

$ ruby trace.rb &
[1] 12345

firehoseモードで全メソッド呼び出しを可視化

取得したプロセスID(PID)をrbtraceコマンドラインツールに渡します。-fオプションは「ファイアホース(firehose)」モードを表し、発生したすべてのイベントを画面に出力します。

$ rbtrace -p 12345 -f
*** attached to process 12345
Fixnum#** <0.000010>
SecureRandom.random_bytes
  Integer#to_int <0.000005>
  SecureRandom.gen_random
    OpenSSL::Random.random_bytes <0.002223>
  SecureRandom.gen_random <0.002243>
SecureRandom.random_bytes <0.002290>

Digest::SHA256.digest
  Digest::Class#initialize <0.000004>
  Digest::Instance#digest
    Digest::Base#reset <0.000005>
    Digest::Base#update <0.000210>
    Digest::Base#finish <0.000006>
    Digest::Base#reset <0.000005>
  Digest::Instance#digest <0.000267>
Digest::SHA256.digest <0.000308>

Kernel#rand
  Kernel#respond_to_missing? <0.000008>
Kernel#rand <0.000071>

Kernel#sleep <1.003233>

これはかなり強力です。どのメソッドが呼び出されたのか、さらに各メソッドの実行にどれほどの時間がかかったのかまで、一目瞭然で確認できます。インデントによって呼び出しの階層構造も把握できるため、パフォーマンスのボトルネック調査にも役立ちます。

特定のメソッドに絞り込む(-mオプション)

関心のある特定のメソッドだけに絞り込みたい場合は、-mオプションを使用します。以下の例では、名前に「digest」を含むメソッドのみをトレースしています。

$ rbtrace -p 12345 -m digest
*** attached to process 12345
Digest::SHA256.digest
  Digest::Instance#digest <0.000201>
Digest::SHA256.digest <0.000220>

Digest::SHA256.digest
  Digest::Instance#digest <0.000287>
Digest::SHA256.digest <0.000343>

応用編:稼働中のサーバーからヒープダンプを取得

このgemのもっとも魅力的な活用例のひとつが、稼働中のWebサーバーからヒープダンプを取得する使い方です。ヒープダンプにはメモリ上のすべてのオブジェクトとそのメタデータが含まれており、本番環境におけるメモリリークの調査・デバッグに非常に有用です。

ヒープダンプの取得には、Sam Saffron氏の記事でも紹介されている以下のようなコマンドを使用します。

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

ここで-eオプションを使うと、文字列として渡したRubyコードを対象プロセス内で実行できます。まさに「コード注入」の実例ですね。

ただし注意点があります。ヒープダンプはファイルサイズが非常に大きくなりがちです。Railsプロセスの場合、数百メガバイト規模になることも珍しくありません。ディスク容量とアプリケーションへの負荷を考慮したうえで実行してください。

以下は、出力されるダンプのごく一部を抜粋したものです。

[
  {
    "type": "ROOT",
    "root": "vm",
    "references": [
      "0x7fb7d38bc3f0",
      "0x7fb7d38b79b8",
      "0x7fb7d38dff80"
    ]
  },
  {
    "type": "ROOT",
    "root": "global_list",
    "references": [
      "0x7fb7d38dff58"
    ]
  },
  {
    "address": "0x7fb7d300c5e8",
    "type": "STRING",
    "class": "0x7fb7d38dcee8",
    "frozen": true,
    "embedded": true,
    "fstring": true,
    "bytesize": 10,
    "value": "@exit_code",
    "encoding": "US-ASCII",
    "memsize": 40,
    "flags": {
      "wb_protected": true,
      "old": true,
      "long_lived": true,
      "marked": true
    }
  },
  {
    "address": "0x7fb7d300c908",
    "type": "STRING",
    "class": "0x7fb7d38dcee8",
    "frozen": true,
    "embedded": true,
    "fstring": true,
    "bytesize": 19,
    "value": "SystemExitException",
    "encoding": "US-ASCII",
    "memsize": 40,
    "flags": {
      "wb_protected": true,
      "old": true,
      "long_lived": true,
      "marked": true
    }
  }
]

このように、オブジェクトの種類(type)、アドレス(address)、サイズ(memsize)、GCに関するフラグなど、詳細な情報がJSON形式で出力されます。取得したダンプを専用ツールで解析すれば、メモリを大量に消費している箇所や意図せず保持され続けているオブジェクトを特定できます。

まとめ

rbtraceを使えば、再起動やデバッガ接続なしに、稼働中のRubyプロセスに対して以下のことが可能になります。

• -f(ファイアホースモード):すべてのメソッド呼び出しと所要時間をリアルタイムに記録
• -m:特定メソッドに絞ったトレース
• -e:稼働中プロセス内への任意コードの注入・実行(ヒープダンプ取得など)

本番環境のパフォーマンスチューニングやメモリリーク調査において、強力な武器となるgemです。ぜひ試してみてください。