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

defined? poor performance #3808

Closed
etehtsea opened this issue Apr 19, 2016 · 15 comments
Closed

defined? poor performance #3808

etehtsea opened this issue Apr 19, 2016 · 15 comments
Milestone

Comments

@etehtsea
Copy link
Contributor

etehtsea commented Apr 19, 2016

Started in newrelic/newrelic-ruby-agent#222

require 'benchmark/ips'
# Uncomment for the second bench
# require 'active_support/dependencies'

Benchmark.ips do |x|
  x.config(warmup: 30, time: 20)
  x.report("const_defined?") do
    Object.const_defined?(:ActionDispatch) &&
      ::ActionDispatch.const_defined?(:Http) &&
      ::ActionDispatch::Http.const_defined?(:ParameterFilter)
  end
  x.report("defined?") { defined?(ActionDispatch::Http::ParameterFilter) }
  x.compare!
end

JRuby 9.0.5.0

/tmp  ⚡ jruby -S check.rb      
Warming up --------------------------------------
      const_defined?   171.651k i/100ms
            defined?     1.043k i/100ms
Calculating -------------------------------------
      const_defined?      6.944M (± 8.1%) i/s -    137.836M in  19.993781s
            defined?     10.139k (± 6.9%) i/s -    202.342k in  20.054383s

Comparison:
      const_defined?:  6943907.0 i/s
            defined?:    10139.3 i/s - 684.85x slower

JRuby 1.7.23

/tmp  ⚡ jruby -S check.rb
Warming up --------------------------------------
      const_defined?   155.373k i/100ms
            defined?     1.073k i/100ms
Calculating -------------------------------------
      const_defined?      3.535M (± 5.9%) i/s -     70.539M
            defined?     11.502k (± 6.1%) i/s -    229.622k

Comparison:
      const_defined?:  3535262.7 i/s
            defined?:    11501.9 i/s - 307.36x slower

MRI 2.3.0

Warming up --------------------------------------
      const_defined?   237.564k i/100ms
            defined?   241.210k i/100ms
Calculating -------------------------------------
      const_defined?      6.708M (± 5.3%) i/s -    133.986M in  20.029896s
            defined?      7.355M (± 5.8%) i/s -    146.656M in  20.006529s

Comparison:
            defined?:  7355217.2 i/s
      const_defined?:  6707708.2 i/s - same-ish: difference falls within error

With ActiveSupport::Dependencies required:

JRuby 9.0.5.0

Warming up --------------------------------------
      const_defined?   156.141k i/100ms
            defined?   347.000  i/100ms
Calculating -------------------------------------
      const_defined?      5.216M (± 6.8%) i/s -    103.834M in  20.003748s
            defined?      3.484k (± 7.5%) i/s -     69.400k in  20.041216s

Comparison:
      const_defined?:  5216398.2 i/s
            defined?:     3483.7 i/s - 1497.36x slower

JRuby 1.7.23

/tmp  ⚡ jruby -S check.rb
Warming up --------------------------------------
      const_defined?   174.217k i/100ms
            defined?   416.000  i/100ms
Calculating -------------------------------------
      const_defined?      4.043M (± 4.8%) i/s -     80.662M
            defined?      4.224k (± 5.1%) i/s -     84.448k

Comparison:
      const_defined?:  4042664.2 i/s
            defined?:     4224.1 i/s - 957.05x slower

MRI 2.3.0

/tmp  ⚡ ruby check.rb 
Warming up --------------------------------------
      const_defined?   223.693k i/100ms
            defined?   231.453k i/100ms
Calculating -------------------------------------
      const_defined?      6.140M (± 5.9%) i/s -    122.360M in  19.998885s
            defined?      6.191M (± 7.9%) i/s -    123.133M in  20.026093s

Comparison:
            defined?:  6190901.7 i/s
      const_defined?:  6140088.9 i/s - same-ish: difference falls within error

P.S.

  • jruby-9.0.5.0 (2.2.3) 2016-01-26 7bee00d Java HotSpot(TM) 64-Bit Server VM 25.77-b03 on 1.8.0_77-b03 +jit [darwin-x86_64]
  • jruby 1.7.23 (1.9.3p551) 2015-11-24 f496dd5 on Java HotSpot(TM) 64-Bit Server VM 1.8.0_77-b03 +jit [darwin-x86_64]
  • ruby 2.3.0p0 (2015-12-25 revision 53290) [x86_64-darwin15]

UPD:

/tmp  ⚡ jruby --version                
jruby 9.1.0.0-SNAPSHOT (2.3.0) 2016-04-19 2d27311 Java HotSpot(TM) 64-Bit Server VM 25.77-b03 on 1.8.0_77-b03 +jit [darwin-x86_64]

/tmp  ⚡ jruby -S check.rb          
Warming up --------------------------------------
      const_defined?   154.530k i/100ms
            defined?   923.000  i/100ms
Calculating -------------------------------------
      const_defined?      7.035M (± 7.0%) i/s -    139.850M in  19.979653s
            defined?      9.367k (± 5.2%) i/s -    187.369k in  20.055586s

Comparison:
      const_defined?:  7034829.3 i/s
            defined?:     9366.8 i/s - 751.04x slower

/tmp  ⚡ jruby -S check.rb                                         
Warming up --------------------------------------
      const_defined?   197.363k i/100ms
            defined?   360.000  i/100ms
Calculating -------------------------------------
      const_defined?      7.055M (± 5.9%) i/s -    140.522M in  19.991747s
            defined?      3.671k (± 3.9%) i/s -     73.440k in  20.034533s

Comparison:
      const_defined?:  7054891.5 i/s
            defined?:     3671.3 i/s - 1921.66x slower
@headius
Copy link
Member

headius commented Apr 19, 2016

Interesting...shouldn't be hard to find the issue. It is helpful to see the real-world perf issues this is causing, as well.

@enebo
Copy link
Member

enebo commented Apr 19, 2016

In this particular case, we are hitting exception logic. If I require action_dispatch then defined? returns constant and it is much less slow. In fact, it is faster than const_defined?:

Warming up --------------------------------------
      const_defined?    72.166k i/100ms
            defined?   103.427k i/100ms
Calculating -------------------------------------
      const_defined?      2.249M (± 6.2%) i/s -     44.743M
            defined?      9.004M (±11.7%) i/s -    176.343M

Comparison:
            defined?:  9003585.2 i/s
      const_defined?:  2249176.7 i/s - 4.00x slower

And I can see when it is not defined we raise a NameError then catch it and make sure it is not some more important exception and then returns nil. So JRuby's exception handling is as slow as molasses as the cost of backtrace generation is really expensive for us.

The solution to this is to redesign defined? to not use exceptions at all internally. This is possible for pure constant case but we need to preserve all semantics of defined? (e.g. Foo::Bar::car of Foo::Bar::Car where Car is a method).

2016-04-19T13:00:04.223-05:00: InterpretedIRMethod: Executing 'fooey'
2016-04-19T13:00:04.224-05:00: InterpretedIRMethod:   0 %self = recv_self()
  1 %v_0 = load_implicit_closure()
  2 %current_scope = copy(scope<0>)
  3 %current_module = copy(module<0>)
  4 check_arity(;req: 0, opt: 0, *r: false, kw: false)
  5 line_num(;n: 3)
  6 %v_3 = get_error_info()
  7 label(LBL_0:8)
  8 exc_region_start(LBL_2:16)
  9 %v_5 = search_const(%current_scope ;name: ActionDispatch, no_priv: false)
  10    %v_6 = search_module_for_const(%v_5 ;name: Http, no_priv: true)
  11    %v_7 = runtime_helper(%v_6, frozen:"ParameterFilter" ;method: IS_DEFINED_CONSTANT_OR_METHOD)
  12    %v_4 = copy(%v_7)
  13    jump(LBL_1:25)
  14    exc_region_end()
  15    label(LBL_2:16)
  16    %v_8 = recv_ruby_exc()
  17    %v_9 = inheritance_search_const(<Class:Object> ;name: Exception, no_priv: false)
  18    %v_10 = rescue_eqq(%v_9, %v_8)
  19    b_true(LBL_3:22, %v_10)
  20    throw(%v_8)
  21    label(LBL_3:22)
  22    restore_error_info(%v_3)
  23    %v_4 = copy(nil)
  24    label(LBL_1:25)
  25    %v_11 = call_1o(%self, %v_4 ;n:p, t:FU, cl:false)
  26    return(%v_11)

@enebo enebo added this to the JRuby 9.1.1.0 milestone Apr 20, 2016
@enebo
Copy link
Member

enebo commented Apr 20, 2016

Quick note on this. Semantics of Ruby defined? for constants is that if the segment of a colon2 starts with a capital letter it will not try and see if it is a method call unlike if the segment is lower case:

Foo::Bar::Gar

If any of these three segments is a method and not a constant defined would return nil. As opposed to:

Foo::bar::Gar

where bar will be looked for as a method and executed as part of defined? resolution. The good news is that these slightly unintuitive semantics means we can fast-path all capital chain constants in a defined call in Java or at least without having to catch a potential exception. Due to some recent discussions of granularity of instructions we will probably make a new instr for this:

constant_value operand1, ...operandn

Where each operand is just a segment of the colon2/3 chain. A failed lookup will return %unassigned.

@headius headius modified the milestones: JRuby 9.1.1.0, JRuby 9.1.2.0 May 11, 2016
@enebo enebo modified the milestones: JRuby 9.1.2.0, JRuby 9.1.3.0 May 23, 2016
@enebo enebo modified the milestones: JRuby 9.1.2.0, JRuby 9.1.3.0 Jun 14, 2016
@enebo
Copy link
Member

enebo commented Jun 14, 2016

Nice. I inadvertently fixed this in 9.1.2.0 by fixing some other MRI tagged issue. We no longer will trigger the exception:

jruby ../snippets/const1.rb
Ignoring interception-0.5 because its extensions are not built.  Try: gem pristine interception --version 0.5
"constant"
Warming up --------------------------------------
      const_defined?    83.021k i/100ms
            defined?   106.034k i/100ms
Calculating -------------------------------------
      const_defined?      3.375M (± 9.0%) i/s -     66.749M
            defined?      7.298M (±11.3%) i/s -    143.676M

Comparison:
            defined?:  7298201.3 i/s
      const_defined?:  3374507.0 i/s - 2.16x slower

The before/after are nearly identical results.

@enebo enebo closed this as completed Jun 14, 2016
@enebo
Copy link
Member

enebo commented Jun 14, 2016

@etehtsea could you verify this is fixed in 9.1.2.0 please?

@enebo enebo modified the milestones: JRuby 9.1.3.0, JRuby 9.1.2.0 Jun 14, 2016
@enebo
Copy link
Member

enebo commented Jun 14, 2016

@etehtsea sorry I fixed this after 9.1.2.0 was put out. It is fixed on master and will be in 9.1.3.0 after all...

@etehtsea
Copy link
Contributor Author

etehtsea commented Jun 15, 2016

I've got different results:

jruby 9.1.3.0-SNAPSHOT (2.3.0) 2016-06-15 f3f5776 Java HotSpot(TM) 64-Bit Server VM 25.77-b03 on 1.8.0_77-b03 [darwin-x86_64]
Warming up --------------------------------------
      const_defined?    33.560k i/100ms
            defined?   688.000  i/100ms
Calculating -------------------------------------
      const_defined?    831.791k (±10.5%) i/s -     16.411M in  20.020891s
            defined?      7.891k (± 9.0%) i/s -    156.864k in  20.061174s

Comparison:
      const_defined?:   831791.0 i/s
            defined?:     7890.7 i/s - 105.41x slower

with require 'active_support/dependencies':

jruby 9.1.3.0-SNAPSHOT (2.3.0) 2016-06-15 f3f5776 Java HotSpot(TM) 64-Bit Server VM 25.77-b03 on 1.8.0_77-b03 [darwin-x86_64]
Warming up --------------------------------------
      const_defined?    31.313k i/100ms
            defined?   244.000  i/100ms
Calculating -------------------------------------
      const_defined?    879.264k (± 7.4%) i/s -     17.504M in  20.020140s
            defined?      2.708k (± 4.7%) i/s -     54.168k in  20.047639s

Comparison:
      const_defined?:   879263.9 i/s
            defined?:     2708.1 i/s - 324.68x slower

@enebo
Copy link
Member

enebo commented Jun 15, 2016

@etehtsea perhaps I am no longer reproducing this because I am not using correct version of gem. Which version of activesupport is this against? I had happened to change some behavior in defined and realized I might have killed the exception thrown and the reran the bench and it seemed cleared up. I also cleaned up my installed gems. I happen to have activesupport 4.2.5 installed atm.

@enebo
Copy link
Member

enebo commented Jun 15, 2016

I just tried making sure this constant cannot exist by adding nonsense on the end of the constant name to guarantee it does not exist and it got even faster. I wonder if this case involves autoload or something in a different version? We are still performing autoload when a constant is on the right-side of a colon2. In any case, I want to see this locally again so I think your versions of gem(s) will do that.

@etehtsea
Copy link
Contributor Author

etehtsea commented Jun 21, 2016

@enebo I made docker image for you. Simply save script posted below to the /tmp/check.rb and run

docker run --rm -v `pwd`/check.rb:/tmp/check.rb etehtsea/jruby:9.1.3.0-160621-centos jruby -v -S /tmp/check.rb

and you should get the same results as I got.

$ docker run --rm -v `pwd`/check.rb:/tmp/check.rb etehtsea/jruby:9.1.3.0-160621-centos jruby -v -S /tmp/check.rb

jruby 9.1.3.0-SNAPSHOT (2.3.0) 2016-06-21 934ae01 OpenJDK 64-Bit Server VM 25.91-b14 on 1.8.0_91-b14 +jit [linux-x86_64]
Fetching gem metadata from https://rubygems.org/..
Fetching version metadata from https://rubygems.org/.
Resolving dependencies...
Installing benchmark-ips 2.6.1
constructing an Installer object with a string is deprecated. Please use Gem::Installer.at (called from: /opt/jruby-9.1.3.0-SNAPSHOT/lib/ruby/gems/shared/gems/bundler-1.11.2/lib/bundler/source/rubygems.rb:135:in `block in install')
Using bundler 1.11.2
Warming up --------------------------------------
      const_defined?    30.529k i/100ms
            defined?     1.008k i/100ms
Calculating -------------------------------------
      const_defined?      5.585M (±12.2%) i/s -    109.508M in  19.955469s
            defined?ca     11.881k (± 6.1%) i/s -    236.880k in  20.018164s

Comparison:
      const_defined?:  5585168.9 i/s
            defined?:    11880.9 i/s - 470.10x slower

Dockerfile:

FROM nimmis/java-centos:openjdk-8-jre

ARG JRUBY_VERSION
ADD jruby-bin-${JRUBY_VERSION}.tar.gz /opt/
ENV PATH /opt/jruby-9.1.3.0-SNAPSHOT/bin:$PATH
RUN ln -s /opt/jruby-9.1.3.0-SNAPSHOT/bin/jruby /opt/jruby-9.1.3.0-SNAPSHOT/bin/ruby && \
    gem install bundler -v 1.11.2

@etehtsea
Copy link
Contributor Author

Forgot to add updated check.rb (with gemfile inlined):

require 'bundler/inline'

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

  gem 'benchmark-ips'
  #gem 'activesupport'
end

require 'benchmark/ips'
# Uncomment for the second bench
# require 'active_support/dependencies'

Benchmark.ips do |x|
  x.config(warmup: 30, time: 20)
  x.report("const_defined?") do
    Object.const_defined?(:ActionDispatch) &&
      ::ActionDispatch.const_defined?(:Http) &&
      ::ActionDispatch::Http.const_defined?(:ParameterFilter)
  end
  x.report("defined?") { defined?(ActionDispatch::Http::ParameterFilter) }
  x.compare!
end

@etehtsea
Copy link
Contributor Author

@enebo ping

@enebo
Copy link
Member

enebo commented Jul 14, 2016

@etehtsea I can for some reason reproduce this again. With that said all my original notes in this issue still apply (my thinking it worked before was from another commit which eliminated exceptions for a subset of defined? calls on constants). I did make some improvements in another commit which solved perf for what I guess was a slightly different case. The main work for today will be:

a. Change internal call for pure constant colon2 chains A::B to not raise (except see c)
b. Make sure we are calling correct call so that A::B where B is autoload does not fire while A::B::C does fire autoload B. Ability to autoload means possibility of exception like a LoadError.
c. A::foo::C needs to still be exception based since we will execute foo.

b means we need an exception handler to be emitted like we do today (which is basically what c is) and so since a and b are not distinguishable when we generate instrs we need to still wrap with exception handling. in the common case of a this will never actually throw.

(PS - I mostly wrote these notes for myself to plan an angle of attack)

@etehtsea
Copy link
Contributor Author

etehtsea commented Jul 14, 2016

@enebo is it worth to reopen this issue just for the sake of tracking its status?

P.S. thanks!

@enebo enebo reopened this Jul 14, 2016
@enebo enebo closed this as completed in 5ff8bd1 Jul 15, 2016
@etehtsea
Copy link
Contributor Author

Warming up --------------------------------------
      const_defined?   197.581k i/100ms
            defined?   259.411k i/100ms
Calculating -------------------------------------
      const_defined?      6.938M (± 8.2%) i/s -    137.714M in  19.995864s
            defined?     18.248M (±10.5%) i/s -    360.062M in  19.986502s

Comparison:
            defined?: 18248492.6 i/s
      const_defined?:  6938116.9 i/s - 2.63x slower

This is awesome, thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants