[ruby-core:81105] [Ruby trunk Bug#11384][Open] multi-threaded autoload sometimes fails

[s.wanabe@gmail.com]

Issue #11384 has been updated by wanabe (_ wanabe).

Status changed from Closed to Open

I re-open this ticket because it remains the issue.
Please do not hesitate to close and open new one if you want.

I think this is an issue of the timing between `rb_provide_feature()` and `autoload_const_set()`.

This is reproduction code that is to reference to https://bugs.ruby-lang.org/issues/11384#note-3 and test_autoload.rb.

```
require "tempfile"

Tempfile.create(['autoload', '.rb']) {|file|
  file.puts 'ZZZ = 1'
  file.close
  1.upto(Float::INFINITY) do |i|
    STDERR.print "#{i}\n"
    autoload(:ZZZ, file.path)
    begin
      t1 = Thread.new { ZZZ }
      t2 = Thread.new { Thread.pass; ZZZ }
      Thread.pass
      [t1, t2].each(&:join)
    ensure
      if Object.const_defined?(:ZZZ)
        Object.send(:remove_const, :ZZZ)
        $".pop
      end
    end
  end
}
```

This is debug print patch.

```
diff --git a/load.c b/load.c
index 75ac4df83f..58dbb47382 100644
--- a/load.c
+++ b/load.c
@@ -563,6 +563,7 @@ rb_provide_feature(VALUE feature)
     rb_str_freeze(feature);
 
     rb_ary_push(features, rb_fstring(feature));
+fprintf(stderr, "%p >>> rb_provide_feature -> rb_ary_push\n", rb_thread_current());
     features_index_add(feature, INT2FIX(RARRAY_LEN(features)-1));
     reset_loaded_features_snapshot();
 }
diff --git a/variable.c b/variable.c
index 6e883c7041..73d040dd61 100644
--- a/variable.c
+++ b/variable.c
@@ -2085,6 +2085,7 @@ autoload_reset(VALUE arg)
 	rb_set_safe_level_force(state->ele->safe_level);
 	rb_ensure(autoload_const_set, (VALUE)&args,
 	          reset_safe, (VALUE)safe_backup);
+fprintf(stderr, "%p <<< autoload_reset <- autoload_const_set\n", rb_thread_current());
     }
 
     /* wakeup any waiters we had */
@@ -2144,8 +2145,11 @@ rb_autoload_load(VALUE mod, ID id)
     struct autoload_data_i *ele;
     struct autoload_state state;
 
+fprintf(stderr, "%p check_autoload_required 0\n", rb_thread_current());
     if (!autoload_defined_p(mod, id)) return Qfalse;
+fprintf(stderr, "%p check_autoload_required 1\n", rb_thread_current());
     load = check_autoload_required(mod, id, &loading);
+fprintf(stderr, "%p check_autoload_required 2 %p\n", rb_thread_current(), load);
     if (!load) return Qfalse;
     src = rb_sourcefile();
     if (src && loading && strcmp(src, loading) == 0) return Qfalse;
```

This is a short extract from output.
(Sorry, I can't attached entire log because too large: 3.2 MB > 2 MB)

> 12170
> 0x7f0004007340 check_autoload_required 0
> 0x7f0004007340 check_autoload_required 1
> 0x7f0004007340 check_autoload_required 2 0x7f0004007390
> 0x7f0004007340 >>> rb_provide_feature -> rb_ary_push
> 0x7f0004007228 check_autoload_required 0
> 0x7f0004007228 check_autoload_required 1
> 0x7f0004007228 check_autoload_required 2 (nil)
> 0x7f0004007340 <<< autoload_reset <- autoload_const_set
> a.rb:11:in `block (3 levels) in <main>': uninitialized constant ZZZ (NameError)

When thread 0x7f0004007228 called check_autoload_required(),
thread 0x7f0004007340 had pushed load script path into `$"` but had not yet called autoload_const_set().

If you want to reproduce easily, `rb_thread_schedule()` may help you.

```
diff --git a/load.c b/load.c
index 75ac4df83f..2d4172e112 100644
--- a/load.c
+++ b/load.c
@@ -563,6 +563,7 @@ rb_provide_feature(VALUE feature)
     rb_str_freeze(feature);
 
     rb_ary_push(features, rb_fstring(feature));
+rb_thread_schedule();
     features_index_add(feature, INT2FIX(RARRAY_LEN(features)-1));
     reset_loaded_features_snapshot();
 }
```

----------------------------------------
Bug #11384: multi-threaded autoload sometimes fails
https://bugs.ruby-lang.org/issues/11384#change-64755

* Author: normalperson (Eric Wong)
* Status: Open
* Priority: Normal
* Assignee: 
* Target version: 
* ruby -v: trunk r51319
* Backport: 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: UNKNOWN
----------------------------------------
~~~
I get this failure once in a blue moon:

#8 test_autoload.rb:46:in `<top (required)>':
     open("zzz.rb", "w") {|f| f.puts "class ZZZ; def self.ok;:ok;end;end"}
     autoload :ZZZ, "./zzz.rb"
     t1 = Thread.new {ZZZ.ok}
     t2 = Thread.new {ZZZ.ok}
     [t1.value, t2.value].join
  #=> "" (expected "okok")
stderr output is not empty
   bootstraptest.tmp.rb:5:in `block in <main>': uninitialized constant ZZZ (Name
+Error)
test_autoload.rb        FAIL 1/8
FAIL 1/1010 tests failed


It is a very rare failure, I extracted it into a standalone script and
it took over 500,000 runs to hit it:

unless test(?e, "zzz.rb")
  open("zzz.rb", "w") {|f| f.puts "class ZZZ; def self.ok;:ok;end;end"}
end
autoload :ZZZ, "./zzz.rb"
t1 = Thread.new {ZZZ.ok}
t2 = Thread.new {ZZZ.ok}
[t1.value, t2.value].join
~~~

I'll work on this when I find time, but maybe somebody else can look at it
sooner.  I'm not sure if it affects older versions.




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