Memory usage keeps increasing #1047
Comments
|
The leak in my app is much more evident: |
|
Thank you for the details, i'll go about reproducing and getting some data shortly. |
|
I'm seeing the same report in my logs. I'm going to try different versions of puma. |
|
I'm experiencing the same issue. |
|
We have the same "ever increasing memory" issue with puma on Heroku, and have never been able to resolve it (since moving to puma 6 months ago). I've spent quite a bit of time with derailed in my local dev environment, but have never been able to reproduce what we're seeing on Heroku. The "solution" mentioned in various other threads is to run the |
|
@schneems I'm starting to wonder if it's something about the malloc that heroku is using. Could you tell us a little about how the heroku ruby's are compiled? |
|
@robinsingh-bw Is that app receiving any traffic? |
|
We use a ubuntu image, cedar 14 uses ubuntu 14. I think it's available via docker hub but not really kept up to date https://hub.docker.com/u/heroku/. We don't do anything special with malloc that I know of. @hone might be able to say more. |
|
No jemalloc or anything? |
|
Hm. ok. |
|
@evanphx The test app on heroku does not receive any traffic at all, the usage just starts going up as soon as the server starts. Also, the logs I pasted are in sequence, I did not cut anything out. It looks like some background thread might be leaking. The leak is much larger in my app where the memory usage is going up by megabytes (not KB like with the test app) even though I am making no web requests. |
|
@robinsingh-bw I'm confused why it doesn't shutdown due to being idle then... |
|
Can you chart the data for a longer period of time? Your application might just have a high resident memory usage and it hasn't 'capped out' |
|
@evanphx Its a hobby instance not a free one. It restarts every 24 hours. |
|
@robinsingh-bw Ah ok. I'm adding a curl every few minutes to keep the free one up and testing now. RSS creep like this is likely the behavior of In your regular app, do you see memory grow and grow until the instance hits the ceiling? |
|
@edwardzyc The test app just keeps going up until the instance is restarted, my app starts getting R14 out of memory. |
|
@robinsingh-bw My concern is that this is actually |
|
I have taken some screenshots of the memory usage graph from heroku. At the beginning usage looks like this: http://imgur.com/brKLOo4 At the end the usage looks like this: http://imgur.com/M8KMHyQ During the same time my production app consumed almost 50mb (although it appears the rss actually went down by 23mb and swap memory went up by 77mb, not sure if thats relevant). Heres the start and end screenshots for it: Note that I did not make any web requests during the time to either of the apps. |
|
Sorry, I can't tell if MALLOC_ARENA_MAX was configured here. It's worthwhile checking even though it looks like puma has only 16 threads. Here's more info. |
|
So I've been running a dyno for the last week and there memory has not grown out of control. It's a sawtooth pattern but I never saw it go above 65MB and generally started around 62MB. @robinsingh-bw On the smaller one, did you see the memory actually grow out of control? Or was it just the other app? |
|
@evanphx It just happens with the other app, smaller one just goes up ~10mb before heroku restarts the dyno. |
|
Why does heroku restart it?
|
|
Its the 24 hour rolling restart. |
|
Ah, gotcha. On the app, how quickly does the memory ramp up and what size
|
|
I posted some screenshots of it earlier: #1047 (comment) |
|
That kind of growth doesn't seem outside the norm how The long and short of it is that I've audit the puma codebase many times now looking for memory leaks using all kinds of tools. So at this stage I'll have to say that this is MRI's interaction with |
|
I see, thanks for looking into this. I just find it peculiar that the memory usage is spiking in my app even though there are 0 web requests, it only happens on heroku not on my local server. Anyway i resorted to a 1gb heroku instance (perhaps that's their intent?). |
|
@robinsingh-bw No problem on this end. I'm going to continue to investigate because I don't like saying "sorry not, my problem." Did you try the malloc arena setting recommended above? |
|
I dunno if it helps. But I noticed this as well. source 'https://rubygems.org'
ruby '2.3.1', engine: 'jruby', engine_version: '9.1.5.0'
gem 'rails', '4.2.7.1'
gem 'sass-rails', '~> 5.0'
gem 'uglifier', '>= 1.3.0'
gem 'coffee-rails', '~> 4.1.0'
gem 'jquery-rails'
gem 'turbolinks'
gem 'jbuilder', '~> 2.0'
gem 'sdoc', '~> 0.4.0', group: :doc
gem 'puma'
gem 'activerecord-jdbcpostgresql-adapter', require: false
group :production do
gem 'rails_12factor'
endHere is the log: |
|
Same here. |
|
Can you reproduce the memory increase locally? Can you provide us with an example app that shows the problem? |
|
I've done some poking around, here's what I've learned:
So, here is my hypothesis for what is happening:
If you do not understand the difference between resident set size, virtual memory and physical memory I would encourage you to read this. Please do correct me if my understanding is wrong. Important note: Several people in this issue have claimed large amounts of unbounded RSS growth, though no one has produced a repro app for this problem. I used the following code to run/track GC: Thread.new do
# hash = {}
while true
sleep(5)
# puts GC.stat(hash)
GC.start
end
endEDIT: After writing this, I learned that MRI does not use MMAP, so thats why that setting had no effect. |
|
A couple of open questions I still have re: what I posted yesterday
|
|
Sometimes I feel like memory work is like working with divining rods. My internal theory for why this is normal is that this +10-20mb is where the Ruby process actually wants to be to be "comfortable" with the amount of memory it has. Ruby processes start with notoriously small heaps and it depending on the random place in your code when a major GC gets kicked off, you may or may not need those "junk" objects. It keeps on increasing until it finds its max. I'm not totally convinced that this isn't happening on a mac or another OS. Few people leave open processes running for 24 hours and have a minute-by-minute graph of the different memory statistics (no I don't think that new relic is reliable). Also different OS tools might report memory differently. Maybe macs give a starting process more memory than it thinks it will need by default and just happens to be in the 10-20mb range so you never observe memory going up, even though utilized memory inside of the process is going up. If this memory increasing problem really isn't happening on mac, one difference could be the implementation of malloc, perhaps OS X is more aggressive about free-ing. This would make more sense for a general purpose OS that doesn't want one long lived process to eat all the resources versus linux where it is very common and desirable to have a handful of extremely long lived processes that you want to consume all the resources (a webserver for example, you want to have max performance, hence max resources). Another difference could be the LXC container we are running things in. These are all theories. |
The problem with this theory is that the number of heap pages is not increasing.
this is true. on Mac I was using
If my hypothesis is correct, the difference is actually in the MMU/kernel, not |
|
@nateberkopec very interesting summary of your findings. Thanks for digging into it. Can you confirm if you're using the defaults for min_threads (0), max_threads(16), and workers (0) (clustered mode disabled)? tldr; let's clarify fork or not...because.... Note, I ask because clustered mode uses fork and ruby's GC 2.1+ fork is not very fork friendly since shared pages are slowly copied to private pages. I've never really documented what we've found but basically any writes to the shared pages, even freeing a single memory location on the page, causes a copy on write of the whole page. We've found that shared memory as reported by /proc//smaps is mostly shared (60-80%) just after fork but gradually drops to (10-30%) shared within several minutes.
Are you using glibc 2.10+? How many threads are in your puma process? In my experience, if you're using more than a and MALLOC_ARENA_MAX isn't set, resident/virtual memory will rise significantly with NO increase in the heap_available_slots as reported by |
I was using Rails 5, which I believe has a min_threads setting of 5 and max-threads of 5 by default. Workers were still 0, so no forking.
I don't believe the glibc version matters because this behavior can be shown with glibc malloc or jemalloc. |
|
Note, this and the other puma memory issues might look like some of us are complaining but honestly, this is really interesting... I'm sure with more people 👀 who can provide their details/symptoms and expertise, we'll figure this out. 👏 @nateberkopec in your comparison, did you use thin in threaded mode or use the default of "non-threaded"? |
Good point @nateberkopec. This is clearly different than other reported issues where the arena max setting mattered.
So, I've had this gut feeling that ruby's GC is allocation based and how this could cause us to not do a full GC for a long time if we time it "wrong". If you do lots of allocations, grow the heap size and continue to allocate objects, everything is fine because the full GCs will triggered on allocations and will happen somewhat regularly. But, if you have ups and downs where full GCs don't occur for a long time during the downs, you might accumulate lots of live slots that could be GC'd but aren't. |
The GC is not aware of the underlying size of the Ruby objects, you can create a single Ruby object backed by 1GB of heap allocated memory and Ruby has no idea, so it won't kick off a GC. It's Ruby's world, you only created one object in the Ruby heap, and there are plenty of slots leftover. So, on that note, I'm wondering if an idling puma is creating a small enough number of Ruby objects to not trigger the GC, but that are backed by much larger heap allocated memory blocks. |
Hmm, interesting idea. To simplify the reproduction of this behavior, check out https://github.com/nateberkopec/pumagarbotest which is a bare rack app that repros the original issue. |
This isn't correct. Try the following code: Thread.new do
prev_result = {}
while true
sleep(5)
str = "0" * 9999999
hash = GC.stat
diff = hash.merge(prev_result) { |k,ov,nv| 0 - (nv - ov) }
puts diff.reject! { |k,v| v == 0 }
prev_result = hash
#GC.start
end
endBasically we're allocating a humongous string every 5 seconds, then diffing GC.stat with the previous run. Note how a GC is triggered every ~20-30 seconds or so. This behavior of GC-triggered-by-heap-allocation is governed by
That said, I think this is probably the case. Puma is creating some heap-backed objects (long strings, etc) while idling. This calls |
|
Strings seem to work differently (I was over-generalizing 😄) probably because Ruby is aware of the memory being allocated. I'm more thinking of DataWrapStruct stuff in a C extension wrapping around a large amount of malloced memory...I saw the statement "they make greater use of C-extensions and manage their memory outside of the Ruby VM" up above and thats why this popped in my head. |
|
Alright, I'm 99% convinced this is normal behavior of heap growth outside the objectspace. No one's actually shown any behavior/produced a repro app that points to a memory leak. The fact that the repro app only repros on Heroku (Ubuntu) and not on macOS just further proves that this is just the behavior of |
|
I hate to bump a thread this old, but I believe this is still an issue. Heroku is a fairly big platform that many people use -- and their own help guides actually suggest using Puma as the preferred Ruby web server. Does the hack of just running GC.start every 5 seconds on every worker actually work? While it's certainly a hack, it definitely beats memory consumption going out of control. I just spent several hours migrating a side project from to use Puma, only to crash straight into this issue. The memory use is fairly clear (switched from using Thin to Puma) -- and I understand that it's a super hacky solution, but if it works...it works?
Coincidentally moved to Puma after reading this article by you, nateberkopec. |
To be 100% clear, you Should Not Do This in production. That is not a workaround. I only included it in the script for demonstration purposes. |
|
@nateberkopec while I'm certainly aware that it works it's a workaround, I'd say that puma_worker_killer's equally silly solution (or setting up a cronjob to run |
|
@nicatronTg If a GC reduces memory usage, you don't have a leak. The definition of a leak is an unmanaged growth on the heap. If you can free memory by garbage collecting it, you've just got either poor GC settings or a weird workload. If running GC.start fixes your problems, you may want to to watch my 2016 RubyConf talk about 12 ways to reduce memory usage in Ruby applications. |
|
@nateberkopec it doesn't fix the problem for me, but in the context of this thread, or at least the way I read your comment, it seemed to mitigate |
|
I'm going to close this issue. If you have an issue with memory growth on Puma please try the following:
If you've tried all of the above and still have problems and can provide a reproduction application with just Puma that grows significantly in a short amount of time, I am happy to reopen. |
|
I'd like to just point out that on Heroku-land, a few months ago with no changes to my code this magically stopped being an issue. I don't remember the exact date but after a scheduled dyno restart I've yet to experience uncontrolled growth ever again. |
Hi,
I have been tracking a memory leak in my app and it seems the leak disappears if I switch to a different webserver, I have tried webrick/unicorn/passenger and none of them have the leak. I also tried running puma with a single process and 1 thread, the leak was still there. I moved puma to a dummy project in an attempt to isolate the problem. I have found that the leak only appears when running on heroku, I cant replicate it on my development server.
Steps to reproduce:
rails new pumaleak
swap out the gemfile with the one provided
bundle
git init
git add -A
git commit -am 'initial commit'
heroku create
heroku labs:enable log-runtime-metrics
git push heroku master
heroku logs -t
Heres my gemfile (no other changes to the default rails app):
Heroku logs (notice the ram going up over time, I ran it overnight and the ram kept going up ~10mb over 24 hours, running a GC does not revert it):
The text was updated successfully, but these errors were encountered: