読者です 読者をやめる 読者になる 読者になる

パーフェクトなCRubyを目指して - 1行のバグ修正に潜む苦労 -

この記事はパーフェクトRuby Advent Calendar 2013 - Adventar の9日目です。
前の日のエントリーはパーフェクトRuby Advent Calendar 2013(8日目) Let's Sinatra Life - たちブログです。
まだ参加できますので、みなさまもぜひ。
パーフェクトRuby Advent Calendar 2013 - Adventar

パーフェクトRuby

Rubyの仕様に大変詳しい同僚への献本をインターセプトして読ませていただきました。
さまざまな機能をまとめたとてもよい本だと思います。
著者のみなさまの苦労が偲ばれました。

パーフェクトRuby (PERFECT SERIES 6)

パーフェクトRuby (PERFECT SERIES 6)

はいっ。

今回は、パーフェクトなCRubyを目指すためGC周りのデバッグの話をします。

1行の修正

Ruby1.9.3に対するこんな感じのパッチを送りました。

diff --git a/object.c b/object.c
index 0a0b260..1ab28a3 100644
--- a/object.c
+++ b/object.c
@@ -285,7 +285,7 @@ rb_obj_clone(VALUE obj)
     }
     clone = rb_obj_alloc(rb_obj_class(obj));
     RBASIC(clone)->klass = rb_singleton_class_clone(obj);
-    RBASIC(clone)->flags = (RBASIC(obj)->flags | FL_TEST(clone, FL_TAINT) | FL_TEST(clone, FL_UNTRUSTED)) & ~(FL_FREEZE|FL_FINALIZE|FL_MARK);
+    RBASIC(clone)->flags = (RBASIC(obj)->flags | FL_TEST(clone, FL_TAINT) | FL_TEST(clone, FL_UNTRUSTED)) & ~(FL_FREEZE|FL_FINALIZE|FL_MARK) | (RBASIC(clone)->flags&FL_MARK);
     init_copy(clone, obj);
     rb_funcall(clone, id_init_clone, 1, obj);
     RBASIC(clone)->flags |= RBASIC(obj)->flags & FL_FREEZE;

これ見つけるの苦労したなぁという話です。
理由とかはツイッターの一連の議論でも…。
nari3 on Twitter: "@unak 一応ChangeLogの方にはもうちょっとだけ詳細に書いてます。 http://t.co/hXEtu3fQ17 rb_obj_alloc()で取れてきたcloneは関数の中でgcが起きてmarkが付いてる可能性があり、それがsweepされちゃいます。"

突然のSEGV

Ruby1.9.3+Sequel+mysql2付近を駆使したサーバを高負荷で回しまくったところ1日に1度ほどの頻度でSEGVするという事象が発生しました。
1日に1度だと原因特定がさすがにしんどいのでもう少し再現性の高いコードを作ることに。
Rubyレベルのバックトレースを見て、この辺かなぁというところのコードを抜き出してきて、100スレッドくらいでぶん回したところ10分くらいで再現するようになりました。
コアを吐くような設定をして、gdbでいろいろと確認します。

gdbで見てみる

gdbでコアをアタッチしてバックトレースを見てみましょう。

(gdb) bt
#0  0x00007f12f51fd8e5 in raise () from /lib64/libc.so.6
#1  0x00007f12f51ff0c5 in abort () from /lib64/libc.so.6
#2  0x000000000056add8 in rb_bug (fmt=0x5a4c8b "Segmentation fault") at error.c:284
#3  0x00000000004b09b8 in sigsegv (sig=<value optimized out>, info=<value optimized out>, ctx=<value optimized out>) at signal.c:609
#4  <signal handler called>
#5  st_lookup (table=0x0, key=35544, value=0x7f12baa62478) at st.c:330
#6  0x000000000050e917 in search_method (klass=18791440, id=35544) at vm_method.c:374
#7  rb_method_entry_get_without_cache (klass=18791440, id=35544) at vm_method.c:393
#8  rb_method_entry (klass=18791440, id=35544) at vm_method.c:426
#9  0x0000000000517f69 in vm_method_search (th=0x21a99f0, initial=<value optimized out>) at vm_insnhelper.c:1371
#10 vm_exec_core (th=0x21a99f0, initial=<value optimized out>) at insns.def:1017
....

あっれ〜、st_lookupに失敗してる。引数のtableを見ると0です。こりゃだめだ。
rb_method_entryとあるのでメソッドが引けてないみたいです。
なんとなくここのidを引いてメソッド名を特定してみましょう。

(gdb) p 35544%global_symbols.id_str->num_bins
643
(gdb) p *global_symbols.id_str->bins[643]->next->next->next->next
$36 = {hash = 35544, key = 35544, record = 28336720, ... }
(gdb) p *(struct RString *)$36->record
$40 = {basic = ... 0x1aa7190 "identifier_output_method", ... }

"identifier_output_method"というのがわかりました。
さて、賢いみなさまはRubyリポジトリにある.gdbinitのrb_id2nameというのを使いましょうね。

これはSequelの以下の部分のメソッド

#sequel/lib/sequel/adapters/mysql2.rb
      def fetch_rows(sql)
        execute(sql) do |r|
          if identifier_output_method
          # ....

あっれ〜、クラスが消えちゃうのなんでぇ〜、という話であります。
この時点のメソッドのレシーバーを覗いてみましょうね。
(ここだとselfのメソッドを読んでるので、rb_psしてvm->cfp->selfで引けたりする)

(gdb) up 10
# vm_exec_coreのところへ
(gdb) p *(struct RVALUE *)recv
$80 = {as = {free = {flags = 0, next = 0x11ebc10},  ...

こいつ死んでるんだぜ…。ということでこのオブジェクトは死んだ後にGCに回収されてfreelistに繋がれたみたいですね。
ほいでクラスを引くときはここのnext(klass)を引いてしまうので、klassが生きてないのは当然だと。
じゃあなんでこのレシーバーのオブジェクトが死ぬのか…、ということが問題になってきます。

疑うフェーズと試すフェーズ

いろいろと疑います。
まずはこのオブジェクトがルートから辿れていないケース。VMのcfpに入ってたらマークされるはずだけどなぁ…とか、考えたり。
あとはmysql2のC拡張ライブラリのRB_GC_GUARD漏れか、とも思ってアセンブラ化して読んだりしたのですが、こちらは大丈夫そう…。

試しにいろんなRubyで試す。

  • 1.9.3のGC.stress(SEGVでない) : ガード漏れじゃない??
  • 1.9.3の最適化オフ(SEGV発生) : ご褒美です!
  • 1.9.3のLazySweepオフ(SEGVでない) : あるぇ〜 ( ・´ー・`)

ということでどうやらLazySweepが怪しいぞ…ということに。なんだろう…。

gdbで試しまくる

幸運なことに5〜10分程度再現するのでgdbで再現コードを回しまくって、メモリ位置の傾向とかを見ていきます。
ちなみに最近のgdbはメモリのランダマイゼーションがデフォルトでオフになるそうなので便利です。
GDB Command Reference - set disable-randomization command

GC回数の傾向と問題のオブジェクトのアドレスを見るとなぜかアドレス的にヒープの一番最初のオブジェクトが死んでしまうことに気付きました(でも位置はバラバラなので結構ツライ)。
なので以下のパッチを当てて、問題のオブジェクトの候補をprintfで出力。

diff --git a/gc.c b/gc.c
index 2b833da..151ccd5 100644
--- a/gc.c
+++ b/gc.c
@@ -2043,6 +2043,8 @@ add_freelist(rb_objspace_t *objspace, RVALUE *p)
 {
     VALGRIND_MAKE_MEM_UNDEFINED((void*)p, sizeof(RVALUE));
     p->as.free.flags = 0;
+    if (objspace->heap.sorted[0].start <= p && objspace->heap.sorted[0].start+80 > p)
+        fprintf(stderr, "free: obj = %p, count = %d\n", p, objspace->count);
     p->as.free.next = freelist;
     freelist = p;
 }

何度か実行させてSEGVの状況を照らし合わせます。

1回目:
free: obj = 0x8403c8, count = 1711
2回目:
free: obj = 0x8405f8, count = 333
3回目:
free: obj = 0x8405f8, count = 222
4回目:
free: obj = 0x840698, count = 241
5回目:
free: obj = 0x8405f8, count = 695
6回目:
free: obj = 0x840558, count = 282
7回目:
free: obj = 0x8405f8, count = 237

うっわー、バラバラ…。でもGCの回数は200回に近い…かも…?

どのタイミングで発生したGCで、オブジェクトが回収されているのか見てみたいですね。
ってことで以下のパッチを当ててGCのタイミングでバックトレースを吐くようにしてみます。
GCのタイミングでバックトレース吐く奴。Ruby1.9.3用。 · GitHub
で、これ後から振り返ると失敗でした。ホントはgc_marksのところに貼らないといけないっすね〜。チョンボチョンボ

あとはGC.countが200回付近で止まるようなbreakpointをgdbに仕込み、そこで表示された候補のオブジェクトのflags(マークビットがあるとこ)に対してwatchpointを張ります。
そうしてやって回していくと…!

Old value = 0
New value = 1
0x000000000044ef6d in rb_class_allocate_instance (klass=23316200) at object.c:1621
1621        OBJSETUP(obj, klass, T_OBJECT);
(gdb)
Continuing.
Hardware watchpoint 2: $29->as.free.flags

...

Old value = 1
New value = 33
gc_mark (objspace=0x83b8a0, th=0x1f9fad0) at gc.c:1756
1756        objspace->heap.live_num++;
(gdb)
Continuing.
Hardware watchpoint 2: $29->as.free.flags

Old value = 33
New value = 1
rb_obj_clone (obj=8668880) at object.c:289
289         init_copy(clone, obj);
(gdb)
Continuing.
Hardware watchpoint 2: $29->as.free.flags

おおっ、途中でマークが付いたのに消されてるところがあるぞ! ということがわかりました!
マークを消したところを確認して、さっきのパッチを作った、という感じです。
同じようにtrunkのバグも見つけたので、そっちもなおしておきました。

答え合わせ

さて何個かの疑問に理屈を付けていくフェーズです。

LazySweepオフにしたら再現しなかったのはなぜか?

LazySweepオンではmarkの状態が付いたままGCを抜けることがあるからですね。
LazySweepオフだとGCを抜けたときにはmarkがついていないキレイなオブジェクトの状態なので、上記のようにマークが途中で消されてしまうということは起こりえません。

再現しづらいのはなぜか?

オブジェクトが生成されてからマークを意図せず消してしまうまでの時間が短いからです。
針を通すようなタイミングでgc_marksが起きないとこの問題は再現しません。
そのためのGC.stress=trueではあるのですが、これだとLazySweepオフ状態になってしまうので再現しないんですよねぇ。
ということで今後のためにLazySweepストレス的なパッチを作ってみたのですけども、あんまり効果なく、パッチ袋にそっとしまいました。
この辺はもうちょっとやらないとなぁ…、といいつつやらないパターン。

必ず先頭のオブジェクトが不正に回収されていたのはなぜか?

これはfreelistの一番最後にいるのがコイツであることが多いからです。

  1. オブジェクト欲しい(問題のオブジェクト)
  2. はいどーぞ。あっfreelistの末尾だった(先頭のオブジェクト)
  3. もう一個オブジェクト欲しい
  4. freelist空じゃん……、よしGCだ!
  5. gc_marks()
  6. 問題のオブジェクトにマークビット付く
  7. バグによってマークビット消される
  8. そのうちLazySweepでオブジェクトが回収される
  9. >SEGV

となります。おそろしや。

最後に

さいきん「GCデバッグってどうやるんですか?」と聞かれたので書いてみました。おそらく理解できた人は少ないと思いますが、私の備忘録も兼ねていますのでこれくらいで…。
この記事を読んでもわかるようにコツは結局『気合』と『諦めの悪さ』ですかね。shinhさんのおっしゃるように

ちなみにこれのデバッグやってるときに何度も挫けそうになりました。簡単そうに書いてますけど1週間くらい悩んでいたので…。そのぶんVMとか多少詳しくなれて…ラッキィ…。

思ったのは、ある問題について一番時間を割いたのが自分だったら、自分が世界で一番詳しくなるのは当然で。これはもう自分で解くしかないんですよね…。
人がなんとかしてくれるだろう、と諦めるのはものすごい簡単で、なんどもそっちにいきたくなるわけなんですけども、なんとか今回は踏ん張れました。

っていう老害みたいなコメントで締めたいと思います。バーチャ楽しいです。