Memory leak under Rack::Test

[mattsnyder]

We've been writing our API using Grape and the DSL is great! However as we write more endpoints and test them with RSpec we've seen memory utilization skyrocket! Upwards of 8+G to test ~7 endpoints!

I wrote a spec file to try and isolate the problem and noticed three classes that with every call to an endpoint leave behind numerous objects that cannot be garbage collected.

Here is the spec I wrote that shows the increase in references for these classes: Grape::Route, Grape::Endpoint,Grape::Util::HashStack,Regexp

And after 3 calls to the endpoint, I saw the reference counts go from

"Grape::Route 25 references"
"Grape::Endpoint 36 references"
"Grape::Util::HashStack 50 references"
"Regexp 4386 references"

to

"Grape::Route 47 references"
"Grape::Endpoint 47 references"
"Grape::Util::HashStack 60 references"
"Regexp 4687 references"

require 'spec_helper'

class GcApi < Grape::API
  prefix 'gcapi'
  format :json

  resources :testing do
    get do
      true
    end

    put do
      false
    end
  end
end

UserTesting::Orders::Application.routes.draw do
  mount GcApi => '/'
end

describe GcApi do
 include Rack::Test::Methods
 def app
   subject
 end

  def log(object, message)
    header = "*"*20 + message + "*"*20
    p header
    p object
    p "*"*header.length
  end

  def dumpit(file)
    counts = Hash.new{ 0 }
    ObjectSpace.each_object do |o|
      counts[o.class] += 1
    end
    file = File.open(file, 'w')
    counts.each do |key, val|
      file.puts(key.to_s + "=" + val.to_s)
    end
    file.close
  end

  def show_references(klass)
    count = 0
    ObjectSpace.each_object(klass) do |o|
      count += 1
    end
    p klass.to_s + " #{count} references"
  end

  def accept_header
    { 'HTTP_ACCEPT' => "application/json" }
  end

  before(:all) do
    GC.start
    log ObjectSpace.count_objects, "BEFOREALL"
    # dumpit("before.txt")
    show_references(Grape::Route)
    show_references(Grape::Endpoint)
    show_references(Grape::Util::HashStack)
    show_references(Regexp)
  end

  after(:all) do
    show_references(Grape::Route)
    show_references(Grape::Endpoint)
    show_references(Grape::Util::HashStack)
    show_references(Regexp)
    GC.start
    log ObjectSpace.count_objects, "AFTERALL"
    # dumpit("after.txt")
  end

  it "should run quickly" do #1635
    get "/gcapi/testing.json", nil, {}
    last_response.body.should == "true"
  end

  it "should run longer" do #1635
    get "/gcapi/testing.json", nil, {}
    last_response.should be_empty # false assumption
  end

  it "should run quickly or maybe not" do #409
    put "/gcapi/testing.json", nil, {}
    last_response.body.should == "false"
  end

  # it "should be able to GC" do
  #   GC.start
  #   sleep 5
  #   log ObjectSpace.count_objects, "BEFORESIMPLETEST"
  #   (1+1).should eql(2)
  #   GC.start
  #   sleep 5
  #   log ObjectSpace.count_objects, "AFTERSIMPLETEST"
  # end
end

[dblock]

Just to confirm, this is only happening under RSpec (Rack::Test)? See if you can port the above into Grape's RSpec tests (the above seems to need UserTesting::Orders::Application and I'd like to remove that one first.

[mattsnyder]

As far as I am aware, yes, only under RSpec. UserTesting::Orders::Application is just a Rails app

[mattsnyder]

@dblock I was able to recreate the scenario in the Grape repo's spec suite. See https://github.com/intridea/grape/pull/667

[dblock]

Thanks @mattsnyder. Maybe you can also fix it? :)

[mattsnyder]

Noticing that each get request in a spec generates 4 un-collectable references to Grape::Endpoint.

For example, this test itself generates 4 references (extracted from the PR demonstrating this bug)

 context "when performing a single call against the endpoint" do
    it 'is adding an uncollectable reference to Grape::Endpoint' do
      GC.start
      pre_test_counts = count_references concerns

      get 'gcapi/testing'
      #expect(last_response.body).to eql "Hello World"

      GC.start
      post_test_counts = count_references concerns

      puts post_test_counts
      expect(post_test_counts).to eql pre_test_counts
    end
  end

I'm looking into the why, but any thoughts off the top of your head @dblock ?

[mattsnyder]

@dblock How does reset! work in the Grape::API class? https://github.com/mattsnyder/grape/blob/master/lib/grape/api.rb#L566

I've not seen this approach used before and it appears this is maybe not releasing everything it should.

[dblock]

The reset! call is more like a setup, implemented here. If calling it explicitly fixes the RSpec issue, then maybe that's the way to go. However, it still seems fishy to me that a stable API would continue growing just because you call its methods :)

[mattsnyder]

It does not fix it. I think I see what #reset! is doing now; basically removing all the setup information after the endpoint has added each route via Rack::Mount::add_route.

What I did notice is that it adds a route for each HTTP verb (GET, POST, OPTIONS, etc) even though I've only defined GET. Do you know why that is? I don't think that is the problem, just curious as to why.

[mattsnyder]

Closing this issue. Found that the memory leak was related to mounting the API in a Rails app and then testing the Grape::API using Rack::Test::Methods in the specs which results in the endpoints recompiling for each test ...thus consuming large amounts of memory.

The uncollected references I observed in the linked PR were accurate since Grape::API is a singleton and a Global object so the actual instance will not get garbage collected.

[dblock]

Wait, so what's the fix for this in your tests?

[slauwers]

I would like to reopen this issue. I'm not mounting my Grape API on Rails, however am seeing massive refcount increases.

The first BEFOREALL:

"********************BEFOREALL********************"
{:TOTAL=>344010, :FREE=>135332, :T_OBJECT=>5175, :T_CLASS=>6959, :T_MODULE=>900, :T_FLOAT=>11, :T_STRING=>101073, :T_REGEXP=>1451, :T_ARRAY=>32492, :T_HASH=>7213, :T_STRUCT=>266, :T_BIGNUM=>6, :T_FILE=>4, :T_DATA=>30814, :T_MATCH=>3, :T_COMPLEX=>1, :T_RATIONAL=>61, :T_NODE=>21175, :T_ICLASS=>1074}
"*************************************************"
"Grape::Route 0 references"
"Grape::Endpoint 10 references"
"Grape::Util::HashStack 15 references"
"Regexp 1452 references"

The last AFTERALL:

"Grape::Route 3064 references"
"Grape::Endpoint 1334 references"
"Grape::Util::HashStack 1335 references"
"Regexp 508903 references"
"********************AFTERALL********************"
{:TOTAL=>5260808, :FREE=>2712706, :T_OBJECT=>439000, :T_CLASS=>79518, :T_MODULE=>915, :T_FLOAT=>11, :T_STRING=>562104, :T_REGEXP=>455508, :T_ARRAY=>590082, :T_HASH=>276601, :T_STRUCT=>512, :T_BIGNUM=>6, :T_FILE=>5, :T_DATA=>43944, :T_MATCH=>3, :T_COMPLEX=>1, :T_RATIONAL=>61, :T_NODE=>26442, :T_ICLASS=>73389}
"************************************************"

Result:

Finished in 36.06 seconds (files took 1.19 seconds to load)
29 examples, 0 failures

I'm fairly inexperienced with Ruby, so digging in more is probably going to be difficult, however, I can spend a fair amount of time on this if required. I attempted to use Grape::API.reset! in the after(:each), to no avail.

@dblock Would you have any pointers as to where to look at, or what to do next?

Thanks

[dblock]

Lets reopen this and hopefully hear from @mattsnyder on what he did to debug this.

@slauwers The problem is likely that there's a new reference to a grape API singleton instance that doesn't get cleaned up across tests. First, I would take an existing public project and try to replicate this, beginning with https://github.com/dblock/grape-on-rack and then https://github.com/dblock/grape-on-rails. Make pull requests that do GC.start and all that kind of stuff and demonstrate the problem. I can help debug.

[slauwers]

Thanks @dblock. Will have a look at that. Will get back to you either tonight or early next week.

[slauwers]

Quick progress report:

I spent a few hours trying to reproduce this in a vanilla grape-on-rack application (which my application is based on). I have not yet been successful in re-creating the same memory leak as the one I am noticing in my own app. I'm unsure how RSpec/Rack::Test load the environment for the tests, so I don't know how much of my app I'm supposed to replicate/mimick into the vanilla grape-on-rack app.

I also tried to identify what kind of object was leaking, to try and isolate the cause. As far as I can tell, the types that are not getting collected are "class" and "String", which is about as useful as a bag of bricks. My lack of understanding of Ruby is most definitely not helping here.

My methodology is probably flawed, so I'll try with a fresh start on monday.

[mattsnyder]

@slauwers @dblock I found under Rails/RSpec my Grape Endpoints were getting loaded into memory like new for each test when I used the Rack::Test:Methods. I went back to using the Rails RSpec request spec helper methods. I still however noticed ref count increases while running the Rails app, but nowhere near what it was doing under test.

I'm currently using Grape with Goliath. I'm configure it to check ref counts, but so far I haven't seen any memory problems.

[slauwers]

OK, so this is my fresh start:

I'm seeing a fairly big increase in refs to Grape::Route and Grape::Endpoint (3060 and 1324 respectively) over the course of my same 29-strong test suite. I've used Robert Klemme's ostats to isolate a bit more precisely what is going on. I've slightly modified the version he proposed to only print the lines where there is a delta and filter the classes that are being collected. The result is as follows:

Grape::Route                                                         87 delta         71
Grape::Util::HashStack                                               68 delta         28
Grape::Endpoint                                                      56 delta         29
Grape::Request                                                        1 delta          1
Grape::Cookies                                                        1 delta          1

@dblock The output above comes directly from grape-on-rack. Is this sufficient to show that there is a leak, or do you need me to dig in further? Would you like me to create PR so you can validate these results on your side?

[dblock]

Yes, please create a PR so more people can help. Thanks!

[slauwers]

FYI, PR created on the grape-on-rack repository. I'm only noticing some inconsistencies in the way endpoint is being used (vs @endpoint) lines 25, 338, 365, 495 and 524 in lib/grape/api.rb, but nothing more than that.

I'm afraid I've spent a bit more than what I could on this issue. Here's hoping to someone else finding the next step. I'll try to pick up on this tomorrow or next week.

[dblock]

@slauwers @mattsnyder I spent a bit of time on this, using code in https://github.com/dblock/grape-on-rack/pull/8.

First, I cannot reproduce the fact that every get generates a new Endpoint reference (or anything runaway). Make sure to add GC.start in an after block to get consistent output.

  after(:all) do
    GC.start
    @stats.collect!
    @stats.display
  end

I can however consistently reproduce that every time we declare an API it doesn't get GC-ed between tests. This is normal, if you're going to create a new type that inherits from Grape::API, it mounts endpoints and holds onto them. But that's not a leak.

module Acme
  class API < Grape::API
  ...
  end
end

Here Acme::API will hold onto its endpoints every time, you can examine Acme::API.endpoints to see them. I've experimented making many requests to this in specs and memory usage is stable, and I don't see any leaks within the API itself.

So, help me see a leak here where iterating over something produces a very large number of allocated objects?

[mattsnyder]

I was only seeing it under test

Sent from my iPhone

On Jan 2, 2015, at 1:27 PM, Daniel Doubrovkine (dB.) @dblockdotorg notifications@github.com wrote:

@slauwers @mattsnyder I spent a bit of time on this, using code in dblock/grape-on-rack#8.

First, I cannot reproduce the fact that every get generates a new Endpoint reference (or anything runaway). Make sure to add GC.start in an after block to get consistent output.

after(:all) do GC.start @stats.collect! @stats.display end I can however consistently reproduce that every time we declare an API it doesn't get GC-ed between tests. This is normal, if you're going to create a new type that inherits from Grape::API, it mounts endpoints and holds onto them. But that's not a leak.

module Acme class API < Grape::API ... end end Here Acme::API will hold onto its endpoints every time, you can examine Acme::API.endpoints to see them.

Help me see a leak here where iterating over something produces a very large number of allocated objects?

— Reply to this email directly or view it on GitHub.

[dblock]

@mattsnyder That's totally fine, I still would like a way to see it myself ;)

[slauwers]

@dblock Having a look at this now. Will get back to you ASAP.

[slauwers]

@dblock Indeed, this may not have been clear in my previous comments, I was unable to reproduce an issue where upon each GET request there was un-GC'd data. I tried from fresh to try and isolate something, however was unsure whether what I was showing was a leak or not. Hence my comment:

Is this sufficient to show that there is a leak, or do you need me to dig in further?

I do however notice this problem (the leaks) in my software. I can't post results of OStats on my software, considering I'm using Sequel and this seems to mess with o.class.name; I'm getting a lot of nil errors if I attempt to use OStat.

I can't work on this any further today, however I'll try to clear some time during the week to reproduce the issue in test. Sorry for the waste of time.

[dblock]

Thanks @slauwers, looking forward to hearing from you.

[yr0]

For anyone having similar trouble and thinking it is Grape's memory leak, please check if you are not doing what is described below.

Here's rough reproduction of what seems like a Grape leak:

require 'grape'
require 'rack/test'

class TestCl < Grape::API
  prefix "api"

  get do
  end
end

describe TestCl do
  include Rack::Test::Methods

  let(:app) { subject }

  100.times do
    it "returns all when get '/'" do
      get "api/"
      expect(1).to eq 1
    end
  end

end

The specs above gradually slow down to almost-infinity devouring away your resources. Here's how to 'fix' it:

require 'grape'
require 'rack/test'

class TestCl < Grape::API
  prefix "api"

  get do
  end
end

describe "TestCl" do
  include Rack::Test::Methods

  let(:app) { TestCl }

  100.times do
    it "returns all when get '/'" do
      get "api/"
      expect(1).to eq 1
    end
  end

end

I.e. point the app to your actual Grape::API class, and not to the subject reference.

[slauwers]

@yr0 Thanks a bunch. This has indeed solved the problem I was having. @dblock, I guess we can close this one.

[dblock]

This makes sense. Every time you use subject it creates an instance of TestCl, which does work, but never gets GCed and is not what you're supposed to use since Grape APIs are classes, not instances. I'd appreciate if @slauwers and @yr0 could quickly parse through Grape tests and README and see if we do this anywhere and potentially PR some doc. Otherwise I think it's one of those gotchas and people will make this "mistake" anyway. Closing this issue.

[slauwers]

@grape: I'm in the process of leaving the company this account is linked to, so doing any kind of work on this during business hours is going to be tricky. I'll see if I can work through this in my spare time, on my @teotwaki account.

On 1 April 2015 at 14:06, Daniel Doubrovkine (dB.) @dblockdotorg < notifications@github.com> wrote:

This makes sense. Every time you use subject it creates an instance of TestCl, which does work, but never gets GCed and is not what you're supposed to use since Grape APIs are classes, not instances. I'd appreciate if @slauwers https://github.com/slauwers and @yr0 https://github.com/yr0 could quickly parse through Grape tests and README and see if we do this anywhere and potentially PR some doc. Otherwise I think it's one of those gotchas and people will make this "mistake" anyway. Closing this issue.

— Reply to this email directly or view it on GitHub https://github.com/intridea/grape/issues/665#issuecomment-88452241.