One semaphore to exclusively load them all #550

jrafanie · 2019-01-28T19:51:28Z

https://bugzilla.redhat.com/show_bug.cgi?id=1671458
Fixes #544

From MartinH's findings in #544, we had one thread at the
cspec[:klass].constantize line while another thread was trying to run
klass.columns_hash, causing a
Circular dependency detected while autoloading... error.

I then tried a bunch of things until I found a way to reliably recreate
this error:

require_relative 'config/environment'

threads = []
4.times do
  threads << Thread.new { Api::Environment.time_attributes }
end
threads.collect(&:join)

I could then run the above script several times in my shell and get the
circular dependency error most of the time.

for x in `seq 1 10`; do; bundle exec ruby test.rb; done

With this test in place, I then tried a few solutions:

Move the klass.columns_hash block into the permit_concurrent_loads
block:

diff --git a/lib/api/environment.rb b/lib/api/environment.rb
index 87b34f99..f4b6554a 100644
--- a/lib/api/environment.rb
+++ b/lib/api/environment.rb
@@ -22,9 +22,10 @@ module Api
         # Temporary measure to avoid thread race condition which could lead to a deadlock
         ActiveSupport::Dependencies.interlock.permit_concurrent_loads do
           klass = cspec[:klass].constantize
-        end
-        klass.columns_hash.each do |name, typeobj|
-          result << name if %w(date datetime).include?(typeobj.type.to_s)
+
+          klass.columns_hash.each do |name, typeobj|
+            result << name if %w(date datetime).include?(typeobj.type.to_s)
+          end
         end
       end
     end

This did not fix the circular dependency error. Perhaps
permit_concurrent_loads doesn't handle arbitrarily deep nested autoloads
cross threads?

I tried Mutex#synchronize and this worked, but I'd rather we work
with the interlock provided by rails.

diff --git a/lib/api/environment.rb b/lib/api/environment.rb
index 87b34f99..f51de73f 100644
--- a/lib/api/environment.rb
+++ b/lib/api/environment.rb
@@ -1,5 +1,6 @@
 module Api
   class Environment
+    ONE_AUTOLOADER_LOCK = Mutex.new
     def self.url_attributes
       @url_attributes ||= Set.new(%w(href))
     end
@@ -19,12 +20,13 @@ module Api
         next if cspec[:klass].blank?
         klass = nil

-        # Temporary measure to avoid thread race condition which could lead to a deadlock
-        ActiveSupport::Dependencies.interlock.permit_concurrent_loads do
+        # Ensure we're the only thread trying to autoload classes and their columns
+        ONE_AUTOLOADER_LOCK.synchronize do
           klass = cspec[:klass].constantize
-        end
-        klass.columns_hash.each do |name, typeobj|
-          result << name if %w(date datetime).include?(typeobj.type.to_s)
+
+          klass.columns_hash.each do |name, typeobj|
+            result << name if %w(date datetime).include?(typeobj.type.to_s)
+          end
         end
       end
     end

I tried Sync.new with SH and EX locks instead of Mutex and this
failed with Thread killed errors.
I changed the permit_concurrent_loads on the interlock to loading
and this worked, but Yuri found this caused a deadlock.
Use loading from 4) and move the columns_hash call into
the loading block. This solves the circular dependency and avoids the
deadlock encountered in 4).

I noticed, permit_concurrent_loads calls yield_shares with compatible: [:load])
and that method has this in the source code comment:

https://github.com/rails/rails/blob/bb22fe9d4a6102d2a28cb1adfd6fe9d38fc9bb22/activesupport/lib/active_support/concurrency/share_lock.rb#L166-L168

  Temporarily give up all held Share locks while executing the
  supplied block, allowing any +compatible+ exclusive lock request
  to proceed.

Perhaps, since we're loading code, permit_concurrent_loads is too
permissive of other exclusive lock requests and we really need to ensure
nothing else is trying to load.

jrafanie · 2019-01-28T19:53:14Z

Note, this whole problem goes away if we autoload this memoized method once at boot before puma worker threads are spawned.

skateman

Tested, looks good 👍

jrafanie · 2019-01-30T17:16:26Z

@skateman @himdel Updated to use the interlock but to request an exclusive lock while we're autoloading. Was there a BZ associated with this bug or just #544?

skateman · 2019-01-31T08:11:31Z

@jrafanie no BZ, but we might need one .. the bug can appear in older versions as well.

jrafanie · 2019-01-31T16:16:58Z

@miq-bot rm_label wip
@miq-bot add_label gaprindashvili/yes
@miq-bot add_label hammer/yes
@miq-bot add_label bug

jrafanie · 2019-01-31T20:04:26Z

Hold off on merging, @yrudman found that this seems to cause the first click after login to spin indefinitely, possibly a deadlock...

@miq-bot add_label wip

miq-bot · 2019-01-31T20:27:48Z

Checked commit jrafanie@67a74c5 with ruby 2.3.3, rubocop 0.52.1, haml-lint 0.20.0, and yamllint 1.10.0
1 file checked, 0 offenses detected
Everything looks fine. 🏆

yrudman · 2019-01-31T20:30:35Z

lib/api/environment.rb

-          result << name if %w(date datetime).include?(typeobj.type.to_s)
+          klass.columns_hash.each do |name, typeobj|
+            result << name if %w(date datetime).include?(typeobj.type.to_s)
+          end


skateman · 2019-01-31T20:52:04Z

I feel bad that I don't understand the whole rails code reloading process well enough to fix something like this 😞

jrafanie · 2019-01-31T22:42:04Z

lib/api/environment.rb

-        # Temporary measure to avoid thread race condition which could lead to a deadlock
-        ActiveSupport::Dependencies.interlock.permit_concurrent_loads do
+        # Ensure we're the only thread trying to autoload classes and their columns
+        ActiveSupport::Dependencies.interlock.loading do


Note, this also works:

Rails.application.executor.wrap do ...

@Fryguy do you prefer the executor wrapper? I can research more tomorrow if that makes sense over the interlock.loading.

Yes, the executor wrapper seemed like a better approach.

haha, executor.wrap deadlocks if I hit compute -> cloud after login 🤣 ... back to .loading

jrafanie · 2019-01-31T22:59:09Z

@miq-bot rm_label wip

Ok, we fixed the issue @yrudman found. The call to columns_hash hits our ar_virtual modification to load_schema! here, which calls define_virtual_delegate which loads the class here, so for now, we need to protect the columns_hash call too.

jrafanie · 2019-01-31T23:01:49Z

Ok, we fixed the issue @yrudman found. The call to columns_hash hits our ar_virtual modification to load_schema! here, which calls define_virtual_delegate which loads the class here, so for now, we need to protect the columns_hash call too.

I need to circle around to @kbrock and @NickLaMuro regarding the load_schema! monkey patch to see if there's another way to avoid the constantizing dynamically in load_schema!

Fryguy · 2019-02-04T20:53:01Z

@kbrock @NickLaMuro When @jrafanie went through this, we came to the conclusion that vanilla Rails' built-in columns_hash (and thus load_schema) never goes through the autoload process, whereas after ar_virtual is introduced, load_schema is changed to autoload some things. This is sort of the fundamental problem.

Since load_schema happens during the code require process, the const_missing ends up causing a cascading require. In a single-thread this is fine for some reason, but in multi-thread, you end up with a collision which manifests as a circular dep (I don't think it's actually circular but instead a shared "did I see this yet" list shows a class as already loaded - but this all gets really confusing to follow)

kbrock · 2019-02-05T15:59:14Z

Not sure if it was documented elsewhere but...

The issue is with virtual attribute's delegate_attribute.
A delegate defines an attribute based upon an attribute in another model.
So when you are loading one schema, it calls another model's schema_load.
Thus entering race condition.

It is the type_for_attribute [here] that calls load_schema! on another class

kbrock · 2019-02-05T16:22:36Z

load_schema does not happen during the class load. It happens because we class_hash.
The issue is the class_hash in one model is causing a class_hash in another model.

A work around could be for us to explicitly state the type of the attribute delegated. That way loading one class is not dependent upon other classes.

One interesting note, has_one does not load the referencing class.

jrafanie · 2019-02-05T16:38:30Z

Still testing this...

https://bugzilla.redhat.com/show_bug.cgi?id=1671458 Fixes ManageIQ#544 From MartinH's findings in ManageIQ#544, we had one thread at the `cspec[:klass].constantize` line while another thread was trying to run `klass.columns_hash`, causing a `Circular dependency detected while autoloading...` error. I then tried a bunch of things until I found a way to reliably recreate this error: ```ruby require_relative 'config/environment' threads = [] 4.times do threads << Thread.new { Api::Environment.time_attributes } end threads.collect(&:join) ``` I could then run the above script several times in my shell and get the `circular dependency` error most of the time. ``` for x in `seq 1 10`; do; bundle exec ruby test.rb; done ``` With this test in place, I then tried a few solutions: 1) Move the `klass.columns_hash` block into the permit_concurrent_loads block: ``` diff --git a/lib/api/environment.rb b/lib/api/environment.rb index 87b34f99..f4b6554a 100644 --- a/lib/api/environment.rb +++ b/lib/api/environment.rb @@ -22,9 +22,10 @@ module Api # Temporary measure to avoid thread race condition which could lead to a deadlock ActiveSupport::Dependencies.interlock.permit_concurrent_loads do klass = cspec[:klass].constantize - end - klass.columns_hash.each do |name, typeobj| - result << name if %w(date datetime).include?(typeobj.type.to_s) + + klass.columns_hash.each do |name, typeobj| + result << name if %w(date datetime).include?(typeobj.type.to_s) + end end end end ``` This did not fix the `circular dependency` error. Perhaps `permit_concurrent_loads` doesn't handle arbitrarily deep nested autoloads cross threads? 2) I tried Mutex#synchronize and this worked, but I'd rather we work with the interlock provided by rails. ``` diff --git a/lib/api/environment.rb b/lib/api/environment.rb index 87b34f99..f51de73f 100644 --- a/lib/api/environment.rb +++ b/lib/api/environment.rb @@ -1,5 +1,6 @@ module Api class Environment + ONE_AUTOLOADER_LOCK = Mutex.new def self.url_attributes @url_attributes ||= Set.new(%w(href)) end @@ -19,12 +20,13 @@ module Api next if cspec[:klass].blank? klass = nil - # Temporary measure to avoid thread race condition which could lead to a deadlock - ActiveSupport::Dependencies.interlock.permit_concurrent_loads do + # Ensure we're the only thread trying to autoload classes and their columns + ONE_AUTOLOADER_LOCK.synchronize do klass = cspec[:klass].constantize - end - klass.columns_hash.each do |name, typeobj| - result << name if %w(date datetime).include?(typeobj.type.to_s) + + klass.columns_hash.each do |name, typeobj| + result << name if %w(date datetime).include?(typeobj.type.to_s) + end end end end ``` 3) I tried Sync.new with SH and EX locks instead of Mutex and this failed with Thread killed errors. 4) I changed the `permit_concurrent_loads` on the interlock to `loading` and this worked, but Yuri found this caused a deadlock. 5) Use `AS::Dep.interlock.loading` from 4) and move the `columns_hash` call into the `loading` block. This solves the circular dependency and avoids the deadlock encountered in 4). I noticed, `permit_concurrent_loads` calls `yield_shares` with `compatible: [:load])` and that method has this in the source code comment: https://github.com/rails/rails/blob/bb22fe9d4a6102d2a28cb1adfd6fe9d38fc9bb22/activesupport/lib/active_support/concurrency/share_lock.rb#L166-L168 ``` Temporarily give up all held Share locks while executing the supplied block, allowing any +compatible+ exclusive lock request to proceed. ``` Perhaps, since we're loading code, `permit_concurrent_loads` is too permissive of other exclusive lock requests and we really need to ensure nothing else is trying to load.

jrafanie · 2019-02-05T16:54:30Z

It turns out Rails.application.executor.wrap do still deadlocks. Oh well, 🤷‍♂️

One semaphore to exclusively load them all (cherry picked from commit e75c9e0) https://bugzilla.redhat.com/show_bug.cgi?id=1673039

simaishi · 2019-02-06T14:28:47Z

Hammer backport details:

$ git log -1
commit b96fac3780976f91b26f286f14cfc308660b0632
Author: Jason Frey <fryguy9@gmail.com>
Date:   Tue Feb 5 15:33:17 2019 -0500

    Merge pull request #550 from jrafanie/ensure_one_autoloader_thread
    
    One semaphore to exclusively load them all
    
    (cherry picked from commit e75c9e08e7ccfe9dbd5c2b687303b6d981d4fd03)
    
    https://bugzilla.redhat.com/show_bug.cgi?id=1673039

jrafanie mentioned this pull request Jan 28, 2019

Very first request sometimes causes Circular dependency error on ConversionHost #544

Closed

miq-bot added the wip label Jan 28, 2019

skateman approved these changes Jan 29, 2019

View reviewed changes

jrafanie closed this Jan 29, 2019

jrafanie reopened this Jan 29, 2019

jrafanie force-pushed the ensure_one_autoloader_thread branch from 76a2d68 to b96b498 Compare January 30, 2019 17:13

jrafanie changed the title ~~[WIP] One semaphore to load them all~~ [WIP] One semaphore to exclusively load them all Jan 30, 2019

jrafanie force-pushed the ensure_one_autoloader_thread branch from b96b498 to 7605f3e Compare January 31, 2019 16:07

jrafanie changed the title ~~[WIP] One semaphore to exclusively load them all~~ One semaphore to exclusively load them all Jan 31, 2019

miq-bot added gaprindashvili/yes bug and removed wip labels Jan 31, 2019

jrafanie changed the title ~~One semaphore to exclusively load them all~~ [WIP] One semaphore to exclusively load them all Jan 31, 2019

miq-bot added the wip label Jan 31, 2019

jrafanie force-pushed the ensure_one_autoloader_thread branch from 7605f3e to 67a74c5 Compare January 31, 2019 20:23

yrudman reviewed Jan 31, 2019

View reviewed changes

jrafanie commented Jan 31, 2019

View reviewed changes

miq-bot changed the title ~~[WIP] One semaphore to exclusively load them all~~ One semaphore to exclusively load them all Jan 31, 2019

miq-bot removed the wip label Jan 31, 2019

jrafanie force-pushed the ensure_one_autoloader_thread branch from 67a74c5 to f9203f8 Compare February 5, 2019 15:32

jrafanie changed the title ~~One semaphore to exclusively load them all~~ [WIP] One semaphore to exclusively load them all Feb 5, 2019

kbrock mentioned this pull request Feb 5, 2019

Allow virtual_delegate type to be passed in ManageIQ/manageiq#18432

Closed

jrafanie force-pushed the ensure_one_autoloader_thread branch from f9203f8 to 8ea4c9c Compare February 5, 2019 16:53

jrafanie changed the title ~~[WIP] One semaphore to exclusively load them all~~ One semaphore to exclusively load them all Feb 5, 2019

Fryguy merged commit e75c9e0 into ManageIQ:master Feb 5, 2019

Fryguy added this to the Sprint 105 Ending Feb 18, 2019 milestone Feb 5, 2019

Fryguy self-assigned this Feb 5, 2019

simaishi pushed a commit that referenced this pull request Feb 6, 2019

Merge pull request #550 from jrafanie/ensure_one_autoloader_thread

b96fac3

One semaphore to exclusively load them all (cherry picked from commit e75c9e0) https://bugzilla.redhat.com/show_bug.cgi?id=1673039

simaishi added hammer/backported and removed hammer/yes labels Feb 6, 2019

jrafanie mentioned this pull request Sep 21, 2020

Overview of code loading issues leading to errors or deadlocks with long running http(s) requests ManageIQ/manageiq#20576

Closed

jrafanie deleted the ensure_one_autoloader_thread branch June 9, 2021 18:39

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

One semaphore to exclusively load them all #550

One semaphore to exclusively load them all #550

jrafanie commented Jan 28, 2019 •

edited

Loading

jrafanie commented Jan 28, 2019

skateman left a comment

jrafanie commented Jan 30, 2019

skateman commented Jan 31, 2019

jrafanie commented Jan 31, 2019

jrafanie commented Jan 31, 2019

miq-bot commented Jan 31, 2019

yrudman Jan 31, 2019

skateman commented Jan 31, 2019

jrafanie Jan 31, 2019

jrafanie Jan 31, 2019

Fryguy Feb 4, 2019

jrafanie Feb 5, 2019

jrafanie commented Jan 31, 2019

jrafanie commented Jan 31, 2019

Fryguy commented Feb 4, 2019

kbrock commented Feb 5, 2019

kbrock commented Feb 5, 2019

jrafanie commented Feb 5, 2019

jrafanie commented Feb 5, 2019

simaishi commented Feb 6, 2019

One semaphore to exclusively load them all #550

One semaphore to exclusively load them all #550

Conversation

jrafanie commented Jan 28, 2019 • edited Loading

jrafanie commented Jan 28, 2019

skateman left a comment

Choose a reason for hiding this comment

jrafanie commented Jan 30, 2019

skateman commented Jan 31, 2019

jrafanie commented Jan 31, 2019

jrafanie commented Jan 31, 2019

miq-bot commented Jan 31, 2019

yrudman Jan 31, 2019

Choose a reason for hiding this comment

skateman commented Jan 31, 2019

jrafanie Jan 31, 2019

Choose a reason for hiding this comment

jrafanie Jan 31, 2019

Choose a reason for hiding this comment

Fryguy Feb 4, 2019

Choose a reason for hiding this comment

jrafanie Feb 5, 2019

Choose a reason for hiding this comment

jrafanie commented Jan 31, 2019

jrafanie commented Jan 31, 2019

Fryguy commented Feb 4, 2019

kbrock commented Feb 5, 2019

kbrock commented Feb 5, 2019

jrafanie commented Feb 5, 2019

jrafanie commented Feb 5, 2019

simaishi commented Feb 6, 2019

jrafanie commented Jan 28, 2019 •

edited

Loading