Heroku Error R14 (Memory quota exceeded): How do I solve this?

Question

I have a Rails 3.1 app on Heroku. I am seeing a lot of these errors:

Error R14 (Memory quota exceeded)

Typically the preceding log entry is showing:

Process running mem=522M(102.1%)

This does vary a little but never by much and can occur after almost any URL request, so it's not related to a specific controller action as far as I can tell.

This is a classic block of log entries:

2012-01-16T02:35:57+00:00 heroku[router]: PUT prizequiz.herokuapp.com/mobile_users/1 dyno=web.1 queue=0 wait=0ms service=55ms status=401 bytes=27
2012-01-16T02:35:58+00:00 heroku[router]: PUT prizequiz.herokuapp.com/mobile_users/1 dyno=web.1 queue=0 wait=0ms service=155ms status=200 bytes=1
2012-01-16T02:36:02+00:00 heroku[router]: PUT prizequiz.herokuapp.com/mobile_users/1 dyno=web.1 queue=0 wait=0ms service=13ms status=401 bytes=27
2012-01-16T02:36:02+00:00 heroku[router]: PUT prizequiz.herokuapp.com/mobile_users/1 dyno=web.1 queue=0 wait=0ms service=147ms status=200 bytes=1
2012-01-16T02:36:09+00:00 heroku[router]: POST prizequiz.herokuapp.com/mobile_users dyno=web.1 queue=0 wait=0ms service=87ms status=201 bytes=624
2012-01-16T02:36:11+00:00 heroku[router]: GET prizequiz.herokuapp.com/quizzes/1/questions dyno=web.1 queue=0 wait=0ms service=5ms status=401 bytes=27
2012-01-16T02:36:11+00:00 heroku[router]: GET prizequiz.herokuapp.com/quizzes/1/questions dyno=web.1 queue=0 wait=0ms service=290ms status=200 bytes=81412
2012-01-16T02:36:15+00:00 heroku[router]: PUT prizequiz.herokuapp.com/mobile_users/1 dyno=web.1 queue=0 wait=0ms service=10ms status=401 bytes=27
2012-01-16T02:36:16+00:00 heroku[router]: PUT prizequiz.herokuapp.com/mobile_users/1 dyno=web.1 queue=0 wait=0ms service=67ms status=200 bytes=1
2012-01-16T02:36:33+00:00 heroku[router]: POST prizequiz.herokuapp.com/quizzes/1/scores dyno=web.1 queue=0 wait=0ms service=10ms status=401 bytes=27
2012-01-16T02:36:33+00:00 heroku[router]: POST prizequiz.herokuapp.com/quizzes/1/scores dyno=web.1 queue=0 wait=0ms service=132ms status=201 bytes=230
2012-01-16T02:36:55+00:00 heroku[web.1]: Process running mem=522M(102.1%)
2012-01-16T02:36:55+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)
2012-01-16T02:37:17+00:00 app[web.1]: 
2012-01-16T02:37:17+00:00 app[web.1]: 
2012-01-16T02:37:17+00:00 app[web.1]: Started POST "/quizzes/1/scores" for 177.53.80.25 at 2012-01-16 02:37:17 +0000
2012-01-16T02:37:17+00:00 app[web.1]: cache: [POST /quizzes/1/scores] invalidate, pass
2012-01-16T02:37:17+00:00 app[web.1]: 
2012-01-16T02:37:17+00:00 app[web.1]: 
2012-01-16T02:37:17+00:00 app[web.1]: Started POST "/quizzes/1/scores" for 177.53.80.25 at 2012-01-16 02:37:17 +0000
2012-01-16T02:37:17+00:00 app[web.1]: cache: [POST /quizzes/1/scores] invalidate, pass
2012-01-16T02:37:17+00:00 heroku[router]: POST prizequiz.herokuapp.com/quizzes/1/scores dyno=web.1 queue=0 wait=0ms service=44ms status=201 bytes=230
2012-01-16T02:37:17+00:00 heroku[web.1]: Process running mem=522M(102.1%)
2012-01-16T02:37:17+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)
2012-01-16T02:37:17+00:00 heroku[router]: POST prizequiz.herokuapp.com/quizzes/1/scores dyno=web.1 queue=0 wait=0ms service=16ms status=401 bytes=27
2012-01-16T02:37:20+00:00 app[web.1]: 
2012-01-16T02:37:20+00:00 app[web.1]: 
2012-01-16T02:37:20+00:00 app[web.1]: Started GET "/quizzes/1/scores/current_game" for 177.53.80.25 at 2012-01-16 02:37:20 +0000
2012-01-16T02:37:20+00:00 app[web.1]: cache: [GET /quizzes/1/scores/current_game] miss
2012-01-16T02:37:20+00:00 app[web.1]: 
2012-01-16T02:37:20+00:00 app[web.1]: 
2012-01-16T02:37:20+00:00 app[web.1]: Started GET "/quizzes/1/scores/current_game" for 177.53.80.25 at 2012-01-16 02:37:20 +0000
2012-01-16T02:37:20+00:00 heroku[router]: GET prizequiz.herokuapp.com/quizzes/1/scores/current_game dyno=web.1 queue=0 wait=0ms service=8ms status=401 bytes=27
2012-01-16T02:37:20+00:00 app[web.1]: cache: [GET /quizzes/1/scores/current_game] miss
2012-01-16T02:37:20+00:00 heroku[router]: GET prizequiz.herokuapp.com/quizzes/1/scores/current_game dyno=web.1 queue=0 wait=0ms service=6ms status=401 bytes=27
2012-01-16T02:37:20+00:00 app[web.1]: 
2012-01-16T02:37:20+00:00 app[web.1]: 
2012-01-16T02:37:20+00:00 app[web.1]: Started POST "/quizzes/1/scores" for 177.53.80.25 at 2012-01-16 02:37:20 +0000
2012-01-16T02:37:20+00:00 heroku[router]: POST prizequiz.herokuapp.com/quizzes/1/scores dyno=web.1 queue=0 wait=0ms service=33ms status=401 bytes=27
2012-01-16T02:37:20+00:00 app[web.1]: cache: [POST /quizzes/1/scores] invalidate, pass
2012-01-16T02:37:20+00:00 app[web.1]: 
2012-01-16T02:37:20+00:00 app[web.1]: 
2012-01-16T02:37:20+00:00 app[web.1]: Started GET "/quizzes/1/scores/current_game" for 177.53.80.25 at 2012-01-16 02:37:20 +0000
2012-01-16T02:37:20+00:00 app[web.1]: 
2012-01-16T02:37:20+00:00 app[web.1]: 

I have New Relic installed but have been unable to identify anything of any use.

Will gladly supply more info if needed. I also have an outstanding support request on Heroku for this but as yet (2 days marked as urgent) I have had no response.

Adding web dynos makes no difference.

UPDATE, I have added the oink gem and this is a sample result

2012-01-26T08:24:25+00:00 app[web.1]: 
2012-01-26T08:24:25+00:00 app[web.1]: 
2012-01-26T08:24:25+00:00 app[web.1]: Started PUT "/mobile_users/1" for 110.49.234.219 at 2012-01-26 08:24:25 +0000
2012-01-26T08:24:26+00:00 app[web.1]: Oink Action: mobile_users#update
2012-01-26T08:24:26+00:00 app[web.1]: Memory usage: 286276 | PID: 16
2012-01-26T08:24:26+00:00 app[web.1]: Instantiation Breakdown: Total: 2 | MobileUser: 2
2012-01-26T08:24:26+00:00 app[web.1]: Oink Log Entry Complete
2012-01-26T08:24:26+00:00 app[web.1]: cache: [PUT /mobile_users/1] invalidate, pass
2012-01-26T08:24:26+00:00 heroku[router]: PUT prizequiz.herokuapp.com/mobile_users/1 dyno=web.1 queue=0 wait=0ms service=460ms status=200 bytes=1
2012-01-26T08:24:38+00:00 heroku[web.1]: Process running mem=537M(104.9%)
2012-01-26T08:24:38+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)
2012-01-26T08:24:43+00:00 app[web.1]: 
2012-01-26T08:24:43+00:00 app[web.1]: 
2012-01-26T08:24:43+00:00 app[web.1]: Started PUT "/mobile_users/1" for 103.1.165.23 at 2012-01-26 08:24:43 +0000
2012-01-26T08:24:43+00:00 heroku[router]: PUT prizequiz.herokuapp.com/mobile_users/1 dyno=web.1 queue=0 wait=0ms service=544ms status=401 bytes=27
2012-01-26T08:24:43+00:00 app[web.1]: Oink Action: mobile_users#update
2012-01-26T08:24:43+00:00 app[web.1]: Memory usage: 288876 | PID: 19
2012-01-26T08:24:43+00:00 app[web.1]: Instantiation Breakdown: Total: 0
2012-01-26T08:24:43+00:00 app[web.1]: Oink Log Entry Complete
2012-01-26T08:24:43+00:00 app[web.1]: cache: [PUT /mobile_users/1] invalidate, pass
2012-01-26T08:24:47+00:00 app[web.1]: 
2012-01-26T08:24:47+00:00 app[web.1]: 
2012-01-26T08:24:47+00:00 app[web.1]: Started PUT "/mobile_users/1" for 103.1.165.23 at 2012-01-26 08:24:47 +0000
2012-01-26T08:24:48+00:00 app[web.1]: Oink Action: mobile_users#update
2012-01-26T08:24:48+00:00 app[web.1]: Memory usage: 286412 | PID: 16
2012-01-26T08:24:48+00:00 app[web.1]: Instantiation Breakdown: Total: 2 | MobileUser: 2
2012-01-26T08:24:48+00:00 app[web.1]: Oink Log Entry Complete
2012-01-26T08:24:48+00:00 heroku[router]: PUT prizequiz.herokuapp.com/mobile_users/1 dyno=web.1 queue=0 wait=0ms service=432ms status=200 bytes=1
2012-01-26T08:24:48+00:00 app[web.1]: cache: [PUT /mobile_users/1] invalidate, pass
2012-01-26T08:24:59+00:00 heroku[web.1]: Process running mem=537M(104.9%)
2012-01-26T08:24:59+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)
2012-01-26T08:25:20+00:00 heroku[web.1]: Process running mem=537M(104.9%)
2012-01-26T08:25:20+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)
2012-01-26T08:25:41+00:00 heroku[web.1]: Process running mem=537M(104.9%)
2012-01-26T08:25:41+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)
2012-01-26T08:26:32+00:00 heroku[router]: PUT prizequiz.herokuapp.com/mobile_users/1 dyno=web.1 queue=0 wait=0ms service=34ms status=401 bytes=27
2012-01-26T08:27:04+00:00 app[web.1]: 
2012-01-26T08:27:04+00:00 app[web.1]: 
2012-01-26T08:27:04+00:00 app[web.1]: Started PUT "/mobile_users/1" for 103.1.165.23 at 2012-01-26 08:27:04 +0000
2012-01-26T08:27:04+00:00 app[web.1]: Oink Action: mobile_users#update
2012-01-26T08:27:04+00:00 app[web.1]: Memory usage: 288876 | PID: 19
2012-01-26T08:27:04+00:00 app[web.1]: Instantiation Breakdown: Total: 2 | MobileUser: 2
2012-01-26T08:27:04+00:00 app[web.1]: Oink Log Entry Complete
2012-01-26T08:27:04+00:00 app[web.1]: cache: [PUT /mobile_users/1] invalidate, pass
2012-01-26T08:27:04+00:00 heroku[router]: PUT prizequiz.herokuapp.com/mobile_users/1 dyno=web.1 queue=0 wait=0ms service=337ms status=200 bytes=1
2012-01-26T08:27:05+00:00 heroku[web.1]: Process running mem=537M(104.9%)
2012-01-26T08:27:05+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)
2012-01-26T08:27:26+00:00 heroku[web.1]: Process running mem=537M(104.9%)
2012-01-26T08:27:26+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)
2012-01-26T08:27:48+00:00 heroku[web.1]: Process running mem=537M(104.9%)
2012-01-26T08:27:48+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)
2012-01-26T08:28:08+00:00 heroku[web.1]: Process running mem=537M(105.0%)
2012-01-26T08:28:08+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)
2012-01-26T08:28:29+00:00 heroku[web.1]: Process running mem=537M(105.0%)
2012-01-26T08:28:29+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)
2012-01-26T08:28:51+00:00 heroku[web.1]: Process running mem=537M(105.0%)
2012-01-26T08:28:51+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)
2012-01-26T08:29:08+00:00 app[web.1]: 
2012-01-26T08:29:08+00:00 app[web.1]: 
2012-01-26T08:29:08+00:00 app[web.1]: Started PUT "/mobile_users/1" for 85.26.234.218 at 2012-01-26 08:29:08 +0000
2012-01-26T08:29:08+00:00 app[web.1]: Oink Action: mobile_users#update
2012-01-26T08:29:08+00:00 app[web.1]: Memory usage: 382404 | PID: 13
2012-01-26T08:29:08+00:00 app[web.1]: Instantiation Breakdown: Total: 0
2012-01-26T08:29:08+00:00 app[web.1]: Oink Log Entry Complete
2012-01-26T08:29:08+00:00 app[web.1]: cache: [PUT /mobile_users/1] invalidate, pass
2012-01-26T08:29:08+00:00 heroku[router]: PUT prizequiz.herokuapp.com/mobile_users/1 dyno=web.1 queue=0 wait=0ms service=86ms status=401 bytes=27
2012-01-26T08:29:09+00:00 app[web.1]: 
2012-01-26T08:29:09+00:00 app[web.1]: 
2012-01-26T08:29:09+00:00 app[web.1]: Started PUT "/mobile_users/1" for 85.26.234.218 at 2012-01-26 08:29:09 +0000
2012-01-26T08:29:09+00:00 app[web.1]: Oink Action: mobile_users#update
2012-01-26T08:29:09+00:00 app[web.1]: Memory usage: 382404 | PID: 13
2012-01-26T08:29:09+00:00 app[web.1]: Instantiation Breakdown: Total: 2 | MobileUser: 2
2012-01-26T08:29:09+00:00 app[web.1]: Oink Log Entry Complete
2012-01-26T08:29:09+00:00 app[web.1]: cache: [PUT /mobile_users/1] invalidate, pass
2012-01-26T08:29:09+00:00 heroku[router]: PUT prizequiz.herokuapp.com/mobile_users/1 dyno=web.1 queue=0 wait=0ms service=160ms status=200 bytes=1
2012-01-26T08:29:11+00:00 app[web.1]: 
2012-01-26T08:29:11+00:00 app[web.1]: 
2012-01-26T08:29:11+00:00 app[web.1]: Started PUT "/mobile_users/1" for 85.26.234.218 at 2012-01-26 08:29:11 +0000
2012-01-26T08:29:11+00:00 heroku[router]: PUT prizequiz.herokuapp.com/mobile_users/1 dyno=web.1 queue=0 wait=0ms service=101ms status=401 bytes=27
2012-01-26T08:29:11+00:00 app[web.1]: Oink Action: mobile_users#update
2012-01-26T08:29:11+00:00 app[web.1]: Memory usage: 382404 | PID: 13
2012-01-26T08:29:11+00:00 app[web.1]: Instantiation Breakdown: Total: 0
2012-01-26T08:29:11+00:00 app[web.1]: Oink Log Entry Complete
2012-01-26T08:29:11+00:00 app[web.1]: cache: [PUT /mobile_users/1] invalidate, pass
2012-01-26T08:29:12+00:00 app[web.1]: 
2012-01-26T08:29:12+00:00 app[web.1]: 
2012-01-26T08:29:12+00:00 app[web.1]: Started PUT "/mobile_users/1" for 85.26.234.218 at 2012-01-26 08:29:12 +0000
2012-01-26T08:29:12+00:00 heroku[web.1]: Process running mem=537M(105.0%)
2012-01-26T08:29:12+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)
2012-01-26T08:29:12+00:00 app[web.1]: Oink Action: mobile_users#update
2012-01-26T08:29:12+00:00 app[web.1]: Memory usage: 288876 | PID: 19
2012-01-26T08:29:12+00:00 app[web.1]: Instantiation Breakdown: Total: 2 | MobileUser: 2
2012-01-26T08:29:12+00:00 app[web.1]: Oink Log Entry Complete
2012-01-26T08:29:12+00:00 app[web.1]: cache: [PUT /mobile_users/1] invalidate, pass
2012-01-26T08:29:12+00:00 heroku[router]: PUT prizequiz.herokuapp.com/mobile_users/1 dyno=web.1 queue=0 wait=0ms service=169ms status=200 bytes=1
2012-01-26T08:29:33+00:00 heroku[web.1]: Process running mem=537M(105.0%)
2012-01-26T08:29:33+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)

I have no idea what that proves other than it seems I am not using as much memory as Heroku thinks I am Memory usage: 288876 vs Process running mem=537M(105.0%)

Answer 1

Try this too

heroku ps

I had 2 console processes that had been running for almost 24 hours. I had some HEAVY things I needed to do in the console and who knows what happened. What I did in the console did an insane amount of writes and reads to the DB and went on for over 10 minutes. So this must have mucked something up.

Runing heroku ps in your terminal will show you all your processes and you might get an "aha".

Kill the zombie processes with

heroku ps:stop run.6654

Dont forget the "run." part

Do heroku ps to verify they are gone and check your logs that the problem is cleared up.

Answer 2

Also, the WEB_CONCURRENCY heroku config can cause this. For example, I have an app running 2 1x dynos. If I use sensible_defaults (another heroku config), it defaults WEB_CONCURRENCY to 2 (based on my dynos). This causes a ton of R14 errors in my logs. If I turn off sensible_defaults, and set WEB_CONCURRENCY=1...the problem goes away.

If you don't set WEB_CONCURRENCY, and you don't use sensible_defaults, and you followed the server (Im using Puma) set up via heroku docs...you'll likely have a line in puma.rb that looks like this:

workers Integer(ENV['WEB_CONCURRENCY'] || 3)  

If thats the case, then WEB_CONCURRENCY isn't set...so it will be 3, which is using even more memory.

In console:

// review existing config settings.

heroku config

// IF sensible_defaults is enabled.

heroku config:set sensible_defaults=disabled

// set WEB_CONCURRENCY

heroku config:set WEB_CONCURRENCY=1

// monitor logs for R14 errors.

Answer 3

For me, replacing RMagick with MiniMagick did the job. Both gems feature same resizing and cropping functions (I'm using carrierwave for image uploads)

1. Gemfile update

   Remove gem 'rmagick'

   and add gem 'mini_magick'

   Run bundle

2. Update carrierwave uploaders

   Replace include CarrierWave::RMagick

   with include CarrierWave::MiniMagick

3. Deploy to Heroku and that's it!

--

Finally I have no R14 Errors after each request.

Answer 4

I had the same issue and upgraded to their 2x dynos as a stop gap while attempting to debug with the oink gem. The config change to double the dynos did not work after a heroku restart nor did taking them to 0 and back up. Doing a git push after adding the oink gem got the upgrade to work, and oink is not showing the same consumption the heroku logs were initially showing.

Answer 5

I was using Mongoid and in my case it was from the 'identity map' being enabled in a non-web request process (so the identity map was never getting cleared and kept growing). Setting Mongoid.identity_map_enabled = false in that process solved the problem.

Answer 6

I had this problem .. to solved using find_in_batches.

If someone still has this error i will put the code here. As it takes long time to run, i found a progress_bar gem that help the user. will let it here too cause i think its mandatory in almost every case.

bar = ProgressBar.new( total )
Texto.find_in_batches(:batch_size => 100) do |textos|
    textos.each{| texto | 
        ...do_stuff...
    }
    bar.increment! textos.size
end

Progress Bar: https://github.com/paul/progress_bar/issues

Answer 7

Look for code with 'Model.all.each do |something|' and replace with Model.find_each do |something|. This will save memory by loading chunks of your model into memory instead of the entire model all at once.

Also, look for opportunities to use in_groups_of or :limit to decrease the number of objects that are saved in memory at one time.

EDIT: for_each -> find_each.

Answer 8

Heroku specifies a RAM limit per dyno in its Acceptable Use Policy.

You could use memprof, specifically Memprof::Middleware, to help find out what's allocating all the memory in your app during requests. This is really only suitable for use in a non-production environment, since it'll slow down your app.

It's common for a Rails app to be allocating many ActiveRecord objects, so you might look for places where you're doing Model.find(:all).select{...}, or similar queries that pull a lot of records from the DB and then process them in Ruby. Better would be to use where to limit what is returned to the Rails app using SQL.