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
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 な方法などなどがあったらコメントなりトラックバックなりで教えてもらえるとうれしいです。