reloading much slower after 2.1 upgrade in development mode for a larger code base and about 25 active admin entities

[koenhandekyn]

Expected behavior

We were hoping the release 2 would bring some reload performance improvements in development mode.

Actual behavior

Reload performance (after touching some class in development mode) has become extremely slow. Strange enough enough, initial load is still about the same speed.

Context

• rails 5.2.x
• ruby 2.6.x
• tested on 2 mac's : i5 / 16gb ram

analysis

from the logs it seems that active admin now somehow triggers a multitude of the same class reloads, below just an extract of one request log that appears to trigger class reloading of the same classes multiple times (and the amount of times seems to be increasing per request)

/Users/koen/Personal/allcrux/app/admin/customer.rb:66: warning: already initialized constant BOOTSWATCH_V3
/Users/koen/Personal/allcrux/app/admin/customer.rb:66: warning: previous definition of BOOTSWATCH_V3 was here
/Users/koen/Personal/allcrux/app/admin/user.rb:7: warning: already initialized constant RANKDIR
/Users/koen/Personal/allcrux/app/admin/user.rb:7: warning: previous definition of RANKDIR was here
/Users/koen/Personal/allcrux/app/admin/customer.rb:66: warning: already initialized constant BOOTSWATCH_V3
/Users/koen/Personal/allcrux/app/admin/customer.rb:66: warning: previous definition of BOOTSWATCH_V3 was here
/Users/koen/Personal/allcrux/app/admin/user.rb:7: warning: already initialized constant RANKDIR
/Users/koen/Personal/allcrux/app/admin/user.rb:7: warning: previous definition of RANKDIR was here
/Users/koen/Personal/allcrux/app/admin/customer.rb:66: warning: already initialized constant BOOTSWATCH_V3
/Users/koen/Personal/allcrux/app/admin/customer.rb:66: warning: previous definition of BOOTSWATCH_V3 was here
/Users/koen/Personal/allcrux/app/admin/user.rb:7: warning: already initialized constant RANKDIR
/Users/koen/Personal/allcrux/app/admin/user.rb:7: warning: previous definition of RANKDIR was here
/Users/koen/Personal/allcrux/app/admin/customer.rb:66: warning: already initialized constant BOOTSWATCH_V3
/Users/koen/Personal/allcrux/app/admin/customer.rb:66: warning: previous definition of BOOTSWATCH_V3 was here
/Users/koen/Personal/allcrux/app/admin/user.rb:7: warning: already initialized constant RANKDIR
/Users/koen/Personal/allcrux/app/admin/user.rb:7: warning: previous definition of RANKDIR was here
/Users/koen/Personal/allcrux/app/admin/customer.rb:66: warning: already initialized constant BOOTSWATCH_V3
/Users/koen/Personal/allcrux/app/admin/customer.rb:66: warning: previous definition of BOOTSWATCH_V3 was here
/Users/koen/Personal/allcrux/app/admin/user.rb:7: warning: already initialized constant RANKDIR
/Users/koen/Personal/allcrux/app/admin/user.rb:7: warning: previous definition of RANKDIR was here
...

[deivid-rodriguez]

I'm guessing it's because of #5740, because it's the only change that could be related, although the intention of that change was the complete opposite... 😅.

Can you confirm that the culprit is that PR and also provide a sample application with reproduction steps?

Thanks!

[koenhandekyn]

looks like it might be related indeed :) ! [ something like on every reload an extra reload hook get's added ] i'll try to see if i can provide a fix in a PR early july (leaving for holidays tomorrow) :)

…

On 20 Jun 2019, at 17:31, David Rodríguez ***@***.***> wrote: I'm guessing it's because of #5740 <#5740>, because it's the only change that could be related, although the intention of that change was the complete opposite... 😅. Can you confirm that the culprit is that PR and also provide a sample application with reproduction steps? Thanks! — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#5787?email_source=notifications&email_token=AAFNM5VESN3QIZHMXQHLZWDP3OPGDA5CNFSM4HZVBAPKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODYFYV3I#issuecomment-504072941>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAFNM5QYI6H6ZKKJHXDU7QDP3OPGDANCNFSM4HZVBAPA>.

[gingerlime]

I think I also bumped into this.

In my case, the puma processes got pegged at around 100% cpu when reloading the page (even without going into admin) when switching to another branch with model / admin changes.

I'm trying to zero-in on what precise changes trigger this, but I can reproduce this fairly consistently. Restarting rails resolves the issue, but it can happen frequently that I switch branches and then the whole rails server becomes extremely slow and unresponsive.

(no problems with Active Admin 1.4.3)

[koenhandekyn]

i also have observed this but only in development mode ... in production context it doesn't seem to occur ....

[gingerlime]

Thanks @koenhandekyn. I would imagine it won't affect production, because production loads rails + active admin only once normally. Still makes development extremely inconvenient in some cases.

[deivid-rodriguez]

@jscheid Have you noticed anything? It seems that your changes were counterproductive for performance in development after all? 😬 Do you have any ideas?

@koenhandekyn Did you manage to spend some time on this?

[gingerlime]

Managed to reproduce with:

• start rails app in development and latest ActiveAdmin 2.1.0
• load any page, refresh (everything works fine and things are fast)
• make a small update to the admin class (in my case, I simply added a single field as input to the form)
• refresh the page ... from this point on, everything is super-slow and puma processes are "working hard"

Even if I undo the change and refresh (without reloading rails), it's basically the same

HTH ?

[oskarpearson]

@gedzubo and I have experienced the same issues in the development environment (production is fine).

The problem seems to be the way that the Rails EventedFileUpdateChecker interacts with the code in active_admin/application.rb and the reloader.

From what we can tell after a brief investigation, the @updated variable at https://github.com/rails/rails/blob/c81af6ae723ccfcd601032167d7b7f57c5449c33/activesupport/lib/active_support/evented_file_update_checker.rb#L50 gets set to true on the first load, but then never gets reset to false - which means Rails reloads all code every time. Normally @updated gets set to false in the execute method at https://github.com/rails/rails/blob/c81af6ae723ccfcd601032167d7b7f57c5449c33/activesupport/lib/active_support/evented_file_update_checker.rb#L96

Reverting to ActiveAdmin 2.0.0 has resolved the issue for us. If there's anything further you'd like us to test, please let us know! We'll try pick this up another time.

Thanks!

[jscheid]

@deivid-rodriguez we haven't been able to upgrade our app to 2.1 yet, but I just ran some tests and I can reproduce this. And rolling back the change from #5740 like so (just as a quick test) does seem to fix the issue:

--- application_orig.rb	2019-07-09 10:42:55.000000000 -0600
+++ application.rb	2019-07-09 10:53:13.000000000 -0600
@@ -187,7 +187,7 @@
     # regenerate the routes as well.
     def attach_reloader
       Rails.application.config.after_initialize do |app|
-        ActiveSupport::Reloader.after_class_unload do
+        ActiveSupport::Reloader.to_prepare(prepend: true) do
           ActiveAdmin.application.unload!
         end

More mysteriously, after making this change load! still gets called only once per change to the app, not twice like I had originally measured. I'm not entirely sure yet what's going on and why this backfired so badly, but at the moment it does look like #5740 should be rolled back...

Back when I opened the PR, you were able to reproduce the original issue (#5739), right? I wonder if #5470 interacts in some unexpected way with an unrelated change in AA or in Rails.

[deivid-rodriguez]

Thanks everyone for digging into this, and sorry for the hassle.

Back when I opened the PR, you were able to reproduce the original issue (#5739), right? I wonder if #5470 interacts in some unexpected way with an unrelated change in AA or in Rails.

I think I run the same profiling code you posted and got the same results, yeah, but I'm not sure.

It looks like the consensus is to rollback the change for now, until we know more and better investigate this double loading issue. So I'll be doing that and cutting a new version now.

[deivid-rodriguez]

I tried to reproduce this, but I couldn't. I thought our test application was unlikely to reproduce since it doesn't use listen and the EventedFileUpdateChecker, but still couldn't reproduce after adding those.

I recall something about listen performing better on Linux because the underlying notification library being more efficient, maybe it's related to that?

Anyways, I plan to revert this in #5801 for the time being.

[deivid-rodriguez]

Also, is someone that can reproduce this able to try if it still reproduces on Rails 6?

[mvz]

@deivid-rodriguez I just tried and I can reproduce this on Rails 6.