Error message "Cannot allocate memory" in logs


(Florian Beer) #1

Hi,
we have been seeing increased amounts of the following messages in the logs:

Cannot allocate memory - df -l . | tail -1 | tr -s ' ' | cut -d ' ' -f 5
Job exception: Wrapped Errno::ENOMEM: Cannot allocate memory - df -l . | tail -1 | tr -s ' ' | cut -d ' ' -f 5

The server has 4GB RAM and there is enough free memory according to free -m but the message keeps popping up nonetheless about every minute. The dfcommand shows enough free harddisk space as well.

Discourse version: 1.1.0.beta2
Latest installed commit: cf4bd67

Does anybody have an idea what to do about this?


Backtraces for the errors:

/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.5/lib/active_support/core_ext/kernel/agnostics.rb:7:in ``'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.5/lib/active_support/core_ext/kernel/agnostics.rb:7:in ``'
/var/www/discourse/lib/cooked_post_processor.rb:255:in `available_disk_space'
/var/www/discourse/lib/cooked_post_processor.rb:246:in `disable_if_low_on_disk_space'
/var/www/discourse/lib/cooked_post_processor.rb:235:in `pull_hotlinked_images'
/var/www/discourse/lib/cooked_post_processor.rb:24:in `post_process'
/var/www/discourse/app/jobs/regular/process_post.rb:16:in `execute'
/var/www/discourse/app/jobs/base.rb:154:in `block (2 levels) in perform'

/var/www/discourse/app/jobs/base.rb:179:in `perform'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/sidekiq-3.1.3/lib/sidekiq/processor.rb:52:in `block (2 levels) in process'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/sidekiq-3.1.3/lib/sidekiq/middleware/chain.rb:122:in `call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/sidekiq-3.1.3/lib/sidekiq/middleware/chain.rb:122:in `block in invoke'
/var/www/discourse/lib/sidekiq/pausable.rb:81:in `call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/sidekiq-3.1.3/lib/sidekiq/middleware/chain.rb:124:in `block in invoke'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/sidekiq-3.1.3/lib/sidekiq/middleware/server/active_record.rb:6:in `call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/sidekiq-3.1.3/lib/sidekiq/middleware/chain.rb:124:in `block in invoke'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/sidekiq-3.1.3/lib/sidekiq/middleware/server/retry_jobs.rb:62:in `call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/sidekiq-3.1.3/lib/sidekiq/middleware/chain.rb:124:in `block in invoke'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/sidekiq-3.1.3/lib/sidekiq/middleware/server/logging.rb:11:in `block in call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/sidekiq-3.1.3/lib/sidekiq/logging.rb:22:in `with_context'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/sidekiq-3.1.3/lib/sidekiq/middleware/server/logging.rb:7:in `call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/sidekiq-3.1.3/lib/sidekiq/middleware/chain.rb:124:in `block in invoke'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/sidekiq-3.1.3/lib/sidekiq/middleware/chain.rb:127:in `call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/sidekiq-3.1.3/lib/sidekiq/middleware/chain.rb:127:in `invoke'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/sidekiq-3.1.3/lib/sidekiq/processor.rb:51:in `block in process'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/sidekiq-3.1.3/lib/sidekiq/processor.rb:94:in `stats'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/sidekiq-3.1.3/lib/sidekiq/processor.rb:50:in `process'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:25:in `public_send'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:25:in `dispatch'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:122:in `dispatch'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/actor.rb:322:in `block in handle_message'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/actor.rb:416:in `block in task'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/tasks.rb:55:in `block in initialize'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/tasks/task_fiber.rb:13:in `block in create'

(Jeff Atwood) #2

Interesting any ideas @sam? 4gb should be plenty.


(Florian Beer) #3

Current free -m output:

             total       used       free     shared    buffers     cached
Mem:          3953       3198        755          0        353       1385
-/+ buffers/cache:       1459       2494
Swap:            0          0          0

(Jeff Atwood) #4

In the meantime you might set up swap as a safety valve.


(Florian Beer) #5

Yes that was my first thought, but after seeing so much free RAM I thought it must be something else.
Will do now anyways and see if the error disappears.


(Florian Beer) #6

Oddly enough the errors stopped after I activated swap even though the RAM was never fully used (I monitored it closely for a few hours after activation). Also I don’t understand why a few MBs of swap are used if there is still >200MB free RAM. But who really understands Linux’s memory management? :wink:

             total       used       free     shared    buffers     cached
Mem:          3953       3733        220          0        479       1706
-/+ buffers/cache:       1547       2405
Swap:         2047         23       2024

(Michael Brown) #7

That’s strange. This is not a high memory operation - rather than reading this as an “Not Enough Memory” error I’d interpret it as “I’m not allowed to allocate memory” and see where that got me.

If you run the original command (df -l . | tail -1 | tr -s ' ' | cut -d ' ' -f 5) from inside the container, do you get an error?

(site note: we could make that a little nicer: df -lP . | awk 'NR==2 {print $5;}')


After a few more minutes of thought, here’s what could be happening. With a pipeline of 4 commands there we need 4 fork()/exec() combinations. We could be bumping into the overcommit limit here.

What’s the output of:

grep . /proc/sys/vm/overcommit_*

If you set vm.overcommit_memory to 2, do the problems go away?

If not, if you bump up overcommit_ratio, do the problems go away?


(Florian Beer) #8

Exactly my thought on the issue, sounds like it wants to allocate but can’t for some reason, but not because it is out of available memory. The original command gave me no errors, it merely reported that the disk is 75% used.

Overcommit limit:

grep . /proc/sys/vm/overcommit_*
/proc/sys/vm/overcommit_memory:0
/proc/sys/vm/overcommit_ratio:50

The initial errors are gone now that I activated swap. Looking at the logs this morning I found 2 new ones that happen roughly every 4 hours:

Job exception: Cannot allocate memory - convert /var/www/discourse/public/uploads/default/5999/dabd867d66e8c23b.png[0] -background transparent -gravity center -thumbnail 421x500^ -extent 421x500 -interpolate bicubic -unsharp 2x0.5+0.7+0 -quality 98 /tmp/discourse-thumbnail20140915-5393-pt58nh.png
Job exception: Wrapped Errno::ENOMEM: Cannot allocate memory - convert /var/www/discourse/public/uploads/default/5999/dabd867d66e8c23b.png[0] -background transparent -gravity center -thumbnail 421x500^ -extent 421x500 -interpolate bicubic -unsharp 2x0.5+0.7+0 -quality 98 /tmp/discourse-thumbnail20140915-5393-pt58nh.png

Seems to be some problem related to sidekiq queue as far as I can tell.


The second one is:

Job exception: Cannot allocate memory - fork(2)

This one might have an interesting backtrace:

/var/www/discourse/lib/backup_restore.rb:158:in `fork'
/var/www/discourse/lib/backup_restore.rb:158:in `start!'
/var/www/discourse/lib/backup_restore.rb:13:in `backup!'
/var/www/discourse/app/jobs/scheduled/create_backup.rb:10:in `execute'
/var/www/discourse/app/jobs/base.rb:154:in `block (2 levels) in perform'

(Kane York) #9

I moved 4 posts to a new topic: Another memory leak support topic


Another memory leak support topic
(Régis Hanol) #13