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

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

[normalperson]

Issue #11384 has been reported by Eric Wong.

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

* Author: Eric Wong
* Status: Open
* Priority: Normal
* Assignee: 
* 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/

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

[shugo]

Issue #11384 has been updated by Shugo Maeda.


Eric Wong wrote:
> Eric Wong <normalperson@yhbt.net> wrote:
>  > Currently testing this in a loop:
>  > http://80x24.org/spew/m/94541be0225540e34f0196e9754ae0eb5c07a4b7.txt
>  
>  Nope, the original failure still happens with this, so there's
>  some other place where we're racing :<

TestAutoload#test_threaded_accessing_constant has failed often since r52139,
and it seems to be the same problem.
I could reproduce the problem easily by the following script:

```
require "tempfile"

Tempfile.create(['autoload', '.rb']) {|file|
  file.puts 'sleep(0.5); class AutoloadTest; X = 1; end'
  file.close
  1.upto(Float::INFINITY) do |i|
    p i
    autoload(:AutoloadTest, file.path)
    begin
      t1 = Thread.new { ::AutoloadTest::X }
      t2 = Thread.new { ::AutoloadTest::X }
      [t1, t2].each(&:join)
    ensure
      if Object.const_defined?(:AutoloadTest)
        Object.send(:remove_const, :AutoloadTest)
        $".pop
      end
    end
  end
}
```

The script causes an error within 100 times on My Ubuntu 14.04 box,
but it runs over 10,000 times with your patch.

Your patch looks good to me, and at least it solves the race condition
of autoload_require(), even if there's still another race condition.
Why don't you commit it?


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

* Author: Eric Wong
* Status: Open
* Priority: Normal
* Assignee: 
* 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/

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

[Eric Wong]

shugo@ruby-lang.org wrote:
> > Eric Wong <normalperson@yhbt.net> wrote:
> >  > http://80x24.org/spew/m/94541be0225540e34f0196e9754ae0eb5c07a4b7.txt
>
> Your patch looks good to me, and at least it solves the race condition
> of autoload_require(), even if there's still another race condition.
> Why don't you commit it?

Thanks for the reminder.  I'll take a closer look at it tomorrow or day
after when I'm more awake.  It's been eons since I wrote that
patch; maybe I did not fully understand the original code I replaced.

Will also take another look at Bug #10892, too.

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

[Eric Wong]

shugo@ruby-lang.org wrote:
> The script causes an error within 100 times on My Ubuntu 14.04 box,
> but it runs over 10,000 times with your patch.

Is my patch still running beyond 10,000 times?

Without the patch, I can't reproduce the error within 200 times
(Debian wheezy + SMP).

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

[Eric Wong]

Eric Wong <normalperson@yhbt.net> wrote:
> shugo@ruby-lang.org wrote:
> > The script causes an error within 100 times on My Ubuntu 14.04 box,
> > but it runs over 10,000 times with your patch.
> 
> Is my patch still running beyond 10,000 times?
> 
> Without the patch, I can't reproduce the error within 200 times
> (Debian wheezy + SMP).

Nevermind, just took over 2000 times to reproduce on my system.
Will commit my patch + followups to reduce autoload_data_i size.

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

[shugo]

Issue #11384 has been updated by Shugo Maeda.


Eric Wong wrote:
> shugo@ruby-lang.org wrote:
>  > The script causes an error within 100 times on My Ubuntu 14.04 box,
>  > but it runs over 10,000 times with your patch.
>  
>  Is my patch still running beyond 10,000 times?

It's still running beyond 49,000 times on my notebook, which sleeps at night.
I'll inform you if any error occurs.


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

* Author: Eric Wong
* Status: Closed
* Priority: Normal
* Assignee: 
* 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/

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

[Eric Wong]

shugo@ruby-lang.org wrote:
> It's still running beyond 49,000 times on my notebook, which sleeps at night.
> I'll inform you if any error occurs.

Actually, I've managed to reproduce around 47,000 times.
So my patch (r52332) seems to help make the problem less obvious,
but yeah, there's still a bug somewhere...

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

[s.wanabe]

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/

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

[Eric Wong]

s.wanabe@gmail.com wrote:
> 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.

No worries, I don't care for ticket organization; all that
matters is problems get fixed.  I will investigate this later
today, or tomorrow at latest.  Thank you for reporting the
problem.

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

[normalperson]

Issue #11384 has been updated by normalperson (Eric Wong).

File 0001-autoload-always-wait-on-loading-thread.patch added
Backport changed from 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: UNKNOWN to 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: UNKNOWN, 2.3: REQUIRED, 2.4: REQUIRED

I think the attached patch should fix it, over 12 million iterations
and still going strong.


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

* 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, 2.3: REQUIRED, 2.4: REQUIRED
----------------------------------------
~~~
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.


---Files--------------------------------
0001-autoload-always-wait-on-loading-thread.patch (1.96 KB)


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

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

[usa]

Issue #11384 has been updated by usa (Usaku NAKAMURA).

Backport changed from 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: UNKNOWN, 2.3: REQUIRED, 2.4: REQUIRED to 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: UNKNOWN, 2.3: DONE, 2.4: REQUIRED

ruby_2_3 r59221 merged revision(s) 58696.

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

* Author: normalperson (Eric Wong)
* Status: Closed
* Priority: Normal
* Assignee: 
* Target version: 
* ruby -v: trunk r51319
* Backport: 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: UNKNOWN, 2.3: DONE, 2.4: REQUIRED
----------------------------------------
~~~
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.


---Files--------------------------------
0001-autoload-always-wait-on-loading-thread.patch (1.96 KB)


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

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

[nagachika00]

Issue #11384 has been updated by nagachika (Tomoyuki Chikanaga).

Backport changed from 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: UNKNOWN, 2.3: DONE, 2.4: REQUIRED to 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: UNKNOWN, 2.3: DONE, 2.4: DONE

ruby_2_4 r59303 merged revision(s) 58696.

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

* Author: normalperson (Eric Wong)
* Status: Closed
* Priority: Normal
* Assignee: 
* Target version: 
* ruby -v: trunk r51319
* Backport: 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: UNKNOWN, 2.3: DONE, 2.4: DONE
----------------------------------------
~~~
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.


---Files--------------------------------
0001-autoload-always-wait-on-loading-thread.patch (1.96 KB)


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