STORESでフルタイムRubyコミッタをやっている遠藤（@mametter）です。
最近Rubyインタプリタのとある問題の修正に成功した（と思う）ので紹介します。といっても格好良い話ではなく、とても泥臭い話です。
問題
RubyのCIで不定期に次のようなエラーが発生していました。いわゆるflaky test。
1) Failure: TestSymbol#test_inspect_under_gc_compact_stress [.../ruby/test/ruby/test_symbol.rb:126]: ":testing" expected but was ":\"\\x00\\x00\\x00\\x00\\x00\\x00\\x00\"".
発生確率が絶妙で、しばしば起きるのですが、デバッグのために狙って再現しようとしても起きないという代物でした。
問題の分析
エラーが起きていたのは次のようなテストです（だいぶ簡略化しています）。
def test_inspect_under_gc_compact_stress GC.auto_compact = true assert_equal(":testing", eval(":testing").inspect) end
つまり、自動コンパクションを有効にした状態で:testingというコードを実行してinspectしたら、":testing"が得られることを確かめています。自動コンパクションについてはプロと読み解く Ruby 3.0 NEWSを参照。
エラーメッセージと合わせて考えても、メモリ関係のバグであることはあきらかです。とてもまずい。
デバッグの試み（失敗）
まず、問題のテストだけを繰り返し実行してみましたが、一向に再現する様子はありませんでした。メモリ関係のバグは単体テストで再現しないことがとても多いです。
多くの場合、この手の問題はテストが失敗しはじめた時期のコミットを疑えば犯人の目星がつきます。しかし、これも無理でした。発生頻度が低くてムラがある *1 ことに加え、今年の1月は他のCIエラーが大量に放置されていた *2 ので、「失敗しはじめた時期」が特定できませんでした（記録に残っていた最古のエラーは2024/02/11のものだった）。
さらに不運なことにこのテスト自体が2023/12/25ごろに追加された（7002e77694）こともあり、以前からもともとインタプリタにあったバグを見つけ出してしまった可能性すら考えられました *3 。こうなると目星はまったくつけられません。
その後、何人かのコミッタがこの問題に気づき、修正を試みたコミットもあったのですが、直らずにくすぶり続けました。
打開のきっかけ
Rubyは、Launchableという、flaky testを指摘してくれるサービスを無料で使わせてもらっています（Misc #20254）。
そのLaunchableが、次のようなエラーがflakyに起きていると報告してきました。
Failure:
TestObjSpace#test_dump_special_consts [/home/runner/work/ruby/ruby/src/test/objspace/test_objspace.rb:419]:
<"{\"type\":\"SYMBOL\", \"value\":\"foo\"}"> expected but was
<"{\"address\":\"0x7f37a2c14ce8\", \"type\":\"SYMBOL\", \"shape_id\":1, \"slot_size\":40, \"class\":\"0x7f37a5f2e9d0\", \"frozen\":true, \"bytesize\":3, \"value\":\"foo\", \"memsize\":40, \"flags\":{\"wb_protected\":true, \"old\":true, \"uncollectible\":true, \"marked\":true}}\n">.
この問題をかんたんに説明すると、Rubyのシンボルには内部的にdynamicとstaticの2種類があり、このテストはstaticを前提としていたが、dynamicだったらエラーになるのでした。byrootが一瞬でそれに気づき、直してくれました（#10479）。
ちなみに、"testing".to_symのようにプログラムで作ったシンボルはdynamic（原則としてGC可能）、:testingやdef testing()のようにコード中の識別子として作ったものはstatic（GC不可能）です（Bug #10686）。
この問題はもとの問題とは直接の関係はなかったのですが、これを見て、もとの問題もdynamic/staticの区別がからんでいるのではと思いつきました。eval(":testing")を繰り返し実行しても再現しないということは、dynamic Symbolが作られないと再現しないのでは。
再現手順の確立
testingというシンボルを扱ってそうなテストを探すと、Prismのテストにあることを発見しました。
https://github.com/ruby/ruby/blob/master/test/prism/fixtures/seattlerb/defn_kwarg_env.txt
ということで、問題のテストとPrismのテストをあわせて実行してみることにしました。
一発ではどうせ再現しないので、whileで繰り返し実行するコマンドを実行し、一晩放置しました。
while make test-all TESTS="test/ruby/test_symbol.rb test/prism/ test/ruby/test_gc_compact.rb" ; do echo ok; done
ちなみにtest/ruby/test_gc_compact.rbも足していますが、これは明確な根拠があるわけではなく、勘です。
すると翌朝、見事テストが失敗していました。しっぽを掴んだ。
乱数のseedを固定することでテストの実行順を固定し、さらに10並列でmake test-allを走らせるようにしたところ、およそ10分に1回くらいで再現性できるようになりました。
ちなみに、この時点ではPrismにバグがあることも結構疑っていて、コードリーディングもしてたのですが、濡れ衣でした（というか、本当にPrismのテストが再現条件に関わっていたのかどうかは、いまでも定かではないです）。詳しく書いてないですが、実際にはこういう寄り道も結構あります。
printfデバッグ
ここまで来たらあとはデバッグするだけです。10並列でプロセス起動しまくって10分に1回程度しか再現しない問題をデバッガでつかまえる方法を思いつかなかったので、パワーで問題箇所を狭めていきました。そう、printfデバッグです。
eval(":testing").inspectのうち、eval(":testing")の返り値の時点で壊れたシンボルになっていた（.inspectは無実）。eval(":testing")はパース時とコンパイル時の2回シンボルを作っていることがわかった。- パース時には正しいシンボルを作れているが、コンパイル時には壊れたシンボルを作っていることがわかった。
しかし、これより縮めるのはむずかしそうでした。というのも、デバッグ出力を挟むと再現しなくなった。GC関係のバグではよくあることです。
バグの特定
しょうがないので、パーサとコンパイラの間の関連しそうなコードを気合で読みます。
運良く、あきらかにまずいコードを発見しました。
rb_parser_string_t * rb_str_to_parser_string(rb_parser_t *p, VALUE str) { /* Type check */ return rb_parser_encoding_string_new(p, RSTRING_PTR(str), RSTRING_LEN(str), rb_enc_get(str)); }
これはRubyではよくある「GCマーク漏れ」のバグのパターンで、スタック上にstrへの参照を残していないので保守的GCが効きません。strが開放されるとRSTRING_PTR(str)がdangling pointerになってしまいます。
ということで、パッチが作れました。RB_GC_GUARDを足すだけのかんたんなパッチ。
diff --git a/parse.y b/parse.y index 9a2535bd2d..b42e8ba682 100644 --- a/parse.y +++ b/parse.y @@ -2082,7 +2082,9 @@ rb_parser_string_t * rb_str_to_parser_string(rb_parser_t *p, VALUE str) { /* Type check */ - return rb_parser_encoding_string_new(p, RSTRING_PTR(str), RSTRING_LEN(str), rb_enc_get(str)); + rb_parser_string_t *ret = rb_parser_encoding_string_new(p, RSTRING_PTR(str), RSTRING_LEN(str), rb_enc_get(str)); + RB_GC_GUARD(str); + return ret; } #endif
パッチの検証
このパッチを当てると、テストをしばらく走らせていても問題が再現しなくなりました。しかし再現しないからといって直ったとは限らない。発見したバグを踏まえて、元の問題が起きていたメカニズムを同僚の笹田と議論しました。
というのも、このパッチで直る理由が自明ではないのです。なぜなら、rb_str_to_parser_stringに渡される文字列はrb_id2strの返り値だったので、この関数内でマーク漏れが起きてもグローバルのシンボルテーブル経由でマークされるはず。つまり誤って文字列が回収されることはないはず。
しかしよく考えると、今回はauto_compactを有効にしている場合に起きる問題でした。compactionはオブジェクトのメモリアドレスを変える（moveといいます）ので、RSTRING_PTR(str)で文字列のアドレスを取り出した後にstrオブジェクトがmoveされてしまうと、RSTRING_PTR(str)がdangling pointerになります。RB_GC_GUARD(str)を足すとオブジェクトのmoveが抑制されるので、この問題は起きない。
よって、今回の問題は「マーク漏れ」ではなく「move抑制漏れ」として説明できそうです。さらにこのパッチでその問題が直ることも説明がつきます。
などと話している間に1時間テストを回し続けていましたが、問題は再現していません。これはきっと大丈夫。気分良くPRを作ってマージしました。
まとめ
このパッチをマージした後、1週間以上CI警察をしていますが、冒頭の問題は見かけていません。この手のバグは直ったと断言するのはむずかしいのですが、まあ直ったんじゃないかな。
flaky testの問題は、端的に言えばCIの監視のノイズになることです。エラーが出ることに慣れてしまうと、より重大なエラーを見逃すなど、ろくなことがありません *4 。また、コントリビュータのPRでこのエラーが起きて、「自分の変更でバグを入れてしまった？」とコントリビュータが無駄に心配してしまう事象も実際に観測されていました。この点でも直したかった。
ということで、数ヶ月ほどflakyに失敗していて誰も直せなかったテストを気合で直した話でした。コミッタの仕事として紹介されるものは、新機能の実装や大きな改善などの目立つ話が多いですが、品質を支えるための泥臭い活動もあるよってことで、あえて紹介してみました。Ruby 3.4が出る前に（たぶん）直ってよかったですね。
