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

Method caches broken between `it` #2194

Closed
tenderlove opened this Issue Mar 7, 2016 · 12 comments

Comments

Projects
None yet
5 participants
@tenderlove

tenderlove commented Mar 7, 2016

Hi,

I noticed that RSpec seems to be breaking method caches between it calls. I haven't had time to track down the issue, but I figured I should report this so that I can a) remind myself to figure it out, and b) if someone else has time to look they can.

Here is a script to demonstrate:

describe "ruby vm" do
  it "should not change" do
    p RubyVM.stat
  end

  it "should not change again" do
    p RubyVM.stat
  end

  it "should not change again and again" do
    p RubyVM.stat
  end
end

I expect the output of RubyVM.stat to be stable between tests, but the output on my machine looks like this:

$ rspec rspec_test.rb 
{:global_method_state=>142, :global_constant_state=>1332, :class_serial=>14849}
.{:global_method_state=>142, :global_constant_state=>1332, :class_serial=>14850}
.{:global_method_state=>142, :global_constant_state=>1332, :class_serial=>14851}
.

Finished in 0.00107 seconds (files took 0.19406 seconds to load)
3 examples, 0 failures

Since :class_serial is increasing, it means that some method cache, somewhere is being broken. I'll guess it's an extend, but I really haven't investigated deeply. Depending on what cache is being broken, it could help runtime performance to fix this.

I was able to reproduce this with 3.4.0 and 3.5.0.beta1. I hope this helps!

@tenderlove

This comment has been minimized.

tenderlove commented Mar 7, 2016

Sorry, I should say this doesn't really have anything to do with the it calls, but that the runner is somehow breaking method caches.

@JonRowe

This comment has been minimized.

Member

JonRowe commented Mar 7, 2016

@tenderlove forgive my ignorance but what does :class_serial mean here? Each it is run as a seperate instance of the defined ExampleGroup so is it possible thats why it increments?

@tenderlove

This comment has been minimized.

tenderlove commented Mar 7, 2016

Hey @JonRowe! Each call site in Ruby keeps a cache of the method being called, so code like foo.bar will keep a cache of where bar is. That way, each time that particular bit of code is executed, Ruby doesn't have to do as much work to look up the method. The cache key is a serial number that is stored on the class of foo, hence :class_serial. Since the key is changing, that means it's very likely that some call sites are getting cache misses when they could be cache hits.

Each it is run as a seperate instance of the defined ExampleGroup so is it possible thats why it increments?

No, that shouldn't be it. The only things that will impact the class serial number is defining new classes, extending an instance, or defining singleton methods on instances.

class A
end

p :INITIAL => RubyVM.stat[:class_serial]

module B
end

p :SHOULD_CHANGE => RubyVM.stat[:class_serial] # should change because of `B`

A.new

p :SHOULD_NOT_CHANGE => RubyVM.stat[:class_serial] # won't change

A.new.extend(B)

p :SHOULD_CHANGE => RubyVM.stat[:class_serial] # changes due to `extend`

a = A.new
def a.singleton
end

p :SHOULD_CHANGE => RubyVM.stat[:class_serial] # changes due to singleton
@myronmarston

This comment has been minimized.

Member

myronmarston commented Mar 7, 2016

Thanks for reporting this, @tenderlove! I've dug into it a bit and found something surprising. It appears that every time you use instance_exec on a new object instance, it increments the serial number, even though there are none of the things you mentioned happening (defining classes, extending instances, defining methods, etc). Check out this IRB session:

irb(main):001:0> group = Class.new
=> #<Class:0x007f9da99155e8>
irb(main):002:0> RubyVM.stat[:class_serial]
=> 6883
irb(main):003:0> group.new.instance_exec {}
=> nil
irb(main):004:0> RubyVM.stat[:class_serial]
=> 6884
irb(main):005:0> group.new.instance_exec {}
=> nil
irb(main):006:0> RubyVM.stat[:class_serial]
=> 6885

This IRB example approximates what RSpec does: each example group is a class, and for each example, a new instance is created and the it block is executed via instance_exec on the fresh instance. This ensures each example has a "clean slate" since it's running in a fresh object instance.

Why does Ruby increment class_serial in this situation?

FWIW, the problem is not with instance_exec itself; if I call it multiple times on the same instance, the serial number is not incremented:

irb(main):007:0> instance = group.new
=> #<#<Class:0x007f9da99155e8>:0x007f9da98fed20>
irb(main):008:0> instance.instance_exec {}
=> nil
irb(main):009:0> RubyVM.stat[:class_serial]
=> 6886
irb(main):010:0> instance.instance_exec {}
=> nil
irb(main):011:0> RubyVM.stat[:class_serial]
=> 6886
irb(main):012:0> instance.instance_exec {}
=> nil
irb(main):013:0> RubyVM.stat[:class_serial]
=> 6886

In theory we could re-use the group instance for multiple examples in RSpec, but that comes with its own set of problems. Creating new objects is the natural way to get a "clean slate" in ruby. To re-use the same instance, we'd have to carefully remove all instance variables on the group instance, which is cumbersome and not a natural approach in Ruby, and might perform worse than any perf gains we'd get out of not busting the method cache.

Any suggestions, @tenderlove?

@tenderlove

This comment has been minimized.

tenderlove commented Mar 7, 2016

Hi @myronmarston! I should have put instance_exec and singleton_class in my examples earlier. Basically anything that access the singleton class on an instance will increment the class serial number. The reason is that an object's "real class" is either the class it's associated with, or the singleton class. Ruby isn't that smart about what you actually do with the singleton class on the object, so just accessing it will create a new class.

I put together some code that will allow you to access the real class of an instance (I'm using this on 2.4.0, but it should work on Ruby 2.3.0 too):

require 'fiddle'
require 'fiddle/import'

extend Fiddle::Importer
dlload

typealias "VALUE", "unsigned long"
typealias "rb_serial_t", "unsigned long"
Basic = ["VALUE flags", "VALUE klass"]

RBasic = struct Basic
RClass = struct(Basic + [
  "VALUE super",
  "rb_classext_t *ptr",
  "rb_id_table *mtable"
])

RClassExt = struct([
  "struct st_table *iv_index_tbl",
  "struct st_table *iv_tbl",
  "struct rb_id_table *const_tbl",
  "struct rb_id_table *callable_m_tbl",
  "rb_subclass_entry_t *subclasses",
  "rb_subclass_entry_t **parent_subclasses",
  "rb_subclass_entry_t **module_subclasses",
  "rb_serial_t class_serial",
  "VALUE origin_",
  "VALUE refined_class",
  "void * allocator",
])

class Object
  def internal_ptr
    pos = self.object_id * 2
    Fiddle::Pointer.new(pos)
  end

  def real_class
    Fiddle::Pointer.new(RBasic.new(internal_ptr).klass).to_value
  end
end

class Class
  def class_serial
    RClassExt.new(RClass.new(internal_ptr).ptr).class_serial
  end
end

class Foo
end

p :INITIAL => Foo.class_serial
foo = Foo.new

p foo.real_class == Foo # => true
p foo.real_class.class_serial == Foo.class_serial # => true

foo.singleton_class
p foo.real_class == Foo # => false
p foo.real_class.class_serial == Foo.class_serial # => false

Accessing the singleton class of the object will change the klass pointer on the object itself. If you always access the singleton class of an instance, then no method caches for that object will ever hit.

After some quality time with lldb, I was able to track down the source of the runtime increments. Here is a log of my lldb session if you want to try reproducing. Here is the stack (note that the stack is upside down compared to ruby's caller):

    from /Users/aaron/.rbenv/versions/ruby-trunk/bin/rspec:22:in `<main>'
    from /Users/aaron/.rbenv/versions/ruby-trunk/bin/rspec:22:in `load'
    from /Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/rspec-core-3.5.0.beta1/exe/rspec:4:in `<top (required)>'
    from /Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/rspec-core-3.5.0.beta1/lib/rspec/core/runner.rb:45:in `invoke'
    from /Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/rspec-core-3.5.0.beta1/lib/rspec/core/runner.rb:78:in `run'
    from /Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/rspec-core-3.5.0.beta1/lib/rspec/core/runner.rb:93:in `run'
    from /Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/rspec-core-3.5.0.beta1/lib/rspec/core/runner.rb:117:in `run_specs'
    from /Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/rspec-core-3.5.0.beta1/lib/rspec/core/reporter.rb:77:in `report'
    from /Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/rspec-core-3.5.0.beta1/lib/rspec/core/runner.rb:118:in `block in run_specs'
    from /Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/rspec-core-3.5.0.beta1/lib/rspec/core/configuration.rb:1680:in `with_suite_hooks'
    from /Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/rspec-core-3.5.0.beta1/lib/rspec/core/runner.rb:119:in `block (2 levels) in run_specs'
    from /Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/rspec-core-3.5.0.beta1/lib/rspec/core/runner.rb:119:in `map'
    from /Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/rspec-core-3.5.0.beta1/lib/rspec/core/runner.rb:119:in `block (3 levels) in run_specs'
    from /Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/rspec-core-3.5.0.beta1/lib/rspec/core/example_group.rb:557:in `run'
    from /Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/rspec-core-3.5.0.beta1/lib/rspec/core/example_group.rb:591:in `run_examples'
    from /Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/rspec-core-3.5.0.beta1/lib/rspec/core/example_group.rb:591:in `map'
    from /Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/rspec-core-3.5.0.beta1/lib/rspec/core/example_group.rb:595:in `block in run_examples'
    from /Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/rspec-core-3.5.0.beta1/lib/rspec/core/example.rb:222:in `run'
    from /Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/rspec-core-3.5.0.beta1/lib/rspec/core/example.rb:431:in `hooks'
    from /Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/rspec-core-3.5.0.beta1/lib/rspec/core/example.rb:431:in `singleton_class'

It looks like the hooks method is the one that's breaking the cache on the example groups instance. I'm not familiar enough with the internals to understand how that's used, but I guess it's just for like before / after stuff? Can we store it somewhere other than the instances' singleton class?

Anyway, if lots of methods are called on the example_group instance, then this may be worth investigating. But if it's not that many, then breaking the cache for that shouldn't matter. If we're not calling that many methods on the example group, then I think we can just close this ticket and keep it in mind for future refactoring efforts.

@myronmarston

This comment has been minimized.

Member

myronmarston commented Mar 7, 2016

Thanks for following up with that detail, @tenderlove. It looks like we may have caught you red handed using something besides puts for debugging :).

Anyhow, you're right about that hooks method. I did some digging of my own into this yesterday and I did not actually find that in my search. I was using a "comment out code bisection" technique, where I kept commenting out code (and/or simplifying to an inlined version for some things) until I narrowed it down to what was causing the serial to increment. When I commented out the hooks usage, the serial still incremented so I didn't look into it our hooks any further (even though I went into the process expecting the hooks to be at fault -- I knew of our use of singleton_class there). I found that the serial was incrementing due to our use of instance_exec.

From what you've said it sounds like both things (our use of singleton_class for hooks and our use of instance_exec to run the example blocks) is causing the serial to increment, and until we can address both we're not going to see the problem go away.

One thing I don't understand is why use of instance_exec is treated by MRI as accessing the singleton class. There's nothing about instance_exec that makes it seem like method caches have to be busted. Of course, you can use things like def and define_method in an instance_exec block, but you can do those things outside an instance_exec block so I don't really get it :(.

@tenderlove do you have any ideas about how we could avoid the use of instance_exec (or at least, avoid using it in a way that triggers the serial increment) given our need to evaluate the blocks in the context of an example group instance to provide the features RSpec provides?

@tenderlove

This comment has been minimized.

tenderlove commented Mar 7, 2016

One thing I don't understand is why use of instance_exec is treated by MRI as accessing the singleton class. There's nothing about instance_exec that makes it seem like method caches have to be busted. Of course, you can use things like def and define_method in an instance_exec block, but you can do those things outside an instance_exec block so I don't really get it :(.

You're right, it's that you can do def and such inside the instance_exec, but if you do that, it's expected to be defined on the singleton class rather than the actual class. So the internals for doing the eval have to allocate the singleton (since it doesn't know what you're going to do inside the block). Doing a def obj.some_method; end will allocate and assign the singleton too.

@tenderlove do you have any ideas about how we could avoid the use of instance_exec (or at least, avoid using it in a way that triggers the serial increment) given our need to evaluate the blocks in the context of an example group instance to provide the features RSpec provides?

Not yet. I don't understand all the use cases yet, so I can't give any good advice (which is why I opened the ticket). I'll poke at RSpec internals more to see if I can better understand what's going on. 😄

@tenderlove

This comment has been minimized.

tenderlove commented Mar 23, 2016

Hi,

I've timeboxed myself to work on this issue and I've hit my time limit, so I'm going to update this ticket with what I've found so far.

I have only focused on removing this call to singleton_class on the example group instance. There are definitely other places where the singleton class is being accessed, but I thought this one would be an easy fix (turns out it's not so easy for me).

This hooks method is really difficult to disconnect from the singleton class because it stores a reference to the singleton class. ISTM, if something needs to be stored on the singleton class for the example group instance, then that thing being stored on the singleton has a 1:1 relationship with the instance. Instead of storing it on the singleton class, why not just store it on the example group instance itself? If "fear of exposing methods on the example instance" is the reason, then just create one instance method (like _rspec_internal_stuff) that returns a context object and store hooks (among other things) there.

I started down the path of creating an object that quacks like a singleton class but is actually just a Plain Old Object:

diff --git a/lib/rspec/core/example.rb b/lib/rspec/core/example.rb
index d568f3e..0c82ef4 100644
--- a/lib/rspec/core/example.rb
+++ b/lib/rspec/core/example.rb
@@ -438,7 +438,11 @@ module RSpec
     private

       def hooks
-        example_group_instance.singleton_class.hooks
+        x = example_group_instance._hooks
+        # HACK: nobody should be accessing `hooks` through the singleton class,
+        # but it seems like they are.
+        example_group_instance.singleton_class.instance_variable_set(:@hooks, x)
+        x
       end

       def with_around_example_hooks
diff --git a/lib/rspec/core/example_group.rb b/lib/rspec/core/example_group.rb
index 7e348db..48a5207 100644
--- a/lib/rspec/core/example_group.rb
+++ b/lib/rspec/core/example_group.rb
@@ -376,11 +376,36 @@ module RSpec

       # @!endgroup

+      class FakeSingletonClass
+        def initialize klass, example_group_instance
+          @klass = klass
+          @example_group_instance = example_group_instance
+        end
+
+        def parent_groups
+          [self] + @klass.parent_groups
+        end
+
+        def hooks
+          @example_group_instance._hooks
+        end
+      end
+
       # @private
       def self.subclass(parent, description, args, registration_collection, &example_group_block)
-        subclass = Class.new(parent)
-        subclass.set_it_up(description, args, registration_collection, &example_group_block)
-        subclass.module_exec(&example_group_block) if example_group_block
+        subclass = Class.new(parent) do
+          def singleton_class
+            puts "Please don't call me! #{caller.first}"
+            super
+          end
+
+          def _hooks
+            @_hooks ||= RSpec::Core::Hooks::HookCollections.new(FakeSingletonClass.new(self.class, self),
+                                                              RSpec::Core::FilterableItemRepository::UpdateOptimized)
+          end
+          set_it_up(description, args, registration_collection, &example_group_block)
+          module_exec(&example_group_block) if example_group_block
+        end

         # The LetDefinitions module must be included _after_ other modules
         # to ensure that it takes precedence when there are name collisions.
@@ -556,7 +581,7 @@ module RSpec
         @currently_executing_a_context_hook = true

         ContextHookMemoized::After.isolate_for_context_hook(example_group_instance) do
-          hooks.run(:after, :context, example_group_instance)
+          example_group_instance._hooks.run(:after, :context, example_group_instance)
         end
       ensure
         before_context_ivars.clear

This made some tests pass, though broke other ones (I was focusing on getting be rspec ./spec/rspec/core/hooks_filtering_spec.rb:336 to pass without accessing the singleton class), but hopefully gives you an idea of what I mean. Eliminating the singleton class as an instance level storage location is an architectural change that I'm not sure I have the time or knowledge to take on. I'm not sure what to do about the instance_exec stuff that @myronmarston mentioned, but unless we can get the code to stop using the singleton class as a storage location, any other fixes won't matter. I feel like I've bitten off more than I can chew. 😞

@tenderlove

This comment has been minimized.

tenderlove commented Mar 24, 2016

Another update, with @matthewd's help, I think we've come up with a way to fix Ruby such that accessing the singleton class won't break the cache for that object. It will only break the cache if you add methods to the singleton instance (like extending an instance with a module or doing def inside an instance_exec). If we can verify that we're not adding new methods to the singleton in RSpec, then I think we could just safely close this issue and say "let Ruby deal with it".

@myronmarston

This comment has been minimized.

Member

myronmarston commented Mar 25, 2016

That would be amazing if this could be solved in Ruby itself :).

@headius

This comment has been minimized.

headius commented Apr 8, 2016

FWIW, I'd still love to see the unnecessary singleton go away. JRuby does not have the cache-busting problem but creating a singleton is still rather expensive (internal caches, method tables, constant tables, and so on).

@xaviershay

This comment has been minimized.

Member

xaviershay commented Jan 15, 2017

Thanks everyone for detailed investigation! Given how invasive I'd naively expect a change around this to be, and that this can be handled (at least in theory) by the Rubies, I'm closing for now.

If someone wants to include actual performance data, or an argument that this would actually be a simple change, I'd reconsider. (For example, something like #2286 )

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment