Bug #11271: TestObjSpace#test_trace_object_allocations_start_stop_clear occasional failure

• Status: Closed
• Assignee: ko1 (Koichi Sasada)
• Target version: -
• ruby -v: ruby 2.2.3p136 (2015-06-17 revision 50923) [x86_64-darwin14]
• Backport: 2.0.0: DONTNEED, 2.1: DONTNEED, 2.2: DONE

[nagachika (Tomoyuki Chikanaga)]

手元の環境で ruby_2_2 ブランチ上で make test-all TESTS=objspace/test_objspace.rb と test_objspace.rb だけ指定して実施すると、以下のような 1 Failure になります。

  1) Failure:
TestObjSpace#test_trace_object_allocations_start_stop_clear [/Users/nagachika/opt/ruby-2.2/src/ruby_2_2/test/objspace/test_objspace.rb:188]:
<nil> expected but was
<"/Users/nagachika/opt/ruby-2.2/src/ruby_2_2/test/lib/test/unit/assertions.rb">.

手元では trunk では再現せず、make test-all を全体で実行した時も発生しません。しかし以下のような理由でこれはたまたま発生してないだけなのではないかと推測します。

ObjectSpace.trace_object_allocations_stop でトレースが停止された後に作られた obj3 が全く関係ない test/lib/test/unit/assertions.rb で確保されたと報告されてしまっているのですが、これは

1. ObjectSpace.trace_object_allocations_start でトレースが開始された後に test/lib/test/unit/assertions.rb でオブジェクト A が確保される(traceobj_arg::object_table に記録される)
2. ObjectSpace.trace_object_allocations_stop でトレースが停止される
3. オブジェクトA が GC で回収される。既にトレースが停止されているので freeobj_i() は実行されず traceobj_arg::object_table のエントリは残ったまま
4. オブジェクトA と同じ struct RVALUE に obj3 が確保される

ということが起きているのではないかと想像して、2. と 3. の順序が入れ変わることを期待して以下のように ObjectSpace.trace_object_allocations_stop の前に GC.start を挿入してみると、発生しなくなりました。

--- a/test/objspace/test_objspace.rb
+++ b/test/objspace/test_objspace.rb
@@ -187,6 +187,7 @@ class TestObjSpace < Test::Unit::TestCase
         obj2 = Object.new
       end
     ensure
+      GC.start
       ObjectSpace.trace_object_allocations_stop
       obj3 = Object.new
     end

そもそも ObjectSpace.trace_object_allocations_start と ObjectSpace.trace_object_allocations_stop で収集してる情報はそういうものなのかもしれないですが(オブジェクトが回収されても object_table には残すモードもあるようですし)、テストを修正するか、ObjectSpace.trace_object_allocations_stop で強制的に GC を走らせてこういう現象がおきにくくするのはどうでしょうか。
ruby_2_2 向けですが GC を走らせる方針では以下のようなパッチでも再現しなくなりました。

Index: ext/objspace/object_tracing.c
===================================================================
--- ext/objspace/object_tracing.c       (revision 50922)
+++ ext/objspace/object_tracing.c       (working copy)
@@ -206,6 +206,7 @@
     }
 
     if (arg->running == 0) {
+       rb_gc_start();
        rb_tracepoint_disable(arg->newobj_trace);
        rb_tracepoint_disable(arg->freeobj_trace);
        arg->newobj_trace = 0;

[ko1 (Koichi Sasada)]

私も気づいていたのですが、見ないことにしておりました。

私自身だと、「テスト変えて解決としよう」と思いたいんですが、
それで利用上、問題ないですかね？

[nagachika (Tomoyuki Chikanaga)]

考えてみると GC.disable の場合もあると思うので ObjectSpace.trace_object_allocations_stop で常に GC.start するのもよくないかもしれませんね。テストのほうで修正するというので良いと思います。 あとテストでの対応は GC.start するのでなくて、逆に GC.disable しておいて ObjectSpace.trace_object_allocations_stop 後の GC を抑制するという方法のほうが確実そうですね(未検証)。

[ko1 (Koichi Sasada)]

そのようにしてもらってもよろしいでしょうか。

[nagachika (Tomoyuki Chikanaga)]

• Status changed from Open to Closed

Applied in changeset r52128.

---

• test/objspace/test_objspace.rb
  (test_trace_object_allocations_start_stop_clear): clear object
  allocation table first to get rid of erronous detection for obj3.
  [ruby-dev:49095] [Bug #11271]

[nagachika (Tomoyuki Chikanaga)]

遅くなりましたが r52128 でテストを修正しました。
ただ実は推測していた GC のタイミングの問題ではなくて、このテストに入ってきた時点で別のテストメソッドでの ObjectSpace.trace_object_allocations で登録された情報が残っていて、それが影響していたようで、GC.disable しただけではエラーは収まりませんでした。
なので test_trace_object_allocations_start_stop_clear の先頭で ObjectSpace.trace_object_allocations_clear で object_table をクリアしておくという修正にしました。いちおう [ruby-dev:49095] で書いたようなシナリオもありえるかと思って GC.disable/GC.enable も追加しています。

[nagachika (Tomoyuki Chikanaga)]

• Backport changed from 2.0.0: DONTNEED, 2.1: DONTNEED, 2.2: REQUIRED to 2.0.0: DONTNEED, 2.1: DONTNEED, 2.2: DONE

Backported into ruby_2_2 branch at r52769.