Major performance regression with enforce_available_locales = true

[cmaion]

Hi guys,

FYI, setting enforce_available_locales to true on 0.6.9 has a major performance hit.

On my (large) Rails (3.2.16) app, avg response time increases by +40-50% by setting this to true. Setting it back to false seems to bring response times back to normal (still need to observe this for a couple of days though).

Cedric

[giosakti]

+1 I'm also having the same problem.

my rspec tests suddenly become an order (or two) of magnitude slower than usual.

[tigrish]

Any metrics greatly appreciated.

[cmaion]

Not sure what you expect exactly, but any simple test makes it obvious.
And a quick scan of the code makes me think that mapping all locales to strings and comparing with passed local --at each translation request-- is certainly sub-optimal ;)

TL;DR: "min 111.7 avg 154.2 max 335.1 median 128.5" => "min 149.8 avg 223.8 max 484.8 median 169.5"

httperf benchmark data (on localhost):

1. clean unicorn restart, enforce_available_locales = false, 10 warmup requests.

Total: connections 100 requests 100 replies 100 test-duration 15.417 s

Connection rate: 6.5 conn/s (154.2 ms/conn, <=1 concurrent connections)
Connection time [ms]: min 111.7 avg 154.2 max 335.1 median 128.5 stddev 65.4
Connection time [ms]: connect 0.1
Connection length [replies/conn]: 1.000

Request rate: 6.5 req/s (154.2 ms/req)
Request size [B]: 105.0

Reply rate [replies/s]: min 6.2 avg 6.4 max 6.6 stddev 0.2 (3 samples)
Reply time [ms]: response 153.6 transfer 0.4
Reply size [B]: header 643.0 content 22544.0 footer 2.0 (total 23189.0)
Reply status: 1xx=0 2xx=100 3xx=0 4xx=0 5xx=0

1. clean unicorn restart, enforce_available_locales = true, 10 warmup requests.

Total: connections 100 requests 100 replies 100 test-duration 22.382 s

Connection rate: 4.5 conn/s (223.8 ms/conn, <=1 concurrent connections)
Connection time [ms]: min 149.8 avg 223.8 max 484.8 median 169.5 stddev 99.2
Connection time [ms]: connect 0.1
Connection length [replies/conn]: 1.000

Request rate: 4.5 req/s (223.8 ms/req)
Request size [B]: 105.0

Reply rate [replies/s]: min 4.2 avg 4.5 max 4.6 stddev 0.2 (4 samples)
Reply time [ms]: response 223.2 transfer 0.5
Reply size [B]: header 643.0 content 22544.0 footer 2.0 (total 23189.0)
Reply status: 1xx=0 2xx=100 3xx=0 4xx=0 5xx=0

[tigrish]

Thanks for the info - can you indicate which Backend you're using and how you're calling the I18n.t method?

And a quick scan of the code makes me think that mapping all locales to strings and comparing with passed local --at each translation request-- is certainly sub-optimal ;)

This is actually the essence of the last security update unfortunately.

[cmaion]

I use the simple YAML backend.
And the vast majority of I18n.t calls are normally done in ERB (<%=t '.whatever' -%>).
Nothing fancy here.

Some optimizations to accelerate the lookup part can probably done though. Some ideas:

• precompute the "sym to string" map (no need to do this for each call I guess)
• transform to a hash for faster lookup / caching
• ...

On my side I prefer to validate user-submitted locale strings when submitted instead of at each use. Makes much more sense for me, and this is much faster (I'm generally doing many I18n.t lookups per view).

[carlosantoniodasilva]

@tigrish I haven't done any benchmark yet, but I think that we could probably make the available_locales list already strings when setting this value (or keep another internal string list), instead of converting the list on every call to locale_available?.

I imagine that could alleviate the issue reported here considerably.

@cmaion how many available locales do you have?

[cmaion]

All default Rails locales. Never bothered to trim them, nor did I see the need for that. Should I?

>> I18n.available_locales
=> [:en, :"es-CR", :ne, :it, :gl, :ru, :eu, :hr, :vi, :"pt-BR", :el, :sr, :hi, :"hi-IN", :mk, :id, :de, :bn, :"es-VE", :lt, :cy, :et, :rm, :uk, :bs, :"de-AT", :ar, :"es-MX", :tl, :nn, :"en-US", :eo, :or, :ca, :sk, :wo, :he, :pl, :tr, :ko, :fr, :"zh-HK", :bg, :af, :hu, :"de-CH", :nl, :"es-CO", :es, :uz, :kn, :"zh-CN", :lv, :sl, :fa, :"en-IN", :"es-PE", :"en-CA", :sw, :da, :cs, :ja, :"en-AU", :pt, :nb, :sv, :fi, :"fr-CA", :"es-AR", :th, :"en-GB", :lo, :mn, :is, :ro, :"en-NZ", :"es-CL", :"it-CH", :"en-IE", :"es-419", :"fr-CH", :az, :"zh-TW"]
>> I18n.available_locales.count
=> 83

Ok so some quick benchmark material here that might be of interest:

>> RUBY_DESCRIPTION
=> "ruby 1.9.3p484 (2013-11-22 revision 43786) [x86_64-linux]"

>> Benchmark.measure { 10000.times { I18n.available_locales.map(&:to_s).include?(:foo.to_s) } }
=>  11.850000   0.000000  11.850000  12.029935

>> Benchmark.measure { available_locales_as_string_array = I18n.available_locales.map(&:to_s); 10000.times { available_locales_as_string_array.include?(:foo.to_s) } }
=>   0.050000   0.000000   0.050000   0.058407

>> Benchmark.measure { available_locales_as_string_hash = I18n.available_locales.map(&:to_s).reduce({}) { |h,s| h[s] = true; h } ; 10000.times { available_locales_as_string_hash[:foo.to_s] } }
=>   0.010000   0.000000   0.010000   0.003648

=> currently spending 1.2ms per translation performed (probably not accounting for generated garbage that will need to be cleaned up later on)
=> 3300x improvment using a precomputed hash... Just saying ;)

[NielsKSchjoedt]

I can confirm that there is a huge performance hit going on here. We have a rails app, that was running rails 4.0.3. When we upgraded to 4.0.4, we saw a huge performance hit. After countless hours of debugging, we figured out that this is the root cause, since enforce_available_locales = true seems to be default in rails 4.0.4. The issue was pointed out too in the comments section of the rails update: http://weblog.rubyonrails.org/2014/3/14/Rails-4-0-4-has-been-released/ Now here are some metrics showing the impact on a fairly large rails app with quite a lot of traffic (I should underline that update of rails from 4.0.3 to 4.0.4 is the ONLY change done between those two deploys. No other changes were deployed):

Putting config.i18n.enforce_available_locales = false in application.rb seems to partly solve the problem. However as pointed out in this post http://stackoverflow.com/questions/20361428/rails-i18n-validation-deprecation-warning, there might still be gems that are hit by this.

[carlosantoniodasilva]

@NielsKSchjoedt thanks for the report and detailed graphs. I'll try to take a look at this soon and see if we can improve the way the enforce locales is being handled, if anyone else does it before me.

[carlosantoniodasilva]

@cmaion @NielsKSchjoedt I've just merged a fix in master that should bring performance back to an acceptable level, almost the same as before as we could benchmark.

I plan to review this implementation in a next minor version, but for now I want to release a patched one with this perf fix and a couple other minor things already in master. If you could try those and report back, that'd be great.

Thank you again for reporting and helping on this one.