segmentation faultの出たmrubyを楽しくデバッグする方法

mrubyを使っていてsegmentation faultとか出て困ったことは無いでしょうか。こういう場合にgdbでデバッグするノウハウを書きます。gdbの使い方についてはここでは説明しません。

逆アセンブラ

gdbでデバッグするならmrubyのバイトコードの逆アセンブラが必要です。標準ではcodedump関数が用意されていますが、なぜかここで説明するような使い方はできないようです。mrubyのJITで使っているものがここにありますので、コピーしてcodedump.cあたりにでも入れておいてくください。

これを使うと、変数mrbとirepが見えていれば、こんな感じでdisasm_irep関数を呼び出すことで逆アセンブルできます。見えていない場合、gdbのupコマンドで呼び出し元を辿っていて見えるところがあればそこで実行可能です。disasm_irepは値を返さないのでcallを使う方がよさそうですが、pの方が短いのでpを良く使っていますが好みの問題です。

(gdb) p disasm_irep (mrb, irep)
   0 OP_ENTER   0:0:1:0:0:0:0
   1 OP_LOADSELF        R3
   2 OP_ARRAY   R4      R4      0
   3 OP_MOVE    R5      R1      ; R1:names
   4 OP_ARYCAT  R4      R5
   5 OP_SEND    R3      :attr_reader    127
   6 OP_LOADSELF        R3
   7 OP_ARRAY   R4      R4      0
   8 OP_MOVE    R5      R1      ; R1:names
   9 OP_ARYCAT  R4      R5
   a OP_SEND    R3      :attr_writer    127
   b OP_RETURN  R3      normal
$6 = void
(gdb)

また、現在どのメソッドやブロックというレベルではなくどの命令を実行中か知りたい場合もあります。そういう場合には、disasm_onceを使います。このばあい、変数pcが見えている必要があります。

(gdb) p disasm_once (mrb, irep, *pc)
OP_ENTER        0:0:1:0:0:0:0
$7 = void
(gdb)

pcはデリファレンスする必要があります。

VMのレジスタ

mrubyのVMではメソッドの引数とかローカル変数とかにRITE VMのレジスタを使います。デバッグで、VMのレジスタがみたいことが良くあります。このような場合は、最寄りの mrb_context_runまでupコマンドで上って行って、p regs[レジスタ番号]とします。レジスタ番号が0は常にselfであることは覚えておいて損はないでしょう。

(gdb) down
#0  mrb_irep_incref (mrb=mrb@entry=0x200398d0, irep=irep@entry=0x400d1250)
    at C:\cygwin\home\PCUser\work\mruby\src\state.c:129
129       irep->refcnt++;
(gdb) up
#1  0x0041f090 in mrb_proc_new (mrb=mrb@entry=0x200398d0,
    irep=irep@entry=0x400d1250)
    at C:\cygwin\home\PCUser\work\mruby\src\proc.c:32
32        mrb_irep_incref(mrb, irep);
(gdb) up
#2  0x00433dc1 in mrb_context_run (mrb=mrb@entry=0x200398d0, proc=0x2003c380,
    proc@entry=0x2003c578, self=..., stack_keep=stack_keep@entry=0)
    at C:\cygwin\home\PCUser\work\mruby\src\vm.c:2321
2321                    p = mrb_proc_new(mrb, nirep);
(gdb) p regs[0]
$8 = {{f = -nan(0xa2003bc60), value = {{{p = 537115744, i = 537115744,
          sym = 537115744}, ttt = 4293918730}}}}

mrubyの生のmrb_value型ではお腹を壊す人は、mrb_p関数が便利です。mrbを渡すことに注意しましょう。

(gdb) p mrb_p(mrb, regs[0])
StopIteration
$9 = void

バックトレース

mrubyがどういった呼び出し履歴で落ちてしまったのか、知りたい場合もよくあります。そんなときは、これを.gdbに入れておけば、mbtと打つとバックトレースが見えます。ただし、mrbが見えている必要があります。

define mbt
  set $p = mrb->c->ci
  while ($p > mrb->c->cibase)
    if (($p->proc->flags & 128) != 0 )
      printf "0x%x   C ", $p
      output $p->proc->body.func
      printf "\n"
    else
      set $irep = $p->proc->body.irep
      set $mid = $p->mid
      set $method_name = mrb_sym2name(mrb, $mid)
      set $filename = $irep->filename
      set $lines = $irep->lines
      if ($filename && $lines)
	if ($p == mrb->c->ci)
	  set $lineno = $lines[pc - $irep->iseq]
	else
	  set $lineno = $lines[($p + 1)->pc - $irep->iseq]
	end
        printf "0x%x MRUBY %s : %s:%d\n", $p, $method_name, $filename, $lineno
      else
        printf "0x%x MRUBY %s : \n", $p, $method_name
      end
    end
    set $p = $p - 1
  end
end

バックトレース出力例はこんな感じです

(gdb) mbt
0x20046380   C (mrb_func_t) 0x46ac00 <mrb_printstr>
0x20046340 MRUBY p :
0x20046300 MRUBY derivative : benchmark/nuralnet.rb:47
0x200462c0 MRUBY output_train : benchmark/nuralnet.rb:50
0x20046280 MRUBY call : benchmark/nuralnet.rb:97
0x20046240 MRUBY each :
0x20046200 MRUBY train : benchmark/nuralnet.rb:99
0x200461c0 MRUBY call : benchmark/nuralnet.rb:124
0x20046180 MRUBY times :
0x20046140 MRUBY call : benchmark/nuralnet.rb:128
0x20046100 MRUBY times :

ちなみに、左側の数字はその階層のcall infoです。いろんな情報が入っているので、この先のデバッグに役立つことでしょう。
たとえば、
0x20046200 MRUBY train : benchmark/nuralnet.rb:99
の行の逆アセンブラを出力してみましょう

(gdb) p disasm_irep(mrb, ((struct mrb_callinfo *)0x20046200)->proc->body.irep)
   0 OP_ENTER   2:0:0:0:0:0:0
   1 OP_LOADSELF        R4
   2 OP_MOVE    R5      R1      ; R1:inputs
   3 OP_SEND    R4      :feed_forward   1
   4 OP_GETIV   R4      @output_layer
   5 OP_MOVE    R5      R2      ; R2:targets
   6 OP_SEND    R4      :zip    1
   7 OP_LAMBDA  R5      I(+1)   2
   8 OP_SENDB   R4      :each   0
   9 OP_GETIV   R4      @hidden_layer
   a OP_LAMBDA  R5      I(+2)   2
   b OP_SENDB   R4      :each   0
   c OP_RETURN  R4      normal

また、この階層でのR2レジスタの内容はこんな感じで表示できます。

(gdb) p mrb_p(mrb, ((struct mrb_callinfo *)0x20046200)->stackent[2])
[0, 0]
$20 = void

irepとかregsとかない場合、または壊れている場合

Segmentation Failtとかが出るということは、irepとかregsが壊れている場合ってのも結構あります。こういう場合はあきらめるしかない？というとまだ粘れます。
mrb->c->ciには、現在実行中のコンテクストが収められていて、この中にirepとかregsとかあるからです。また、mrb->c->ci[-1]とすると、callerのコンテクストが得られます。これを利用すると、callerの逆アセンブルをしたりできます。先ほどの、gdbのmbtマクロはこの辺のノウハウが詰まっていますので、読んでみるとよいかと思います。

regsはmrb->c->stackを指しているので、mrb->c->stackでregsの代わりにアクセスできます。

(gdb) p mrb_p(mrb, mrb->c->stack[0])
StopIteration
$11 = void
(gdb) p disasm_irep (mrb, mrb->c->ci->proc->body.irep)
   0 OP_ENTER   0:0:1:0:0:0:0
   1 OP_LOADSELF        R3
   2 OP_ARRAY   R4      R4      0
   3 OP_MOVE    R5      R1      ; R1:names
   4 OP_ARYCAT  R4      R5
   5 OP_SEND    R3      :attr_reader    127
   6 OP_LOADSELF        R3
   7 OP_ARRAY   R4      R4      0
   8 OP_MOVE    R5      R1      ; R1:names
   9 OP_ARYCAT  R4      R5
   a OP_SEND    R3      :attr_writer    127
   b OP_RETURN  R3      normal
$12 = void
(gdb)

mrb->c->ci[-戻る深さ].proc->body.irepはよく使いますので、覚えておくといいでしょう。

(gdb) p disasm_irep (mrb, mrb->c->ci[-1].proc->body.irep)
   0 OP_LOADSELF        R1
   1 OP_LOADSYM R2      :result
   2 OP_SEND    R1      :attr_accessor  1
   3 OP_RETURN  R0      normal
$14 = void
(gdb)

それでも駄目な時のwatch point

こんな感じで何が悪いのかが分かったとします。segmentation faultは変数とかオブジェクトに想定していない値が入っているものです。変数やデータ構造の値が壊れている、GCかコンパイラのバグか？って思う心をぐっと抑えて、落ちつきましょう。
壊れているのがオブジェクトである場合、幸いです。彼らにはwatchコマンドが与えられるからです。watchコマンドは変数だけではなく、アドレスを指定することもできます。
x86ではハードウエア支援があるので掛けていてもそれほど速度も落ちません。

最後はやっぱりprintf

watchはとても強力ですが、長い長い実行の末にはじめて起きるという種類のバグには向きません。こういうのにはやはりprintfでしょう。