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

define_method performance degradation #3391

Closed
film42 opened this issue Oct 12, 2015 · 5 comments
Closed

define_method performance degradation #3391

film42 opened this issue Oct 12, 2015 · 5 comments

Comments

@film42
Copy link

film42 commented Oct 12, 2015

I noticed a performance degradation with define_method in jruby 9k recently. It sounds like this might have more to do with block overhead with IR in jruby 9k though (#3389 (comment)).

Here's what I found:

I'm running these with --profile.api flag enabled.

require 'jruby/profiler'
class Foo
  define_method(:bar) do
  end
end

# Warm the VM
100_000.times { Foo.new.bar }

# Profile
f = Foo.new
profile_data = JRuby::Profiler.profile do
  100_000.times { f.bar }
end

profile_printer = JRuby::Profiler::FlatProfilePrinter.new(profile_data)
puts profile_printer.printProfile(STDOUT)

1.7:

     total        self    children       calls  method
----------------------------------------------------------------
      0.06        0.04        0.02           1  Fixnum#times
      0.02        0.02        0.00      100000  Foo#bar

9k:

     total        self    children       calls  method
----------------------------------------------------------------
      0.09        0.06        0.03           1  Fixnum#times
      0.03        0.03        0.00      100000  Foo#bar

There are some occasions where I can get 9k to run as fast as 1.7 for a single test, but the in general, 1.7 seems to be faster than 9k.

Btw, I'm thinking this is block related since #times is also much slower on 9k.

@enebo
Copy link
Member

enebo commented Oct 12, 2015

This commit might interest you: 3c3055d

9.0.2.0+ will contain this, but it is currently more limited than it needs to be (as outlined in the commit message). So with your sample snippet above we now run that method a couple times faster than 1.7, but many other define_methods will probably show the slowdown you have reported.

@enebo
Copy link
Member

enebo commented Oct 12, 2015

For record here is a benchmark I used for the commit I mentioned above:

require 'benchmark/ips'

class Foo
  b = 1
  define_method(:fooced) do |a|
    b
    a
  end

  define_method(:foo) do |a|
    a
  end

  def bar(a)
    a
  end
end

foo = Foo.new


Benchmark.ips do |x|
  x.report "define_method w/ capture" do
    foo.fooced(1)
    foo.fooced(1)
    foo.fooced(1)
    foo.fooced(1)
    foo.fooced(1)
    foo.fooced(1)
    foo.fooced(1)
    foo.fooced(1)
    foo.fooced(1)
    foo.fooced(1)
  end

  x.report "def" do
    foo.bar(1)
    foo.bar(1)
    foo.bar(1)
    foo.bar(1)
    foo.bar(1)
    foo.bar(1)
    foo.bar(1)
    foo.bar(1)
    foo.bar(1)
    foo.bar(1)
  end

  x.report "define_method" do
    foo.foo(1)
    foo.foo(1)
    foo.foo(1)
    foo.foo(1)
    foo.foo(1)
    foo.foo(1)
    foo.foo(1)
    foo.foo(1)
    foo.foo(1)
    foo.foo(1)
  end


end

@film42
Copy link
Author

film42 commented Oct 12, 2015

@enebo Thanks for point out that commit, I saw it over the weekend and got super excited. The case that led to creating this issue was a block referencing parent scope which would not take advantage of your optimization. I'm really looking forward to seeing what comes next though :).

@headius
Copy link
Member

headius commented Oct 12, 2015

My numbers on @enebo's bench actually seem to show that define_method with capture is currently faster on 9k than on 1.7 (and of course without capture it's way faster now):

[] ~/projects/jruby $ jruby bench_define_method.rb 
Calculating -------------------------------------
define_method w/ capture
                        53.266k i/100ms
                 def   105.543k i/100ms
       define_method    84.974k i/100ms
-------------------------------------------------
define_method w/ capture
                          1.093M (± 6.9%) i/s -      5.486M
                 def      3.751M (± 8.5%) i/s -     18.576M
       define_method      2.864M (± 7.6%) i/s -     14.276M

[] ~/projects/jruby $ rvm jruby-1.7.21 do ruby bench_define_method.rb 
Calculating -------------------------------------
define_method w/ capture
                        49.267k i/100ms
                 def   150.373k i/100ms
       define_method    57.282k i/100ms
-------------------------------------------------
define_method w/ capture
                        821.773k (± 5.6%) i/s -      4.138M
                 def      5.311M (± 8.7%) i/s -     26.315M
       define_method    825.927k (± 4.9%) i/s -      4.124M

Of larger worry is the performance of a plain def here, but that's not related to this bug either.

@film42
Copy link
Author

film42 commented Oct 14, 2015

@headius @enebo The benchmark-ips gem is awesome! I'm seeing similar results to you guys, meaning define_method is much faster, but def is slower (different issue, like you said, @headius). Thanks for looking into this guys. I'll keep profiling and let you know if I find anything :)

@film42 film42 closed this as completed Oct 14, 2015
@enebo enebo added this to the Invalid or Duplicate milestone Oct 15, 2015
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