Skip to content
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

Reduce String allocations in ActionController::Parameters#permitted_scal... #19037

Conversation

tgxworld
Copy link
Contributor

...ar_filter.

Script used: https://github.com/eileencodes/integration_performance_test/blob/master/test/integration/documents_allocations_create_test.rb.

Before:

[["rails/actionpack/lib/action_controller/metal/strong_parameters.rb", 540, :T_STRING], [52820, 0, 52406, 0, 2, 5676390]]
[["rails/actionpack/lib/action_controller/metal/strong_parameters.rb", 540, :T_NODE], [17448, 0, 17318, 0, 2, 675600]]
[["rails/actionpack/lib/action_controller/metal/strong_parameters.rb", 540, :T_ARRAY], [17448, 0, 17321, 0, 2, 675600]]
[["rails/actionpack/lib/action_controller/metal/strong_parameters.rb", 540, :T_REGEXP], [5816, 0, 5774, 0, 2, 3777730]]

After:

[["rails/actionpack/lib/action_controller/metal/strong_parameters.rb", 543, :T_NODE], [18006, 0, 17503, 0, 2, 696240]]
[["rails/actionpack/lib/action_controller/metal/strong_parameters.rb", 543, :T_ARRAY], [12004, 0, 11670, 0, 2, 464160]]

cc/ @eileencodes @tenderlove

@@ -537,7 +537,10 @@ def permitted_scalar_filter(params, key)
params[key] = self[key]
end

keys.grep(/\A#{Regexp.escape(key)}\(\d+[if]?\)\z/) do |k|
@@permitted_scalar_filter_regexps ||= {}
@@permitted_scalar_filter_regexps[key] ||= /\A#{Regexp.escape(key)}\(\d+[if]?\)\z/
Copy link
Contributor Author

Choose a reason for hiding this comment

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

Not sure if there is a better way to memoize this, I'm open to suggestions.

Copy link
Contributor

Choose a reason for hiding this comment

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

Won't storing it in a class variable make Parameters unsafe for multiple threads?

@kaspth
Copy link
Contributor

kaspth commented Feb 23, 2015

I can never understand the output of allocation_tracer. Does this mean we're allocating 52000 less strings and 5800 less regexes?

What kind of a performance boost does these reduced allocations give us? 😄

@eileencodes
Copy link
Member

@tgxworld can you post the top 5 for after no just the ones still related to strong_parameters. Can you additionally run the StackProf and tell us what the garbage collection was before and after your change? Sometimes the allocation tracer isn't correct. If you run it a couple more times the number of allocations can change drastically.

@kaspth this is showing that the allocations to the regex and string are no longer in the top 5 allocations. This doesn't have performance gains as much as we are trying to reduce the amount of time that integration tests spend in the garbage collector. Previously we were spending 13% of our time there.

@kaspth
Copy link
Contributor

kaspth commented Feb 23, 2015

@eileencodes Got it 👍

@tgxworld
Copy link
Contributor Author

@eileencodes

Before top 5 allocations:

[[".rbenv/versions/2.2.0/lib/ruby/2.2.0/uri/common.rb", 383, :T_STRING], [113913, 334, 111786, 0, 27, 6033310]]
[["rack/lib/rack/utils.rb", 87, :T_STRING], [111143, 55, 105505, 0, 27, 12658416]]
[["rails-dev-box/rails/activerecord/lib/active_record/connection_adapters/sqlite3_adapter.rb", 243, :T_STRING], [59948, 2, 56564, 0, 29, 2319440]]
[["rails-dev-box/rails/actionpack/lib/action_controller/metal/strong_parameters.rb", 540, :T_STRING], [54566, 0, 51441, 0, 2, 5854976]]
[["rails-dev-box/rails/activesupport/lib/active_support/subscriber.rb", 99, :T_STRING], [53962, 0, 50868, 0, 2, 2088000]]

After top 5 allocations:

[[".rbenv/versions/2.2.0/lib/ruby/2.2.0/uri/common.rb", 383, :T_STRING], [113963, 674, 123027, 0, 29, 6003132]]
[["rack/lib/rack/utils.rb", 87, :T_STRING], [111142, 112, 108813, 0, 29, 12666952]]
[["rails-dev-box/rails/activerecord/lib/active_record/connection_adapters/sqlite3_adapter.rb", 243, :T_STRING], [60008, 3, 57594, 0, 31, 2326600]]
[["rails-dev-box/rails/activesupport/lib/active_support/subscriber.rb", 99, :T_STRING], [53990, 0, 51740, 0, 1, 2093520]]
[["rails-dev-box/rails/activesupport/lib/active_support/notifications/instrumenter.rb", 52, :T_HASH], [50983, 22, 49121, 0, 27, 8200920]]

Also, how were you able to measure the time spent in GC consistently? StackProf varies every run. I've gotten results from 6% to 8%.

==================================
  Mode: cpu(1000)
  Samples: 1851 (0.00% miss rate)
  GC: 166 (8.97%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       115   (6.2%)         115   (6.2%)     block in SQLite3::Statement#each
        74   (4.0%)          74   (4.0%)     ActiveSupport::PerThreadRegistry#instance
       125   (6.8%)          67   (3.6%)     SQLite3::Database#prepare
        56   (3.0%)          56   (3.0%)     ThreadSafe::NonConcurrentCacheBackend#[]
        36   (1.9%)          36   (1.9%)     ActiveRecord::Base.logger
        52   (2.8%)          34   (1.8%)     block (2 levels) in Class#class_attribute
        32   (1.7%)          32   (1.7%)     #<Module:0x007fe582d3c470>.decode_www_form_component
        28   (1.5%)          28   (1.5%)     block (4 levels) in Class#class_attribute
        26   (1.4%)          26   (1.4%)     ActiveSupport::Notifications::Fanout::Subscribers::Evented#subscribed_to?
        31   (1.7%)          25   (1.4%)     ActionController::Parameters#permitted_scalar_filter
        26   (1.4%)          22   (1.2%)     ActiveRecord::AttributeSet#[]
        26   (1.4%)          21   (1.1%)     ActiveSupport::HashWithIndifferentAccess#update
        18   (1.0%)          18   (1.0%)     Rack::Request#initialize
        16   (0.9%)          16   (0.9%)     Rack::Test::Cookie#path
        16   (0.9%)          16   (0.9%)     #<Module:0x007fe582d3c470>.encode_www_form_component
        14   (0.8%)          14   (0.8%)     MonitorMixin#mon_enter
        28   (1.5%)          14   (0.8%)     Rack::Test::Cookie#valid?
        13   (0.7%)          13   (0.7%)     ActiveSupport::Notifications::Event#initialize
        47   (2.5%)          12   (0.6%)     Rack::Utils#parse_query
        12   (0.6%)          12   (0.6%)     String#blank?
       112   (6.1%)          11   (0.6%)     SQLite3::Database#execute
        10   (0.5%)          10   (0.5%)     ActiveSupport::Configurable::ClassMethods#config
        61   (3.3%)          10   (0.5%)     ActiveSupport::Subscriber#finish
        28   (1.5%)          10   (0.5%)     block in Rack::Utils#parse_query
        10   (0.5%)          10   (0.5%)     URI::RFC3986_Parser#split
        19   (1.0%)           9   (0.5%)     JSON#generate
         9   (0.5%)           9   (0.5%)     ActiveSupport::HashWithIndifferentAccess#convert_key
         9   (0.5%)           9   (0.5%)     ActiveSupport::SubscriberQueueRegistry#get_queue
        10   (0.5%)           8   (0.4%)     ActionController::Parameters#convert_value_to_parameters
        17   (0.9%)           8   (0.4%)     Rack::MockRequest.env_for
==================================
  Mode: cpu(1000)
  Samples: 1787 (0.00% miss rate)
  GC: 161 (9.01%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       103   (5.8%)         103   (5.8%)     block in SQLite3::Statement#each
        62   (3.5%)          62   (3.5%)     ThreadSafe::NonConcurrentCacheBackend#[]
        61   (3.4%)          61   (3.4%)     ActiveSupport::PerThreadRegistry#instance
       103   (5.8%)          50   (2.8%)     SQLite3::Database#prepare
        32   (1.8%)          32   (1.8%)     block (4 levels) in Class#class_attribute
        60   (3.4%)          30   (1.7%)     block (2 levels) in Class#class_attribute
        25   (1.4%)          25   (1.4%)     #<Module:0x007f2b1b5b7a78>.decode_www_form_component
        25   (1.4%)          25   (1.4%)     ActiveRecord::Base.logger
        25   (1.4%)          22   (1.2%)     ActiveRecord::AttributeSet#[]
        31   (1.7%)          21   (1.2%)     ActiveSupport::HashWithIndifferentAccess#update
        19   (1.1%)          19   (1.1%)     #<Module:0x007f2b1b5b7a78>.encode_www_form_component
        17   (1.0%)          17   (1.0%)     ActiveSupport::Notifications::Fanout::Subscribers::Evented#subscribed_to?
        16   (0.9%)          16   (0.9%)     ActiveSupport::Notifications::Event#initialize
        16   (0.9%)          16   (0.9%)     ActiveSupport::Configurable::ClassMethods#config
        15   (0.8%)          15   (0.8%)     block (2 levels) in ActionDispatch::Http::ParameterFilter::CompiledFilter#call
        20   (1.1%)          14   (0.8%)     Rack::Test::Cookie#valid?
        13   (0.7%)          13   (0.7%)     MonitorMixin#mon_enter
        13   (0.7%)          13   (0.7%)     Fixnum#to_s
        66   (3.7%)          11   (0.6%)     ActiveSupport::Subscriber#finish
        36   (2.0%)          11   (0.6%)     ActiveSupport::Subscriber#start
        11   (0.6%)          11   (0.6%)     Rack::Request#initialize
        23   (1.3%)          10   (0.6%)     block in Rack::Utils#parse_query
        15   (0.8%)          10   (0.6%)     ActiveSupport::HashWithIndifferentAccess#convert_value
        93   (5.2%)           9   (0.5%)     SQLite3::Database#execute
        15   (0.8%)           9   (0.5%)     Rack::Utils#normalize_params
         9   (0.5%)           9   (0.5%)     Arel::Collectors::PlainString#<<
        16   (0.9%)           8   (0.4%)     Time#minus_with_coercion
        18   (1.0%)           8   (0.4%)     JSON#generate
         8   (0.4%)           8   (0.4%)     Rack::Test::Cookie#path
        11   (0.6%)           8   (0.4%)     ActiveRecord::ConnectionAdapters::Quoting#_type_cast

ActionController::Parameters#permitted_scalar_filter does not appear in the stack after the patch.

@spastorino
Copy link
Contributor

You should use ThreadSafe::Cache for this

@tenderlove
Copy link
Member

Can we figure out a way to do this without class variables? I don't really want to add more caches if we can avoid it.

…calar_filter.

Script used: https://github.com/eileencodes/integration_performance_test/blob/master/test/integration/documents_allocations_create_test.rb.

Before:

```
[["rails/actionpack/lib/action_controller/metal/strong_parameters.rb", 540, :T_STRING], [52820, 0, 52406, 0, 2, 5676390]]
[["rails/actionpack/lib/action_controller/metal/strong_parameters.rb", 540, :T_NODE], [17448, 0, 17318, 0, 2, 675600]]
[["rails/actionpack/lib/action_controller/metal/strong_parameters.rb", 540, :T_ARRAY], [17448, 0, 17321, 0, 2, 675600]]
[["rails/actionpack/lib/action_controller/metal/strong_parameters.rb", 540, :T_REGEXP], [5816, 0, 5774, 0, 2, 3777730]]
```

After:
```
[["rails/actionpack/lib/action_controller/metal/strong_parameters.rb", 543, :T_NODE], [18006, 0, 17503, 0, 2, 696240]]
[["rails/actionpack/lib/action_controller/metal/strong_parameters.rb", 543, :T_ARRAY], [12004, 0, 11670, 0, 2, 464160]]
```
@tgxworld tgxworld force-pushed the reduce_string_allocation_in_ac_parameters branch from f007b3b to a6caa7a Compare February 24, 2015 07:49
@tgxworld
Copy link
Contributor Author

@eileencodes May I know how you determine if we're spending less time in GC? I used stackprof but the percentage of time spent in GC varies quite a bit giving inconsistent results. Since we're allocating 50k lesser Strings, I was expecting to see an improvement since the other 'reducing allocations' pull requests normally reduces them in the range of 10k.

Thanks in advance!

@eileencodes
Copy link
Member

@tgxworld I need to look at this more closely but am strapped for time this week. I'll try to get a look at it on Thursday but it probably won't be before then. 😄

As for the GC it depends; one other way we determined that there was a change was looking at total allocated objects. The problem with the allocations that we didn't realize before is it changes a lot if GC runs but then maybe on subsequent runs there's not change. We're still figuring out the best method of measurement overall. Aaron and I saw a drop in GC that didn't vary more than 0.03-0.07% with our last change. I'm sorry that's not very clear 😞

@tgxworld
Copy link
Contributor Author

I need to look at this more closely but am strapped for time this week. I'll try to get a look at it on Thursday but it probably won't be before then.

No rush, whenever you're free 😄

As for the GC it depends; one other way we determined that there was a change was looking at total allocated objects. The problem with the allocations that we didn't realize before is it changes a lot if GC runs but then maybe on subsequent runs there's not change. We're still figuring out the best method of measurement overall. Aaron and I saw a drop in GC that didn't vary more than 0.03-0.07% with our last change. I'm sorry that's not very clear

Thanks for clearing things up! I did use GC.stat but I was only looking at the number of times GC was called. I'll look into the number of allocations in this case as well. Thanks for the guidance! 😸

@tgxworld
Copy link
Contributor Author

tgxworld commented Apr 3, 2015

I decided to see where the strings were being allocated. Just by interpolating within / /, it allocates an array and 6 strings. https://gist.github.com/tgxworld/c1f0ba82a2d1a5bedf2e

If we were to use Regexp.new, we'll get better results. https://gist.github.com/tgxworld/766759f70c1041e16750

Switching to Regexp.new will also reduce allocations.

Before:
[["rails/actionpack/lib/action_controller/metal/strong_parameters.rb", 539, :T_STRING], [55034, 0, 53328, 0, 2, 5886330]]
[["rails/actionpack/lib/action_controller/metal/strong_parameters.rb", 539, :T_NODE], [18006, 0, 17449, 0, 2, 698160]]
[["rails/actionpack/lib/action_controller/metal/strong_parameters.rb", 539, :T_ARRAY], [18006, 0, 17450, 0, 2, 698160]]
[["rails/actionpack/lib/action_controller/metal/strong_parameters.rb", 539, :T_REGEXP], [6002, 0, 5817, 0, 2, 3903878]]

After:
[["rails/actionpack/lib/action_controller/metal/strong_parameters.rb", 539, :T_STRING], [36906, 0, 35683, 0, 2, 2925668]]
[["rails/actionpack/lib/action_controller/metal/strong_parameters.rb", 539, :T_NODE], [18006, 0, 17413, 0, 2, 696720]]
[["rails/actionpack/lib/action_controller/metal/strong_parameters.rb", 539, :T_ARRAY], [12004, 0, 11610, 0, 2, 464480]]
[["rails/actionpack/lib/action_controller/metal/strong_parameters.rb", 539, :T_REGEXP], [6002, 0, 5805, 0, 2, 3489406]]

The best way I can think of right now is still to cache the permitted keys. Any recommendation is welcomed. Thanks!

@tgxworld
Copy link
Contributor Author

tgxworld commented May 8, 2015

Closing this. I just realized we shouldn't be caching user's input as we might end up with a whole bunch of irrelevant cache.

Not sure how I can reduce allocations here without caching.

@tgxworld tgxworld closed this May 8, 2015
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.

None yet

5 participants