CoreからRubyのバックトレースを表示するgdbruby.rbを作った
gdbperl.plというスクリプトがあります。そんｋする樋口証さん作の、gdbを操作してPerlのプロセスのバックトレースを取るツールです。生きているプロセスだけではなく、coreを取っておけばそのcoreからバックトレースが取れるのが特徴です。
gcoreというコマンドが/usr/binあたりにあって、これを使えば走っているプロセスのcoreを取得することができます。よって、本番環境で気軽にcoreを取ってgdbperl.plにかけることによって、刺さっているポイントを見つけたりすることができます。超便利。
くわしくは、Perlスクリプトをgdbでデバッグを参照ください。
んで、その便利なgdbperl.plをRubyに移植してみました。その名もgdbruby.rb。単純。
使い方とか
Rubyはデバッグシンボル付きのものをご用意ください。
生きているプロセスにアタッチする場合には、プロセスIDを指定してください。
$ gdbruby.rb 24113
coreファイルを指定する場合には、rubyの実行ファイルのパスも指定してください。
$ gdbruby.rb core.24113 `rbenv which ruby`
これで環境変数やCのスタックトレースと共に、Rubyのバックトレースが出力されます。
出力結果はこんな感じです。
command: gdb -silent -nw /home/tasuku/.rbenv/versions/2.0.0-p247/bin/ruby 19008 environ: ruby_version: "2.0.0" c_backtrace: #0 0x00007f8fb71d8d21 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0 #1 0x00007f8fb77769e2 in native_cond_timedwait (ts=, mutex= , cond= ) at thread_pthread.c:359 #2 native_sleep (th=0x7f8fb85b45d0, timeout_tv=0x7fff2eaff4f0) at thread_pthread.c:1017 #3 0x00007f8fb7779c38 in sleep_timeval (th=0x7f8fb85b45d0, tv=..., spurious_check=spurious_check@entry=1) at thread.c:1000 #4 0x00007f8fb7779e44 in rb_thread_wait_for (time=...) at thread.c:1069 #5 0x00007f8fb76a4ac8 in rb_f_sleep (argc=1, argv=0x7f8fb63de188) at process.c:4105 #6 0x00007f8fb7758d3f in vm_call_cfunc_with_frame (th=th@entry=0x7f8fb85b45d0, reg_cfp=reg_cfp@entry=0x7f8fb64ddc00, ci=ci@entry=0x7f8fb90a0ec8) at vm_insnhelper.c:1469 #7 0x00007f8fb776948d in vm_call_cfunc (ci=0x7f8fb90a0ec8, reg_cfp=0x7f8fb64ddc00, th=0x7f8fb85b45d0) at vm_insnhelper.c:1559 #8 vm_call_method (th=0x7f8fb85b45d0, cfp=0x7f8fb64ddc00, ci=0x7f8fb90a0ec8) at vm_insnhelper.c:1751 #9 0x00007f8fb775d7ca in vm_exec_core (th=0x7f8fb85b45d0, initial=initial@entry=0) at insns.def:1017 #10 0x00007f8fb776185a in vm_exec (th=0x3, th@entry=0x1) at vm.c:1201 #11 0x00007f8fb7761f40 in eval_string_with_cref (self=self@entry=140255256203120, src=140255256202000, scope=8, cref=cref@entry=0x0, file=0x7f8fb780182a "(eval)", line=1) at vm_eval.c:1251 #12 0x00007f8fb77623e5 in eval_string (line= , file= , scope= , src= , self=140255256203120) at vm_eval.c:1292 #13 rb_f_eval (argc=1, argv= , self=140255256203120) at vm_eval.c:1340 #14 0x00007f8fb7758d3f in vm_call_cfunc_with_frame (th=th@entry=0x7f8fb85b45d0, reg_cfp=reg_cfp@entry=0x7f8fb64dde80, ci=ci@entry=0x7f8fb909ebd0) at vm_insnhelper.c:1469 #15 0x00007f8fb776948d in vm_call_cfunc (ci=0x7f8fb909ebd0, reg_cfp=0x7f8fb64dde80, th=0x7f8fb85b45d0) at vm_insnhelper.c:1559 #16 vm_call_method (th=0x7f8fb85b45d0, cfp=0x7f8fb64dde80, ci=0x7f8fb909ebd0) at vm_insnhelper.c:1751 #17 0x00007f8fb775d7ca in vm_exec_core (th=0x7f8fb85b45d0, initial=initial@entry=0) at insns.def:1017 #18 0x00007f8fb776185a in vm_exec (th=0x7f8fb909f869, th@entry=0x7f8fb85b45d0) at vm.c:1201 #19 0x00007f8fb776baf5 in rb_iseq_eval_main (iseqval=iseqval@entry=140255256209680) at vm.c:1449 #20 0x00007f8fb762f8ba in ruby_exec_internal (n=0x7f8fb8b96910) at eval.c:250 #21 0x00007f8fb7632347 in ruby_exec_node (n=0x7f8fb8b96910) at eval.c:315 #22 ruby_run_node (n= ) at eval.c:307 #23 0x00007f8fb762ebeb in main (argc=2, argv=0x7fff2eb005a8) at main.c:36 ruby_backtrace: [13] sleep() <- /home/tasuku/gdbruby/spec/target/call.rb:42 [12] Module1::Class1#block in method6() <- /home/tasuku/gdbruby/spec/target/call.rb:42 [11] Module1::Class1#method7() <- /home/tasuku/gdbruby/spec/target/call.rb:47 [10] Module1::Class1#method6() <- /home/tasuku/gdbruby/spec/target/call.rb:40 [9] Module1::Class1#method5() <- /home/tasuku/gdbruby/spec/target/call.rb:35 [8] Module1::Class1#rescue in method4() <- /home/tasuku/gdbruby/spec/target/call.rb:26 [7] Module1::Class1#method4() <- /home/tasuku/gdbruby/spec/target/call.rb:23 [6] Module1::Class1#method3() <- (eval):1 [5] eval() <- /home/tasuku/gdbruby/spec/target/call.rb:17 [4] Module1::Class1#method3() <- /home/tasuku/gdbruby/spec/target/call.rb:17 [3] method2() <- /home/tasuku/gdbruby/spec/target/call.rb:12 [2] method1() <- /home/tasuku/gdbruby/spec/target/call.rb:7 [1] <main>() <- /home/tasuku/gdbruby/spec/target/call.rb:51
詳しいオプションとかはREADMEを見てね。
つらい
想定より作るのが大変でした。
Perl版が、スレッドありなしやPerlのバージョンによって変数名などを切り替えていて、複数バージョンに対応するのは大変そうだな、と予想していました。Ruby版は2.0.0にバージョン固定すれば楽だろう、という適当な見通しで実装し始めましたが、予想以上につらかった…
まず、複数のスレッドが走っていること。どうやら、タイマー用か何かのスレッドと、メインの実行スレッドが別れている様子。生きてるプロセスにアタッチする場合には現在実行中のスレッドにgdbがくっついてくれるんだけど、core経由の場合には若いスレッド番号にコンテキストが移っちゃう。backtraceの中身を見てしのぎました。
バックトレースでC言語の関数を表示するために、rb_id2str()という関数相当の操作を実装しました。rb_id2str()ではst_tableというデータ構造が用いられています。st_tableはRubyのHash実装のベースのようなものだと思いねえ。hash関数と、その同値性を判定する関数を差し替えられるようになっているのですが、デフォルトっぽい場合のみにしか対応せずにお茶を濁しました。
実装するマクロや変数の数は思ったより多かったです。Rubyの内部データはVALUE型が使われていることが多いのですが、これを解釈可能にするのにちょっと手間がかかりますね。
酒飲みながらニコ生でライブコーディングすることによって、そのつらさをちょっと緩和してなんとかリリースまでたどり着けました。
今後の予定
Rubyのバックトレースで関数の引数を出すのはちょっと大変です。@mrkn先生のGistに、バックトレースに引数を出す方法が書いてあります。gdb経由で関数呼び出しができる(=rb_inspect()とかrb_eval()とか呼べちゃう)生きているプロセス相手ならともかく、coreからこれ相当の操作を行うのはちょっと大変。とはいえ、出来なくはないはず。
Ruby 1.8のときには、threadに対してwait_forというメンバがあって、WAIT_FDでどのfdを待っているかとか、WAIT_TIME/WAIT_JOIN/WAIT_PIDとか取れたりして、刺さる系の調査に役立ちそうだった。そういう情報も出せたらいいな。
あとは、ObjectSpaceをナメてObject一覧を出したりとか、いろんな便利機能は思いつきそうです。
id:hirose31さんのinspect-perl-procは、core経由での操作を諦めて生きているプロセスだけに限定するかわりにいろんな便利情報を出しています。この方向性もありかと思います。
あとがき
生きているRubyのプロセスや、そこから取ったcoreファイルからバックトレースを出せるgdbruby.rbを書きました。本番運用のお供にお使いください。
Rubyは初心者なので、かなり適当な実装です。Pull Requestなどの突っ込みを随時お待ちしています。
そんｋといえば鴨語ですが、大人になってから里衣座さんに会えたときはとてもうれしかったです。
