RubyのPathnameライブラリが本体組み込みになったらGC周りのテスト失敗がおきた

こんにちは。ruby-devチームの遠藤（@mametter）です。

次期バージョンのRubyでは、pathnameがRuby本体組み込みとなり、require "pathname"なしで利用可能になる予定です。 Rubyで書き捨てスクリプトを書いてる自分のような人は地味にうれしいかもしれません。

Feature #17473: Make Pathname to embedded class of Ruby - Ruby - Ruby Issue Tracking System

さて、pathnameの組み込みがマージされた直後、非常に興味深いバグが発生しました。今回はそのデバッグの経緯を技術ブログとして共有したいと思います。

問題の発生：特定環境でのみ失敗するテスト

コミッタのhsbtさんがpathnameの組み込み化をマージした後、なぜかRubyのCIの一部が落ちるようになりました。失敗していたのはtest/ruby/test_allocation.rbに含まれる、GCというか、オブジェクト生成の挙動を検証するテストです。

具体的には、可変長引数を使ったメソッド呼び出しで余分な配列が確保されないことを確認するテストです。インタプリタ内部のテストなので、Pathnameのような上位層には一切依存していません。

失敗が確認されていたのは、macOS SonomaとOpenBSDのCIだけでした。そして、これらの環境が共通して使っているclangが最初に疑われました。

hsbtさんが調査を始めていましたが、面白そうだったのでデバッグに参戦することにしました。手元の環境では再現しなかったので、macOS SonomaのCI環境にログインしてデバッグし始めました。 hsbtさんから「--disable-yjitオプションをつけたときだけ落ちる」と聞いたので、試してみたら無事に再現しました。

原因の切り分け：不可解な依存関係

hsbtさんに「pathnameの実装を削除すると再現しなくなる」と聞いたので、pathname_builtin.rbのコードを部分的に削除し、何を消したら再現しなくなるのかを探ることにしました。

こういうときは大抵、pathname_builtin.rbの中の特定のコードが問題で、それを消したら再現しなくなるものなのですが、今回はちょっと違いました。再現性が、削除するコードの「内容」ではなく「量」に依存しているように見えたのです。どこでもいいからある程度のコード量を削ると、再現性が下がります。

ここでいう「再現性が下がる」とは、「失敗する確率が下がる」ではなく、「失敗するテストの件数が減る（！）」というものでした。こんなの見たことない。

そこで、アプローチを変更し、問題が発生しているtest/ruby/test_allocation.rbを簡略化していくことにしました。すると、さらに奇妙な事実が判明します。テストコード中で使用されていないローカル変数の定義を一行削除するだけで、問題が再現しなくなったのです。一見すると、ロジックでは説明がつかない挙動でした。

仮説と検証：シンボル数がトリガーか？

この「コード量」や「無関係な変数定義」に挙動が左右されるという状況から、一つの仮説を立てました。それは「インタプリタ全体のシンボルの数が特定の閾値を超えた場合に、何かが起きるのではないか」というものです。

この仮説を検証するため、以下のシンプルな再現コードを作成しました。

# 意図的に多数のシンボルを生成し、内部状態を閾値に近づける
10000.times {|n| eval("x#{ n } = nil") }

counts = {}
a = []
f = proc {}

GC.start
GC.disable

# 実行前のアロケーション数を測定
before = ObjectSpace.count_objects(counts)[:T_ARRAY]

# テスト対象のコード
f.call(*a)

# 実行後のアロケーション数を測定
after = ObjectSpace.count_objects(counts)[:T_ARRAY]

# beforeとafterが一致しない場合、意図しないアロケーションが発生している
p [before, after]

このコードを実行したところ、仮説は的中し、beforeとafterで配列の数が増えているという結果を安定して再現できました。冒頭の10000というループ回数は環境の内部状態に依存するマジックナンバーです。この数値を各環境ごとに探索するスクリプトを書いたところ、Linux+gccといった、当初問題が起きていなかった環境でも問題を再現させることに成功しました。当初疑われていたmacOS SonomaやOpenBSDも、clangも、--disable-yjitも、全部無実でした。

根本原因の特定

自分が慣れたLinux環境で問題を再現できたことで、gdbによる詳細な解析が可能になりました。配列オブジェクトが生成されそうなary_alloc_heap関数にブレークポイントを設定し、意図しないアロケーションがどこで起きているかを追跡しました。

その結果、取得したバックトレースはこんなものでした。

(gdb) bt
#0  ary_alloc_heap ... at array.c:695
...
#4  ... in register_static_symid_str ... at symbol.c:617
#5  ... in rb_intern3 ... at symbol.c:787 // シンボル生成
...
#10 ... in count_objects ... at gc.c:2520 // オブジェクト数をカウント中
...

つまり、ObjectSpace.count_objectsの実行中に、新たなシンボルが生成され、その過程で配列アロケーションが発生しているのでした。

真相：観測行為が結果を歪めていた

問題の全容が明らかになりました。

ObjectSpace.count_objectsは、結果を{ :T_ARRAY => 100, :T_STRING => 100, ... }という形式のハッシュで返す。
このハッシュを生成する際、まず:T_ARRAYの値（配列の総数）を確定させる。
次に、ハッシュのキーである:T_STRINGというシンボルをrb_intern3で生成しようとする。
この時、シンボル一覧を管理する配列の空きがちょうどなくなった場合に、新しい配列が確保される。（新しい配列の確保が起きるかどうかが問題発生の閾値になっていた）
このアロケーションは、既に行われた:T_ARRAYのカウントには含まれない。しかし、テストコードの実行後に再度count_objectsを呼び出すと、この時に生成された配列がカウントされてしまい、結果としてアロケーション数が1つ増えたように見えていた。

オブジェクト数を数えるという観測行為そのものが、観測対象である配列の数を変えてしまうという、稀な副作用が原因でした。

結論と対策

原因が特定できれば、修正はシンプルです。 count_objectsがハッシュのキーとして使用するすべてのシンボルを、オブジェクトのカウント前にあらかじめ生成しておくことで、実行中の意図しないアロケーションを防ぎました。

github.com

まとめ

pathnameの組み込みは、あくまで全体のシンボル数を押し上げるトリガーに過ぎず、根本原因はObjectSpace.count_objectsの挙動にありました。今回は決定論的に再現可能な問題であったため解析は比較的容易でしたが、インタプリタのような複雑度のソフトウェアにおいて一見無関係な変更が思わぬ副作用を引き起こす好例だと思ったので紹介しました。

このような地道な品質改善活動を通じて、Rubyは日々進化しています。今後のリリースにもご期待ください。

謝辞

このデバッグは一人でやったわけではありません。 Pathnameの組み込みを主導してこの問題の再現条件の調査もやってくれてたhsbtさん、再現コードができたあとの分析をいっしょにやってくれたko1、nobuさん、ありがとうございました。

STORES Product Blog

こだわりを持ったお商売を支える「STORES」のテクノロジー部門のメンバーによるブログです。