Skip to content

Introduce Journey::Ast to avoid extra ast walks #39935

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged

Conversation

composerinteralia
Copy link
Member

This commit introduces a new Journey::Ast class that wraps the root
node of an ast. The purpose of this class is to reduce the number of
walks through the ast by consolidating necessary processing of nodes in
a single pass and holding onto values that can be used later.

Benefits

  • Performance improvements (see benchmarks below)
  • Keeps various ast manipulations together in a single class, rather
    than scattered throughout
  • Adding some names to things will hopefully make this code a little
    easier to follow for future readers

Benchmarks

We benchmarked loading a real routes file with > 3500 routes.
master was at a9336a6 when we ran these. Note that these benchmarks
also include a few small changes that we didn't include in this commit,
but that we will follow up with after this gets merged - these
additional changes do not change the benchmarks significantly.

Time:

master      - 0.798 ± 0.024 (500 runs)
this branch - 0.695 ± 0.029 (500 runs)

Allocations:

master      - 980149 total allocated objects
this branch - 931357 total allocated objects

Stackprof:

Seeing ActionDispatch::Journey::Visitors::Each#visit more frequently
on the stack is what led us down this path in the first place. These
changes seem to have done the trick.

master:
  TOTAL    (pct)     SAMPLES    (pct)     FRAME
    52   (0.5%)          52   (0.5%)     ActionDispatch::Journey::Nodes::Node#symbol?
    58   (0.5%)          45   (0.4%)     ActionDispatch::Journey::Scanner#scan
    45   (0.4%)          45   (0.4%)     ActionDispatch::Journey::Nodes::Cat#type
    43   (0.4%)          43   (0.4%)     ActionDispatch::Journey::Visitors::FunctionalVisitor#terminal
    303  (2.7%)          43   (0.4%)     ActionDispatch::Journey::Visitors::Each#visit
    69   (0.6%)          40   (0.4%)     ActionDispatch::Routing::Mapper::Scope#each

this commit:
  TOTAL    (pct)     SAMPLES    (pct)     FRAME
    82   (0.6%)          42   (0.3%)     ActionDispatch::Journey::Scanner#next_token
    31   (0.2%)          31   (0.2%)     ActionDispatch::Journey::Nodes::Node#symbol?
    30   (0.2%)          30   (0.2%)     ActionDispatch::Journey::Nodes::Node#initialize

Co-authored-by: Eric Milford ericmilford@gmail.com

@eugeneius this could use an initial review, if you are interested

@rails-bot rails-bot bot added the actionpack label Jul 27, 2020
@composerinteralia composerinteralia force-pushed the journey-performance-improvements branch from aa21dea to ccabbc0 Compare July 27, 2020 16:13
@eugeneius
Copy link
Member

My initial review:

  • This is really cool. 13% faster! 🏇
  • How did you produce the benchmark results in the description? I'd like to see if I can replicate them on our app at work, which has a similar number of routes.
  • Are these new AST objects needed at runtime, or only while the routes are being defined? If it's the latter, I wonder how much more memory is now retained due to the memoized data. Maybe there's an opportunity to loop through the routes at the end and nil out their ASTs.

I'll take a closer look at the implementation soon.

@eugeneius eugeneius self-assigned this Jul 27, 2020
@composerinteralia
Copy link
Member Author

composerinteralia commented Jul 27, 2020

@eugeneius

How did you produce the benchmark results in the description? I'd like to see if I can replicate them on our app at work, which has a similar number of routes.

I pointed my app to my local Rails and added this to my routes file:

Rails.application.routes.draw do
+  before_object_count = GC.stat[:total_allocated_objects]
+  time = Benchmark.realtime do
    #... all the route definitions
+  end
+  puts GC.stat[:total_allocated_objects] - before_object_count
+  puts time
end

Then ran bin/rails runner true to see the output. The total allocated objects count was pretty consistent, so I didn't feel the need to do multiple runs there.

For the timing I ran this not terribly elegant script, passing the refs I wanted to test out as arguments. You might want to change 500 to something more reasonable - I ran this and then went to bed.

def report(filename, ljust)
  times = File.read("journey_benchmark/#{filename}").lines.map(&:chomp).map(&:to_f)
  median = times.inject(&:+) / times.length
  dev = Math.sqrt((times.map { |time| (time - median)**2 }).inject(&:+) / (times.length - 1))

  puts "#{filename.ljust(ljust)} - #{median.round(3)} ± #{dev.round(3)} (#{times.length} runs)"
end

def run_benchmark(ref)
  puts "Running benchmark for '#{ref}'"

  Dir.chdir("path/to/local/rails") do
    `git checkout #{ref}`
  end

  500.times do 
    `bin/rails runner true | tail -1 >> "journey_benchmark/#{ref}"`
  end
end

Dir.chdir("path/to/application") do
  ARGV.each do |ref|
    run_benchmark(ref)
  end

  ljust = ARGV.map(&:length).max
  ARGV.each do |ref|
    report(ref, ljust)
  end
end

I'm sure there is a better way to do this...

@composerinteralia
Copy link
Member Author

composerinteralia commented Jul 27, 2020

Are these new AST objects needed at runtime, or only while the routes are being defined? If it's the latter, I wonder how much more memory is now retained due to the memoized data. Maybe there's an opportunity to loop through the routes at the end and nil out their ASTs.

Great question. We should try to measure the retained memory. We might not need the ast objects anymore after building the simulator in lib/action_dispatch/journey/routes.rb, but we may have to do something to make clearing them out work with clear_cache!. I will think about it.

@composerinteralia composerinteralia force-pushed the journey-performance-improvements branch from ccabbc0 to 5c8c836 Compare July 27, 2020 21:33
@composerinteralia
Copy link
Member Author

composerinteralia commented Jul 27, 2020

I put this in RouteSet#eager_load! and then eager loaded the routes at the bottom of my routes file.

      def eager_load!
        router.eager_load!
        routes.each(&:eager_load!)
        require 'objspace'
        GC.start
        puts ObjectSpace.each_object(Object).count
        nil
      end
master      - 1141852
this commit - 1159326

Is this a reasonable way to measure what was retained?

Update: if I wipe out the references from within eager_load! this number goes down to 1110148. I'm unsure whether this is actually the right place to do that, but the idea seems generally promising.

@composerinteralia
Copy link
Member Author

composerinteralia commented Jul 28, 2020

Are these new AST objects needed at runtime, or only while the routes are being defined? If it's the latter, I wonder how much more memory is now retained due to the memoized data. Maybe there's an opportunity to loop through the routes at the end and nil out their ASTs.

Once possibility is to clear out the AST objects at the end of RouteSet#eager_load!. This would ensure that we don't retain these extra objects in any environment that eager loads (although we would still retain them in other environments, like the standard dev and test environments). But one concern we have here is whether there is ever a case where somebody would add routes after eager loading. If so, that could be a problem because adding a new route would clear out the ast and simulator, at which point we would not have what we need to rebuild the simulator.

We found two tests that involve creating a simulator and then adding a new route after, but I don't know how realistic these tests are. These two test also don't have anything to do with eager loading.

  • def test_routes_changed_correctly_after_clear
    rs = ::ActionDispatch::Routing::RouteSet.new
    rs.draw do
    get "ca" => "ca#aa"
    get "cb" => "cb#ab"
    get "cc" => "cc#ac"
    ActiveSupport::Deprecation.silence do
    get ":controller/:action/:id"
    get ":controller/:action/:id.:format"
    end
    end
    hash = rs.recognize_path "/cc"
    assert_not_nil hash
    assert_equal %w(cc ac), [hash[:controller], hash[:action]]
    rs.draw do
    get "cb" => "cb#ab"
    get "cc" => "cc#ac"
    ActiveSupport::Deprecation.silence do
    get ":controller/:action/:id"
    get ":controller/:action/:id.:format"
    end
    end
    hash = rs.recognize_path "/cc"
    assert_not_nil hash
    assert_equal %w(cc ac), [hash[:controller], hash[:action]]
    end
    end
  • def test_simulator_changes
    mapper.get "/foo(/:id)", to: "foo#bar", as: "aaron"
    sim = routes.simulator
    mapper.get "/foo(/:id)", to: "foo#bar", as: "gorby"
    assert_not_equal sim, routes.simulator
    end

Update:

After some discussion with Rafael França and Matthew Draper I think we should preserve the ability to add more routes after eager loading. So instead we can clear out all the cached values inside the ast objects after eager loading, then recalculate those values again if necessary.

@casperisfine
Copy link
Contributor

Is this a reasonable way to measure what was retained?

Somewhat yes. But I'd suggest using http://github.com/SamSaffron/memory_profiler for a breakdown of what was retained etc.

@casperisfine
Copy link
Contributor

Profiling this branch against our application full boot sequence.

Baseline is e2cc2d1dfca51d15567671f2634fc28025480c1b (because I had it handy)
Tested commit is: 5c8c8364c361140c89bab88452ac54d231e51ad9
So diff is: e2cc2d1...5c8c836

Most stackprof results will be CPU profiles unless specified otherwise.

First I do see the nice #visit reduction (2.5% -> 1.7%):

$ bundle exec bin/stackprof ~/Downloads/rails-stackprof-cpu-baseline.dump --method='ActionDispatch::Journey::Visitors::Each#visit'
ActionDispatch::Journey::Visitors::Each#visit (/tmp/bundle/ruby/2.7.0/bundler/gems/rails-e2cc2d1dfca5/actionpack/lib/action_dispatch/journey/visitors.rb:160)
  samples:   115 self (0.2%)  /   1284 total (2.5%)
  callers:
    6223  (  484.7%)  ActionDispatch::Journey::Visitors::FunctionalVisitor#binary
    1284  (  100.0%)  ActionDispatch::Journey::Visitors::FunctionalVisitor#accept
     221  (   17.2%)  ActionDispatch::Journey::Visitors::FunctionalVisitor#nary
     167  (   13.0%)  ActionDispatch::Journey::Visitors::FunctionalVisitor#unary
  callees (1169 total):
    6988  (  597.8%)  ActionDispatch::Journey::Visitors::FunctionalVisitor#visit
     289  (   24.7%)  ActionDispatch::Journey::GTG::Builder#build_followpos
     199  (   17.0%)  ActionDispatch::Journey::Nodes::Node#symbol?
     171  (   14.6%)  ActionDispatch::Routing::Mapper::Mapping#initialize
      62  (    5.3%)  ActionDispatch::Journey::Nodes::Node#group?
      35  (    3.0%)  ActionDispatch::Journey::Nodes::Terminal#terminal?
      17  (    1.5%)  ActionDispatch::Journey::Nodes::Node#terminal?
      17  (    1.5%)  ActionDispatch::Journey::Nodes::Symbol#symbol?
       2  (    0.2%)  ActionDispatch::Journey::Nodes::Group#group?
$ bundle exec bin/stackprof ~/Downloads/rails-stackprof-cpu-journey.dump --method='ActionDispatch::Journey::Visitors::Each#visit'
ActionDispatch::Journey::Visitors::Each#visit (/tmp/bundle/ruby/2.7.0/bundler/gems/rails-5c8c8364c361/actionpack/lib/action_dispatch/journey/visitors.rb:160)
  samples:    10 self (0.0%)  /    706 total (1.7%)
  callers:
    3252  (  460.6%)  ActionDispatch::Journey::Visitors::FunctionalVisitor#binary
     706  (  100.0%)  ActionDispatch::Journey::Visitors::FunctionalVisitor#accept
     200  (   28.3%)  ActionDispatch::Journey::Visitors::FunctionalVisitor#nary
      96  (   13.6%)  ActionDispatch::Journey::Visitors::FunctionalVisitor#unary
  callees (696 total):
    3710  (  533.0%)  ActionDispatch::Journey::Visitors::FunctionalVisitor#visit
     250  (   35.9%)  ActionDispatch::Journey::GTG::Builder#build_followpos
     149  (   21.4%)  ActionDispatch::Journey::Ast#initialize
      70  (   10.1%)  ActionDispatch::Journey::Nodes::Node#group?
      58  (    8.3%)  ActionDispatch::Journey::Nodes::Node#symbol?
       4  (    0.6%)  ActionDispatch::Journey::Nodes::Symbol#symbol?
       3  (    0.4%)  ActionDispatch::Journey::Nodes::Group#group?

If I look at Rails::Application::RoutesReloader#reload! it's marginally faster now, but it's definitely called much less:

$ bundle exec bin/stackprof ~/Downloads/rails-stackprof-cpu-baseline.dump --method='Rails::Application::RoutesReloader#reload!'
Rails::Application::RoutesReloader#reload! (/tmp/bundle/ruby/2.7.0/bundler/gems/rails-e2cc2d1dfca5/railties/lib/rails/application/routes_reloader.rb:19)
  samples:     0 self (0.0%)  /   6108 total (11.8%)
  callers:
    6108  (  100.0%)  Rails::Application::RoutesReloader#updater
  callees (6108 total):
    4837  (   79.2%)  Rails::Application::RoutesReloader#load_paths
    1269  (   20.8%)  ActionDispatch::Routing::RouteSet#eager_load!
       2  (    0.0%)  Rails::Application::RoutesReloader#finalize!
$ bundle exec bin/stackprof ~/Downloads/rails-stackprof-cpu-journey.dump --method='Rails::Application::RoutesReloader#reload!'
Rails::Application::RoutesReloader#reload! (/tmp/bundle/ruby/2.7.0/bundler/gems/rails-5c8c8364c361/railties/lib/rails/application/routes_reloader.rb:19)
  samples:     0 self (0.0%)  /   4886 total (11.6%)
  callers:
    4886  (  100.0%)  Rails::Application::RoutesReloader#updater
  callees (4886 total):
    3775  (   77.3%)  Rails::Application::RoutesReloader#load_paths
    1110  (   22.7%)  ActionDispatch::Routing::RouteSet#eager_load!
       1  (    0.0%)  Rails::Application::RoutesReloader#finalize!

On the memory front, I see a slight increase.

The total retention post boot is up by 2.7MB for us (to take with a grain of salt as there are some variance. We're a bit above what I consider to be the margin of error, but not by that much).

On the retentions attributed to journey itself (NB: again these are not perfectly precise, a retention can very easily attributed to the wrong source):

The total allocations during boot is up by about 12800 (again can very well be in the margin of error).

Baseline:
allocated memory by file
-----------------------------------
  33.25 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-e2cc2d1dfca5/actionpack/lib/action_dispatch/routing/mapper.rb
  20.89 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-e2cc2d1dfca5/actionpack/lib/action_dispatch/journey/path/pattern.rb
   9.74 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-e2cc2d1dfca5/actionpack/lib/action_dispatch/journey/gtg/builder.rb
   8.00 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-e2cc2d1dfca5/actionpack/lib/action_dispatch/journey/visitors.rb
   4.61 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-e2cc2d1dfca5/actionpack/lib/action_dispatch/journey/parser.rb
   4.49 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-e2cc2d1dfca5/actionpack/lib/action_dispatch/journey/scanner.rb

retained memory by file
-----------------------------------
   7.89 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-e2cc2d1dfca5/actionpack/lib/action_dispatch/journey/path/pattern.rb
   4.61 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-e2cc2d1dfca5/actionpack/lib/action_dispatch/journey/parser.rb
   4.45 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-e2cc2d1dfca5/actionpack/lib/action_dispatch/routing/mapper.rb
   2.36 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-e2cc2d1dfca5/actionpack/lib/action_dispatch/journey/visitors.rb
   1.84 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-e2cc2d1dfca5/actionpack/lib/action_dispatch/journey/gtg/transition_table.rb
   1.69 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-e2cc2d1dfca5/actionpack/lib/action_dispatch/routing/route_set.rb
   1.11 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-e2cc2d1dfca5/actionpack/lib/action_dispatch/journey/route.rb
 969.32 kB  /tmp/bundle/ruby/2.7.0/gems/graphql-1.10.14/lib/graphql/schema.rb

Patch:
allocated memory by file
-----------------------------------
  32.64 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-5c8c8364c361/actionpack/lib/action_dispatch/routing/mapper.rb
  20.56 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-5c8c8364c361/actionpack/lib/action_dispatch/journey/path/pattern.rb
   9.74 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-5c8c8364c361/actionpack/lib/action_dispatch/journey/gtg/builder.rb
   8.76 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-5c8c8364c361/actionpack/lib/action_dispatch/journey/visitors.rb
   4.89 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-5c8c8364c361/actionpack/lib/action_dispatch/journey/nodes/node.rb
   4.61 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-5c8c8364c361/actionpack/lib/action_dispatch/journey/parser.rb

retained memory by file
-----------------------------------
   7.69 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-5c8c8364c361/actionpack/lib/action_dispatch/journey/path/pattern.rb
   4.89 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-5c8c8364c361/actionpack/lib/action_dispatch/routing/mapper.rb
   4.61 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-5c8c8364c361/actionpack/lib/action_dispatch/journey/parser.rb
   2.48 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-5c8c8364c361/actionpack/lib/action_dispatch/journey/nodes/node.rb
   2.36 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-5c8c8364c361/actionpack/lib/action_dispatch/journey/visitors.rb
   1.84 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-5c8c8364c361/actionpack/lib/action_dispatch/journey/gtg/transition_table.rb
   1.69 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-5c8c8364c361/actionpack/lib/action_dispatch/routing/route_set.rb
   1.11 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-5c8c8364c361/actionpack/lib/action_dispatch/journey/route.rb

So the speedup does indeed seem visible on our app, and the memory increase if any isn't a show stopper.

instead we can clear out all the cached values inside the ast objects after eager loading

Let me know if you'd like me to memory profile that.

@composerinteralia composerinteralia force-pushed the journey-performance-improvements branch from cc13db6 to 45f657e Compare July 29, 2020 18:52
@composerinteralia
Copy link
Member Author

@casperisfine thanks so much for running those profiles. @emilford and I added a commit that will hopefully cut down on the retained memory, and would be most grateful if you could run the profile again with the new commit.

@composerinteralia
Copy link
Member Author

This is what I am seeing:

Before clearing out ast objects in 45f657e

retained memory by file                                                                                                             
-----------------------------------                                                                                                 
   3834102  /Users/daniel/Desktop/oss/rails/rails/actionpack/lib/action_dispatch/journey/path/pattern.rb                            
   3025661  /Users/daniel/Desktop/oss/rails/rails/actionpack/lib/action_dispatch/routing/mapper.rb                                  
   2964176  /Users/daniel/Desktop/oss/rails/rails/actionpack/lib/action_dispatch/journey/parser.rb                                  
   2110720  /Users/daniel/Desktop/oss/rails/rails/actionpack/lib/action_dispatch/routing/route_set.rb                               
   1932016  /Users/daniel/Desktop/oss/rails/rails/actionpack/lib/action_dispatch/journey/nodes/node.rb                              
   1633624  /Users/daniel/Desktop/oss/rails/rails/actionpack/lib/action_dispatch/journey/visitors.rb                                
   1257578  /Users/daniel/Desktop/oss/rails/rails/actionpack/lib/action_dispatch/journey/gtg/transition_table.rb                    
    808310  /Users/daniel/Desktop/oss/rails/rails/actionpack/lib/action_dispatch/journey/route.rb                                   
    230664  /Users/daniel/.asdf/installs/ruby/2.7.1/lib/ruby/2.7.0/set.rb 

After clearing out ast objects in 45f657e

retained memory by file                                                                                                               
-----------------------------------                                                                                                   
   3989742  /Users/daniel/Desktop/oss/rails/rails/actionpack/lib/action_dispatch/journey/path/pattern.rb                              
   2964176  /Users/daniel/Desktop/oss/rails/rails/actionpack/lib/action_dispatch/journey/parser.rb                                    
   2690877  /Users/daniel/Desktop/oss/rails/rails/actionpack/lib/action_dispatch/routing/mapper.rb                                    
   2110720  /Users/daniel/Desktop/oss/rails/rails/actionpack/lib/action_dispatch/routing/route_set.rb                                 
   1633624  /Users/daniel/Desktop/oss/rails/rails/actionpack/lib/action_dispatch/journey/visitors.rb                                  
   1257578  /Users/daniel/Desktop/oss/rails/rails/actionpack/lib/action_dispatch/journey/gtg/transition_table.rb                      
    808310  /Users/daniel/Desktop/oss/rails/rails/actionpack/lib/action_dispatch/journey/route.rb                                     
    230664  /Users/daniel/.asdf/installs/ruby/2.7.1/lib/ruby/2.7.0/set.rb   

Baseline

retained memory by file                                                                                                                                                                                                                                                    
-----------------------------------                                                                                                 
   3834102  /Users/daniel/Desktop/oss/rails/rails/actionpack/lib/action_dispatch/journey/path/pattern.rb                            
   2707037  /Users/daniel/Desktop/oss/rails/rails/actionpack/lib/action_dispatch/routing/mapper.rb                                  
   2110720  /Users/daniel/Desktop/oss/rails/rails/actionpack/lib/action_dispatch/routing/route_set.rb                               
   1633624  /Users/daniel/Desktop/oss/rails/rails/actionpack/lib/action_dispatch/journey/visitors.rb                                
   1557832  /Users/daniel/Desktop/oss/rails/rails/actionpack/lib/action_dispatch/journey/parser.rb                                  
   1257578  /Users/daniel/Desktop/oss/rails/rails/actionpack/lib/action_dispatch/journey/gtg/transition_table.rb                    
    808310  /Users/daniel/Desktop/oss/rails/rails/actionpack/lib/action_dispatch/journey/route.rb                                   
    239200  /Users/daniel/Desktop/oss/rails/rails/actionpack/lib/action_dispatch/journey/nodes/node.rb                              
    230664  /Users/daniel/.asdf/installs/ruby/2.7.1/lib/ruby/2.7.0/set.rb 

We could probably do a little better in path/pattern, except that we have to hold onto the ast root node to make the new test_drawing_more_routes_after_eager_loading test pass. This is a weird test, and I think an unlikely scenario, but it is currently the way things work and we wanted to preserve that for now.

@casperisfine
Copy link
Contributor

$ bundle exec bin/stackprof ~/Downloads/stackprof-shopify-boot-production-cpu\ \(3\).dump  --method='ActionDispatch::Journey::Visitors::Each#visit'
ActionDispatch::Journey::Visitors::Each#visit (/tmp/bundle/ruby/2.7.0/bundler/gems/rails-45f657eca631/actionpack/lib/action_dispatch/journey/visitors.rb:160)
  samples:     8 self (0.0%)  /    824 total (1.6%)
  callers:
    3794  (  460.4%)  ActionDispatch::Journey::Visitors::FunctionalVisitor#binary
     824  (  100.0%)  ActionDispatch::Journey::Visitors::FunctionalVisitor#accept
     240  (   29.1%)  ActionDispatch::Journey::Visitors::FunctionalVisitor#nary
     110  (   13.3%)  ActionDispatch::Journey::Visitors::FunctionalVisitor#unary
  callees (816 total):
    4324  (  529.9%)  ActionDispatch::Journey::Visitors::FunctionalVisitor#visit
     302  (   37.0%)  ActionDispatch::Journey::GTG::Builder#build_followpos
     202  (   24.8%)  ActionDispatch::Journey::Ast#initialize
      71  (    8.7%)  ActionDispatch::Journey::Nodes::Node#symbol?
      53  (    6.5%)  ActionDispatch::Journey::Nodes::Node#group?
       6  (    0.7%)  ActionDispatch::Journey::Nodes::Symbol#symbol?
       2  (    0.2%)  ActionDispatch::Journey::Nodes::Group#group?
$ bundle exec bin/stackprof ~/Downloads/stackprof-shopify-boot-production-cpu\ \(3\).dump --method='Rails::Application::RoutesReloader#reload!'
Rails::Application::RoutesReloader#reload! (/tmp/bundle/ruby/2.7.0/bundler/gems/rails-45f657eca631/railties/lib/rails/application/routes_reloader.rb:19)
  samples:     0 self (0.0%)  /   5651 total (11.0%)
  callers:
    5651  (  100.0%)  Rails::Application::RoutesReloader#updater
  callees (5651 total):
    4418  (   78.2%)  Rails::Application::RoutesReloader#load_paths
    1231  (   21.8%)  ActionDispatch::Routing::RouteSet#eager_load!
       2  (    0.0%)  Rails::Application::RoutesReloader#finalize!

Total memory retention is now down by about 2MB (compared to the previous baseline).

retained memory by file
-----------------------------------
   7.69 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-45f657eca631/actionpack/lib/action_dispatch/journey/path/pattern.rb
   4.46 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-45f657eca631/actionpack/lib/action_dispatch/routing/mapper.rb
   2.37 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-45f657eca631/actionpack/lib/action_dispatch/journey/parser.rb
   2.36 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-45f657eca631/actionpack/lib/action_dispatch/journey/visitors.rb
   1.84 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-45f657eca631/actionpack/lib/action_dispatch/journey/gtg/transition_table.rb
   1.68 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-45f657eca631/actionpack/lib/action_dispatch/routing/route_set.rb
   1.11 MB  /tmp/bundle/ruby/2.7.0/bundler/gems/rails-45f657eca631/actionpack/lib/action_dispatch/journey/route.rb

So that looks very good from my end.

@composerinteralia
Copy link
Member Author

composerinteralia commented Jul 30, 2020

Tests added and all the numbers seem to be looking pretty good. This is ready for another review when somebody has a chance.

if node.terminal?
terminals << node
end
end
Copy link
Member

@eileencodes eileencodes Aug 3, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This feels like a lot for initialize - what do you think about pulling the tree iteration out into a private method and then calling that from initialize?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, that makes sense to me. Thanks!

@composerinteralia composerinteralia force-pushed the journey-performance-improvements branch from 7843c50 to f984804 Compare August 4, 2020 13:59
@composerinteralia composerinteralia force-pushed the journey-performance-improvements branch from f984804 to 56e3e85 Compare August 19, 2020 17:23
@composerinteralia
Copy link
Member Author

@tenderlove I would be interested in getting your thoughts on this PR at some point as well (no rush). The tl;dr for the benchmarks is that this seems to be a positive change for shopify and github/github.

Base automatically changed from master to main January 14, 2021 17:01
@rails-bot
Copy link

rails-bot bot commented Apr 14, 2021

This pull request has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs.
Thank you for your contributions.

@rails-bot rails-bot bot added the stale label Apr 14, 2021
@composerinteralia
Copy link
Member Author

@eileencodes @jhawthorn this is something @emilford and I had worked on to improve boot time for GitHub. If this is something you are still interested in I'd be happy to revive this PR, otherwise I'll go ahead and close it.

@casperisfine
Copy link
Contributor

@composerinteralia I'll be happy to merge it.

@rails-bot rails-bot bot removed the stale label Apr 20, 2021
@rails-bot
Copy link

rails-bot bot commented Jul 19, 2021

This pull request has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs.
Thank you for your contributions.

@rails-bot rails-bot bot added the stale label Jul 19, 2021
@rails-bot rails-bot bot closed this Jul 26, 2021
@eileencodes eileencodes reopened this Jul 26, 2021
@rails-bot rails-bot bot removed the stale label Jul 26, 2021
@eileencodes
Copy link
Member

@composerinteralia do you want to pick this up again? There were some changes to journey so it'll need a rebase and possible a new benchmark/profile.

@composerinteralia
Copy link
Member Author

Oh right, I forgot about this. I'd planned on working on it a few months ago, but got distracted by an unexpected job search. Yeah, I should be able to get to it in the next couple weeks.

@composerinteralia composerinteralia force-pushed the journey-performance-improvements branch 2 times, most recently from 2242d7c to bf86dac Compare July 27, 2021 19:48
@composerinteralia
Copy link
Member Author

composerinteralia commented Jul 27, 2021

Rebased and reworked a little to take #41024 into consideration. I also wrote a cleaner benchmark to show that drawing routes is a bit faster with this PR:

Before:

Warming up --------------------------------------
drawing a simple route
                       435.000  i/100ms
drawing a complex route
                       306.000  i/100ms
Calculating -------------------------------------
drawing a simple route
                          4.067k (± 9.7%) i/s -     20.445k in   5.074692s
drawing a complex route
                          2.852k (± 6.2%) i/s -     14.382k in   5.063012s

After:

Warming up --------------------------------------
drawing a simple route
                       517.000  i/100ms
drawing a complex route
                       393.000  i/100ms
Calculating -------------------------------------
drawing a simple route
                          4.725k (± 6.2%) i/s -     23.782k in   5.052018s
drawing a complex route
                          3.532k (± 5.0%) i/s -     17.685k in   5.019272s
Benchmark
# frozen_string_literal: true

require "bundler/inline"

gemfile(true) do
  source "https://rubygems.org"

  git_source(:github) { |repo| "https://github.com/#{repo}.git" }

  gem "rails", path: "/Users/composerinteralia/code/rails/rails"
  gem "benchmark-ips"
  gem "stackprof"
  gem "memory_profiler"
end

require "action_controller"

class FooController < ActionController::Base; end

result = Benchmark.ips do |x|
  x.report("drawing a simple route") {
    rs_simple = ActionDispatch::Routing::RouteSet.new
    rs_simple.draw do
      get "/path", to: "controller#action"
    end
    rs_simple.eager_load!
  }

  x.report("drawing a complex route") {
    rs_simple = ActionDispatch::Routing::RouteSet.new
    rs_simple.draw do
      get "/path/(optional)/:symbol/with-:constraint/*glob", constraints: { constraint: /[abc]+/}, to: "controller#action"
    end
    rs_simple.eager_load!
  }
end

@composerinteralia
Copy link
Member Author

This CI failures don't look obviously related. Are there any known problems at the moment, or do I need to do some digging?

@byroot
Copy link
Member

byroot commented Jul 27, 2021

Are there any known problems at the moment, or do I need to do some digging?

Most of the failures are ruby-head. We just passed midnight UTC so we got a new version, some upstream change must have broken the suite, I'll likely have a look.

And yeah the one Ruby 3.0 postgres failure is clearly unrelated.

@byroot
Copy link
Member

byroot commented Jul 27, 2021

Ah most of these I already fixed with bbaf40b, a few remaining ones in Active Record will need some extra work.

@composerinteralia composerinteralia force-pushed the journey-performance-improvements branch from bf86dac to 2369b1e Compare July 27, 2021 22:35
@casperisfine
Copy link
Contributor

So I tested this against our app again. Not sure if intended, and we can probably update our code, but it does break one test:

NoMethodError: undefined method `names' for #<ActionDispatch::Journey::Nodes::Cat:0x00007f03518f1870 @left=#<ActionDispatch::Journey::Ast:0x00007f...

As for boot performance, ActionDispatch::Journey::Visitors::Each#visit is down from 2.3% to 1.1%, and Rails::Application::RoutesReloader#reload! is down from 6.3% to 4.3%.

As for memory, heap-profiler is reporting a 2MiB increase overall, but again it's not necessarily significant.

So 👍 from my end, but maybe have a look at that NoMethodError, maybe it's private API, in which case it's on us to update.

Other than that, I'm still happy to merge, you'll just have to squash your commits into one.

@composerinteralia
Copy link
Member Author

Thank you for doing that! Are you able to look into that NoMethodError a bit more, or provide more of the stack trace? Seems like there is a Journey::Path::Pattern getting initialized with a CAT node wrapping the AST, instead of the AST directly. I'm not sure how that would happen.

@rafaelfranca
Copy link
Member

We have some monkey patch in the routing code that is creating the ActionDispatch::Journey::Nodes::Cat object directly. This is the code:

        def concat_paths(prefix, suffix)
          joined_ast = ActionDispatch::Journey::Nodes::Cat.new(prefix.ast, suffix.ast)
          prefix_sep = prefix.instance_variable_get(:@separators).split
          suffix_sep = suffix.instance_variable_get(:@separators).split
          build_pattern(
            joined_ast,
            prefix.requirements.merge(suffix.requirements),
            (prefix_sep + suffix_sep).uniq,
            prefix.anchored,
          )
        end

We should just fix that.

This commit introduces a new `Journey::Ast` class that wraps the root
node of an ast. The purpose of this class is to reduce the number of
walks through the ast by taking a single pass through each node and
caching values for later use.

To avoid retaining additional memory, we clear out these ast objects
after eager loading.

Benefits
---

* Performance improvements (see benchmarks below)
* Keeps various ast manipulations together in a single class, rather
  than scattered throughout
* Adding some names to things will hopefully make this code a little
  easier to follow for future readers

Benchmarks
---

We benchmarked loading a real routes file with > 3500 routes.
master was at a9336a6 when we ran these. Note that these benchmarks
also include a few small changes that we didn't include in this commit,
but that we will follow up with after this gets merged - these
additional changes do not change the benchmarks significantly.

Time:

```
master      - 0.798 ± 0.024 (500 runs)
this branch - 0.695 ± 0.029 (500 runs)
```

Allocations:

```
master      - 980149 total allocated objects
this branch - 931357 total allocated objects
```

Stackprof:

Seeing `ActionDispatch::Journey::Visitors::Each#visit` more frequently
on the stack is what led us down this path in the first place. These
changes seem to have done the trick.

```
master:
  TOTAL    (pct)     SAMPLES    (pct)     FRAME
    52   (0.5%)          52   (0.5%)     ActionDispatch::Journey::Nodes::Node#symbol?
    58   (0.5%)          45   (0.4%)     ActionDispatch::Journey::Scanner#scan
    45   (0.4%)          45   (0.4%)     ActionDispatch::Journey::Nodes::Cat#type
    43   (0.4%)          43   (0.4%)     ActionDispatch::Journey::Visitors::FunctionalVisitor#terminal
    303  (2.7%)          43   (0.4%)     ActionDispatch::Journey::Visitors::Each#visit
    69   (0.6%)          40   (0.4%)     ActionDispatch::Routing::Mapper::Scope#each

this commit:
  TOTAL    (pct)     SAMPLES    (pct)     FRAME
    82   (0.6%)          42   (0.3%)     ActionDispatch::Journey::Scanner#next_token
    31   (0.2%)          31   (0.2%)     ActionDispatch::Journey::Nodes::Node#symbol?
    30   (0.2%)          30   (0.2%)     ActionDispatch::Journey::Nodes::Node#initialize
```

See also the benchmark script in rails#39935 (comment)

Co-authored-by: Eric Milford <ericmilford@gmail.com>
@composerinteralia composerinteralia force-pushed the journey-performance-improvements branch from 2369b1e to f353057 Compare July 29, 2021 20:38
Copy link
Contributor

@kaspth kaspth left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Quite the Journey on this PR! Glad we're doing less walking around these trees, an Astute find!

@rafaelfranca rafaelfranca merged commit a41f810 into rails:main Jul 29, 2021
@composerinteralia composerinteralia deleted the journey-performance-improvements branch July 29, 2021 22:42
end

@spec
@ast = nil
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we need to set the @ast to nil? We have code that get two patterns and join then and I can't find a way to made that code work if we don't have the original ast anymore.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not to say that this breaks other methods in this object, so the object will be in an invalid state after eager load.

Copy link
Member

@rafaelfranca rafaelfranca Aug 12, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If the reason to not keep the @ast is to avoid to keep the arrays that are stored in the Ast object, we could keep the ast.tree like it was being done before.

diff --git a/actionpack/lib/action_dispatch/journey/path/pattern.rb b/actionpack/lib/action_dispatch/journey/path/pattern.rb
index 4cd862f791..41a04fdcc0 100644
--- a/actionpack/lib/action_dispatch/journey/path/pattern.rb
+++ b/actionpack/lib/action_dispatch/journey/path/pattern.rb
@@ -4,11 +4,11 @@ module ActionDispatch
   module Journey # :nodoc:
     module Path # :nodoc:
       class Pattern # :nodoc:
-        attr_reader :ast, :names, :requirements, :anchored
-        alias :spec :ast
+        attr_reader :ast, :names, :requirements, :anchored, :spec
 
         def initialize(ast, requirements, separators, anchored)
           @ast          = ast
+          @spec         = ast.tree
           @requirements = requirements
           @separators   = separators
           @anchored     = anchored

@composerinteralia what do you think?

requirements_anchored would still be broken after eager loading though, but we could probably cache that method before removing the @ast.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I added the line to clear out the Ast objects after eager load in response to concerns about increasing retained memory. I was aware this would break some methods, but those methods are not public api and not called after eager load so I thought it would be OK.

Bringing back the original behavior of spec to return the root Node rather than an Ast makes sense to me. That way we can clear out the Ast and still be able to return the root node. I've opened #43006 to do that, as well as clean up a few other small details.

I'm not sure we need to cache requirements_anchored, unless there's a use case for calling that after eager_load. We use it to partition the route, which only happens when first adding the route.

rafaelfranca pushed a commit that referenced this pull request Aug 12, 2021
#39935 changed the behavior of
`Path::Pattern#spec` and `Route#ast` to return an `Ast` rather than the
root `Node`. After eager loading, however, we clear out the `Ast` to
limit retained memory and these methods return `nil`.

While these methods are not public and they aren't used internally after
eager loading, having them return `nil` makes it difficult for
applications that had been using these methods to get access to the
root `Node`.

This commit restores the behavior of these two methods to return the
root `Node`. The `Ast` is still available via `Path::Pattern#ast`, and
we still clear it out after eager loading.

Now that spec is a `Node` and not an `Ast` masquerading as one, we can
get rid of the delegate methods on `Ast.

Since `Route#ast` now returns the root `Node`, the newly added
`Route#ast_root` is no longer necessary so I've removed it.

I also removed the unused `@decorated_ast` method, which should have
been removed in #39935.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

7 participants