From: nagachika00@...
Date: 2015-11-27T20:44:15+00:00
Subject: [ruby-dev:49391] [Ruby trunk - Bug #11271] TestObjSpace#test_trace_object_allocations_start_stop_clear occasional failure

Issue #11271 has been updated by 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.

----------------------------------------
Bug #11271: TestObjSpace#test_trace_object_allocations_start_stop_clear occasional failure
https://bugs.ruby-lang.org/issues/11271#change-55115

* Author: Tomoyuki Chikanaga
* Status: Closed
* Priority: Normal
* Assignee: Koichi Sasada
* 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
----------------------------------------
手元の環境で 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;
~~~



-- 
https://bugs.ruby-lang.org/