mariusandra/slow-rails-reload-development.md

## slow-rails-reload-development.md

      
    Raw
  

              slow-rails-reload-development.md
            
          
    This is a draft of an issue I intend to post on the rails/rails repo.
Update: the issue is posted
Hello,
TL;DR; My fairly large Rails app (173 models, 208 controllers) is suffering from a continuously increasing slowdown that makes it hard to work on it. Each reload of the code takes longer than the previous one, with delays increasing to minutes after just a few reloads. I have identified a cause and it's also present on new apps (rails new leaky). No solution yet.
For the past years I've been coping with an issue that Rails feels extremely slow when developing. I start the server, wait for it to boot up and open the site. It takes a minute or two before it loads.
Then I have to make a change to a controller, model or other .rb file and hit reload in the browser. It takes some seconds and the changed page opens just fine. However after each following change, the reload takes longer and longer. After a few rounds, it's faster to restart the server than to wait for Rails to reload the code. I'm often waiting minutes before anything shows up again.
At first I thought the issue has something to do with activeadmin, a properly slow gem in its own right. Since it always takes forever to reload if I make any change in the admin area, I thought the increasing slowness was just part of the package and I tolerated it for longer than I should have. Lately though it got so unbearable that I needed to find a solution.
So I started profiling. Opening on page in admin from a cold boot, I get this beautiful firegraph:

(using rack-mini-profiler with ?pp=flamegraph&flamegraph_sample_rate=20).
I guess this is a relatively normal startup. I need to see if I can somehow cache sprockets and check why is Thor still there, but other than that the app loads nicely.
Let's hit reload:

The graph follows the same shape as the previous one, just the part with sprockets is much smaller.
So far so good. Now let's make a change in a .rb file and then hit reload:

It takes a while for the page to load. Well over 30 seconds. That's because ActiveAdmin needs to re-load all 100 or so pages just to draw a menu and generate all the paths. Oh well. However that's not the issue here.
The issue is that this part starts to get longer:

.. and longer:

.. and even longer:

.. and after about 6 reloads (I skipped a few images), it's half the size of the ActiveAdmin reload time...

After 10+ reloads I will be waiting minutes before anything opens. That's enough time to check HN and forget what you were doing.
So who is this culprit? It's this guy: ActionDispatch::Routing::RouteSet::NamedRouteCollection#clear!
The full stacktrace is here.
        def clear!
          @path_helpers.each do |helper|
            @path_helpers_module.send :remove_method, helper
          end

          @url_helpers.each do |helper|
            @url_helpers_module.send  :remove_method, helper
          end

          @routes.clear
          @path_helpers.clear
          @url_helpers.clear
        end
Huh. It takes an increasingly longer time to clear path helpers?
As far as I know, path and url helpers are modules, which are automatically included in all controllers and views. To get *_path methods into other classes (e.g. models), one should add include Rails.application.routes.url_helpers to the class.
So it's taking longer and longer to remove the *_path and *_url methods from @path_helpers_module.
Does this mean that this module is included in more and more classes, which don't get garbage collected? Let's find out.
Throwing caution to the wind, I opened and edited the route_set.rb file in the gem's folder and added some debug code.
First just to measure what gets slower (it's the @*_helpers.each blocks, not the .clear calls)
!! @path_helpers.remove_method(@url_helpers.each) in 0.1322 sec
!! @url_helpers_module.remove_method(@url_helpers.each) in 0.1383 sec
!! @routes.clear in 0.0 sec
!! @path_helpers.clear in 0.0 sec
!! @url_helpers.clear in 0.0 sec

# next times:
!! @path_helpers.remove_method(@url_helpers.each) in 0.2533 sec
!! @path_helpers.remove_method(@url_helpers.each) in 0.3978 sec
... etc

Then to measure if there are just more @path_helpers and @url_helpers. Nope, their number remains constant:
!! @path_helpers.count == 822
!! @path_helpers.remove_method(@url_helpers.each) in 0.1371 sec

!! @path_helpers.count == 822
!! @path_helpers.remove_method(@url_helpers.each) in 0.2666 sec

So it must be that the module is included in an ever increasing number of classes:
ObjectSpace.each_object(Object).select{|o| o.class.ancestors.include?(@url_helpers_module) }.count

=> 275 # first time
=> 474 # second...
=> 602

Bingo!
It appears that on each reload, Rails reloads new versions all the classes, yet doesn't dispose of the old versions.
Who are all these classes?
 > ObjectSpace.each_object(Object).select{|o| o.class.ancestors.include?(@url_helpers_module) }.map { |o| o.class.to_s }.sort.join(' ')
=> "#<Class:0x00007fda669591b8> ... cut for brevity ... #<Class:0x00007fda85692668> #<Class:0x00007fda85711f08> #<Class:0x00007fda857b5d88> Admin::RequestsController Admin::RequestsController"
Every reload adds a bunch of classes that look like this: #<#<Class:0x00007fda668c8d48>:0x00007fda668c3690 @_routes=#<ActionDispatch::Routing::RouteSet:0x00007fda8015ad08>> and one controller of the page I'm accessing (Admin::RequestsController).
Digging around, it seems that those classes are instances of this proxy class that's created when you call Rails.application.routes.url_helpers.
So it seems something still holds a reference to the controllers from previous requests... and all those proxy url helper modules that are included in so many places.
I installed the ruby-mass gem in the hopes of figuring it out. Unfortunately I didn't get far. I couldn't find if there was any gem that for whichever reason kept references to the old classes.
So I decided to see if I could replicate the issue with a smaller app. I didn't have to look far.
Just a simple rails new bla, rails g model something, rake db:migrate, rails g controller something was enough to replicate this.
Hacking route_set.rb and adding these lines:
 count = ObjectSpace.each_object(Object).select{|o| o.class.ancestors.include?(@url_helpers_module) }.count
 classes = ObjectSpace.each_object(Object).select{|o| o.class.ancestors.include?(@url_helpers_module) }.map { |o| o.class.to_s }.sort.select { |i| !i.include?('#') }
 puts count
 p classes

gives the following ouptut, after making a small change in something_controller.rb and hitting reload:
# no reload
1
[]
!! @url_helpers.count == 12
!! @url_helpers_module.remove_method(@url_helpers.each) in 0.0001 sec

# after the first reload
5
["SomethingController"]
!! @url_helpers.count == 12
!! @url_helpers_module.remove_method(@url_helpers.each) in 0.0 sec

# second reload
9
["SomethingController", "SomethingController"]
!! @url_helpers.count == 12
!! @url_helpers_module.remove_method(@url_helpers.each) in 0.0001 sec

# third reload
13
["SomethingController", "SomethingController", "SomethingController"]
!! @url_helpers.count == 12
!! @url_helpers_module.remove_method(@url_helpers.each) in 0.0001 sec

# fourth reload
17
["SomethingController", "SomethingController", "SomethingController", "SomethingController"]
!! @url_helpers.count == 12
!! @url_helpers_module.remove_method(@url_helpers.each) in 0.0001 sec
The number of classes, from which the path helpers need to be cleared from, keeps increasing by 4 per reload. In an app as small as this, you don't notice it. However if it keeps increasing by an extra 200 classes each reload, it becomes a problem.
Let's select all the SomethingControllers and see who has references to them:
cs = ObjectSpace.each_object(Object).select{ |o| o.class.ancestors.include?(@url_helpers_module) }.select { |o| !o.class.to_s.include?('#') }
cs.map(&:to_s)
=> ["#<SomethingController:0x00007f93d15ad630>", "#<SomethingController:0x00007f93d15d65d0>", "#<SomethingController:0x00007f93d160e520>"]

ids = cs.map { |c| Mass.references(c) }.map{ |k| k.keys }.flatten.select { |k| k !~ /Pry/ }.map{ |k| k.split('#').last.to_i }
=> ["ActionDispatch::Request#70136424506820",
 "ActionDispatch::Request#70136424506980",
 "ActionDispatch::Request#70136424869360",
 "ActionDispatch::Request#70136424572740",
 "ActionDispatch::Request#70136424572900",
 "ActionDispatch::Request#70136430985940",
 "ActionDispatch::Request#70136424704460",
 "ActionDispatch::Request#70136424704620",
 "ActionDispatch::Request#70136424801680"]
The SomethingControllers are only referenced by some ActionDispatch::Requests that are hanging around.
Looking at who is referencing those requests:
ids.map { |id| [id,Mass.references(Mass[id])] }.to_h
=> {70136424506820=>{"SomethingController#70136424655640"=>["@_request"], "ActionDispatch::Response#70136424655900"=>["@request"], "ActionDispatch::Http::Headers#70136424674980"=>["@req"]},
 70136424506980=>{"ActionDispatch::Request::Session#70136424506960"=>["@req"], "ActionDispatch::Cookies::CookieJar#70136424672740"=>["@request"]},
 70136424869360=>{"ActionDispatch::RemoteIp::GetIp#70136424869340"=>["@req"]},
 
 70136424572740=>{"ActionDispatch::Http::Headers#70136424736180"=>["@req"], "SomethingController#70136424739560"=>["@_request"], "ActionDispatch::Response#70136424739820"=>["@request"]},
 70136424572900=>{"ActionDispatch::Request::Session#70136424572880"=>["@req"], "ActionDispatch::Cookies::CookieJar#70136424758900"=>["@request"]},
 70136430985940=>{"ActionDispatch::RemoteIp::GetIp#70136430985920"=>["@req"]},
 
 70136424704460=>{"ActionDispatch::Http::Headers#70136424850800"=>["@req"], "SomethingController#70136424854160"=>["@_request"], "ActionDispatch::Response#70136424854420"=>["@request"]},
 70136424704620=>{"ActionDispatch::Request::Session#70136424704600"=>["@req"], "ActionDispatch::Cookies::CookieJar#70136424873540"=>["@request"]},
 70136424801680=>{"ActionDispatch::RemoteIp::GetIp#70136424801660"=>["@req"]}}
I investigated all of them in depth (via Mass.references) and couldn't find any top node that held a reference to any object from all the 3 different requests. The objects from each request however seem to have slightly cyclical relationships (e.g. a request holds a session, a session holds an env, the env holds the session and the request... or something like that). I'm not sure if this changes anything - they could and should be removed in bulk after a reload.
Starting the GC manually does nothing.
And now I'm stuck.
Does anyone have an idea what is happening, if it's perhaps a feature not a bug, and how can I fix this so that my reload times go back to around 30 seconds? 😄
Thanks for reading! 🍻