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

Ever-increasing memory with a custom runner and a single spec file #2767

Open
agis opened this issue Sep 28, 2020 · 7 comments · May be fixed by #2987
Open

Ever-increasing memory with a custom runner and a single spec file #2767

agis opened this issue Sep 28, 2020 · 7 comments · May be fixed by #2987

Comments

@agis
Copy link
Contributor

agis commented Sep 28, 2020

Subject of the issue

In a custom RSpec runner I'm using, I've noticed an ever-increasing memory usage with each spec file (the same file, actually) that the runner executes. I don't know if this expected or not, so I'm opening an issue here to get your insights as well.

Your environment

  • Ruby version: 2.5.5 (also tested with 2.7.1)
  • rspec-core version: 3.9.2

Steps to reproduce

Clone the reproduction repository:

$ git clone git@github.com:agis/rspec-memory-issue.git
$ cd rspec-memory-issue
$ bundle install
$ bundle exec ruby test.rb

Expected behavior

I'd expect memory usage to reach a plateau.

Actual behavior

Memory usage grows indefinitely (reaches some gigabytes after 2-3 minutes). This is probably due to the fact that RSpec creates a class for each describe/it block if the spec file. However, these classes never get garbage collected (which is expected I suppose), but they also get redefined every time the same file gets loaded.

For instance, ObjectSpace.each_object(RSpec::Core::ExampleGroup).each.count shows ever increasing values with each loop:

iteration #1: 28 (a few kilobytes)
...
iteration #1096: 3232 (100MB)
...
iteration #4100: 8552 (325MB)
.....

Likewise, the defined classes look like this:

ObjectSpace.each_object(Class) { |x| puts x }
#...
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::HdisajfidajidjsIajfdklsajFkldsajLkfdsa                                                                        
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::Hmmmmmmm::HeyHeyHey
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::HdisajfidajidjsIajfdklsajFkldsajLkfdsa::FkofkofkoekoFkeoAkofeKaokfEo                                          
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::HdisajfidajidjsIajfdklsajFkldsajLkfdsa                                                                        
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::Hmmmmmmm::HeyHeyHey
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::Hmmmmmmm
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::HdisajfidajidjsIajfdklsajFkldsajLkfdsa::FkofkofkoekoFkeoAkofeKaokfEo                                          
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::HdisajfidajidjsIajfdklsajFkldsajLkfdsa                                                                        
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::HdisajfidajidjsIajfdklsajFkldsajLkfdsa::FkofkofkoekoFkeoAkofeKaokfEo                                          
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::Hmmmmmmm::HeyHeyHey
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::Hmmmmmmm
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::Hmmmmmmm
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::HdisajfidajidjsIajfdklsajFkldsajLkfdsa::FkofkofkoekoFkeoAkofeKaokfEo                                          
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::HdisajfidajidjsIajfdklsajFkldsajLkfdsa::FkofkofkoekoFkeoAkofeKaokfEo                                          
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::HdisajfidajidjsIajfdklsajFkldsajLkfdsa                                                                        
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::Hmmmmmmm::HeyHeyHey
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::Hmmmmmmm
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::Hmmmmmmm::HeyHeyHey
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::Hmmmmmmm
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::HdisajfidajidjsIajfdklsajFkldsajLkfdsa::FkofkofkoekoFkeoAkofeKaokfEo                                          
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::HdisajfidajidjsIajfdklsajFkldsajLkfdsa                                                                        
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::Hmmmmmmm::HeyHeyHey
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::Hmmmmmmm
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::HdisajfidajidjsIajfdklsajFkldsajLkfdsa::FkofkofkoekoFkeoAkofeKaokfEo                                          
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::HdisajfidajidjsIajfdklsajFkldsajLkfdsa                                                                        
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::Hmmmmmmm::HeyHeyHey
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo::Hmmmmmmm
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo
RSpec::ExampleGroups::SomethingWsomewhereFoFoFo
=> 45350

So they're repeatedly defined as different class objects. Is this expected behavior?

Thanks in advance.

@agis agis changed the title Ever-increasing memory usage with a custom runner and a single spec file Ever-increasing memory with a custom runner and a single spec file Sep 29, 2020
@JonRowe
Copy link
Member

JonRowe commented Sep 29, 2020

So they're repeatedly defined as different class objects. Is this expected behavior?

Yes, you've called reset which clears the old constants and allows the specs to be reloaded, you can see the same behaviour from plain Ruby.

# Repeated class re-opening does not creating new classes.
2.7.1 :001 > class AC; class DC; end; end
 => nil
2.7.1 :002 > class AC; class DC; end; end
 => nil
2.7.1 :003 > x = []; ObjectSpace.each_object(Class) { |y| x << y if y.to_s =~ /^AC/ }; x
 => [AC::DC, AC]

# However removing the constant does allow new classes to be created with the same name.
2.7.1 :004 > AC.send :remove_const, "DC"
 => AC::DC
2.7.1 :005 > class AC; class DC; end; end
 => nil
2.7.1 :006 > AC.send :remove_const, "DC"
 => AC::DC
2.7.1 :007 > class AC; class DC; end; end
 => nil
2.7.1 :008 >  x = []; ObjectSpace.each_object(Class) { |y| x << y if y.to_s =~ /^AC/ }; x
 => [AC::DC, AC::DC, AC::DC, AC]

Why do we do this? Because otherwise reloaded files could conflict, its a lot easier to remove the whole thing than it is to try to work out whats changed. Theres also no guarantee you'd be running the same files again, so it makes sense to clean house.

In fact if you skip the reset you should find they get different names (there's conflict detection code), to the "world" that the file is reloaded is irrelevant, it's a new spec file to load and parse.

Would we expect memory usage to go up? Probably not, running this with a manual GC.compact does seem to keep the memory usage down, but not plateau, so there is possible a leak somewhere, interestingly your memory profile output focuses a lot on the option parser.

@agis
Copy link
Contributor Author

agis commented Oct 6, 2020

Would we expect memory usage to go up? Probably not, running this with a manual GC.compact does seem to keep the memory usage down, but not plateau, so there is possible a leak somewhere, interestingly your memory profile output focuses a lot on the option parser.

I've been running GC.compact every 1000 iterations, yet after 10k iterations memory is at ~800MB (from a few kilobytes in the first iterations), so yes, it doesn't make a significant difference.

The memory profile points to optparse as far as "allocated memory/objects" are concerned. But this memory is actually reclaimed by MRI, so I believe it's not relevant in our case. We actually care about "retained memory/objects", and the profile points at rspec-core and specifically rspec/core/metadata.rb.

For reference, I'm attaching the memory profile I took: memory_profile_3453_1601972084.txt Interestingly, the profile reports only a few megabytes (150MB) worth of retained data whereas the dump was taken when the process' RSS was at 2GB. So I suspect that the profile is not accurate. I'll try to dig into this.


That said, if the class objects are never cleared as you demonstrated and are never garbage collected (which they aren't), isn't it expected for the memory to be ever-increasing?

@JonRowe
Copy link
Member

JonRowe commented Oct 6, 2020

That said, if the class objects are never cleared as you demonstrated and are never garbage collected (which they aren't), isn't it expected for the memory to be ever-increasing?

They are cleared by us, the output you are seeing is their name, not the classes themselves. Unless remove_const does actually keep the old class around somewhere, in which case it sound like a Ruby bug, we are keeping no reference to the classes ourselves.

@agis
Copy link
Contributor Author

agis commented Oct 7, 2020

That said, if the class objects are never cleared as you demonstrated and are never garbage collected (which they aren't), isn't it expected for the memory to be ever-increasing?

They are cleared by us, the output you are seeing is their name, not the classes themselves. Unless remove_const does actually keep the old class around somewhere, in which case it sound like a Ruby bug, we are keeping no reference to the classes ourselves.

Actually they're class objects (i.e the actual classes themselves). For example:

[7] pry(main)> whereami

From: /home/hyu/dev/rspec-memory-issue/test.rb:38 :

    33: sleep 3
    34:
    35: loop do
    36:   binding.pry if $debug
    37:
 => 38:   puts "run #{i}"
    39:   i += 1
    40:
    41:   RSpec.reset
    42:   RSpec.clear_examples
    43:

# demonstrating that it's actually classes that are kept around
[12] pry(main)> RSpec.reset
=> nil
[13] pry(main)> RSpec.clear_examples
=> {}
[14] pry(main)> x = ObjectSpace.each_object(Class).to_a.last
=> RSpec::ExampleGroups::SomethingWsomewhereFoFoFo
[15] pry(main)> x.object_id
=> 47382510390120
[16] pry(main)> x.new
=> #<RSpec::ExampleGroups::SomethingWsomewhereFoFoFo (no description provided)>
[20] pry(main)> x.class
=> Class
[21] pry(main)> x.superclass
=> RSpec::Core::ExampleGroup
[26] pry(main)> x.declaration_locations
=> [["/home/hyu/dev/rspec-memory-issue/spec/foo_spec.rb", 3],
 ["/home/hyu/dev/rspec-memory-issue/spec/foo_spec.rb", 4],
 ["/home/hyu/dev/rspec-memory-issue/spec/foo_spec.rb", 5],
 ["/home/hyu/dev/rspec-memory-issue/spec/foo_spec.rb", 6],
 ["/home/hyu/dev/rspec-memory-issue/spec/foo_spec.rb", 12],
 ["/home/hyu/dev/rspec-memory-issue/spec/foo_spec.rb", 13],
 ["/home/hyu/dev/rspec-memory-issue/spec/foo_spec.rb", 14]]


[18] pry(main)> ObjectSpace.each_object(Class).to_a.count
=> 8251
[19] pry(main)> puts i
1313
=> nil

@JonRowe
Copy link
Member

JonRowe commented Oct 7, 2020

Open to suggested improvements, but this isn't a memory leak, it's Ruby being Ruby...

We call remove_const and expect Ruby to not keep around anonymous classes, e.g. classes that don't have a constant anymore. We reuse the constant sure, but the alternative would be to use our name conflict avoiding code, the output would be the same.

We don't keep references to the classes.

@agis
Copy link
Contributor Author

agis commented Oct 9, 2020

I see your point. However, using a simple script, it seems that Ruby does the right thing and garbage collects classes after you remove their respective constants (and therefore they can no longer be referenced so they're eligible for GC):

GC.disable

class Foo
  class Bar
  end
end

puts "Foo.object_id: #{Foo.object_id}"
puts "Foo::Bar.object_id: #{Foo::Bar.object_id}"

puts "Defined classes: "
puts "\t#{ObjectSpace.each_object(Class).select { |c| c.to_s.match?("Foo") }}"

puts
puts "Removed const: #{Foo.send(:remove_const, :Bar)}"
puts

GC.start(immediate_sweep: true, full_mark: true)
puts "GC'ed"
puts

puts "Defined classes: "
puts "\t#{ObjectSpace.each_object(Class).select { |c| c.to_s.match?("Foo") }}"

puts "Foo.object_id: #{Foo.object_id}"
puts "Foo::Bar.object_id: #{Foo::Bar.object_id}"

Executing this outputs (as expected):

$ ruby test2.rb
Foo.object_id: 47452839765820
Foo::Bar.object_id: 47452839765740
Defined classes: 
        [Foo::Bar, Foo]

Removed const: Foo::Bar

GC'ed

Defined classes: 
        [Foo]
Foo.object_id: 47452839765820
Traceback (most recent call last):
test2.rb:27:in `<main>': uninitialized constant Foo::Bar (NameError)

So from this inconsistent behavior between this script and the original rspec script I deduce that in RSpec's case there's some reference somewhere that prevents all these class definitions from being garbage collected. I'll have to get familiar with RSpec's inner workings, but in the meantime, if you have any pointers or ideas, let me know please.

@JonRowe
Copy link
Member

JonRowe commented Oct 9, 2020

No as far as I know we don't hold any reference after a rest, if you find one feel free to open a PR.

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

Successfully merging a pull request may close this issue.

2 participants