注
自分の頭の整理のためのエントリーです。
よって超長い。
mruby-spec
以前、mrubyでruby/specを走らせるやつを書いたのですが、
その後どうなったのかまとめてみます。
ksss9.hatenablog.com
成果
ruby/specで、まず手を付けていたのはlanguage specでした。
言語の基礎が壊れてたらイカンだろうということで根っこから見ています。
正直言ってまだ走り切ることも困難です。というのもSEGVするから。
SEGVするとそこから先のspecを走らせることができなくなるため、地道に直していました。
大体はmac上でデバッグしているのでlldbを使いました。
lldbでlanguage specを走らせてみて、どこで止まったか追ってみます。
mrubyのcommit hashは d58c2585d4d63f13beeb890046ce6c7b514fab91 でした
$ pwd
ksss/mruby-spec
$ lldb mruby/bin/mruby
(lldb) run mspec/bin/mspec-run spec/language
... いっぱいspecが落ちる表示が出る ...
[/ | ======== 20% | 00:00:00] 19F 51EProcess 3230 stopped
* thread #1: tid = 0x16e74f, 0x000000010006eb9e mruby`get_closure_irep(mrb=0x00000001003002d0, level=0) + 254 at eval.c:31, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x4800000001)
frame #0: 0x000000010006eb9e mruby`get_closure_irep(mrb=0x00000001003002d0, level=0) + 254 at eval.c:31
28 if (!e) return NULL;
29 proc = c->cibase[e->cioff].proc;
30
-> 31 if (!proc || MRB_PROC_CFUNC_P(proc)) {
32 return NULL;
33 }
34 return proc->body.irep;
うんぜんぜんわからん。ちなみに止まる部分は実行する毎に変わったりします。
Cレベルでのバックトレースを取ってみます。
(lldb) bt
* thread #1: tid = 0x16fbc3, 0x000000010006eb9e mruby`get_closure_irep(mrb=0x0000000100400390, level=0) + 254 at eval.c:31, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x3500000001)
* frame #0: 0x000000010006eb9e mruby`get_closure_irep(mrb=0x0000000100400390, level=0) + 254 at eval.c:31
frame #1: 0x000000010006e985 mruby`search_variable(mrb=0x0000000100400390, vsym=326, bnest=0) + 37 at eval.c:44
frame #2: 0x000000010006e903 mruby`patch_irep(mrb=0x0000000100400390, irep=0x0000000101865dd0, bnest=0) + 723 at eval.c:122
frame #3: 0x000000010006e595 mruby`create_proc_from_string(mrb=0x0000000100400390, s="x=1", len=3, binding=mrb_value @ 0x00007fff5fbfd1c0, file="(eval)", line=1) + 1205 at eval.c:194
frame #4: 0x000000010006ddef mruby`f_eval(mrb=0x0000000100400390, self=mrb_value @ 0x00007fff5fbfd398) + 191 at eval.c:215
frame #5: 0x000000010003ee15 mruby`mrb_vm_exec(mrb=0x0000000100400390, proc=0x000000010202cca0, pc=0x000000010183ab90) + 6613 at vm.c:1150
frame #6: 0x000000010003d427 mruby`mrb_vm_run(mrb=0x0000000100400390, proc=0x000000010107e670, self=mrb_value @ 0x00007fff5fbfe080, stack_keep=0) + 135 at vm.c:759
frame #7: 0x00000001000458fb mruby`mrb_top_run(mrb=0x0000000100400390, proc=0x000000010107e670, self=mrb_value @ 0x00007fff5fbfe0f0, stack_keep=0) + 187 at vm.c:2440
frame #8: 0x000000010006302f mruby`load_exec(mrb=0x0000000100400390, p=0x000000010201d420, c=0x0000000101851ee0) + 1183 at parse.y:5694
frame #9: 0x0000000100062b73 mruby`mrb_load_file_cxt(mrb=0x0000000100400390, f=0x00007fff79291218, c=0x0000000101851ee0) + 67 at parse.y:5703
frame #10: 0x0000000100094217 mruby`load_rb_file(mrb=0x0000000100400390, filepath=mrb_value @ 0x00007fff5fbfe410) + 247 at mrb_require.c:425
frame #11: 0x000000010009305e mruby`load_file(mrb=0x0000000100400390, filepath=mrb_value @ 0x00007fff5fbfe450) + 142 at mrb_require.c:437
frame #12: 0x0000000100092a13 mruby`mrb_load(mrb=0x0000000100400390, filename=mrb_value @ 0x00007fff5fbfe490) + 51 at mrb_require.c:455
frame #13: 0x00000001000931d5 mruby`mrb_f_load(mrb=0x0000000100400390, self=mrb_value @ 0x00007fff5fbfe4f0) + 133 at mrb_require.c:470
frame #14: 0x000000010003ee15 mruby`mrb_vm_exec(mrb=0x0000000100400390, proc=0x000000010107ec40, pc=0x00000001004a0e98) + 6613 at vm.c:1150
frame #15: 0x000000010003d427 mruby`mrb_vm_run(mrb=0x0000000100400390, proc=0x0000000101047950, self=mrb_value @ 0x00007fff5fbff1d0, stack_keep=0) + 135 at vm.c:759
frame #16: 0x00000001000458a4 mruby`mrb_top_run(mrb=0x0000000100400390, proc=0x0000000101047950, self=mrb_value @ 0x00007fff5fbff240, stack_keep=0) + 100 at vm.c:2434
frame #17: 0x000000010006302f mruby`load_exec(mrb=0x0000000100400390, p=0x0000000101019820, c=0x0000000100432020) + 1183 at parse.y:5694
frame #18: 0x0000000100062b73 mruby`mrb_load_file_cxt(mrb=0x0000000100400390, f=0x00007fff79291050, c=0x0000000100432020) + 67 at parse.y:5703
frame #19: 0x0000000100001509 mruby`main(argc=3, argv=0x00007fff5fbff668) + 905 at mruby.c:226
frame #20: 0x00007fff9b92e5ad libdyld.dylib`start + 1
frame #21: 0x00007fff9b92e5ad libdyld.dylib`start + 1
一見意味不明ですが、よくみるとeval.cでcreate_proc_from_string関数に"x=1"という文字列を渡していることに気が付きます。
$ cd spec && pwd
ksss/mruby-spec/spec
$ git grep x=1 language
language/and_spec.rb: # evaluates (x=1) and (y=2)
language/ensure_spec.rb: eval('x=1') # to prevent opts from triggering
どうやらlanguage/ensure_spec.rbがクサいっぽいです。
it "in no-exception scenarios, is the value of the last statement of the protected body" do
begin
v = 1
eval('x=1')
v
ensure
v = 2
end.should == 1
end
ありました。eval('x=1')の部分が実に怪しいです。
しかしながら単純にmruby -e 'eval("x=1")'としてもSEGVしません。
再現コードを書こうにも、mspecのコードを読んでできるだけ余計なコードを削除して展開して……。
とやっていると、「ある時点でメソッドを展開するとSEGVが起こらなくなる」という現象に遭遇しました。
最初はサッパリでしたが、途中で「もしやメソッドの呼び出しスタックが深くなるとSEGVが起こりやすくなるのでは？」とひらめき、
1.times{1.times{1.times{1.times{1.times{1.times{1.times{1.times{
1.times{1.times{1.times{1.times{1.times{1.times{1.times{1.times{
begin
eval('raise')
rescue => e
print e.backtrace
end
}}}}}}}}
}}}}}}}}
とすることでSEGVを再現できることをたまたま発見できました。
ところがどっこい。
この再現コードはこれまでと全く違う部分でSEGVしているようです。
(lldb) run t.rb
Process 4744 launched: '/Users/yuki/src/github.com/ksss/mruby-spec/mruby/bin/mruby' (x86_64)
Process 4744 stopped
* thread #1: tid = 0x173171, 0x00007fff95b04132 libsystem_c.dylib`strlen + 18, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x0)
frame #0: 0x00007fff95b04132 libsystem_c.dylib`strlen + 18
libsystem_c.dylib`strlen:
-> 0x7fff95b04132 <+18>: pcmpeqb (%rdi), %xmm0
0x7fff95b04136 <+22>: pmovmskb %xmm0, %esi
0x7fff95b0413a <+26>: andq $0xf, %rcx
0x7fff95b0413e <+30>: orq $-0x1, %rax
(lldb) up
frame #1: 0x0000000100030d8b mruby`mrb_str_cat_cstr(mrb=0x0000000100600000, str=mrb_value @ 0x00007fff5fbfe380, ptr=0x0000000000000000) + 43 at string.c:2585
2582 MRB_API mrb_value
2583 mrb_str_cat_cstr(mrb_state *mrb, mrb_value str, const char *ptr)
2584 {
-> 2585 return mrb_str_cat(mrb, str, ptr, strlen(ptr));
2586 }
2587
2588 MRB_API mrb_value
(lldb) up
frame #2: 0x000000010000645d mruby`mrb_restore_backtrace(mrb=0x0000000100600000) + 541 at backtrace.c:415
412 mrb_str_cat(mrb, mrb_entry, &entry->sep, 1);
413 }
414
-> 415 mrb_str_cat_cstr(mrb, mrb_entry, mrb_sym2name(mrb, entry->method_id));
416 }
417
418 mrb_ary_push(mrb, backtrace, mrb_entry);
(lldb) up
frame #3: 0x0000000100014eec mruby`exc_get_backtrace(mrb=0x0000000100600000, exc=mrb_value @ 0x00007fff5fbfe510) + 156 at error.c:190
187 backtrace = mrb_iv_get(mrb, exc, attr_name);
188 if (mrb_nil_p(backtrace)) {
189 if (mrb_obj_ptr(exc) == mrb->backtrace.exc && mrb->backtrace.n > 0) {
-> 190 backtrace = mrb_restore_backtrace(mrb);
191 mrb->backtrace.n = 0;
192 mrb->backtrace.exc = 0;
193 }
(lldb) up
frame #4: 0x000000010003ee15 mruby`mrb_vm_exec(mrb=0x0000000100600000, proc=0x000000010081f670, pc=0x000000010064ba58) + 6613 at vm.c:1150
1147 ci->argc = n;
1148 ci->nregs = n + 2;
1149 }
-> 1150 result = m->body.func(mrb, recv);
1151 mrb_gc_arena_restore(mrb, ai);
1152 if (mrb->exc) goto L_RAISE;
1153 /* pop stackpos */
どうやらException#backtraceを呼び出した時にmrb_sym2name(mrb, entry->method_id)がNULLを返してしまい、strlen(NULL)のような形になってしまっているようです。entry->method_idは23459のような数字でした。これはシンボルのIDのはずなのですが、2万個もシンボルを作っていないはずなので多すぎます。この値が異常っぽいです。それゆえmrb_sym2nameはシンボルIDから文字列に変換するメソッドなのですが、該当するシンボルがないのでNULLを返しているようです。
そもそもmrubyのbacktraceはどうやって取っているのでしょうか？
それすら全くわからなかったので、ひたすらコードを読みました。
すると、次のようなことが見えてきました。
- mrubyのbacktrace情報は
mrb->c->ciから取ってきている
mrb->cはstruct mrb_contextのことで、struct mrb_contextにはcibase, ci, ciendというメンバーがある。cibaseは単に配列で、ciは配列の現在位置、ciendはメモリを確保している最後の印。- 最初に
cibaseに長さ32個分のメモリを確保、ci = cibaseとして初期化される。
- mruby側でメソッドを呼び出すたびに
ciポインタは一つ進み、これまでどういうスタックで呼ばれてきたのかを記録している。
ciがciendまでくると、mrb_reallocで確保するメモリが2倍に伸長される。
backtraceはciの位置から一つづつcibaseの位置にもどりつつスタックの情報をbacktrace用に作っていて、肝心要のentry->method_idはci->midからコピーしている。
https://github.com/mruby/mruby/blob/501e1ef2605541b98b6f0d2ba2fec69ff068f1cf/src/backtrace.c#L147
当然ci->midは今のスタックのメソッド名(シンボル)でおかしな値はここからコピーされていることがわかった。
さて、ci->midはどこから来るのか。この値はシンボルなので加減算はされないだろう。
さらにあたりをつけると、こんな異常で毎回大きく異る値をとり得るのは、未初期化な場合だろう。
ではciスタックは、どこで作られるんだろう。
実は2箇所しかない。
初期化時と伸長時だ。
https://github.com/mruby/mruby/blob/501e1ef2605541b98b6f0d2ba2fec69ff068f1cf/src/vm.c#L93
https://github.com/mruby/mruby/blob/501e1ef2605541b98b6f0d2ba2fec69ff068f1cf/src/vm.c#L226
ヤバイこのまま細かく書いているといつまでたっても終わらない。どんどん巻いていくと、mrb_callocはじつはmemsetで0初期化する処理が含まれているのでここで異常な値が入るとは考えにくい。
そしてmrb_reallocはその名の通りreallocするので0初期化しない。
さらに、このmrb_reallocでcibaseを取り直しているcipushはmrubyのevalメソッドからmrb_top_runを通じて呼ばれている。
そしてなんと、このパスではci->midはなにも操作されない。reallocで確保されたメモリではあるが、野ざらしで雑草がぼうぼうに生えた空き地があるだけだ。その雑草が23459。ようやく犯人(草)を掴んだ。
ここで雑草を抜いて綺麗にしておけばなんとかなる。
mrubyの場合、mid=0がCRubyでの<main>を意味するようだ。mrubyではこの場合、単にメソッド名を表示していない。
$ ruby -e 'eval("raise")'
-e:1:in `eval': (eval):1:in `<main>' (RuntimeError)
from -e:1:in `eval'
from -e:1:in `<main>'
$ mruby -e 'eval("raise")'
trace:
[0] (eval):1
[1] -e:1
(eval):1: RuntimeError
これでようやく一つ倒した。ここまでで一週間以上かかっている。
さて、ここまできても最初に見つけたSEGVはなおっていない。つらい。
気を取り直して調べていこう。
lldbで見つけた部分を思い出そう。
28 if (!e) return NULL;
29 proc = c->cibase[e->cioff].proc;
30
-> 31 if (!proc || MRB_PROC_CFUNC_P(proc)) {
32 return NULL;
33 }
34 return proc->body.irep;
ここでいろいろ調べてみると、e->cioffは-1であることがわかった。
(lldb) p e->cioff
(ptrdiff_t) $0 = -1
前回、cibaseはスタックの最初であることが分かっていた。cibase[-1]ではあきらかにおかしい。つまりこの時点でe->cioffか-1なのがおかしいことになる。
e->cioffとはなにか。そもそもe(REnv*)とはなにか。
REnvで検索していくと、mrb_callinfoとRProcという構造体にメンバーとして含まれている。
https://github.com/mruby/mruby/blob/501e1ef2605541b98b6f0d2ba2fec69ff068f1cf/include/mruby/proc.h#L32-L40
https://github.com/mruby/mruby/blob/08a1dd2ac89333bd928a3300f712d1a7fb57e8ff/include/mruby.h#L72-L85
また、REnv型としてメモリ確保されているのはproc.cのenv_new、さらにenv_newをclosure_setupが呼んでいる。
https://github.com/mruby/mruby/blob/08a1dd2ac89333bd928a3300f712d1a7fb57e8ff/src/proc.c#L37-L64
closure...クロージャーと言えば、なぜか外側の変数をメソッド内で保持している不思議な奴だった気がするやつだ。
ここで、「struct REnvは外側の環境を保存しておくためのものではないか？」という仮説が浮かび上がる。
ほかにも「環境変数を表すやつか？」とかいろんな仮説が浮かんでは死んでいった。今回もそうだろうか？
proc.hには気になるマクロがある。
https://github.com/mruby/mruby/blob/08a1dd2ac89333bd928a3300f712d1a7fb57e8ff/include/mruby/proc.h#L27-L28
そういえば問題はe->cioff = -1のときなんだった。忘れてた。
これはMRB_ENV_UNSHARE_STACKされた時と見るのが可能性が高そうだ。
多分この数字によってREnvのモードが変わる的な数字だと思う。
cioffの名の通り、おそらくciのoffsetなんだろう。
https://github.com/ksss/mruby/blob/501e1ef2605541b98b6f0d2ba2fec69ff068f1cf/src/proc.c#L45
をみると、cibaseからciがどれぐらい動いているのかを保存している。
おそらくREnvがciスタックにアクセスしたいときに、どのスタックを呼び出せばいいかを保存しているものと見た。
cioff=-1ということはciスタックを参照することはないんだけど、REnvが使われるかもしれないから残しておきたいフラグなのかなあと推測。
MRB_ENV_UNSHARE_STACKが使われるのはcipopされた時だ。自分でも何を言っているのかわからなくなってきた。
vm.cを読むと、cipopとcipushという関数がある。cipopというからにはciスタックを元に戻る操作なんだろう。逆にcipushはci
スタックを積み上げる操作。
さらにヒントになったのが、blameしていてみつけたこのPR
github.com
この再現コードでいわゆる"unshare"なREnvを使うことができる。
いろいろいじってみると、たしかに問題のeval.cのあの部分で問題を再現できるのだけど、どうもSEGVにならない。
28 if (!e) return NULL;
29 proc = c->cibase[e->cioff].proc;
30
-> 31 if (!proc || MRB_PROC_CFUNC_P(proc)) {
32 return NULL;
33 }
34 return proc->body.irep;
ここでprocはNULLを指しているからだ。
ここで前回の問題が浮かんだ。"ciスタックが深いと再現するのでは？"
そうしてできたのがPRの再現コード。
def m
Proc.new { eval('raise') }
end
1.times{1.times{1.times{1.times{1.times{1.times{1.times{1.times{
1.times{1.times{1.times{1.times{1.times{1.times{1.times{1.times{
m.call
}}}}}}}}
}}}}}}}}
ついに来た。これで勝つるというやつだ。
eval.cで問題になっているのは、evalメソッドでRubyコード文字列を引数にして実行した場合に変数も使えるようにしている部分だった。
ここではcioffからciスタックをたどって、その時点の実行コードを読み込もうとしていたが、mメソッド内のciスタックはすでにpopしているのでeはunsharedになっている。これをevalメソッドが引いてきた時にアウトとそういうことっぽい。
つまりはevalメソッド実行時にunshredなREnvが存在すること自体はおかしくないので、もしunshredなら無視するように修正した。
はーこれに二週間かっかったけど勉強になった。
スタックが深くなると起こるバグはほかにもある気がするので、いつかまたハマったら思い出してみよう。
これもruby/spec/languageを走らせて遭遇した。
$ lldb mruby/bin/mruby
(lldb) run mspec/bin/mspec-run spec/language/variables_spec.rb
...
* thread #1: tid = 0x1acaab, 0x00000001000023ff mruby`mrb_ary_concat(mrb=0x0000000100202ad0, self=mrb_value @ 0x00007fff5fbfd3a0, other=mrb_value @ 0x00007fff5fbfd390) + 47 at array.c:273, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x28)
frame #0: 0x00000001000023ff mruby`mrb_ary_concat(mrb=0x0000000100202ad0, self=mrb_value @ 0x00007fff5fbfd3a0, other=mrb_value @ 0x00007fff5fbfd390) + 47 at array.c:273
270 {
271 struct RArray *a2 = mrb_ary_ptr(other);
272
-> 273 ary_concat(mrb, mrb_ary_ptr(self), a2->ptr, a2->len);
274 }
275
276 static mrb_value
(lldb) up
frame #1: 0x00000001000437fa mruby`mrb_vm_exec(mrb=0x0000000100300390, proc=0x00000001008460f0, pc=0x000000010070ccf0) + 25562 at vm.c:2122
2119
2120 CASE(OP_ARYCAT) {
2121 /* A B mrb_ary_concat(R(A),R(B)) */
-> 2122 mrb_ary_concat(mrb, regs[GETARG_A(i)],
2123 mrb_ary_splat(mrb, regs[GETARG_B(i)]));
2124 ARENA_RESTORE(mrb, ai);
2125 NEXT;
(lldb) up
frame #2: 0x000000010003d407 mruby`mrb_vm_run(mrb=0x0000000100300390, proc=0x00000001008321d0, self=mrb_value @ 0x00007fff5fbfe070, stack_keep=0) + 135 at vm.c:759
756 }
757 stack_extend(mrb, irep->nregs, stack_keep);
758 mrb->c->stack[0] = self;
-> 759 return mrb_vm_exec(mrb, proc, irep->iseq);
760 }
761
762 MRB_API mrb_value
mrb_ary_concatでの引数otherがnilになっているので、nilをarrayとして扱おうとして落ちている。再現率100%だ。やった。
OP_ARYCATというvm命令でおきていて、mrb_ary_splatという関数がnilを返しているようだ。
Rubyでsplatと言えば、*での展開するヤツのことだ。
a = *nil #=> [] a = *'a' #=> ["a"] a = *1 #=> [1] a, b, c = *[1,2,3]; a #=> 1
さて、次の場合はどうなるか。
o = Object.new
a = *o
答えはStringやIntegerと同じく、自身を[]で囲む。
o = Object.new
a = *o
実はこのsplatはto_aメソッドがなければ単に[]で囲んで、to_aがあればそれを呼び出すようになっている。
o = Object.new
def o.to_a
['hi']
end
a = *o
ここから更に細かいが、CRubyでは、to_aメソッドを読んで、nilならto_aメソッドがなかった時と同じく単に[]で囲む。
nilじゃなければArray#concatと同じことをする。くっつけるのは他の変数達。
a = *1, *'', *o
=> [1, "", "hi"]
コードは多分この辺
https://github.com/ruby/ruby/blob/d432af3df7ffa3fb2666674f70dab685e73de374/insns.def#L491-L513
これがmrubyでは実装されておらず、splatは単にto_aの結果を返しているだけだった。
するとto_aメソッドがarray以外を返すと、mrb_ary_concatメソッドでarrayとして処理しようとしてバグとなる。
ここではCRubyと同じ動きになるように、mrb_ary_splatを修正した。
CRubyの挙動にも詳しくなれてmrubyのバグも直って一石二鳥！
このブログ自体も時間をかけて作成されたため、途中で口調が変わっている。
おしまい。
