coﾘ・ー・ﾝ＜2nd life

■Ruby で debug する7つの方法

Perl での print debug の方法の紹介がブーム(?)だったので、自分がよく行ってる Ruby での debug 方法7つについて書いてみます。

p

ご存じの人も多い Kernel#p メソッド。これを使うとオブジェクトの内容を見やすい形で出力してくれます。

>> p ({:foobar => :baz})
{:foobar=>:baz}

Object#inspect を使うと、p で出力するときと同じ文字列を String として取得できます。

>> puts ({:foobar => :baz}).inspect
{:foobar=>:baz}

初心者の頃この p での出力を使う方法がわからなくて困った記憶が…。

pp

pp というライブラリを使うと、p より、より見やすい形式で出力してくれます。たとえば

>> a = Array.new(10) { {:foobar => :baz} }
>> p a
[{:foobar=>:baz}, {:foobar=>:baz}, {:foobar=>:baz}, {:foobar=>:baz}, {:foobar=>:baz}, {:foobar=>:baz}, {:foobar=>:baz}, {:foobar=>:baz}, {:foobar=>:baz}, {:foobar=>:baz}]

な感じで、Array や Hash の内容が大きくなってくると、きれいに折り返しされず見づらくなってしまいますが、pp を使うとこれが解消できます。

>> require 'pp'
>> pp a
[{:foobar=>:baz},
 {:foobar=>:baz},
 {:foobar=>:baz},
 {:foobar=>:baz},
 {:foobar=>:baz},
 {:foobar=>:baz},
 {:foobar=>:baz},
 {:foobar=>:baz},
 {:foobar=>:baz},
 {:foobar=>:baz}]

また pp の出力を String として取得したい場合は PP.pp の第一引数に object を、第二引数に空文字列を渡すことで取得できます。

>> str = PP.pp(a,'')
>> puts str
[{:foobar=>:baz},
 {:foobar=>:baz},
 {:foobar=>:baz},
 {:foobar=>:baz},
 {:foobar=>:baz},
 {:foobar=>:baz},
 {:foobar=>:baz},
 {:foobar=>:baz},
 {:foobar=>:baz},
 {:foobar=>:baz}]

わりと BK な取得方法ですが、ソースを見た感じではこれ以外の方法が無い気がします。

追記

ruby >= 1.8.5 な添付ライブラリの pp.rb では Kernel#pretty_inspect が追加されており、

str = obj.pretty_inspect

で文字列として取得できます。コメントにて教えてもらいました。

y

require 'yaml' すると、Kernel#y メソッドが追加され、y obj で YAML 形式で Object の中身を見ることができます。

>> y ({:foobar => :baz})
---
:foobar: :baz

pp でいいじゃん、という気がするので個人的にはほとんど使ってませんが、ときたま html 上にオブジェクトの中身を表示させたい時に使うときがあります。なぜなら p/pp では Object#inspect まんまの表示なので、

>> p Object.new
#<Object:0x409095bc>

とタグで囲まれて出力されるため、HTMLエスケープが必要なのですが、YAMLの場合は

>> y Object.new
--- !ruby/object {}

と必要ないためです。

backtrace を追う

いままでプログラムがどうやって実行されてきたのかを追うには backtrace を見るのが一番です。以前は Exception を発生させてその backtrace を見る、というなんとも微妙なことをしていたんですが、ちょうど一年ほど前 id:ha-tan:20051014:1129218253 で教えてもらい、caller を見ればよいことがわかりました。

なので

class Foo
  def foo
    bar
  end
  def bar
    baz
  end
  def baz
    p caller
  end
end

Foo.new.foo

な呼び出しは

["call.rb:6:in `bar'", "call.rb:3:in `foo'", "call.rb:13"]

と、最初に13行目でメソッドが呼びだされ、次に foo メソッド内部3行目でメソッドが呼び出され、その後 bar メソッド内部の6行目で呼び出され…、と容易に追っかけることができます。

set_trace_func

set_trace_func という組み込み関数で、メソッド呼び出しや式の評価など、様々なイベントにフックして手続きオブジェクトを実行可能です。

割と何でもできる強力なリフレクションとして使えますが、重くなるのでデバッグ専用な感じです。

たとえば bar という名前のメソッドが呼び出された時にアクションを起こしたいときはこんな感じに。

class Foo
  def foo
    bar
  end
  def bar
  end
end

class Bar < Foo
  def bar
  end
end

set_trace_func lambda { |event, file, line ,id, binding, klass|
  if event == 'call' && id == :bar
    puts "call method bar file:#{file} line:#{line}"
  end
}

Foo.new.foo
Bar.new.foo

結果は

call method bar file:call.rb line:5
call method bar file:call.rb line:10

logger を使う

Class を作るときは logger インターフェイスを作っておくと何かと便利です。最近の個人的なスタンダードなテンプレは

require 'logger'
class Foo
  def initialize(logger = nil)
    @logger = logger || Logger.new(STDERR)
  end
  attr_reader :logger
  def foo
    logger.debug 'call:foo'
  end
end

Foo.new.foo 
#=> D, [2006-10-10T12:33:16.581481 #10500] DEBUG -- : call:foo

な感じで initialize でインスタンス変数に logger を入れておき、attr_reader で読み取り用のアクセサに @logger を設定することで、そのクラス内側からはどこからでも logger で参照できるようにしてます。Rails 脳。

またこのクラスを Rails から呼び出して使う時は

Foo.new RAILS_DEFAULT_LOGGER

で Rails 標準の logger インスタンスを利用してログがはけて便利です。

profiler を使う

速度が問題になってきたら profile.rb を使います。ライブラリ単体などなら、-rprofile を付けて実行するだけで OK です。

$ ruby -rprofile call.rb
  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 66.67     0.02      0.02       84     0.24     0.24  Module#method_added
 33.33     0.03      0.01        2     5.00    20.00  Kernel.require
  0.00     0.03      0.00        1     0.00     0.00  Array#[]
  0.00     0.03      0.00        4     0.00     0.00  Thread#critical=
  0.00     0.03      0.00        2     0.00     0.00  Fixnum#*
  0.00     0.03      0.00        1     0.00     0.00  MonitorMixin.mon_exit
以下略

こんな感じで出力されます。しかし profile.rb は遅いので困るときがありますが、そんなときには ruby-prof を使いましょう。利用方法は profile.rb とほとんど同じで

$ ruby -runprof call.rb

とするだけです。

ただこの Ruby インタプリタ起動時に require の方法で問題になるのは、実行結果すべてでプロファイリングしてしまうため、フレームワーク中の一部分だけをプロファイリングしたいときなどに困ります。そんな場合は、RubyProf.profile メソッドにブロックを渡せば OK です。で、結果を Printer で出力します。

require 'rubygems'
require 'ruby-prof'
require 'stringio'

# この部分だけプロファイリング
result = RubyProf.profile do
  100.times { Regexp.new 'foo' }
end

printer = RubyProf::FlatPrinter.new(result)
strio = StringIO.new
printer.print(strio)
puts strio.string # 結果を文字列として取得

整形した文字列で取得したいときが面倒なので、こんなライブラリを書いて使ってます。

require 'rubygems'
require 'ruby-prof'
require 'stringio'

module RubyProf
  def profiler(&block)
    result = RubyProf.profile &block
    printer = RubyProf::FlatPrinter.new(result)
    strio = StringIO.new
    printer.print(strio)
    strio.string
  end
  module_function :profiler
end

これを require すると

result = RubyProf.profiler {
  100.times { Regexp.new 'foo' }
}
logger.debug result

だけで文字列として結果として取得できるので、logger なりなんなりに出力します。

こんな感じでよくやる debug 方法を紹介しましたが、より better な方法などなどがあったらコメントなりトラックバックなりで教えてもらえるとうれしいです。

ツイートする

Permalink | コメント(11) | トラックバック(4) | 13:09