failed to allocate memory

[Brandon Keepers]

I was chatting with erh on IRC and he asked me to post here about my
error.

I have a Rails app running in Passenger with mongo 0.9 and after a few
minutes of use, I get the following error:

NoMemoryError (failed to allocate memory):
/usr/lib/ruby/gems/1.8/gems/mongodb-mongo-0.9/lib/mongo/db.rb:
326:in `recv'
/usr/lib/ruby/gems/1.8/gems/mongodb-mongo-0.9/lib/mongo/db.rb:
326:in `receive_full'
/usr/lib/ruby/gems/1.8/gems/mongodb-mongo-0.9/lib/mongo/cursor.rb:
206:in `object_from_stream'
/usr/lib/ruby/gems/1.8/gems/mongodb-mongo-0.9/lib/mongo/cursor.rb:
191:in `next_object_on_wire'
/usr/lib/ruby/gems/1.8/gems/mongodb-mongo-0.9/lib/mongo/cursor.rb:
157:in `read_objects_off_wire'
/usr/lib/ruby/gems/1.8/gems/mongodb-mongo-0.9/lib/mongo/cursor.rb:
153:in `read_all'
/usr/lib/ruby/gems/1.8/gems/mongodb-mongo-0.9/lib/mongo/cursor.rb:
217:in `send_query_if_needed'
/usr/lib/ruby/gems/1.8/gems/mongodb-mongo-0.9/lib/mongo/cursor.rb:
195:in `refill_via_get_more'
/usr/lib/ruby/gems/1.8/gems/mongodb-mongo-0.9/lib/mongo/cursor.rb:
179:in `num_remaining'
/usr/lib/ruby/gems/1.8/gems/mongodb-mongo-0.9/lib/mongo/cursor.rb:
50:in `more?'
/usr/lib/ruby/gems/1.8/gems/mongodb-mongo-0.9/lib/mongo/cursor.rb:
116:in `to_a'

The server has 512MB of RAM. Watching `free -m` at the time of the
error shows ~250MB of free memory. We have passenger limited to 4 app
instances. After the error, the instance taking up the most memory
was using 60MB.

Any ideas?

Thanks,
Brandon

[Michael Dirolf]

Hmm - I'll be sure to take a look at this when I get a chance and see
if I can come up with anything.

[Michael Dirolf]

So the line that is failing is trying to do a simple recv call on a
socket. It's even more confusing that it seems like your server has
memory available but for some reason the ruby process is failing to
allocate it. I don't have any real thoughts / suggestions here without
access to the box in question.

If you're able to explore more let us know what you find - if it is
somehow an issue with the ruby driver we'd love to figure this out.

[Michael Dirolf]

out of curiosity, are you using the c extension? if so can you try the
same again after uninstalling the c extension?

[John Nunemaker]

I had him install that too and it kept happening I think. I'm going to
have him try logging stuff in the driver so we can see if it is a
specific call or any call after a certain amount of time. Maybe we can
get more specific data.

[Shane Hanna]

Did anything come of this? I have the same issue now.

My application is multi-threaded, event machine + merb under Ruby
1.9.1 and Mongo 0.9.6 if that helps at all. I'll continue to try and
nail it down to something easily testable.

Oh I'm also getting the following run time error occasionally. I
assume mongo is having issues reading back stuff it already managed to
serialize. Version issues between the ruby driver and the db?

Unknown type 103, key =
/home/shane/projects/oursignal/gems/gems/mongodb-mongo-0.9/lib/mongo/
util/bson.rb:223:in `deserialize'
/home/shane/projects/oursignal/gems/gems/mongodb-mongo-0.9/lib/mongo/
cursor.rb:209:in `object_from_stream'
/home/shane/projects/oursignal/gems/gems/mongodb-mongo-0.9/lib/mongo/
cursor.rb:191:in `next_object_on_wire'
/home/shane/projects/oursignal/gems/gems/mongodb-mongo-0.9/lib/mongo/
cursor.rb:157:in `read_objects_off_wire'
/home/shane/projects/oursignal/gems/gems/mongodb-mongo-0.9/lib/mongo/
cursor.rb:153:in `read_all'
/home/shane/projects/oursignal/gems/gems/mongodb-mongo-0.9/lib/mongo/
cursor.rb:217:in `send_query_if_needed'
/home/shane/projects/oursignal/gems/gems/mongodb-mongo-0.9/lib/mongo/
cursor.rb:195:in `refill_via_get_more'
/home/shane/projects/oursignal/gems/gems/mongodb-mongo-0.9/lib/mongo/
cursor.rb:179:in `num_remaining'
/home/shane/projects/oursignal/gems/gems/mongodb-mongo-0.9/lib/mongo/
cursor.rb:56:in `next_object'
/home/shane/projects/oursignal/gems/gems/mongodb-mongo-0.9/lib/mongo/
collection.rb:73:in `find_first'

Shane.

On Jul 8, 10:34 am, John Nunemaker <nunema...@gmail.com> wrote:
> I had him install that too and it kept happening I think. I'm going to  
> have him try logging stuff in the driver so we can see if it is a  
> specific call or any call after a certain amount of time. Maybe we can  
> get more specific data.
>

> On Jul 7, 2009, at 4:07 PM, Michael Dirolf <m...@10gen.com> wrote:
>
>
>
> > out of curiosity, are you using the c extension? if so can you try the
> > same again after uninstalling the c extension?
>
> > On Jul 7, 2009, at 3:49 PM, Michael Dirolf wrote:
>
> >> So the line that is failing is trying to do a simple recv call on a
> >> socket. It's even more confusing that it seems like your server has

> >>memoryavailable but for some reason the ruby process is failing to
> >>allocateit. I don't have any real thoughts / suggestions here

> >>>> error shows ~250MB of freememory. We have passenger limited to 4

[Michael Dirolf]

> Did anything come of this? I have the same issue now.
>
> My application is multi-threaded, event machine + merb under Ruby
> 1.9.1 and Mongo 0.9.6 if that helps at all. I'll continue to try and
> nail it down to something easily testable.

We haven't any luck tracking this down. Are you using the C extension?
If so can you try again after uninstalling it? Shooting in the dark a
bit.

> Oh I'm also getting the following run time error occasionally. I
> assume mongo is having issues reading back stuff it already managed to
> serialize. Version issues between the ruby driver and the db?
>
> Unknown type 103, key =
> /home/shane/projects/oursignal/gems/gems/mongodb-mongo-0.9/lib/mongo/
> util/bson.rb:223:in `deserialize'
> /home/shane/projects/oursignal/gems/gems/mongodb-mongo-0.9/lib/mongo/
> cursor.rb:209:in `object_from_stream'
> /home/shane/projects/oursignal/gems/gems/mongodb-mongo-0.9/lib/mongo/
> cursor.rb:191:in `next_object_on_wire'
> /home/shane/projects/oursignal/gems/gems/mongodb-mongo-0.9/lib/mongo/
> cursor.rb:157:in `read_objects_off_wire'
> /home/shane/projects/oursignal/gems/gems/mongodb-mongo-0.9/lib/mongo/
> cursor.rb:153:in `read_all'
> /home/shane/projects/oursignal/gems/gems/mongodb-mongo-0.9/lib/mongo/
> cursor.rb:217:in `send_query_if_needed'
> /home/shane/projects/oursignal/gems/gems/mongodb-mongo-0.9/lib/mongo/
> cursor.rb:195:in `refill_via_get_more'
> /home/shane/projects/oursignal/gems/gems/mongodb-mongo-0.9/lib/mongo/
> cursor.rb:179:in `num_remaining'
> /home/shane/projects/oursignal/gems/gems/mongodb-mongo-0.9/lib/mongo/
> cursor.rb:56:in `next_object'
> /home/shane/projects/oursignal/gems/gems/mongodb-mongo-0.9/lib/mongo/
> collection.rb:73:in `find_first'

If there is any way you can get a repeatable test case from this that
would be a huge help.

[scottmotte]

This error has also occurred with me after running mongodb for
approximately 4 days with an application.

http://files.getdropbox.com/u/190299/failed-to-allocate.png

My app is merb with Ruby Enterprise 1.8.6 patch 287. I'm on mongo
0.9.6, and using the mongo ruby driver 0.9. I also did not have any
instances running hot, and had plenty of free memory on a 512mb slice.

I am not using the c extension gem. I will give that a shot and post
back - though it will probably be apprx another 4 days I'm guessing.

[Michael Dirolf]

I'll take another look and see if I can figure anything out with this.
Any work towards an easy to reproduce test case would be greatly
appreciated, if possible.

[Nicolas Fouché]

Brandon,

please check this discussion about Passenger forks
http://groups.google.com/group/mongodb-user/browse_thread/thread/f31e2d23de38136a
and tell us if it resolves your problem.

Nicolas

> error shows ~250MB of freememory. We have passenger limited to 4 app  

[Michael Dirolf]

Scott can you paste your entire stack trace somewhere?

On Aug 1, 2009, at 2:55 PM, scottmotte wrote:

>

> This error has also occurred with me after running mongodb for
> approximately 4 days with an application.
>
> http://files.getdropbox.com/u/190299/failed-to-allocate.png
>
> My app is merb with Ruby Enterprise 1.8.6 patch 287. I'm on mongo
> 0.9.6, and using the mongo ruby driver 0.9. I also did not have any
> instances running hot, and had plenty of free memory on a 512mb slice.
>
> I am not using the c extension gem. I will give that a shot and post
> back - though it will probably be apprx another 4 days I'm guessing.
>
>
>
> On Jul 24, 7:30 am, Michael Dirolf <m...@10gen.com> wrote:
>>> Did anything come of this? I have the same issue now.
>>
>>> My application is multi-threaded, event machine + merb under Ruby
>>> 1.9.1 and Mongo 0.9.6 if that helps at all. I'll continue to try and
>>> nail it down to something easily testable.
>>
>> We haven't any luck tracking this down. Are you using the C
>> extension?
>> If so can you try again after uninstalling it? Shooting in the dark a
>> bit.
>>
>>
>>
>>> Oh I'm also getting the following run time error occasionally. I
>>> assume mongo is having issues reading back stuff it already
>>> managed to
>>> serialize. Version issues between the ruby driver and the db?
>>
>>> Unknown type 103, key =

[scottmotte]

Ok, it occurred again. 6 days later this time.

here's the stack trace. http://gist.github.com/164081

You can actually go on and look at it right now though Michael. I'll
leave it up through this afternoon.

Login with dude/dude

Following this, I think I'm just gonna set things up to restart the db
once a day until a solution is found.

On Aug 5, 10:39 am, Michael Dirolf <m...@10gen.com> wrote:
> Scott can you paste your entire stack trace somewhere?
>
> On Aug 1, 2009, at 2:55 PM, scottmotte wrote:
>
>
>
> > This error has also occurred with me after running mongodb for
> > approximately 4 days with an application.
>
> >http://files.getdropbox.com/u/190299/failed-to-allocate.png
>
> > My app is merb with Ruby Enterprise 1.8.6 patch 287. I'm on mongo
> > 0.9.6, and using the mongo ruby driver 0.9. I also did not have any

> > instances running hot, and had plenty of freememoryon a 512mb slice.

[scottmotte]

Sorry, the url on that was http://staging.twinstang.com login: dude,
password: dude to view the stack trace.

On Aug 5, 10:39 am, Michael Dirolf <m...@10gen.com> wrote:
> Scott can you paste your entire stack trace somewhere?
>
> On Aug 1, 2009, at 2:55 PM, scottmotte wrote:
>
>
>
> > This error has also occurred with me after running mongodb for
> > approximately 4 days with an application.
>
> >http://files.getdropbox.com/u/190299/failed-to-allocate.png
>
> > My app is merb with Ruby Enterprise 1.8.6 patch 287. I'm on mongo
> > 0.9.6, and using the mongo ruby driver 0.9. I also did not have any

> > instances running hot, and had plenty of freememoryon a 512mb slice.

[scottmotte]

Michael, I think this might be related to an array key being updated.
Can you let me know that you were able to look at my stack trace. I'm
gonna restart this and see if I can repeat error.

On Aug 7, 11:33 am, scottmotte <sc...@scottmotte.com> wrote:
> Sorry, the url on that washttp://staging.twinstang.com  login: dude,

[scottmotte]

Ok, the error rescued itself. I'm going to try to repeat the issue
now.

[Michael Dirolf]

actually it's not letting me log in - but i saw the link you pasted so
hopefully that is enough.

[scottmotte]

I'm closer on this Michael. I can somewhat reproduce it in my app now
- and I can reproduce it locally running bin/merb on mongrel
(essentially script/server). Therefore, I think we can rule out it
being a passenger issue.

Here's my stack trace:
http://gist.github.com/164488

Here's what I'm doing:
I have pilots similar to twitter users where the pilots can follow and
unfollow each other. I keep this information in an array of followers
[], and following[] for each user document.

When a user clicks follow an action gets called that calls @user.follow
(followed_user) and vice versa for @user.unfollow(followed_user). When
I do each back and forth with each other quickly, I occasionally run
into the memory allocation error - so it seems to be related to
deleting from the array field and/or making uniq, and/or deleting an
item from an array field.

def follow(followed_user)
if followed_user.id != id
# update @user's followING list
self.following << followed_user.id
self.following.uniq! # make unique
# update @followed_user followERS list
followed_user.followers << id
followed_user.followers.uniq!
# make the saves
self.save
followed_user.save
end
end

def unfollow(followed_user)
if followed_user.id != id
# update @user's followING list
self.following.delete(followed_user.id)
# update @followed_user followERS list
followed_user.followers.delete(id)
# make the saves
self.save
followed_user.save
end
end


There is a catch though. This only occurs when I am logged in with a
user that has more than a 1,000 flights. I can't get this to occur
with a user that just has like 20 flights so it seems to be related to
the number of flights. Flights are to a pilot like tweets are to a
twitter user.

class Flight
belongs_to :user
end

class User
has_many :flights
end

Since, there is a relationship intertwined here and the error only
happens when my user who has many flights and who is doing the
following/unfollowing maybe it is related to the way mongodb builds
those relationships and stores them in RAM for quick access?

I hope that helps some more. I'm going to try to look into things some
more, but that is as far as I can go I think without some more
direction.

[scottmotte]

Ok, i've determined now it's related just to my follow method. And the
more 'flights' the increased chance for the error to occur. I'm now at
over 2,000 flights and the error occurs almost every time I follow.

Getting closer!

> ...
>
> read more »

[scottmotte]

Wow, this is related to merb's run_later or I guess to threading in
general.

Here's my action:

if @user.follow(followed_user)
run_later do
send_mail(UserMailer, :follow, { :from =>
AppConfig.site.email, :to => followed_user.email, :subject => "#
{@user.login} is now following you on Twinstang!" }, { :followed_user
=> followed_user, :follower => @user })
end
redirect "/#{followed_user.login}", :message => {:notice =>
"Follow was successful"}
else
redirect "/#{followed_user.login}", :message => {:error => "You
can't follow yourself."}
end

If I remove run_later I do not get the error. More specifically, I
just have to remove the :followed_user => followed_user portion. I
tried renaming variables thinking somehow there was a name conflict
with followed_user, but that is not the case.

It has something to do with threading then I suppose - since one app
having the issue above was multi-threaded, the other was using
passenger, and my own was using merb's run_later to spin off a task
into another thread.

Additionally, if I move the run_later block above the @user.follow
(followed_user) method, I instead get a Type Error: no c decoder for
this type yet (0) http://gist.github.com/164531

> ...
>
> read more »

[scottmotte]

On the last post, ignore the part 'More specifically, I just have to
remove the :followed_user => followed_user portion.' I was wrong
there, I still have to remove the entire send_mail method

On Aug 8, 3:02 pm, scottmotte <sc...@scottmotte.com> wrote:
> Wow, this is related to merb's run_later or I guess to threading in
> general.
>
> Here's my action:
>
>     if @user.follow(followed_user)
>       run_later do
>         send_mail(UserMailer, :follow, { :from =>
> AppConfig.site.email, :to => followed_user.email, :subject => "#

> {...@user.login} is now following you on Twinstang!" }, { :followed_user

> ...
>
> read more »

[Michael Dirolf]

Scott,

Thanks for all of the details and for keeping us posted with your
efforts here. I've been working on recreating this failure in a test
case using the ruby driver directly, not through a web server -
focusing on playing around with threads since you seemed to narrow the
issue down to that.

So far no direct success but I have found a couple issues with
threading in the driver which are fixed in the newly released 0.11 -
give this a shot and keep reporting here - hopefully we'll figure this
one out soon.

- Mike

[scottmotte]

Michael. Great work, and thank you. Finally got around to installing >
0.11 and things are working well. I've repeatedly tried to repeat the
error and it has not re-occurred. You solved that threading issue.
Thanks.

On Aug 10, 1:24 pm, Michael Dirolf <m...@10gen.com> wrote:
> Scott,
>
> Thanks for all of the details and for keeping us posted with your  
> efforts here. I've been working on recreating this failure in a test  
> case using the ruby driver directly, not through a web server -  
> focusing on playing around with threads since you seemed to narrow the  
> issue down to that.
>
> So far no direct success but I have found a couple issues with  
> threading in the driver which are fixed in the newly released 0.11 -  
> give this a shot and keep reporting here - hopefully we'll figure this  
> one out soon.
>
> - Mike
>
> On Aug 8, 2009, at 7:34 PM,scottmottewrote:
>
>
>
> > On the last post, ignore the part 'More specifically, I just have to
> > remove the :followed_user => followed_user portion.' I was wrong
> > there, I still have to remove the entire send_mail method
>

> >> On Aug 8, 1:56 pm,scottmotte<sc...@scottmotte.com> wrote:
>
> >>> Ok, i've determined now it's related just to my follow method. And  
> >>> the
> >>> more 'flights' the increased chance for the error to occur. I'm  
> >>> now at
> >>> over 2,000 flights and the error occurs almost every time I follow.
>
> >>> Getting closer!
>

> ...
>
> read more »

[Michael Dirolf]

great, let us know if you run into any more issues.