Slow app boot when trying to observe ActiveRecord::Base

[joakimk]

If you observe ActiveRecord::Base in order to do something if any model is changed there is some bug in how the observers lists are created causing the app boot to take a long time when eager loading code.

In our case we had an observer that removed comments if a model was destroyed and it had associated comments.

I've reproduced the issue here: https://github.com/barsoom/reproduce_observer_error

We don't use observers in any apps anymore, but thought I'd post this in case someone else had the same issue.

[henrik]

Just as Google food: in our case, we (I'm on the same team as @joakimk) noticed this as Resque workers taking a long time to boot (several minutes) after upgrading from Rails 3 to Rails 4 and switching to rails-observers.

[anthonyjsmith]

The list of observed models seems to grow exponentially, containing each model many times (duplicates). It is apparently solved by putting models.uniq! in Observing.observe(*models). I'll try to put a fix together...

[henrik]

👍

[henrik]

@anthonyjsmith Do you consider this issue solved? Just wondering if we can remove https://github.com/barsoom/reproduce_observer_error.

[anthonyjsmith]

It's been a few years, and I'm not working with Rails any more, so my memory is a bit hazy, but yes, I consider it solved.

[anthonyjsmith]

... although the pull request seems to still be open, so maybe it isn't fully solved yet...? #36

[cjbottaro]

Definitely not resolved yet, it takes us like 20 seconds to load each constant. Stack trace is always in this code:

 0: /Users/cjbottaro/.gem/ruby/2.3.3/gems/activesupport-5.1.6/lib/active_support/core_ext/regexp.rb:7:in `match?'
 1: /Users/cjbottaro/.gem/ruby/2.3.3/gems/activerecord-5.1.6/lib/active_record/dynamic_matchers.rb:33:in `block in match'
 2: /Users/cjbottaro/.gem/ruby/2.3.3/gems/activerecord-5.1.6/lib/active_record/dynamic_matchers.rb:33:in `each'
 3: /Users/cjbottaro/.gem/ruby/2.3.3/gems/activerecord-5.1.6/lib/active_record/dynamic_matchers.rb:33:in `find'
 4: /Users/cjbottaro/.gem/ruby/2.3.3/gems/activerecord-5.1.6/lib/active_record/dynamic_matchers.rb:33:in `match'
 5: /Users/cjbottaro/.gem/ruby/2.3.3/gems/activerecord-5.1.6/lib/active_record/dynamic_matchers.rb:8:in `respond_to_missing?'
 6: /Users/cjbottaro/.gem/ruby/2.3.3/gems/rails-observers-0.1.5/lib/rails/observers/active_model/observing.rb:309:in `respond_to?'
 7: /Users/cjbottaro/.gem/ruby/2.3.3/gems/rails-observers-0.1.5/lib/rails/observers/active_model/observing.rb:309:in `block in observe'
 8: /Users/cjbottaro/.gem/ruby/2.3.3/gems/rails-observers-0.1.5/lib/rails/observers/active_model/observing.rb:309:in `collect!'
 9: /Users/cjbottaro/.gem/ruby/2.3.3/gems/rails-observers-0.1.5/lib/rails/observers/active_model/observing.rb:309:in `observe'
10: /Users/cjbottaro/.gem/ruby/2.3.3/gems/rails-observers-0.1.5/lib/rails/observers/active_model/observing.rb:358:in `observed_class_inherited'
11: /Users/cjbottaro/.gem/ruby/2.3.3/gems/rails-observers-0.1.5/lib/rails/observers/active_model/observing.rb:352:in `update'
12: /Users/cjbottaro/.gem/ruby/2.3.3/gems/rails-observers-0.1.5/lib/rails/observers/active_model/observing.rb:147:in `block in notify_observers'
13: /Users/cjbottaro/.gem/ruby/2.3.3/gems/rails-observers-0.1.5/lib/rails/observers/active_model/observing.rb:147:in `each'
14: /Users/cjbottaro/.gem/ruby/2.3.3/gems/rails-observers-0.1.5/lib/rails/observers/active_model/observing.rb:147:in `notify_observers'
15: /Users/cjbottaro/.gem/ruby/2.3.3/gems/rails-observers-0.1.5/lib/rails/observers/active_model/observing.rb:199:in `inherited'