From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Original-To: poffice@blade.nagaokaut.ac.jp Delivered-To: poffice@blade.nagaokaut.ac.jp Received: from kankan.nagaokaut.ac.jp (smtp.nagaokaut.ac.jp [133.44.2.24]) by blade.nagaokaut.ac.jp (Postfix) with ESMTP id 7B6231BA0015 for ; Fri, 12 May 2017 07:59:34 +0900 (JST) Received: from voscc.nagaokaut.ac.jp (voscc.nagaokaut.ac.jp [133.44.1.100]) by kankan.nagaokaut.ac.jp (Postfix) with ESMTP id D9D26B5D844 for ; Fri, 12 May 2017 08:43:45 +0900 (JST) Received: from neon.ruby-lang.org (neon.ruby-lang.org [221.186.184.75]) by voscc.nagaokaut.ac.jp (Postfix) with ESMTP id 24A7418CC80A for ; Fri, 12 May 2017 08:43:45 +0900 (JST) Received: from neon.ruby-lang.org (localhost [IPv6:::1]) by neon.ruby-lang.org (Postfix) with ESMTP id 090C312071B; Fri, 12 May 2017 08:43:44 +0900 (JST) X-Original-To: ruby-core@ruby-lang.org Delivered-To: ruby-core@ruby-lang.org Received: from o1678916x28.outbound-mail.sendgrid.net (o1678916x28.outbound-mail.sendgrid.net [167.89.16.28]) by neon.ruby-lang.org (Postfix) with ESMTPS id 2609A1205C8 for ; Fri, 12 May 2017 08:43:40 +0900 (JST) DKIM-Signature: v=1; a=rsa-sha1; c=relaxed/relaxed; d=sendgrid.me; h=from:to:references:subject:mime-version:content-type:content-transfer-encoding:list-id; s=smtpapi; bh=C9f9xskb8M7SmLfIKkiDu653z5k=; b=fkxDB9uzX+r1aT3PPF 7G5ZJaVm8g5HH/LfPZ7bnwQVlP152fdoPfvxWgmiIlDic7fhy0USxYd6RWR3ebqQ fr6o1l3c0Sa0sVMOnwqMEeWVelPxR3UCMQesePj80haUg7Fh1qZaqR+RtOtNPw3K A3eHGa9PolJ6d4wEwZixd5DMU= Received: by filter0231p1las1.sendgrid.net with SMTP id filter0231p1las1-10845-5914F72A-B 2017-05-11 23:43:38.230550302 +0000 UTC Received: from herokuapp.com (ec2-54-161-228-42.compute-1.amazonaws.com [54.161.228.42]) by ismtpd0035p1mdw1.sendgrid.net (SG) with ESMTP id HAQBuFjES3eS4lEdzid_Pw Thu, 11 May 2017 23:43:38.079 +0000 (UTC) Date: Thu, 11 May 2017 23:43:37 +0000 From: s.wanabe@gmail.com To: ruby-core@ruby-lang.org Message-ID: References: Mime-Version: 1.0 X-Redmine-MailingListIntegration-Message-Ids: 56129 X-Redmine-Project: ruby-trunk X-Redmine-Issue-Id: 11384 X-Redmine-Issue-Author: normalperson X-Redmine-Sender: wanabe X-Mailer: Redmine X-Redmine-Host: bugs.ruby-lang.org X-Redmine-Site: Ruby Issue Tracking System X-Auto-Response-Suppress: All Auto-Submitted: auto-generated X-SG-EID: ync6xU2WACa70kv/Ymy4QrNMhiuLXJG8OTL2vJD1yS7EMpZB+Ua0noX5BKBwsoCHH3Tw3yrGTMQeNN /30EPUa2kFcwmqjk7HNbm3jbWgZa1Uui+Vugi63VkiYekaN+My9+oLCtHTaX2LCh3aaovA1WjK0NL4 Yu9/cFG7nNRrgQ/hO4lFSSFPD83PvgjZMhKPIHin38QbV+iNTmlG8pNQ8w== X-ML-Name: ruby-core X-Mail-Count: 81105 Subject: [ruby-core:81105] [Ruby trunk Bug#11384][Open] multi-threaded autoload sometimes fails X-BeenThere: ruby-core@ruby-lang.org X-Mailman-Version: 2.1.15 Precedence: list Reply-To: Ruby developers List-Id: Ruby developers List-Unsubscribe: , List-Post: List-Help: List-Subscribe: , Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Errors-To: ruby-core-bounces@ruby-lang.org Sender: "ruby-core" 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
': 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 `': 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
': 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/