rails/ruby memory leak
ara.t.howard
i've been chasing my tail on a tiny memory leak for a few days. i
isolated the cause to what amounts to a rails project with database
sessions enabled. now i'm not sure that the leak is in rails, in fact
i think it's in ruby's cgi/session.rb but i want to gather a few data
points to confirm the leak i'm seeing. if you have a little time,
check out
http://drawohara.tumblr.com/post/13655303
or just grab the project from
http://s3.amazonaws.com/drawohara.com.downloads/leak.tgz
and get it running on your box. it should be *very* quick to do if
you have sqlite3 installed. running it is also easy, but seeing the
leak can take a bit of time - 30 minutes to 6 hours depending on how
fast your box can hammer ./script/server. anyhow, people can report
here or to me directly. i'll summarize my findings and, if there is
in fact a leak in either ruby or rails - follow up with a bug report.
kind regards.
Aleksey Kondratenko
> hi all
>
> i've been chasing my tail on a tiny memory leak for a few days. i
> isolated the cause to what amounts to a rails project with database
> sessions enabled. now i'm not sure that the leak is in rails, in fact
> i think it's in ruby's cgi/session.rb but i want to gather a few data
> points to confirm the leak i'm seeing. if you have a little time,
> check out
About a month ago I've found similar (or, probably, same) leak while
checking our application for leaks. It leaks very slow. And it's seems
to be not Rails issue. Something with $1, $2, ... variable handling in
ruby itself. I think I still have those valgrind report files at home.
I had not enough time to dig it seriously deep and code in that place of
MRI is not very easy, so I gave up.
ara.t.howard
On Oct 1, 2007, at 5:54 AM, Aleksey Kondratenko wrote:
>
> About a month ago I've found similar (or, probably, same) leak while
> checking our application for leaks. It leaks very slow. And it's seems
> to be not Rails issue. Something with $1, $2, ... variable handling in
> ruby itself. I think I still have those valgrind report files at home.
>
> I had not enough time to dig it seriously deep and code in that
> place of
> MRI is not very easy, so I gave up.
that is good to know. everyone who has reported so far has seen the
same results: a very slow leak over time. of course it only shows up
with sessions, but that is going to affect just about every rails
project. at this point i'm more concerned with finding a workaround
in rails than trying to patch ruby - but i'm not sure if it's
possible. i'm running out of steam too. nevertheless this is a
pretty steady leak - it should be fixable.
cheers.
a @ http://drawohara.com/
--
we can deny everything, except that we have the possibility of being
better. simply reflect on that.
h.h. the 14th dalai lama
ara.t.howard
> About a month ago I've found similar (or, probably, same) leak while
> checking our application for leaks. It leaks very slow. And it's seems
> to be not Rails issue. Something with $1, $2, ... variable handling in
> ruby itself. I think I still have those valgrind report files at home.
>
> I had not enough time to dig it seriously deep and code in that place of
> MRI is not very easy, so I gave up.
i had forgotten to mention: i do NOT see the leak using FileStore
sessions - only when db sessions are turned on do i see the leak. my
whole app does nothing but render a single string so sessions have
been the only variable. did you notice this? how bare bones of an
app did you test and see this behavior? i've gotten in about 10
reports now and everyone is seeing this slow memory consumption: at
this point i still think it's in ruby but the fact that only database
sessions seem to trigger it has me worried.
cheers.
Piyush Ranjan
Although I do need to hack a few things to show flash and/or error messages as sessions are switched off but I feel it is worth it.
Frederick Cheung
On Oct 1, 9:14 pm, "Piyush Ranjan" <piyush...@gmail.com> wrote:
> Just a thought : I do not use sessions in most of my critical applications
> which need to serve more than 10K req/sec (a magic no. I have zeroed upon).
> I rely on a completely cookie based authentication system which AFAIK is
> quiet safe(a lot of central auth system use such an approach), it gives me a
> major performance boosthttp://pranjan.blogspot.com/2007/07/wanna-make-your-rails-app-faster....
Or of course use the new cookie-base session store.
Fred
ara.t.howard
On Oct 1, 2:14 pm, "Piyush Ranjan" <piyush...@gmail.com> wrote:
> Just a thought : I do not use sessions in most of my critical applications
> which need to serve more than 10K req/sec (a magic no. I have zeroed upon).
> I rely on a completely cookie based authentication system which AFAIK is
> quiet safe(a lot of central auth system use such an approach), it gives me a
> major performance boosthttp://pranjan.blogspot.com/2007/07/wanna-make-your-rails-app-faster....
> Although I do need to hack a few things to show flash and/or error messages
> as sessions are switched off but I feel it is worth it.
that's very interesting indeed. i'm just about do confirm that the
normal file based sessions do not leak and also test stephan kaas'
alternate db backed sessions. if both do not leak i can narrow my
search to rails' activerecord store. if either do i'll be 99% sure
the leak is in ruby and probably have to resort to dmalloc and co.
uggh.
your suggestion, however, is a very good one and could be quite
suitable for our application. thanks a bunch.
ara.t.howard
>
> that's very interesting indeed. i'm just about do confirm that the
> normal file based sessions do not leak and also test stephan kaas'
> alternate db backed sessions. if both do not leak i can narrow my
> search to rails' activerecord store. if either do i'll be 99% sure
> the leak is in ruby and probably have to resort to dmalloc and co.
> uggh.
>
so far, after > 100,000 requests neither FileStore or SQLSessionStore
are not leaking. only ActiveRecordStore is...
Michael Koziarski
> are not leaking. only ActiveRecordStore is...
What rev are you testing? Does it include my new attributes code?
That broke ARStore initially...
--
Cheers
Koz
ara.t.howard
>
> What rev are you testing?
cfp:~ > rails --version
Rails 1.2.3
cfp:~ > ruby --version
ruby 1.8.6 (2007-03-13 patchlevel 0) [i686-darwin8.9.1]
cfp:~ > uname -srm
Darwin 8.10.1 i386
cfp:~ > gem list sqlite3
*** LOCAL GEMS ***
sqlite3-ruby (1.2.1)
SQLite3/Ruby is a module to allow Ruby scripts to interface with a
SQLite3 database.
think that's all that's relevant.... (btw i see the leak on mysql and
postgresql too). more info, including test app, here:
http://drawohara.tumblr.com/post/13655303
> Does it include my new attributes code?
> That broke ARStore initially...
can you give me a quick grep to tell?
cheers.
ara.t.howard
ran for 300,000 requests with 1.2.3 and FIleStore - no leak.
check checked out edge and am testing the new cookie based sessions,
then i'll test the database store with edge...
ara.t.howard
>
> What rev are you testing? Does it include my new attributes code?
> That broke ARStore initially...
>
testing against svn rails shows file and cookie stores not leaking but
activerecord store continuing to leak.
Michael Koziarski
> activerecord store continuing to leak.
So it's not my new attribute code.... I did enjoy the benchmarks you
published though ...
I have another report of a memory leak of some sort which I'm
currently investigating, if I can track it down I'll let you know...
--
Cheers
Koz
ara.t.howard
On Oct 4, 2007, at 12:14 AM, Michael Koziarski wrote:
>
>> testing against svn rails shows file and cookie stores not leaking
>> but
>> activerecord store continuing to leak.
>
> So it's not my new attribute code.... I did enjoy the benchmarks you
> published though ...
yeah it looks like we can't blame you ;-)
i'm not sure where to go from here - dike (leak detector) keeps
suggesting that it's somehow cgi/session.rb:165 that's leaking with
arstore but i made zero progress hacking around and above that code
to eliminate the leak, also it's odd that file store also uses cgi/
session.rb yet does not leak... so, at this point, my gut says it's
just something peculiar about the way in which the session lib is
used from ar store or, just as likely, some obscure leak in ruby
itself that's causing the problem. however, knowing that i can drop
cookie sessions in, eliminate the leak, and get a huge speed boost -
is mighty powerful motivation not to fix ar store ;-) i'll probably
give one more look at debugging in in edge and then cry 'uncle'.
>
> I have another report of a memory leak of some sort which I'm
> currently investigating, if I can track it down I'll let you know...
have you checked out dike?
http://codeforpeople.com/lib/ruby/dike/dike-0.0.3/README
gem install dike
i'd be curious to know if it helped you any.
Jeremy Kemper
> i'm not sure where to go from here - dike (leak detector) keeps
> suggesting that it's somehow cgi/session.rb:165 that's leaking with
> arstore but i made zero progress hacking around and above that code
> to eliminate the leak, also it's odd that file store also uses cgi/
> session.rb yet does not leak... so, at this point, my gut says it's
> just something peculiar about the way in which the session lib is
> used from ar store or, just as likely, some obscure leak in ruby
> itself that's causing the problem. however, knowing that i can drop
> cookie sessions in, eliminate the leak, and get a huge speed boost -
> is mighty powerful motivation not to fix ar store ;-) i'll probably
> give one more look at debugging in in edge and then cry 'uncle'.
Hey Ara, I noticed you're running 1.8.6 patchlevel 0. Could you try
with the current 1.8.6?
I hammered your test app and see rsize solidly between 20428-20532 and
object count consistently alternating between 144773 and 38070 +- 3.
I'm on ruby 1.8.6 (2007-05-30 patchlevel 5000) [i686-darwin8.9.1]
Best,
jeremy
ara.t.howard
On Oct 4, 2007, at 3:53 PM, Jeremy Kemper wrote:
>
> Hey Ara, I noticed you're running 1.8.6 patchlevel 0. Could you try
> with the current 1.8.6?
>
will do.
> I hammered your test app and see rsize solidly between 20428-20532 and
> object count consistently alternating between 144773 and 38070 +- 3.
>
for how many requests? for me it takes a good 50-100k to
definitively see the leak - as amazing as that sounds...
> I'm on ruby 1.8.6 (2007-05-30 patchlevel 5000) [i686-darwin8.9.1]
i'll report back tomorrow or whenever i reach 100k requests.
Jeremy Kemper
> > I hammered your test app and see rsize solidly between 20428-20532 and
> > object count consistently alternating between 144773 and 38070 +- 3.
>
> for how many requests? for me it takes a good 50-100k to
> definitively see the leak - as amazing as that sounds...
I stopped at just over 25000 requests to give my laptop fan a rest, poor thing.
I'll try again and let it run longer.
jeremy
Nathaniel Brown
Anyone reference a blog post or two I can learn from?
Nathaniel Steven Henry Brown
604-724-6624
ara.t.howard
On Oct 4, 2007, at 3:53 PM, Jeremy Kemper wrote:
> I'm on ruby 1.8.6 (2007-05-30 patchlevel 5000) [i686-darwin8.9.1]
stable-snapshot is @ 110
where's that 5k come from?
kind regards.
Jeremy Kemper
> On Oct 4, 2007, at 3:53 PM, Jeremy Kemper wrote:
> > I'm on ruby 1.8.6 (2007-05-30 patchlevel 5000) [i686-darwin8.9.1]
>
> stable-snapshot is @ 110
>
> where's that 5k come from?
I built it from the ruby_1_8 branch; that's the default patchlevel.
For example, I just recompiled and now have
ruby 1.8.6 (2007-10-02 patchlevel 5000) [i686-darwin8.10.1]
jeremy
ara.t.howard
On Oct 4, 2007, at 3:53 PM, Jeremy Kemper wrote:
> I'm on ruby 1.8.6 (2007-05-30 patchlevel 5000) [i686-darwin8.9.1]
got it. just compiled stable-snapshot, fresh gems, fresh rails - and
i'm off and smoking my macbook...
it is not enough to be compassionate. you must act.
ara.t.howard
yup i got that. i'm at the same now, with svn rails, and nothing but
rubygems, fcgi, and sqlite3 installed via gems. currently, with my
machine on a frozen pizza box to keep it cool, i'm seeing
---
69400
->: pid: 21467, vsize: 53648, rsize: 21196, uri: /home/, n: 130374
<-: pid: 21467, vsize: 53632, rsize: 21168, uri: /home/, n: 40974
->: pid: 21467, vsize: 53632, rsize: 21212, uri: /home/, n: 132090
<-: pid: 21467, vsize: 53632, rsize: 21192, uri: /home/, n: 39510
->: pid: 21467, vsize: 53632, rsize: 21208, uri: /home/, n: 131916
<-: pid: 21467, vsize: 53632, rsize: 21192, uri: /home/, n: 39510
->: pid: 21467, vsize: 53632, rsize: 21212, uri: /home/, n: 131916
<-: pid: 21467, vsize: 53632, rsize: 21188, uri: /home/, n: 39510
->: pid: 21467, vsize: 53632, rsize: 21212, uri: /home/, n: 131916
<-: pid: 21467, vsize: 53632, rsize: 21196, uri: /home/, n: 39510
->: pid: 21467, vsize: 53632, rsize: 21612, uri: /home/, n: 131914
<-: pid: 21467, vsize: 53632, rsize: 21596, uri: /home/, n: 39508
->: pid: 21467, vsize: 53632, rsize: 21612, uri: /home/, n: 131914
<-: pid: 21467, vsize: 53616, rsize: 21552, uri: /home/, n: 39507
->: pid: 21467, vsize: 53632, rsize: 21620, uri: /home/, n: 131913
<-: pid: 21467, vsize: 53632, rsize: 21600, uri: /home/, n: 39508
->: pid: 21467, vsize: 53632, rsize: 21612, uri: /home/, n: 131914
<-: pid: 21467, vsize: 53616, rsize: 21556, uri: /home/, n: 39511
->: pid: 21467, vsize: 53632, rsize: 21612, uri: /home/, n: 131917
<-: pid: 21467, vsize: 53632, rsize: 21600, uri: /home/, n: 39508
that first number is the number of requests. so, if the leak is
still there, it's slowed considerably - about 1k per 100 requests.
it's very very slow but afaikt, it's still there. i'll run till 100k
or my box burst into fire...
cheers.
share your knowledge. it's a way to achieve immortality.
ara.t.howard
On Oct 5, 2007, at 10:33 AM, Jeremy Kemper wrote:
> I built it from the ruby_1_8 branch; that's the default patchlevel.
>
> For example, I just recompiled and now have
> ruby 1.8.6 (2007-10-02 patchlevel 5000) [i686-darwin8.10.1]
here's where i'm at
1) ruby 1.8.6 (2007-06-18 patchlevel 5000) [i686-darwin8.10.1]
2) latest rubygems + fcgi and sqlite gems
3) rails is straight is edge out of svn
and, after 200k requests
---
200000
->: pid: 21467, vsize: 53648, rsize: 21196, uri: /home/, n: 130374
<-: pid: 21467, vsize: 53632, rsize: 21168, uri: /home/, n: 40974
->: pid: 21467, vsize: 53632, rsize: 21212, uri: /home/, n: 132090
<-: pid: 21467, vsize: 53632, rsize: 21192, uri: /home/, n: 39510
->: pid: 21467, vsize: 53632, rsize: 21208, uri: /home/, n: 131916
<-: pid: 21467, vsize: 53632, rsize: 21192, uri: /home/, n: 39510
->: pid: 21467, vsize: 53632, rsize: 21212, uri: /home/, n: 131916
<-: pid: 21467, vsize: 53632, rsize: 21188, uri: /home/, n: 39510
->: pid: 21467, vsize: 53632, rsize: 21212, uri: /home/, n: 131916
<-: pid: 21467, vsize: 53632, rsize: 21196, uri: /home/, n: 39510
->: pid: 21467, vsize: 55720, rsize: 23696, uri: /home/, n: 131914
<-: pid: 21467, vsize: 55720, rsize: 23676, uri: /home/, n: 39509
->: pid: 21467, vsize: 55720, rsize: 23696, uri: /home/, n: 131915
<-: pid: 21467, vsize: 55720, rsize: 23680, uri: /home/, n: 39508
->: pid: 21467, vsize: 55720, rsize: 23700, uri: /home/, n: 131914
<-: pid: 21467, vsize: 55720, rsize: 23692, uri: /home/, n: 39511
->: pid: 21467, vsize: 55720, rsize: 23700, uri: /home/, n: 131917
<-: pid: 21467, vsize: 55720, rsize: 23680, uri: /home/, n: 39511
->: pid: 21467, vsize: 55720, rsize: 23704, uri: /home/, n: 131917
<-: pid: 21467, vsize: 55720, rsize: 23680, uri: /home/, n: 39508
so, afaikt, the leak is still there for ar store. note that, until
around 70k requests i as doubting it as it's so slow. clearly new
though, the logs show a slow but monotonic increase.
i'm testing cookie based sessions with above config now.
has *anyone* actually run through as many iterations as i have? if
your machine gets hot setting it on a frozen pizza and going out for
a beer works well.
cheers.
Michael Koziarski
> still provides functionality like carts and such for our apps?
>
> Anyone reference a blog post or two I can learn from?
I think you may have misunderstood this thread? Edge Rails still has
sessions? Why would you try to design without them?
--
Cheers
Koz
ara.t.howard
On Oct 4, 2007, at 3:53 PM, Jeremy Kemper wrote:
> Hey Ara, I noticed you're running 1.8.6 patchlevel 0. Could you try
> with the current 1.8.6?
>
> I hammered your test app and see rsize solidly between 20428-20532 and
> object count consistently alternating between 144773 and 38070 +- 3.
>
> I'm on ruby 1.8.6 (2007-05-30 patchlevel 5000) [i686-darwin8.9.1]
my results with stable-snapshot ruby, rails edge, and cookie based
sessions:
---
200000
->: pid: 13870, vsize: 53648, rsize: 21264, uri: /home/, n: 140302
<-: pid: 13870, vsize: 53632, rsize: 21240, uri: /home/, n: 42142
->: pid: 13870, vsize: 53632, rsize: 21264, uri: /home/, n: 105988
<-: pid: 13870, vsize: 53632, rsize: 21248, uri: /home/, n: 39811
->: pid: 13870, vsize: 53632, rsize: 21268, uri: /home/, n: 105723
<-: pid: 13870, vsize: 53632, rsize: 21248, uri: /home/, n: 39921
->: pid: 13870, vsize: 53632, rsize: 21268, uri: /home/, n: 105722
<-: pid: 13870, vsize: 53632, rsize: 21248, uri: /home/, n: 39923
->: pid: 13870, vsize: 53632, rsize: 21264, uri: /home/, n: 105723
<-: pid: 13870, vsize: 53632, rsize: 21244, uri: /home/, n: 39923
->: pid: 13870, vsize: 54676, rsize: 22040, uri: /home/, n: 105723
<-: pid: 13870, vsize: 54676, rsize: 22024, uri: /home/, n: 39921
->: pid: 13870, vsize: 54676, rsize: 22032, uri: /home/, n: 105722
<-: pid: 13870, vsize: 54676, rsize: 22020, uri: /home/, n: 39921
->: pid: 13870, vsize: 54676, rsize: 22040, uri: /home/, n: 105722
<-: pid: 13870, vsize: 54660, rsize: 21976, uri: /home/, n: 39923
->: pid: 13870, vsize: 54676, rsize: 22040, uri: /home/, n: 105723
<-: pid: 13870, vsize: 54676, rsize: 22012, uri: /home/, n: 39921
->: pid: 13870, vsize: 54660, rsize: 21988, uri: /home/, n: 105722
<-: pid: 13870, vsize: 54676, rsize: 22020, uri: /home/, n: 39922
that's 200k requests.
so, at this point i'm pretty confident in saying
- stable rails/ruby leaks with ar store
- edge rails/ruby *might* leak with ar store. slowly.
- edge rails /ruby *probably* does not leak with cookie store. if it
does, it exceptionally slowly.
when my machine cools down i'll summarize on my blog.
i still have no idea *why* ar store seems to leak with stable rails/
ruby but knowing what i do know i think i'm going to compile stable-
snapshot on our servers, migrate to cookie based sessions, and forget
about it unless someone else is really chomping to get to the bottom
of this?
cheers.
Julian Tarkhanov
On 5-okt-2007, at 23:12, ara.t.howard wrote:
> i still have no idea *why* ar store seems to leak with stable rails/
> ruby but knowing what i do know i think i'm going to compile stable-
> snapshot on our servers, migrate to cookie based sessions, and forget
> about it unless someone else is really chomping to get to the bottom
> of this?
Could that be related to method generation on fetched records?
--
Julian 'Julik' Tarkhanov
please send all personal mail to
me at julik.nl
ara.t.howard
On Oct 5, 2007, at 3:13 PM, Julian Tarkhanov wrote:
> Could that be related to method generation on fetched records?
well, in all the leaks object count is steady. but i supposed it
could be.
Jeremy Kemper
>
> 1) ruby 1.8.6 (2007-06-18 patchlevel 5000) [i686-darwin8.10.1]
>
> 2) latest rubygems + fcgi and sqlite gems
>
> 3) rails is straight is edge out of svn
>
> and, after 200k requests
> so, afaikt, the leak is still there for ar store. note that, until
> around 70k requests i as doubting it as it's so slow. clearly new
> though, the logs show a slow but monotonic increase.
>
> i'm testing cookie based sessions with above config now.
>
> has *anyone* actually run through as many iterations as i have? if
> your machine gets hot setting it on a frozen pizza and going out for
> a beer works well.
I tried with 1.2.4 and saw very slow rsize growth also, from 28212 ->
28852 after 80000 requests.
I'm going to try with sessions off and a simple Session.find(:first)
in the action.
jeremy
ara.t.howard
On Oct 5, 2007, at 4:51 PM, Jeremy Kemper wrote:
>
> I tried with 1.2.4 and saw very slow rsize growth also, from 28212 ->
> 28852 after 80000 requests.
>
> I'm going to try with sessions off and a simple Session.find(:first)
> in the action.
>
> jeremy
thanks alot jeremy - the pizza trick really did work!
also, i'm going to leave this running on my linux box for a week to
see what that does. the slowness of it is frustrating - if only it
leaked more... ;-)
Julian Tarkhanov
On 5-okt-2007, at 23:26, ara.t.howard wrote:
> well, in all the leaks object count is steady. but i supposed it
> could be.
exactly! method creation makes symbols, not objects I beleive
probably if you keep tabs on the symbol table...
ara.t.howard
On Oct 5, 2007, at 6:34 PM, Julian Tarkhanov wrote:
> exactly! method creation makes symbols, not objects I beleive
> probably if you keep tabs on the symbol table...
yes i see what you are saying, however to constitute a leak the
symbols generated would have to be different somehow each time.
while possible, it seems unlikely. nevertheless i'll have a look at
it using Symbol.all_symbols.
cheers.
share your knowledge. it's a way to achieve immortality.
ara.t.howard
On Oct 5, 2007, at 6:34 PM, Julian Tarkhanov wrote:
> exactly! method creation makes symbols, not objects I beleive
> probably if you keep tabs on the symbol table...
an updated post and tar ball can be found here
http://drawohara.tumblr.com/post/14421265
i added tracking of the number of symbols. they don't seem to grow.
cheers.
it is not enough to be compassionate. you must act.
ara.t.howard
On Oct 5, 6:34 pm, Julian Tarkhanov <list...@julik.nl> wrote:
> On 5-okt-2007, at 23:26, ara.t.howard wrote:
>
> > well, in all the leaks object count is steady. but i supposed it
> > could be.
>
> exactly! method creation makes symbols, not objects I beleive
> probably if you keep tabs on the symbol table...
> --
doesn't look like it
http://drawohara.tumblr.com/post/14421265
note the symbol and object counts remain steady
i also updated the tar ball online if anyone want's to have a go.
cheers.