gdbを使ったrubyのデバッグ

技術部の国分 (@k0kubun) です。

先日byebugの高速化を行っていた最中、変更を加えたbyebugを使っていると一定の確率でrubyがSEGVするバグを発見しました。 私はC言語のコードのデバッグの経験はなかったのですが、デバッガの使い方を調べながらSEGVの原因調査を行いパッチを送ったところ無事取り込まれ、最新の高速なbyebugが安全に使えるようになりました。

その際、ruby自体をデバッグするために必要な情報が分散していて大変だったので、まだrubyのデバッグをしたことがないけれどやってみたいという人を対象に、gdbというデバッガを使ったrubyのデバッグの方法を紹介します。

デバッグ用にrubyをビルドする

デバッグ時に変数名やソースコードなどの情報を見るためには、最適化オプションをオフにしてデバッグ用にrubyをビルドしておく必要があります。

rubyのデバッグ用ビルド手順

GitHubにあるrubyのリポジトリをcloneしてデバッグ用にビルドする手順を紹介します。 デバッグに必要なgccのコンパイルオプションに関しての詳細はこちらのドキュメントをご覧ください。

$ git clone https://github.com/ruby/ruby
$ cd ruby
# ./configureを(再)生成
$ autoreconf
# -O0で最適化を無効にする。debugflagsはデフォルトで "-ggdb3" になっています。
$ ./configure optflags="-O0"
$ make
$ make install

これにより生成される./rubyを使ってデバッグしていきます。*1

ビルドしたrubyをrbenvから使うには

もしビルドしたrubyã‚’rbenvで管理したい場合は~/.rbenv/versions/以下にインストールする必要があります。以下のような手順でtrunkとしてrbenvから使えるようにできます。

# ~/.rbenv/versions/trunk にインストールされるようにする
$ ./configure optflags="-O0" --prefix="${HOME}/.rbenv/versions/trunk"
$ make
$ make install

デバッグに使う時は、./rubyの代わりに$(RBENV_VERSION=trunk rbenv which ruby)を指定してください。

gdbでrubyの動作を追ってみる

では、以下のコードがrubyにどのように処理されるのかgdbを使って実際に追ってみましょう。

str = 'world'
str.prepend('hello ')
puts str

rubyのメソッドが実装されている関数名を調べる

str.prepend('hello ')の前後で変数strがどう変わるかを見てみます。 String#prependが実行される直前でブレークするためには、まずそれがCのソースのどこで実装されているか知る必要があります。

ruby-docのString#prependのページで「click to toggle source」というリンクをクリックすると、以下のようにString#prependはrb_str_prependで実装されていることがかります。

調べた関数でブレークする

どの関数でブレークするかがわかったら、以下のように目的の関数にbreakし、runでスクリプトを走らせます。

$ echo "str = 'hello'\nstr << ' world'.freeze\nputs str" > ./hello.rb
$ gdb --args ./ruby ./hello.rb
(gdb) break rb_str_prepend
Breakpoint 1 at 0xdc16b: file string.c, line 2689.
(gdb) run
Starting program: /home/vagrant/ruby/ruby ./hello.rb
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/i386-linux-gnu/libthread_db.so.1".
[New Thread 0xb7ae5b40 (LWP 2272)]

Breakpoint 1, rb_str_prepend (str=2151591520, str2=2151591700) at string.c:2689
2689        StringValue(str2);

rb_str_prependで実行を止められました。

状況を確認する

上記の出力だけだと今どこにいるのかわかりにくいですが、デバッグ用にrubyをビルドしているおかげで、listを叩くと以下のように周辺のソースコードを表示することができます。

(gdb) list
2684     */
2685
2686    static VALUE
2687    rb_str_prepend(VALUE str, VALUE str2)
2688    {
2689        StringValue(str2);
2690        StringValue(str);
2691        rb_str_update(str, 0L, 0L, str2);
2692        return str;
2693    }

strとstr2は何か確認してみましょう。VALUEはポインタなので、pで値をそのまま表示するとオブジェクトのアドレスが表示されます。

(gdb) p str
$1 = 2151591520
(gdb) p str2
$2 = 2151591700

このオブジェクトの値を確認するにはどうすればいいでしょうか。ruby内にはデバッグ用にrb_pという関数が定義されており、これをcallで呼び出すと値を確認できます。

(gdb) call rb_p(str)
" world"

もしgdbã‚’rubyのリポジトリ内で実行していれば、rubyのリポジトリにある.gdbinitでrb_pã‚’call rb_pにするコマンドが定義されているため、rb_pだけで確認できます。

(gdb) rb_p(str2)
"hello"

他にも、rb_backtraceを使うとrubyレベルでのバックトレースが見れます。

(gdb) rb_backtrace
        from ./hello.rb:2:in `<main>'
        from ./hello.rb:2:in `prepend'

これはgdbのコマンドですが、backtraceを叩くとCレベルでのバックトレースが見れます。

(gdb) backtrace
#0  rb_str_prepend (str=2151591520, str2=2151591700) at string.c:2691
#1  0x801381b1 in call_cfunc_1 (func=0x800dc165 <rb_str_prepend>, recv=2151591520, argc=1, argv=0xb7ae6020)
    at vm_insnhelper.c:1542
#2  0x80138b52 in vm_call_cfunc_with_frame (th=0x802a3c18, reg_cfp=0xb7b65fc8, calling=0xbfffede8, ci=0x80380ab8,
    cc=0x803d8058) at vm_insnhelper.c:1709
#3  0x80138c57 in vm_call_cfunc (th=0x802a3c18, reg_cfp=0xb7b65fc8, calling=0xbfffede8, ci=0x80380ab8,
    cc=0x803d8058) at vm_insnhelper.c:1804
#4  0x80139816 in vm_call_method_each_type (th=0x802a3c18, cfp=0xb7b65fc8, calling=0xbfffede8, ci=0x80380ab8,
    cc=0x803d8058) at vm_insnhelper.c:2091
#5  0x80139e81 in vm_call_method (th=0x802a3c18, cfp=0xb7b65fc8, calling=0xbfffede8, ci=0x80380ab8, cc=0x803d8058)
    at vm_insnhelper.c:2215
#6  0x8013a06c in vm_call_general (th=0x802a3c18, reg_cfp=0xb7b65fc8, calling=0xbfffede8, ci=0x80380ab8,
    cc=0x803d8058) at vm_insnhelper.c:2258
#7  0x8013cccd in vm_exec_core (th=0x802a3c18, initial=0) at insns.def:995
#8  0x8014c33c in vm_exec (th=0x802a3c18) at vm.c:1636
#9  0x8014cbc6 in rb_iseq_eval_main (iseq=0x803eafa0) at vm.c:1879
#10 0x80018fd5 in ruby_exec_internal (n=0x803eafa0) at eval.c:244
#11 0x800190dd in ruby_exec_node (n=0x803eafa0) at eval.c:309
#12 0x800190ab in ruby_run_node (n=0x803eafa0) at eval.c:301
#13 0x80017224 in main (argc=2, argv=0xbffff764) at main.c:36

ステップ実行する

変数の推移を確認しながらステップ実行をしてみましょう。nextを叩くと1行ずつ先に進むことができます。

2689        StringValue(str2);
(gdb) next
2690        StringValue(str);
(gdb) next
2691        rb_str_update(str, 0L, 0L, str2);

rb_str_updateという何か更新が走りそうな関数の手前に止まりました。この行ではstrとstr2の値はどう変わるでしょうか。

(gdb) next
2692        return str;
(gdb) rb_p(str)
"hello world"
(gdb) rb_p(str2)
"hello"

#prependのレシーバになっていた" world"のみ値が変わっていることが確認できました。

デバッグ中に任意の式を実行する

rb_eval_string_protect関数を使うと、デバッグの途中で任意の式を実行することができます。

(gdb) call rb_eval_string_protect("str << '!'", 0)
$3 = 2151591520
(gdb) rb_p str
"hello world!"

strの末尾に"!"を追加できました。continueで最後まで走らせるとどうなるでしょうか。

(gdb) continue
Continuing.
hello world!

このように、putsに渡る引数をデバッグ中に変更できていることが確認できました。 チュートリアルは以上です。最後に今回使用したコマンドをまとめておきます。

コマンド	操作内容
break f	関数fにブレークポイントを貼る
run	プログラムを実行する
list	現在いる位置のソースを確認する
p	Cレベルでの値を確認する
backtrace	Cレベルでのバックトレースを表示する
rb_p	rubyレベルでの値を確認する
rb_backtrace	rubyレベルでのバックトレースを表示する
next	次の行に移動する
continue	最後まで実行する
call rb_eval_string_protect("...", 0)	任意の式を実行する

rubyがSEGVした時のデバッグ方法

UNIXプロセスが異常終了すると、プロセスのメモリの状態をそのまま保存したコアファイルというものが生成されます。 rubyがSEGVしたときもそのコアファイルをgdbから読み込むことで、後からSEGVした瞬間の状況を調査することができます。

ただし環境によってはデフォルトでコアダンプが無効になっていることがあるので、以下のようにコアダンプを有効にしてからrubyをSEGVさせます。

$ ulimit -c # core file sizeを確認。0ならコアダンプされない
$ ulimit -c unlimited # コアファイルのサイズを最大にする

その後以下のようにするとSEGV時の状況を調査することができます。

# 例えばOSXでは /cores/core.XXXXX に作られる
$ gdb -c /path/to/core ./ruby

それ以外のデバッグ操作はrubyの動作を追いかけた時と同じです。

まとめ

rubyのデバッグを始めるのに必要な知識を一通り紹介しましたがいかがだったでしょうか。 普段rubyを使う側の立場だとC言語のデバッグに必要な知識はなかなか身につかないですが、やってみるとrubyの内部の挙動がわかって面白いので是非お試しください。

*1:2019/01/24 追記 https://twitter.com/k0kubun/status/1088222074307395584. https://twitter.com/k0kubun/status/1088373905994084352