Heroku JVM tuning

Question

I've written an application on Play2 framework for Heroku and am having memory issues.

2013-03-21T01:28:35+00:00 heroku[web.1]: Process running mem=543M(106.1%)
2013-03-21T01:28:35+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)

Locally I've profiled it with the same JVM settings and memory restrictions on Heroku (512MB) but almost instantly when I send requests at Heroku it runs our of heap space.

JAVA_OPTS:    -Xmx384m -Xss512k -XX:+UseCompressedOops

I wouldn't have any issues if I could profile what's going on there, but the java-agent doest seem to work for me.

I havent come across any memory leaks that I've seen. I do know that every object I create is and will only be used once so I could make my young gen large and my old gen small. I've tried different JVM values but can't seem to find the right combination to get this working without the correct profiling.

I've read all the Heroku docs on tuning and such with no avail. Does anyone have any ideas on this, or maybe point me in the right direction?

EDIT

I still have not been able to get remote monitoring working, but here is some dumps from my local test system before and after 1 full CG.

{Heap before GC invocations=1747 (full 0):
 PSYoungGen      total 42496K, used 42496K [0x00000000f5560000, 0x00000000fded0000, 0x0000000100000000)
  eden space 42176K, 100% used [0x00000000f5560000,0x00000000f7e90000,0x00000000f7e90000)
  from space 320K, 100% used [0x00000000fde80000,0x00000000fded0000,0x00000000fded0000)
  to   space 640K, 0% used [0x00000000fdd90000,0x00000000fdd90000,0x00000000fde30000)
 PSOldGen        total 106176K, used 105985K [0x00000000e0000000, 0x00000000e67b0000, 0x00000000f5560000)
  object space 106176K, 99% used [0x00000000e0000000,0x00000000e67804c8,0x00000000e67b0000)
 PSPermGen       total 43712K, used 43684K [0x00000000d5a00000, 0x00000000d84b0000, 0x00000000e0000000)
  object space 43712K, 99% used [0x00000000d5a00000,0x00000000d84a9338,0x00000000d84b0000)
2013-03-21T14:09:36.827-0700: [GC [PSYoungGen: 42496K->384K(41536K)] 148481K->106450K(147712K), 0.0027940 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
Heap after GC invocations=1747 (full 0):
 PSYoungGen      total 41536K, used 384K [0x00000000f5560000, 0x00000000fde90000, 0x0000000100000000)
  eden space 41152K, 0% used [0x00000000f5560000,0x00000000f5560000,0x00000000f7d90000)
  from space 384K, 100% used [0x00000000fdd90000,0x00000000fddf0000,0x00000000fddf0000)
  to   space 640K, 0% used [0x00000000fddf0000,0x00000000fddf0000,0x00000000fde90000)
 PSOldGen        total 106176K, used 106066K [0x00000000e0000000, 0x00000000e67b0000, 0x00000000f5560000)
  object space 106176K, 99% used [0x00000000e0000000,0x00000000e6794968,0x00000000e67b0000)
 PSPermGen       total 43712K, used 43684K [0x00000000d5a00000, 0x00000000d84b0000, 0x00000000e0000000)
  object space 43712K, 99% used [0x00000000d5a00000,0x00000000d84a9338,0x00000000d84b0000)
}
{Heap before GC invocations=1748 (full 1):
 PSYoungGen      total 41536K, used 384K [0x00000000f5560000, 0x00000000fde90000, 0x0000000100000000)
  eden space 41152K, 0% used [0x00000000f5560000,0x00000000f5560000,0x00000000f7d90000)
  from space 384K, 100% used [0x00000000fdd90000,0x00000000fddf0000,0x00000000fddf0000)
  to   space 640K, 0% used [0x00000000fddf0000,0x00000000fddf0000,0x00000000fde90000)
 PSOldGen        total 106176K, used 106066K [0x00000000e0000000, 0x00000000e67b0000, 0x00000000f5560000)
  object space 106176K, 99% used [0x00000000e0000000,0x00000000e6794968,0x00000000e67b0000)
 PSPermGen       total 43712K, used 43684K [0x00000000d5a00000, 0x00000000d84b0000, 0x00000000e0000000)
  object space 43712K, 99% used [0x00000000d5a00000,0x00000000d84a9338,0x00000000d84b0000)
2013-03-21T14:09:36.830-0700: [Full GC [PSYoungGen: 384K->0K(41536K)] [PSOldGen: 106066K->13137K(52224K)] 106450K->13137K(93760K) [PSPermGen: 43684K->43684K(87936K)], 0.0666250 secs] [Times: user=0.06 sys=0.01, real=0.07 secs] 
Heap after GC invocations=1748 (full 1):
 PSYoungGen      total 41536K, used 0K [0x00000000f5560000, 0x00000000fde90000, 0x0000000100000000)
  eden space 41152K, 0% used [0x00000000f5560000,0x00000000f5560000,0x00000000f7d90000)
  from space 384K, 0% used [0x00000000fdd90000,0x00000000fdd90000,0x00000000fddf0000)
  to   space 640K, 0% used [0x00000000fddf0000,0x00000000fddf0000,0x00000000fde90000)
 PSOldGen        total 52224K, used 13137K [0x00000000e0000000, 0x00000000e3300000, 0x00000000f5560000)
  object space 52224K, 25% used [0x00000000e0000000,0x00000000e0cd4528,0x00000000e3300000)
 PSPermGen       total 87936K, used 43684K [0x00000000d5a00000, 0x00000000dafe0000, 0x00000000e0000000)
  object space 87936K, 49% used [0x00000000d5a00000,0x00000000d84a9338,0x00000000dafe0000)
}

EDIT

This is what I can get -- which isnt much, but this is what happens after 100 requests as everything starts to degrade, you can see web.2 already swapped in this dump

2013-03-21T22:24:23+00:00 heroku[web.1]: source=heroku.13369226.web.1.d615093e-77a3-42b1-8da1-a228bd7582a1 measure=load_avg_1m val=0.41
2013-03-21T22:24:23+00:00 heroku[web.1]: source=heroku.13369226.web.1.d615093e-77a3-42b1-8da1-a228bd7582a1 measure=memory_total val=246.95 units=MB
2013-03-21T22:24:23+00:00 heroku[web.1]: source=heroku.13369226.web.1.d615093e-77a3-42b1-8da1-a228bd7582a1 measure=memory_rss val=246.91 units=MB
2013-03-21T22:24:23+00:00 heroku[web.1]: source=heroku.13369226.web.1.d615093e-77a3-42b1-8da1-a228bd7582a1 measure=memory_cache val=0.05 units=MB
2013-03-21T22:24:23+00:00 heroku[web.1]: source=heroku.13369226.web.1.d615093e-77a3-42b1-8da1-a228bd7582a1 measure=memory_swap val=0.00 units=MB
2013-03-21T22:24:23+00:00 heroku[web.1]: source=heroku.13369226.web.1.d615093e-77a3-42b1-8da1-a228bd7582a1 measure=memory_pgpgin val=72259 units=pages
2013-03-21T22:24:23+00:00 heroku[web.1]: source=heroku.13369226.web.1.d615093e-77a3-42b1-8da1-a228bd7582a1 measure=memory_pgpgout val=9039 units=pages
2013-03-21T22:24:25+00:00 heroku[web.2]: source=heroku.13369226.web.2.cb423d08-dd15-41c1-9843-95bcdc269111 measure=load_avg_1m val=0.30
2013-03-21T22:24:25+00:00 heroku[web.2]: source=heroku.13369226.web.2.cb423d08-dd15-41c1-9843-95bcdc269111 measure=memory_total val=532.83 units=MB
2013-03-21T22:24:25+00:00 heroku[web.2]: source=heroku.13369226.web.2.cb423d08-dd15-41c1-9843-95bcdc269111 measure=memory_rss val=511.86 units=MB
2013-03-21T22:24:25+00:00 heroku[web.2]: source=heroku.13369226.web.2.cb423d08-dd15-41c1-9843-95bcdc269111 measure=memory_cache val=0.04 units=MB
2013-03-21T22:24:25+00:00 heroku[web.2]: source=heroku.13369226.web.2.cb423d08-dd15-41c1-9843-95bcdc269111 measure=memory_swap val=20.93 units=MB
2013-03-21T22:24:25+00:00 heroku[web.2]: source=heroku.13369226.web.2.cb423d08-dd15-41c1-9843-95bcdc269111 measure=memory_pgpgin val=145460 units=pages
2013-03-21T22:24:25+00:00 heroku[web.2]: source=heroku.13369226.web.2.cb423d08-dd15-41c1-9843-95bcdc269111 measure=memory_pgpgout val=14414 units=pages
2013-03-21T22:24:25+00:00 heroku[web.2]: Process running mem=532M(104.1%)
2013-03-21T22:24:25+00:00 heroku[web.2]: Error R14 (Memory quota exceeded)
2013-03-21T22:24:29+00:00 heroku[web.4]: source=heroku.13369226.web.4.25274242-a3af-4d2e-9da3-44e5e0a45c09 measure=load_avg_1m val=1.83
2013-03-21T22:24:29+00:00 heroku[web.4]: source=heroku.13369226.web.4.25274242-a3af-4d2e-9da3-44e5e0a45c09 measure=memory_total val=400.66 units=MB
2013-03-21T22:24:29+00:00 heroku[web.4]: source=heroku.13369226.web.4.25274242-a3af-4d2e-9da3-44e5e0a45c09 measure=memory_rss val=400.61 units=MB
2013-03-21T22:24:29+00:00 heroku[web.4]: source=heroku.13369226.web.4.25274242-a3af-4d2e-9da3-44e5e0a45c09 measure=memory_cache val=0.05 units=MB
2013-03-21T22:24:29+00:00 heroku[web.4]: source=heroku.13369226.web.4.25274242-a3af-4d2e-9da3-44e5e0a45c09 measure=memory_swap val=0.00 units=MB
2013-03-21T22:24:29+00:00 heroku[web.4]: source=heroku.13369226.web.4.25274242-a3af-4d2e-9da3-44e5e0a45c09 measure=memory_pgpgin val=113336 units=pages
2013-03-21T22:24:29+00:00 heroku[web.4]: source=heroku.13369226.web.4.25274242-a3af-4d2e-9da3-44e5e0a45c09 measure=memory_pgpgout val=10767 units=pages
2013-03-21T22:24:29+00:00 heroku[web.3]: source=heroku.13369226.web.3.2132f01f-94b1-4151-8fa8-09cdb2774919 measure=load_avg_1m val=0.25
2013-03-21T22:24:29+00:00 heroku[web.3]: source=heroku.13369226.web.3.2132f01f-94b1-4151-8fa8-09cdb2774919 measure=memory_total val=397.70 units=MB
2013-03-21T22:24:29+00:00 heroku[web.3]: source=heroku.13369226.web.3.2132f01f-94b1-4151-8fa8-09cdb2774919 measure=memory_rss val=397.64 units=MB
2013-03-21T22:24:29+00:00 heroku[web.3]: source=heroku.13369226.web.3.2132f01f-94b1-4151-8fa8-09cdb2774919 measure=memory_cache val=0.05 units=MB
2013-03-21T22:24:29+00:00 heroku[web.3]: source=heroku.13369226.web.3.2132f01f-94b1-4151-8fa8-09cdb2774919 measure=memory_swap val=0.00 units=MB
2013-03-21T22:24:29+00:00 heroku[web.3]: source=heroku.13369226.web.3.2132f01f-94b1-4151-8fa8-09cdb2774919 measure=memory_pgpgin val=112163 units=pages
2013-03-21T22:24:29+00:00 heroku[web.3]: source=heroku.13369226.web.3.2132f01f-94b1-4151-8fa8-09cdb2774919 measure=memory_pgpgout val=10353 units=pages

Answer 1

I had the same issue. Heroku is telling you the machine is running out of memory, not the Java VM. There is actually a bug in the Heroku Play 2.2 deployment, the startup script reads java_opts, not JAVA_OPTS.

I fixed it by setting both:

heroku config:add java_opts='-Xmx384m -Xms384m -Xss512k -XX:+UseCompressedOops'
heroku config:add JAVA_OPTS='-Xmx384m -Xms384m -Xss512k -XX:+UseCompressedOops'

I also had to set -Xms otherwise I got an error saying the min and max were incompatible. I guess Play2.2 was using a default higher than 384m.

To find out your total memory used, this is a useful equation (pre java 8):

Max memory = [-Xmx] + [-XX:MaxPermSize] + number_of_threads * [-Xss]